Java Logging之JUL系列——Logger Hierarchy

本文介绍JUL中日志记录器Logger的层级结构,JUL中Logger是按照树状结构进行组织的,日志记录器之间的父子关系是根据点号(.)进行区分的,比如有两个日志记录器,名字分别是cn.codecrazycn.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
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 159,835评论 4 364
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 67,598评论 1 295
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 109,569评论 0 244
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 44,159评论 0 213
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 52,533评论 3 287
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 40,710评论 1 222
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,923评论 2 313
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,674评论 0 203
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 34,421评论 1 246
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,622评论 2 245
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,115评论 1 260
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,428评论 2 254
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 33,114评论 3 238
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,097评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,875评论 0 197
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 35,753评论 2 276
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,649评论 2 271

推荐阅读更多精彩内容