Java日志系统分析

大家在写Java代码的时候经常会与log对象打交道,用法一般是在需要打log的类的静态域LOG中存储一个从工厂获取的java.util.logging.Logger对象,然后用该对象向控制台输出log。

合理的日志可以帮助我们观察系统运行情况、监控性能、追踪bug。日志的重要性无需赘述,想必大家都遇到过线上出bug,但是由于日志不充分无法定位问题的抓狂的场景。日志系统的设计初衷是方便开发者管理复杂应用程序中各式各样的log,提供不同的log级别、输出形式,并且可以灵活定制。

private static final LOG = Logger.getLogger(SomeClass.class);
LOG.info("log message.");

前一段时间将购物助手的log系统做迁移,顺便了解了下现在主流Java log框架的特性和实现,写出来和大家分享下。

本文旨在介绍Java日志系统的实现结构以及各个日志类库之间的关系,着重介绍一些实现原理。log系统的配置使用方法暂时略过。

一、Java日志系统结构

Java日志系统发展至今主要分成两层:日志实现库和日志接口框架(logging facade),按创立时间排序

实现库主要有:log4j 1.2,java.util.logging(简称JUL),logback,log4j 2.0
接口框架有:Commons-logging(简称JCL)和SLF4J(Simple Loggging Facade for Java)

二、JUL/log4j实现结构

jul

上图是JUL的结构,log4j的结构也大致相同,详见附录1。

  • Logger
  • 应用程序输出log用的对象,一般通过工厂LogManager/LogFactory获得,并且以当前class的完整类名作为名称,比如outfox.armani.zhushou.dao.Book163Dao。

  • LogRecord(log4j里叫LoggingEvent)
  • 存储一条log信息的对象,包括log字符串、线程上下文、格式化字符串、log等级、时间戳等信息,用于log格式化、过滤。

  • Formatter(log4j里叫Layout)
  • 用于格式化LogRecord的对象,比如Log4j的PatternLayout会将配置中的格式化字符串格式化输出成log文本:

    [%d{HH:mm:ss:SSS\}] %p %T %c{1\} | %m%n
    [23:00:18:147] INFO 91942 SalePageQuery | Start parse sale page
    

    formatter

  • Handler(log4j里叫Appender)
  • 控制log输出的对象,默认的一般是ConsoleHandler。查看java.util.logging.Handler和org.apache.log4j.Appender的继承关系:

    appender

    可以看出log4j提供了很多不同类型的输出方式。除了ConsoleAppender,还有每天更换一个日志文件的DailyRollingFileAppender、写入数据库的JDBCAppender、windows环境下的NTEventLogAppender、什么都不做的NullAppender等等。

  • Filter
  • Filter对象用于对Log对象的过滤。

    JUL log4j
    接口 java.util.logging.Filter org.apache.log4j.spi.Filter
    默认实现 DenyAllFilter LevelMatchFilter
    LevelRangeFilter StringMatchFilter
    作用对象 Logger或者Handler Appender
    类型 boolean isLoggable(LogRecord)
    true接受,false过滤
    int decide(LogginEvent)
    链式,-1过滤,0执行下一个Filter,1接受

了解了log实现库的结构,我们就能通过配置文件或者自己定制的方法实现各种各样的log形式和输出。比如我想把线上log中符合某些格式的Exception log发到RD邮箱甚至POPO里,以log4j为例,只需要做下面几件事:

  • 写一个ExceptionFilter,根据LoggingEvent中的Throwable进行过滤
  • 用SMTPAppender或者自己实现一个POPOAppender发送log
  • 如果想对log格式自定义,实现一个ExceptionLayout,将LoggingEvent转成String
  • 在log4j.xml中定义一个新的Appender,并为其指定Filter和Layout

三、Log接口框架

事实上只使用JUL或者log4j就可以完成记录log的工作了,我们写的大多数代码也是这么做的,那么SLF4J和JCL这种log接口框架是做什么的呢?

Log接口框架从不同的log实现中抽象出一个统一的接口,主要是Logger,Log接口框架本身不做log格式化、输出的工作,只是负责找到一个log实现库,调用该log实现库的方法输出log。

目的

1. 让代码从某个特定的log实现中解耦

这点的意义在于,如果你在开发一个工具模块提供给其他系统使用,这时候你想输出一些帮助使用者的log,但是你并不知道外部系统会用什么log系统,如果你随便使用一个log实现,那么这就要求调用者也使用相同的log实现,否则就没法对你输出的log进行格式化和过滤,甚至完全看不到log。而如果使用log接口框架,就不会有这种问题。

拿大家熟悉的工程环境的例子说明这种耦合带来的问题。购物搜索和购物助手依赖的某些包中用log4j输出log,而购物搜索和购物助手不使用log4j,classpath下没有log4j的配置文件,log4j找不到配置文件就不做任何输出,并输出下面这几行大家很眼熟的log

log4j:WARN No appenders could be found for logger ().
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

另外,购物助手2.9以前和现在购物搜索的配置环境下,不只是看不到使用log4j的log输出,也看不到JCL的log,比如spring的log。这是因为ivy依赖里有log4j,log4j的jar包就会在classpath下,根据JCL的绑定顺序会绑定log实现到log4j上,而log4j又找不到配置,所以JCL的log也不会输出。证实这点很简单,扔一个log4j.xml到classpath下然后重启resin,就会看到一堆从来没有见过的spring的log,比如一些bean的初始化和url mapping结果。

2. 降低切换log实现库的难度

log接口框架统一不同log实现库的接口差别,使得不改变代码就可以在不同log实现之间切换。不同log实现库的API虽然大同小异,但是这些差别使得切换log实现库的成本大大提高。比如JUL的log等级分成FINEST、FINER、FINE,而log4j则是TRACE、DEBUG、INFO。接口框架通过对Logger、LogFactory这些log接口做一层浅包装(facade),统一不同log实现的接口,并提供对不同log实现的绑定支持。

log实现库的绑定

Log接口框架需要绑定一个实现库才能正常工作。绑定的方法分成两种:动态绑定和静态绑定。

JCL:动态绑定(延迟绑定)

JUL作为第一个log接口框架,使用了基于反射的动态绑定的方法,原理很简单,预先定义好支持的log实现的工厂类的全路径到一个数组中,遍历这个数组,调用Class.forName依次尝试寻找各个log实现,如果当前class loader没找到,就去父class loader去找,直到找到任意一个实现为止。这个逻辑的代码在org.apache.commons.logging.impl.LogFactoryImpl#discoverLogImplemetation函数中,非常简短。

这种方法有致命的缺陷,这也正是SLF4J诞生的原因。Java EE的web容器,为了实现servlet规范中同一个容器中不同web app之间、web app和web容器之间的隔离,都使用的自己实现的class loader,逻辑和标准的class loader不同,导致一系列的无法正常发现log实现库的问题。Taxonomy of class loader problems encountered when using Jakarta Commons Logging这篇文章做了非常详尽的分析解释,文章的作者正是log4j和SLF4J的作者Ceki Gülcü,有兴趣的同学可以仔细阅读。

SLF4J:静态绑定

SLF4J为了解决JCL的class loader问题使用了静态绑定也就是编译期绑定的方法。原理也很简单,代码逻辑主要在slf4j.jar包中的org.slf4j.LogFactory#bind方法中。

SLF4J的LogFactory在slf4j-api.jar中,通过调用静态单例StaticLoggerBinder的getLoggerFactory方法得到真正的log实现库的工厂。但是slf4j-api.jar中并没有StaticLoggerBinder的实现。SLF4J给每个支持的log实现另外提供了一个单独的适配jar完成绑定,比如slf4j-jdk14.jar、slf4j-log412.jar、slf4-simple.jar、slf4j-nop.jar等,每个适配jar包都包含一个StaticLoggerBinder的实现,这个实现直接调用所绑定实现的工厂类并返回。所以classpath有slf4j-api.jar加一个log实现库的jar再加对应的适配jar,就能正常工作(SLF4J会检查是否有多个适配jar同时存在,如果有就会报错)。

SLF4J log桥接

SLF4J还提供log桥接的功能,也就是将老代码中使用其他log实现或者JUL的log导入到SLF4J以便统一管理,支持对Log4j、JUL和JCL的桥接。使用桥接以后,不用修改代码,原先代码中(包括依赖jar包)所有的log都是通过SLF4J绑定的log实现库输出。

桥接的实现方法是,对于JCL,jcl-over-slf4j.jar这个jar包,实现了原来commons-logging.jar中的org.apache.commons.logging.LogFactory,所以只要在ivy里替换commons-logging.jar为jcl-over-slf4j.jar,原来程序里所有用JCL输出的log就跑到了SLF4J中。log4j的桥接方法也是一样,用log4j-over-slf4j.jar替换log4j.jar。

JUL的桥接方法比较特殊,因为java.util包是不能被替换的,jul-to-slf4j.jar使用的方法是将JUL的root logger的handler替换成SLF4JBridgeHandler,这个handler用SLF4J的logger输出log。这种桥接方式在resin3环境下会有问题,resin3为了提供一些对log格式定制的功能,自己重写的一个LogManager,并通过class loader替换了JUL的LogManager,这个manager会向根logger加入一个handler,这个handler在web app的代码里是没法删除的,这就导致了如果使用slf4j的JUL桥接,原先的log就会被打印两遍。。。

附录1的图说明了不同的桥接模式。

四、总结

不同的log实现库结构大同小异,在功能特性丰富程度上有所差异

SLF4J已经基本取代JCL成为主流log接口框架,其解决了class loader问题,并且提供了更

建议大家使用SLF4J做log输出,log实现推荐logback或者log4j,因为有异步log的支持,并且可配置性比较高。JUL的log只能在原线程中同步输出,如果日质量比较大,会带来性能问题。之后会写一篇文章介绍log4j的一些配置使用的方法以及不同log实现库的一些差异。

五、附录

1. log4j结构示意图
log4j-arch

2. SLF4J桥接方式示意图

slf4j-bridge

六、参考资料

This entry was posted in 技术学习 and tagged , , , , . Bookmark the permalink.

发表评论

电子邮件地址不会被公开。 必填项已用*标注

此站点使用Akismet来减少垃圾评论。了解我们如何处理您的评论数据