Java Logging之JUL系列——Logger Hierarchy

本文介绍JUL中日志记录器Logger的层级结构，JUL中Logger是按照树状结构进行组织的，日志记录器之间的父子关系是根据点号(.)进行区分的，比如有两个日志记录器，名字分别是cn.codecrazy和cn.codecrazy.logging,那么前者就是后者的父日志记录器。通过后者的getParent()得到的Logger就是名字为cn.codecrazy的Logger。

根日志记录器（RootLogger)的名字是""(空字符串)，所有的日志记录器都是根日志记录器的后代。RootLogger是JUL帮我们创建的，不需要我们手动创建。我们可以直接通过Logger.getLogger("")得到RootLogger。

RootLogger的默认级别是INFO，默认Handler是ConsoleHander，该ConsoleHander的Formatter默认是SimpleFormatter。当我们通过如下语句创建Logger时：

public class JavaLogging {
    private static final Logger logger = Logger.getLogger("cn.codecrazy");
    public static void main(String[] args) {
        logger.info("Hello, Java Logging");
    }
}

我们创建了一个名称为cn.codecrazy的Logger，除此之外JUL还自动帮我们创建了一个RootLogger，虽然说cn.codecrazy的父日志记录器的名称理论上是cn，但是由于我们并没有创建一个名称为cn的日志记录器，因此cn.codecrazy的父Logger默认就是RootLogger(名称为""）。我们可以看下如下代码：

public class JavaLogging {
    private static final Logger logger = Logger.getLogger("cn.codecrazy");
    public static void main(String[] args) {
        Logger parent = logger.getParent();
        System.out.println("parent name = " + parent.getName());
        System.out.println("parent level = " + parent.getLevel());
        System.out.println("parent handler = " + parent.getHandlers()[0]);
        System.out.println("parent formatter = " + parent.getHandlers()[0].getFormatter());
        logger.info("Hello, Java Logging");
        System.out.println("sub name = " + logger.getName());
        System.out.println("sub level = " + logger.getLevel());
        System.out.println("sub handler lenght = " + logger.getHandlers().length);
    }
}

输出结果如下所示：

parent name = 
parent level = INFO
parent handler = java.util.logging.ConsoleHandler@4b67cf4d
parent formatter = java.util.logging.SimpleFormatter@7ea987ac
Aug 12, 2018 9:18:27 PM cn.codecrazy.study.logging.JavaLogging main
INFO: Hello, Java Logging
sub name = cn.codecrazy
sub level = null
sub handler lenght = 0

可以看出来cn.codecrazy的父Logger是RootLogger,RootLogger的名字为空字符串("")，级别是INFO，handler是ConsoleHadler，Formatter是SimpleFormatter。而cn.codecrazy日志记录器的level是null，也没有handler。

虽然cn.codecrazy日志记录器的getLevel()方法返回的值是null，但是该Logger是有级别的，getLevel()返回的是Logger对象的levelObject属性，但Logger还有一个属性是levelValue，真正进行级别比较的时候用的是levelValue，虽然levelObject的值为null，但是levelValue的值继承了它的父Logger的值，父Logger的级别是INFO，因此cn.codecrazy的levelValue的值就是INFO级别对应的整型值(800)。

cn.codecrazy确实是没有handler，但是通过cn.codecrazy记录日志时，会首先遍历自身的handlers，调用每一个handler的publish()方法对日志信息进行输出，然后如果该Logger的useParentHandlers属性为true的话，还会遍历其父Logger的handlers，并依次调用这些handler的publish()方法对日志进行输出，如果父Logger还有父Logger的话，并且其useParentHandlers属性也为true，则会继续依次调用父Logger的父Logger的handlers的publish()方法，直至追溯到RootLogger为止，或者追溯到某个父Logger的useParentHandlers属性为false，就不再向上层追溯了。

代码在java.util.logging.Logger类的log(LogRecord logRecord)方法中，所有的记录日志的方法最终都会调用到该方法，代码如下所示：

public void log(LogRecord record) {
    if (!isLoggable(record.getLevel())) {
        return;
    }
    Filter theFilter = filter;
    if (theFilter != null && !theFilter.isLoggable(record)) {
        return;
    }

    // Post the LogRecord to all our Handlers, and then to
    // our parents' handlers, all the way up the tree.

    Logger logger = this;
    while (logger != null) {
        final Handler[] loggerHandlers = isSystemLogger
                ? logger.accessCheckedHandlers()
                : logger.getHandlers();

        for (Handler handler : loggerHandlers) {
            handler.publish(record);
        }

        final boolean useParentHdls = isSystemLogger
                ? logger.useParentHandlers
                : logger.getUseParentHandlers();

        if (!useParentHdls) {
            break;
        }

        logger = isSystemLogger ? logger.parent : logger.getParent();
    }
}

由于我们的cn.codecrazy没有handler，而useParentHandlers属性默认为true，于是就使用其父Logger的handler进行输出，在这里就是RootLogger的ConsoleHandler，因此我们通过logger.info方法最终才能将信息输出到控制台，并且是以SimpleFormatter所指定的格式，这是RootLogger的默认配置。

如果我们再手动给cn.codecrazy的logger添加一个Handler,那么日志就会被输出两次，第一次是通过cn.codecrazy日志记录器的handler进行输出的，另一次是其父Logger的Handler输出的。如果我们把useParentHandlers属性设置为false，那么就不会再使用父Logger的handler进行输出。代码如下所示：

public class JavaLogging {
    private static final Logger logger = Logger.getLogger("cn.codecrazy");
    static {
        logger.addHandler(new ConsoleHandler());
        logger.setUseParentHandlers(false);
    }
    public static void main(String[] args) {
        logger.info("Hello, Java Logging");
    }
}

代码中虽然给cn.codecrazy这个子Logger添加了一个Handler,但是useParentHandlers被设置为false，因此最终的日志信息也不会被输出两次。

我们先理顺一下logger.info(“msg”)该语句的整个执行流程。假设logger的名称为cn.codecrazy，它的父Logger是RootLogger，RootLogger的各属性均采用默认。整个流程如下：

• 比较logger的级别是否高于INFO,由于logger没有设定级别，因此使用父Logger的级别(INFO)。
• 发现不高于，于是调用logger的Filter的isLoggable方法对信息进行过滤，由于logger没有添加Filter,因此不进行过滤。
• 依次调用logger的handlers，由于该logger没有指定handler，于是不进行日志输出。
• 判断useParentHandler，发现是true，因此调用其父Logger的handler的publish方法。
• 父Logger的Handler的publish方法中首先判断Hander的级别是否高于INFO。
• 不高于，继续调用Handler的Filter的isLoggable方法进行过滤。
• 由于该Handler没有配置Filter，因此跳过该步骤，并使用ConsoleHandler的getFormatter().format(LogRecord)方法进行格式化。
• 最终调用write方法将格式化之后的数据输出到控制台。

一个Logger对应1个Level，对应0个或1个Filter，对应0个或多个Handler，对应0个或1个ParentLogger 。
一个Handler对应1个Level，对应0个或1个Filter，对应1个Formatter。

下面我们重点分析一下日志级别和过滤器在多级日志记录器中的影响，我们先用如下方式创建三个Logger:

public class JavaLogging {
    private static final Logger logger1 = Logger.getLogger("");
    private static final Logger logger2 = Logger.getLogger("cn");
    private static final Logger logger3 = Logger.getLogger("cn.codecrazy");
    static {
        logger2.addHandler(new ConsoleHandler());
        logger3.addHandler(new ConsoleHandler());
    }

    public static void main(String[] args) {
        logger1.info("logger1");
        logger2.info("logger2");
        logger3.info("logger3");
    }
}

输出如下所示：

Aug 12, 2018 10:11:30 PM java.util.logging.LogManager$RootLogger log
INFO: logger1
Aug 12, 2018 10:11:30 PM cn.codecrazy.study.logging.JavaLogging main
INFO: logger2
Aug 12, 2018 10:11:30 PM cn.codecrazy.study.logging.JavaLogging main
INFO: logger2
Aug 12, 2018 10:11:30 PM cn.codecrazy.study.logging.JavaLogging main
INFO: logger3
Aug 12, 2018 10:11:30 PM cn.codecrazy.study.logging.JavaLogging main
INFO: logger3
Aug 12, 2018 10:11:30 PM cn.codecrazy.study.logging.JavaLogging main
INFO: logger3

logger1即是我们的RootLogger(通过getLogger("")方法中传入空字符串可得到该RootLogger实例)，logger1默认就有一个ConsoleHander，我们再手动帮logger2和logger3添加ConsoleHandler。总共创建了3个Logger，它们之间具有父子关系。logger3的父Logger是logger2，logger2的父Logger是logger1。通过前面对logger.info方法的整个流程的论述，我们很容易理解这里的输出为什么logger1输出了一次，logger2输出了2次，logger3输出了3次。

如果我们给Logger设置一个Filter的话，情况会如何呢?在上述代码中加上如下语句：
logger2.setFilter(logRecord->false);

即给logger2添加一个过滤器，该过滤器过滤掉所有日志，即经过该过滤器之后，不会有日志信息进行输出。这种情况下输出会是什么样的呢?

根据我们前面的论述，logger1.info(“logger1”)方法会输出一次"logger1"，然后执行logger2.info(“logger2”)，由于logger2有过滤器，在将日志信息交给Handler处理之前就已经被拦截了，因此不会输出”logger2″，并且不会将输出请求向上传递给父Logger,最终的输出结果中"logger2"一次都不会出现。

而执行logger3.info(“logger3”)时，由于logger3没有设置过滤器，因此会将日志信息交给logger3的Handler进行输出，之后再向上递交给logger2的handler进行输出，最后递交给logger1的handler进行输出，因此"logger3"会输出三次。

也就是说在logger2上设置过滤器，不会过滤从下层传上来的日志信息，因为下层传上来的日志信息只是要调用父Logger的Handler的publish方法，跟父Logger是否设置了Filter没有关系，但是如果父Logger的Hander中设置了Filter的话，还是会影响下层传递上来的日志信息的。原因是调用publish方法之前会先调用Handler的isLoggable()方法，而该方法中用到了Handler的Filter,Handler中的isLoggable()方法如下所示：

public boolean isLoggable(LogRecord record) {
    final int levelValue = getLevel().intValue();
    if (record.getLevel().intValue() < levelValue || levelValue == offValue) {
        return false;
    }
    final Filter filter = getFilter();
    if (filter == null) {
        return true;
    }
    return filter.isLoggable(record);
}

我们再探讨一下如果给logger2设置其他的级别时在日志层级中的影响。将设置Filter的代码替换成设置级别，代码如下所示:

public class JavaLogging {
    private static final Logger logger1 = Logger.getLogger("");
    private static final Logger logger2 = Logger.getLogger("cn");
    private static final Logger logger3 = Logger.getLogger("cn.codecrazy");
    static {
        logger2.addHandler(new ConsoleHandler());
        logger3.addHandler(new ConsoleHandler());
        logger2.setLevel(Level.WARNING);
    }

    public static void main(String[] args) {
        logger1.info("logger1");
        logger2.info("logger2");
        logger3.info("logger3");
    }
}

该代码的输出结果为：

Aug 12, 2018 10:50:30 PM java.util.logging.LogManager$RootLogger log
INFO: logger1

只有"logger1"被输出来了。我们可以分析一下，在执行logger2.info(“logger2”)时，由于logger2的级别被设置成了WARNING，高于INFO，因此该信息不会被输出来，也不会向上传递给父Logger。

而在执行logger3.info(“logger3”)时，由于logger3没有设置级别，因此继承了它的父Logger的级别，即logger2的级别(WARNING)，因此"logger3"也不能输出，并且也不会向上传递给它的父Logger的Handler进行处理。

我们可以显示地将logger3的级别设置为INFO，代码如下所示：

public class JavaLogging {
    private static final Logger logger1 = Logger.getLogger("");
    private static final Logger logger2 = Logger.getLogger("cn");
    private static final Logger logger3 = Logger.getLogger("cn.codecrazy");
    static {
        logger2.addHandler(new ConsoleHandler());
        logger3.addHandler(new ConsoleHandler());
        logger2.setLevel(Level.WARNING);
        logger3.setLevel(Level.INFO);
    }

    public static void main(String[] args) {
        logger1.info("logger1");
        logger2.info("logger2");
        logger3.info("logger3");
    }
}

此时的输出如下所示：

Aug 12, 2018 10:56:50 PM java.util.logging.LogManager$RootLogger log
INFO: logger1
Aug 12, 2018 10:56:50 PM cn.codecrazy.study.logging.JavaLogging main
INFO: logger3
Aug 12, 2018 10:56:50 PM cn.codecrazy.study.logging.JavaLogging main
INFO: logger3
Aug 12, 2018 10:56:50 PM cn.codecrazy.study.logging.JavaLogging main
INFO: logger3

此时执行logger3.info(“logger3”)时，由于logger3的级别不高于INFO，因此"logger3"会被logger3的Handler进行输出，并且会被向上传递给logger2的Handler进行处理，并最后交给logger1的Handler进行处理，于是"logger3"被输出了三次。

如果我们将logger2的Handler的级别设置为WARNING的话又会是什么情况呢？代码如下：

public class JavaLogging {
    private static final Logger logger1 = Logger.getLogger("");
    private static final Logger logger2 = Logger.getLogger("cn");
    private static final Logger logger3 = Logger.getLogger("cn.codecrazy");
    static {
        ConsoleHandler consoleHandler = new ConsoleHandler();
        consoleHandler.setLevel(Level.WARNING);
        logger2.addHandler(consoleHandler);
        logger3.addHandler(new ConsoleHandler());
        logger2.setLevel(Level.WARNING);
        logger3.setLevel(Level.INFO);
    }

    public static void main(String[] args) {
        logger1.info("logger1");
        logger2.info("logger2");
        logger3.info("logger3");
    }
}

根据我们前面论述的流程，可以推断，此时"logger3"会被输出2次，在向上递交到logger2的Handler进行输出时会被logger2的Handler过滤掉，不进行输出，但是依然会再向上递交到logger1的Handler进行处理。最终的输出结果为：

Aug 12, 2018 11:02:30 PM java.util.logging.LogManager$RootLogger log
INFO: logger1
Aug 12, 2018 11:02:30 PM cn.codecrazy.study.logging.JavaLogging main
INFO: logger3
Aug 12, 2018 11:02:30 PM cn.codecrazy.study.logging.JavaLogging main
INFO: logger3