图解编程:Java日志框架——SLF4J的设计

2,765 阅读10分钟

如果把工作看作是一个遇到问题-解决问题的过程,那么在拿一份薪水的同时,我们也需要多问一下自己:在解决问题的过程中,我们学到了什么?

很多人可能会抱怨,自己是初级码农,天天写CRUD,接触不到架构、接触不到复杂场景。那么如何实现从初级到中级再到高级的跃迁?它实际暗含在每一天的积累中。首先要学会发现问题,在解决之余,留一些时间给自己溯源、复盘,就能给自己带来一些进步,而这些细微的提升,正是充实和丰富自己知识网络的绝佳机会。

事情的起因,在使用slf4j作为日志框架时,当一段代码抛出异常,进行异常捕获之后,日志中却没有打印相应的调用栈。

首先来看看这段代码:

try{
  int i = 1 / 0;
} catch (Exception reqEx) {
       LOGGER.error("xxx about:{}, cause:{}", ip, reqEx);
}

你觉得它会输出哪些东西?

在检查日志时,我们发现,这段代码在捕获异常之后,在有些机器上执行结果会打印出exception的异常栈,有些机器上则只会单纯地把reqEx当做一个普通对象,打印toString信息,不会打印出异常栈。

测试发现,如上代码在logback下,会输出栈异常信息:

xxx about:10.10.10.10, cause:{}
java.lang.ArithmeticException: / by zero
	at com.zzc.test.dubbo.ProviderBootStrap.main(ProviderBootStrap.java:32)

可以看到尽管有两个{},但是最后一个参数如果是Throwable类型的话,则优先当做Throwable处理,会打印出异常栈信息。

但是相同的代码在log4j下,输出情况则有所区别:

xxx about:10.10.10.10, cause: java.lang.ArithmeticException: / by zero

可以看到,log4j下会优先选择满足占位符,尽管最后一个参数是异常类型,则也进行了toStirng输出,而异常的toString并不会将异常栈一起输出。

为什么会这样呢?这就需要先给大家普及一下slf4j相关的门面模式(也称为外观模式)的知识了,像slf4j的官网所说的一样

The Simple Logging Facade for Java (SLF4J) serves as a simple facade or abstraction for various logging frameworks, such as java.util.logging, logback and log4j. SLF4J allows the end-user to plug in the desired logging framework at deployment time. Note that SLF4J-enabling your library/application implies the addition of only a single mandatory dependency, namely slf4j-api-2.0.0-alpha2-SNAPSHOT.jar.

翻译成中文就可以这么理解:slf4j为多种多样的日志框架(比如logging, logback and log4j)充当门面或抽象化的接口,本身并没有具体实现如何进行日志地打印以及日志打印的格式这些细节。需要具体的日志框架来实现并执行。

先从概念上了解一下:门面模式(Facade Pattern),外部与一个子系统的通信必须通过一个统一的外观对象进行,为子系统中的一组接口提供一个一致的界面,外观模式定义了一个高层接口,这个接口使得这一子系统更加容易使用。门面模式又称为外观模式,它是一种对象结构型模式。 为了具体说明这个门面模式是如何工作的,这里写了一个简单例子,让我们根据这个例子看看这里面的学问。

上面所说的“高层接口”指的就是slf4j,而子系统则是诸如logging, logback and log4j这种具体实现。

为了更加直观地理解门面模式,举一个通俗易懂的例子:

一般的医院都会分为挂号、门诊、化验、收费、取药等。病人要想治好自己的病(相当于一个客户端想要实现自己的功能)就要和医院的各个部门打交道。首先,病人需要挂号,然后门诊,如果医生要求化验的话,病人就要去化验,然后再回到门诊室,最后拿药,经过一系列复杂的过程后才能完成看病的过程。如下图所示:

解决这种不便的方式就是引入门面模式。如果我们在医院设立一个接待员的话,病人只负责和接待员接触,由接待员负责与医院的各个部门打交道,如下图所示:

相较于医院,现在很多的体检机构,都有这种“专门的接待员”,本质就是门面模式。

为了具体说明门面模式在slf4j中是如何工作的,这里写了一个简单例子,让我们根据这个例子看看这里面的学问。

    private  static final Logger LOGGER = LoggerFactory.getLogger(Main.class);
    public static void main(String[] args) {
        LOGGER.info("Hello,World");
    }

如上程序,所以大家很可能在运行的时候发现,调用了LOGGER.info方法但是没有任何日志打印出来,并且控制台上还出现了如下的警告。

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

debug发现,LOGGER.info调用的是org.slf4j.helpers.NOPLogger#info,但是这是一个空实现。这种情况往往就是大家只引入了slf4j-api这个门面的jar包,但是没告诉SLF4J如何去打印日志,所以slf4j采用了默认空实现的方式。那这些异常又是怎么回事呢?

我们进入源码看看是如何根据LoggerFactory.getLogger是如何获取到对应的Logger的。以下代码都来自于slf4j1.7.29版本。

跟入源码

首先会去拿对应的LoggerFactory,这是个全局单例的对象。

  public static Logger getLogger(String name) {
        ILoggerFactory iLoggerFactory = getILoggerFactory();
        return iLoggerFactory.getLogger(name);
  }

继续跟到org.slf4j.LoggerFactory#getILoggerFactory方法中,

 public static ILoggerFactory getILoggerFactory() {
        if (INITIALIZATION_STATE == UNINITIALIZED) {
            synchronized (LoggerFactory.class) {
                if (INITIALIZATION_STATE == UNINITIALIZED) {
                    INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                    performInitialization();
                }
            }
        }
        switch (INITIALIZATION_STATE) {
        case SUCCESSFUL_INITIALIZATION:
            return StaticLoggerBinder.getSingleton().getLoggerFactory();
        case NOP_FALLBACK_INITIALIZATION:
            return NOP_FALLBACK_FACTORY;
        case FAILED_INITIALIZATION:
            throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
        case ONGOING_INITIALIZATION:
            // support re-entrant behavior.
            // See also http://jira.qos.ch/browse/SLF4J-97
            return SUBST_FACTORY;
        }
        throw new IllegalStateException("Unreachable code");
    }

可以看到当if (INITIALIZATION_STATE == UNINITIALIZED),即当第一次获取时,此时处于未初始化时,则首先调用performInitialization进行初始化。(这里还用了双重检测避免多线程下重复初始化)

performInitialization方法随后调用核心方法bind,可以看到该方法的catch块中看到了我们熟悉的那段警告。

    private final static void bind() {
        try {
            Set<URL> staticLoggerBinderPathSet = null;
            if (!isAndroid()) { // 非安卓应用
                staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
                reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
            }
            StaticLoggerBinder.getSingleton();
            INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            reportActualBinding(staticLoggerBinderPathSet);
            fixSubstituteLoggers(); // 这个方法我们后面会说到
            replayEvents();        // 同上
            SUBST_FACTORY.clear();  // 清空缓存日志事件队列
        } catch (NoClassDefFoundError ncde) {
            String msg = ncde.getMessage();
            if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
                INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;
                Util.report("Failed to load class \"org.slf4j.impl.StaticLoggerBinder\".");
                Util.report("Defaulting to no-operation (NOP) logger implementation");
                Util.report("See " + NO_STATICLOGGERBINDER_URL + " for further details.");
            } else {
                failedBinding(ncde);
                throw ncde;
            }
        } 
         ....省略
    }

对于非安卓应用,会调用findPossibleStaticLoggerBinderPathSet,该方法是重中之重,从名字来看,该方法会去寻找所有可能的StaticLoggerBinder类路径,Failed to load class "org.slf4j.impl.StaticLoggerBinder".我们在警告中也看到过该类的身影,所以此类就是关键所在了。

private static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class";
static Set<URL> findPossibleStaticLoggerBinderPathSet() {
        Set<URL> staticLoggerBinderPathSet = new LinkedHashSet<URL>();
        try {
            ClassLoader loggerFactoryClassLoader = LoggerFactory.class.getClassLoader();
            Enumeration<URL> paths;
            if (loggerFactoryClassLoader == null) {
                paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH);
            } else {
                paths = loggerFactoryClassLoader.getResources(STATIC_LOGGER_BINDER_PATH);
            }
            while (paths.hasMoreElements()) {
                URL path = paths.nextElement();
                staticLoggerBinderPathSet.add(path);
            }
        } catch (IOException ioe) {
            Util.report("Error getting resources from path", ioe);
        }
        return staticLoggerBinderPathSet;
    }

可以看到,该方法会去当前应用的classpath下去找所有的org/slf4j/impl/StaticLoggerBinder.class并且返回。(2.0版本以上用了SPI机制去发现,具体看github.com/qos-ch/slf4…)。

搜索了一下,当前程序应用果然找不到该类,所以就会有了应用启动的时候那段警告,并且降级到org.slf4j.helpers.NOPLogger的空实现了。我们再去其他日志正常打印的应用下搜索下该类,可以看到:

几个你经常看到伴随着slf4j-api这个jar包一起引入的jar中都会有这个类的存在,且如果发现某一个应用有多个org/slf4j/impl/StaticLoggerBinder类,则会打印出类似Found binding in [jar:file:/Users/xxx/.m2/repository/org/slf4j/slf4j-log4j12/1.7.25/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]这样的警告,并且按照类加载顺序选择最靠前的一个进行使用。

问题所在

看到这里,大家可能就明白了,为啥平常在使用日志的时候,除了引入slf4j-api这个jar包之外,还会引入其他的诸如log4j、logback这类的jar包。简而言之,就是slf4j提供了一个日志的标准,各大厂家都去遵循标准来进行具体的实现。尽管实现可能有细小的差异,就像我上面说的那个问题在log4j和logback下的行为并不完全一致,所以在日常写代码中,也尽可能地需要遵循标准方式进行打印日志,例如最初的那个起因的代码,我们只需要改成LOGGER.error("xxx about:{}, cause:", ip, reqEx);即可以在任何实现下都打印出异常栈信息了,即异常不需要去匹配{}占位符。

一个优秀设计

这里额外需要说到的一个设计,感兴趣的读者可以看一下,不感兴趣可以跳过看下一段。

case ONGOING_INITIALIZATION:的情况下,此时是因为其他线程已经在初始化LoggerFactory了,为了避免阻塞等待初始化,当其他线程发现有线程已经在初始化时则会返回一个SUBST_FACTORY,该对象是SubstituteLoggerFactory类型,在其上调用getLogger会返回一个临时的SubstituteLogger

SubstituteLogger是一个装饰者类,所有方法的调用都会交给真正的Logger对象进行处理,如info方法所示:

 public void info(String msg, Throwable t) {
        delegate().info(msg, t);
  }

delegate方法的处理也很容易理解,当delegate为空时,则判断createdPostInitialization是否为真,为真则返回NOP_LOGGER,否则通过getEventRecordingLogger返回一个EventRecodingLogger,该Logger会将所有日志包装成事件,放到对应的队列中缓存。

 private volatile Logger _delegate;
 Logger delegate() {
        if(_delegate != null) {
            return _delegate;
        }
        if(createdPostInitialization) {
            return NOPLogger.NOP_LOGGER;
        } else {
            return getEventRecordingLogger();
        }
    }

_delegate对象在另一个线程初始化LoggerFactory完成之后,调用org.slf4j.LoggerFactory#fixSubstituteLoggers方法进行注入。

而之前缓存的日志事件也会由该初始化线程调用org.slf4j.LoggerFactoryreplayEvents方法由真正的Logger进行重放。

这个设计点使得多线程在初始化LoggerFactory的时候不会阻塞对方,并且也不会影响在初始化结束之前的日志记录。

Java日志框架的混乱历史

看到这里,有心的读者肯定会有这么一个疑惑,为什么Java日志框架需要一个门面标准,而不是统一一个类库的实现标准?

首先来看看历史的车轮:

Java日志框架的发展历史

  • log4j是Java社区最早的日志框架,推出后一度成为Java的事实日志标准,据说Apache曾建议Sun把log4j加入到Java标准库中,但是被Sun拒绝。

  • 在Java1.4中,Sun在标准库中推出了自己的日志框架java.util.logging,功能相对简陋。

  • 虽然logging相对简陋,但还是有类库采用了它,这就出现了同一个项目中同时使用log4j和logging要维护两套配置的问题,Apache试图解决这个问题,推出了JCL日志门面(接口),定义了一套日志接口,底层实现支持log4j和logging,但是并没有解决多套配置的问题。

  • log4j的主力开发Ceki Gülcü由于某些原因离开了Apache,创建了slf4j日志门面(接口),并实现了性能比log4j性能更好的logback(如果Ceki Gülcü没有离开Apache,这应该就是log4j2的codebase了)

  • Apache不甘示弱,成立了不兼容log4j 1.x的log4j2项目,引入了logback的特性(还酸酸地说解决了logback架构上存在的问题),但目前采用率不是很高。

当你在开发一个新项目,进行日志框架选型时,尽量避免采用单一的实现,更好的方式是使用门面模式,秉承面向接口编程的思想。这样做有什么好处呢?尤其是当你的代码是以SDK的形式提供给他人的,假如你的SDK中写死了logback,而调用方使用的是log4j,那么就会产生冲突;而如果你使用的是门面,就能与具体实现解耦。

下面这张图就展示了slf4j门面是如何配合其他具体实现框架工作的。其中可以看到,在面对log4j和logging时,slf4j需要一个额外的适配层来进行适配,这是因为log4j和logging比较老,当初的设计就不是面向门面的。

image