JDK Logging 深刻分析

日志输出是全部系统必备的，不少开发人员可能由于经常使用log4j而忽视了JDK logging模块，二者之间是否有联系？是怎样的联系？JDK logging处理细节是怎么样的？

#0 系列目录#

• 2种日志接口框架，4种日志实现框架
• jdk-logging、log4j、logback日志介绍及原理
• jcl与jul、log4j一、log4j二、logback的集成原理
• slf4j与jul、log4j一、log4j二、logback的集成原理
• slf4j、jcl、jul、log4j一、log4j二、logback大总结
• slf4j + log4j原理实现及源码分析
• Apache Log4j
• Log4j架构分析与实战
• Log4J配置文件详解
• Apache Commons Logging
• Commons Logging 架构分析
• JDK Logging
• JDK Logging 深刻分析
• Logback
• 从Log4j迁移到LogBack的理由
• Logback 深刻分析
• Apache Log4j2
• Log4j2架构分析与实战
• Log4j2配置文件详解

#1 从例子开始# JDK Logging的使用很简单，以下代码所示，先使用Logger类的静态方法getLogger就能够获取到一个logger，而后在任何地方均可以经过获取到的logger进行日志输入。好比相似logger.info("Main running.")的调用。

package com.bes.logging;

import java.util.logging.Level;
import java.util.logging.Logger;

public class LoggerTest {
      private static Loggerlogger = Logger.getLogger("com.bes.logging");
      public static void main(String argv[]) {
               // Log a FINEtracing message
               logger.info("Main running.");
               logger.fine("doingstuff");
               try {
                         Thread.currentThread().sleep(1000);// do some work
               } catch(Exception ex) {
                         logger.log(Level.WARNING,"trouble sneezing", ex);
               }
               logger.fine("done");
      }
}

不作任何代码修改和JDK配置修改的话，运行上面的例子，你会发现，控制台只会出现【Main running.】这一句日志。以下问题应该呈如今你的大脑里…

1. 【Main running.】之外的日志为何没有输出？怎么让它们也可以出现？
2. 日志中出现的时间、类名、方法名等是从哪里输出的？
3. 为何日志就会出如今控制台？
4. 大型的系统可能有不少子模块(可简单理解为有不少包名)，如何对这些子模块进行单独的日志级别控制？
5. apache那个流行的log4j项目和JDK的logging有联系吗，怎么实现本身的LoggerManager？

带着这些问题，可能你更有兴趣了解一下JDK的logging机制，本章为你分析这个简单模块的机制。 #2 术语解答# ##2.1 Logger##

1. 代码须要输入日志的地方都会用到Logger，这几乎是一个JDK logging模块的代言人，咱们经常用Logger.getLogger("com.aaa.bbb");得到一个logger，而后使用logger作日志的输出。
2. logger其实只是一个逻辑管理单元，其多数操做都只是做为一个中继者传递别的<角色>，好比说：Logger.getLogger(“xxx”)的调用将会依赖于LogManager类，使用logger输入日志信息的时候会调用logger中的全部handler进行日志的输入。
3. logger是有层次关系的，咱们可通常性的理解为包名之间的父子继承关系。每一个logger一般以java包名为其名称。子logger一般会从父logger继承logger级别、handler、ResourceBundle名(与国际化信息有关)等。
4. 整个JVM会存在一个名称为空的root logger，全部匿名的logger都会把root logger做为其父。

##2.2 LogManager## LogManager：整个JVM内部全部logger的管理，logger的生成、获取等操做都依赖于它，也包括配置文件的读取。LogManager中会有一个Hashtable【private Hashtable<String,WeakReference<Logger>> loggers】用于存储目前全部的logger，若是须要获取logger的时候，Hashtable已经有存在logger的话就直接返回Hashtable中的，若是hashtable中没有logger，则新建一个同时放入Hashtable进行保存。

##2.3 Handler## Handler：用来控制日志输出的，好比JDK自带的ConsoleHanlder把输出流重定向到System.err输出，每次调用Logger的方法进行输出时都会调用Handler的publish方法，每一个logger有多个handler。咱们能够利用handler来把日志输入到不一样的地方(好比文件系统或者是远程Socket链接)。

##2.4 Formatter## Formatter：日志在真正输出前须要进行必定的格式化，好比是否输出时间？时间格式？是否输入线程名？是否使用国际化信息等都依赖于Formatter。

##2.5 Log Level## Log Level：没必要说，这是作容易理解的一个，也是logging为何能帮助咱们适应从开发调试到部署上线等不一样阶段对日志输出粒度的不一样需求。JDK Log级别从高到低为OFF(2^31-1)—>SEVERE(1000)—>WARNING(900)—>INFO(800)—>CONFIG(700)—>FINE(500)—>FINER(400)—>FINEST(300)—>ALL(-2^31)，每一个级别分别对应一个数字，输出日志时级别的比较就依赖于数字大小的比较。可是须要注意的是：不只是logger具备级别，handler也是有级别，也就是说若是某个logger级别是FINE，客户但愿输入FINE级别的日志，若是此时logger对应的handler级别为INFO，那么FINE级别日志仍然是不能输出的。

##2.6 对应关系##

1. LogManager与logger是1对多关系，整个JVM运行时只有一个LogManager，且全部的logger均在LogManager中。
2. logger与handler是多对多关系，logger在进行日志输出的时候会调用全部的hanlder进行日志的处理。
3. handler与formatter是一对一关系，一个handler有一个formatter进行日志的格式化处理。
4. 很明显：logger与level是一对一关系，hanlder与level也是一对一关系。

#3 Logging配置# JDK默认的logging配置文件为：$JAVA_HOME/jre/lib/logging.properties，可使用系统属性java.util.logging.config.file指定相应的配置文件对默认的配置文件进行覆盖，配置文件中一般包含如下几部分定义：

1. handlers：用逗号分隔每一个Handler，这些handler将会被加到root logger中。也就是说即便咱们不给其余logger配置handler属性，在输出日志的时候logger会一直找到root logger，从而找到handler进行日志的输入。

2. level是root logger的日志级别。

3. <handler>.xxx是配置具体某个handler的属性，好比java.util.logging.ConsoleHandler.formatter即是为ConsoleHandler配置相应的日志Formatter。

4. logger的配置，全部以[.level]结尾的属性皆被认为是对某个logger的级别的定义，如com.bes.server.level=FINE是给名为[com.bes.server]的logger定义级别为FINE。顺便说下，前边提到过logger的继承关系，若是还有com.bes.server.webcontainer这个logger，且在配置文件中没有定义该logger的任何属性，那么其将会从[com.bes.server]这个logger进行属性继承。除了级别以外，还能够为logger定义handler和useParentHandlers(默认是为true)属性，如com.bes.server.handler=com.bes.test.ServerFileHandler(须要是一个extends java.util.logging.Handler的类)，com.bes.server.useParentHandlers=false(意味着com.bes.server这个logger进行日志输出时，日志仅仅被处理一次，用本身的handler输出，不会传递到父logger的handler)。如下是JDK配置文件示例：

handlers= java.util.logging.FileHandler,java.util.logging.ConsoleHandler
.level= INFO
java.util.logging.FileHandler.pattern = %h/java%u.log
java.util.logging.FileHandler.limit = 50000
java.util.logging.FileHandler.count = 1
java.util.logging.FileHandler.formatter =java.util.logging.XMLFormatter
java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter =java.util.logging.SimpleFormatter
com.xyz.foo.level = SEVERE
sun.rmi.transport.tcp.logLevel = FINE;

#4 Logging执行原理# ##4.1 Logger的获取##

1. 首先是调用Logger的以下方法得到一个logger：

public static synchronized Logger getLogger(String name) {
        LogManager manager =LogManager.getLogManager();
        return manager.demandLogger(name);
    }

2. 上面的调用会触发java.util.logging.LoggerManager的类初始化工做，LoggerManager有一个静态化初始化块(这是会先于LoggerManager的构造函数调用的~_~)：

static {  
    AccessController.doPrivileged(newPrivilegedAction<Object>() {  
        public Object run() {  
            String cname =null;  
            try {  
                cname =System.getProperty("java.util.logging.manager");  
                if (cname !=null) {  
                    try {  
                        Class clz =ClassLoader.getSystemClassLoader().loadClass(cname);  
                        manager= (LogManager) clz.newInstance();  
                    } catch(ClassNotFoundException ex) {  
                        Class clz =Thread.currentThread().getContextClassLoader().loadClass(cname);  
                        manager= (LogManager) clz.newInstance();  
                    }  
                }  
            } catch (Exceptionex) {  
                System.err.println("Could not load Logmanager \"" + cname+ "\"");  
                ex.printStackTrace();  
            }  
            if (manager ==null) {
                manager = newLogManager();
            }  
            manager.rootLogger= manager.new RootLogger();
            manager.addLogger(manager.rootLogger);
            Logger.global.setLogManager(manager);
            manager.addLogger(Logger.global);
            return null;  
        }  
    });  
}

从静态初始化块中能够看出LoggerManager是可使用系统属性java.util.logging.manager指定一个继承自java.util.logging.LoggerManager的类进行替换的，好比Tomcat启动脚本中就使用该机制以使用本身的LoggerManager。

不论是JDK默认的java.util.logging.LoggerManager仍是自定义的LoggerManager，初始化工做中均会给LoggerManager添加两个logger，一个是名称为””的root logger，且logger级别设置为默认的INFO；另外一个是名称为global的全局logger，级别仍然为INFO。

LogManager”类”初始化完成以后就会读取配置文件(默认为$JAVA_HOME/jre/lib/logging.properties)，把配置文件的属性名的属性值这样的键值对保存在内存中，方便以后初始化logger的时候使用。

3. 1步骤中Logger类发起的getLogger操做将会调用java.util.logging.LoggerManager的以下方法：

Logger demandLogger(String name) {
        Logger result =getLogger(name);
        if (result == null) {
            result = newLogger(name, null);
            addLogger(result);
            result =getLogger(name);
        }
        return result;
    }

能够看出，LoggerManager首先从现有的logger列表中查找，若是找不到的话，会新建一个looger并加入到列表中。固然很重要的是新建looger以后须要对logger进行初始化，这个初始化详见java.util.logging.LoggerManager#addLogger()方法中，改方法会根据配置文件设置logger的级别以及给logger添加handler等操做。

到此为止logger已经获取到了，你同时也须要知道此时你的logger中已经有级别、handler等重要信息，下面将分析输出日志时的逻辑。

##4.2 日志的输出## 首先咱们一般会调用Logger类下面的方法，传入日志级别以及日志内容。

public void log(Levellevel, String msg) {
        if (level.intValue() < levelValue ||levelValue == offValue) {
            return;
        }
        LogRecord lr = new LogRecord(level, msg);
        doLog(lr);
    }

该方法能够看出，Logger类首先是进行级别的校验，若是级别校验经过，则会新建一个LogRecord对象，LogRecord中除了日志级别，日志内容以外还会包含调用线程信息，日志时刻等；以后调用doLog(LogRecord lr)方法。

private void doLog(LogRecord lr) {
        lr.setLoggerName(name);
        String ebname =getEffectiveResourceBundleName();
        if (ebname != null) {
            lr.setResourceBundleName(ebname);
            lr.setResourceBundle(findResourceBundle(ebname));
        }
        log(lr);
    }

doLog(LogRecord lr)方法中设置了ResourceBundle信息(这个与国际化有关)以后便直接调用log(LogRecord record)方法。

public void log(LogRecord record) {
        if (record.getLevel().intValue() <levelValue || levelValue == offValue) {
            return;
        }
        synchronized (this) {
            if (filter != null &&!filter.isLoggable(record)) {
                return;
            }
        }
        Logger logger = this;
        while (logger != null) {
            Handler targets[] = logger.getHandlers();
            if(targets != null) {
                for (int i = 0; i < targets.length; i++) {
                    targets[i].publish(record);
                }
            }
            if(!logger.getUseParentHandlers()) {
                break;
            }
            logger= logger.getParent();
        }
    }

很清晰，while循环是重中之重，首先从logger中获取handler，而后分别调用handler的publish(LogRecordrecord)方法。while循环证实了前面提到的会一直把日志委托给父logger处理的说法，固然也证实了可使用logger的useParentHandlers属性控制日志不进行往上层logger传递的说法。到此为止logger对日志的控制差很少算是完成，接下来的工做就是看handler的了，这里咱们以java.util.logging.ConsoleHandler为例说明日志的输出。

public class ConsoleHandler extends StreamHandler {
        public ConsoleHandler() {
            sealed = false;
            configure();
            setOutputStream(System.err);
            sealed = true;
        }
    }

ConsoleHandler构造函数中除了须要调用自身的configure()方法进行级别、filter、formatter等的设置以外，最重要的咱们最关心的是setOutputStream(System.err)这一句，把系统错误流做为其输出。而ConsoleHandler的publish(LogRecordrecord)是继承自java.util.logging.StreamHandler的，以下所示：

public synchronized void publish(LogRecord record) {
        if(!isLoggable(record)) {
            return;
        }
        String msg;
        try {
            msg =getFormatter().format(record);
        } catch (Exception ex){
            // We don't want tothrow an exception here, but we
            // report theexception to any registered ErrorManager.
            reportError(null,ex, ErrorManager.FORMAT_FAILURE);
            return;
        }       
        try {
            if (!doneHeader) {
                writer.write(getFormatter().getHead(this));
                doneHeader =true;
            }
            writer.write(msg);
        } catch (Exception ex){
            // We don't want tothrow an exception here, but we
            // report theexception to any registered ErrorManager.
            reportError(null,ex, ErrorManager.WRITE_FAILURE);
        }
    }

方法逻辑也很清晰，首先是调用Formatter对消息进行格式化，说明一下：格式化实际上是进行国际化处理的重要契机。而后直接把消息输出到对应的输出流中。须要注意的是handler也会用本身的level和LogRecord中的level进行比较，看是否真正输出日志。

#5 总结# 至此，整个日志输出过程已经分析完成。细心的读者应该能够解答以下四个问题了。

1. 【Main running.】之外的日志为何没有输出？怎么让它们也可以出现？

这就是JDK默认的logging.properties文件中配置的handler级别和跟级别均为info致使的，若是但愿看到FINE级别日志，须要修改logging.properties文件,同时进行以下两个修改

java.util.logging.ConsoleHandler.level= FINE//修改
com.bes.logging.level=FINE//添加

2. 日志中出现的时间、类名、方法名等是从哪里输出的？

请参照[java.util.logging.ConsoleHandler.formatter= java.util.logging.SimpleFormatter]配置中指定的java.util.logging.SimpleFormatter类，其public synchronized String format(LogRecord record) 方法说明了一切。

public synchronized String format(LogRecord record) {
        StringBuffer sb = new StringBuffer();
        // Minimize memory allocations here.
        dat.setTime(record.getMillis());
        args[0] = dat;
        StringBuffer text = new StringBuffer();
        if (formatter == null) {
            formatter = new MessageFormat(format);
        }
        formatter.format(args, text, null);
        sb.append(text);
        sb.append(" ");
        if (record.getSourceClassName() != null) {     
            sb.append(record.getSourceClassName());
        } else {
            sb.append(record.getLoggerName());
        }
        if (record.getSourceMethodName() != null) {
            sb.append(" ");
            sb.append(record.getSourceMethodName());
        }
        sb.append(lineSeparator);
        String message = formatMessage(record);
        sb.append(record.getLevel().getLocalizedName());
        sb.append(": ");
        sb.append(message);
        sb.append(lineSeparator);
        if (record.getThrown() != null) {
            try {
                StringWriter sw = newStringWriter();
                PrintWriter pw = newPrintWriter(sw);
                record.getThrown().printStackTrace(pw);
                pw.close();
                sb.append(sw.toString());
            } catch (Exception ex) {
            }
        }
        return sb.toString();
    }

3. 为何日志就会出如今控制台？

看到java.util.logging.ConsoleHandler 类构造方法中的[setOutputStream(System.err)]语句，相信你已经明白。

4. 大型的系统可能有不少子模块(可简单理解为有不少包名)，如何对这些子模块进行单独的日志级别控制？

在logging.properties文件中分别对各个logger的级别进行定义，且最好使用java.util.logging.config.file属性指定本身的配置文件。

5. 扩充：apache那个流行的log4j项目和JDK的logging有联系吗，怎么实现本身的LoggerManager？

没联系，两个都是日志框架具体实现，二者的LoggerManager实现逻辑大致一致，只是具体细节不一样。Log4j相关内容，具体可参见Log4j架构分析与实战 & slf4j + log4j原理实现及源码分析。