Java 日志的江湖

这个议题在网上已经有很多很多讨论的文章了,但是我还是决定自己“重造一遍轮子”。因为:

诗句

起因

最近在协助重构公司内部的一个RPC框架,这个系统中要记录日志。因为以前开发的所有项目几乎都是具体的应用,也就是不会被其他项目引用;或者一些纯接口性质的、不需要记录日志的二方库。所以没什么经验,在这个中间件项目中也直接依赖了logback。然而对于中间件项目来说,这是不被允许的,因为你不知道你的jar最终会被其他用户引入到怎样的系统中,而用户系统中的日志系统与中间件中的日志系统又有怎样的关系。所以我决定趁这次机会,把java世界里的日志系统捋一捋。

Java 日志框架的发展史

先来看看Java世界里日志框架的发展史。
本段内容主要引自于此文

  • 1996年早期,欧洲安全电子市场项目组决定编写它自己的程序跟踪API(Tracing API)。经过不断的完善,这个API终于成为一个十分受欢迎的Java日志软件包,即Log4j。后来Log4j成为Apache基金会项目中的一员。
  • 期间Log4j近乎成了Java社区的日志标准。据说Apache基金会还曾经建议sun引入Log4j到java的标准库中,但Sun拒绝了。
  • 2002年Java1.4发布,Sun推出了自己的日志库JUL(Java Util Logging),其实现基本模仿了Log4j的实现。在JUL出来以前,log4j就已经成为一项成熟的技术,使得log4j在选择上占据了一定的优势。
  • 接着,Apache推出了Jakarta Commons Logging,JCL只是定义了一套日志接口(其内部也提供一个Simple Log的简单实现),支持运行时动态加载日志组件的实现,也就是说,在你应用代码里,只需调用Commons Logging的接口,底层实现可以是log4j,也可以是Java Util Logging。
  • 后来(2006年),Ceki Gülcü(log4j的作者)不适应Apache的工作方式,离开了Apache。然后先后创建了slf4j(日志门面接口,类似于Commons Logging)和Logback(Slf4j的实现)两个项目,并回瑞典创建了QOS公司,QOS官网上是这样描述Logback的:The Generic,Reliable Fast&Flexible Logging Framework(一个通用,可靠,快速且灵活的日志框架)。
  • 现今,Java日志领域被划分为两大阵营:Commons Logging阵营和SLF4J阵营。
    Commons Logging在Apache大树的笼罩下,有很大的用户基数。但有证据表明,形式正在发生变化。2013年底有人分析了GitHub上30000个项目,统计出了最流行的100个Libraries,可以看出slf4j的发展趋势更好:

图片

  • Apache眼看有被Logback反超的势头,于2012-07重写了log4j 1.x,成立了新的项目Log4j 2。Log4j 2具有logback的所有特性。

门面,实现类,桥接包

经历了上述的发展,现在使用日志框架时往往会涉及三个层面的东西。

  • 门面
    • Slf4j: The simple logging facade for java.
    • JCL: Jakarta Commons Logging.
  • 实现类
    • log4j-1.2
    • log4j-2.x
    • logback
    • jul: java.util.logging
  • 桥接包
    • SLF4J LOG4J 12 Binding
    • JUL To SLF4J Bridge
    • JCL 1.1.1 Implemented Over SLF4J ??
    • SLF4J JDK14 Binding
    • Apache Log4j Commons Logging Bridge

slf4j的官网给出了集成其他日志系统的架构图:

slf4j

门面主要只负责定义接口,实现类才负责具体的编码工作。桥接包顾名思义就是桥接门面和实现类。比如SLF4J LOG4J 12 Binding这个桥接包可以使Slf4j和log4j1.2结合起来正常工作。一个已经成型的系统如果使用了这个模式,底层又想将log4j1.2换成log4j2.0实现,则只需要替换实现包为log4j2.x以及桥接包为 Log4j 2 SLF4J Binding。

Slf4j 源码解读

如此灵活的插拔方式,忍不住想要通过源码一探其究竟。
通常情况下,都是这样使用slf4j的:

1
2
3
4
5
6
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

...

Logger logger = LoggerFactory.getLogger(Demo.class);

这里看不到任何跟实现类有关联的代码,然而我们已经可以使用get到的logger打日志了。那么slf4j到底是怎么找到实现类的了?跟进去。

1
2
3
4
5
6
7
8
9
10
11
12
13

/**
* Return a logger named according to the name parameter using the
* statically bound {@link ILoggerFactory} instance.
*
* @param name
* The name of the logger.
* @return logger
*/

public static Logger getLogger(String name) {
ILoggerFactory iLoggerFactory = getILoggerFactory(); //获取工场类
return iLoggerFactory.getLogger(name); //通过工场类拿到logger.
}

getILoggerFactory()这一步是绑定实现类的关键所在。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36

static volatile int INITIALIZATION_STATE = UNINITIALIZED; //初始状态是UNINITIALIZED

...

/**
* Return the {@link ILoggerFactory} instance in use.
* <p/>
* <p/>
* ILoggerFactory instance is bound with this class at compile time. //这里提到编译时绑定,还有一种是运行时绑定,后面会介绍二者的区别。
*
* @return the ILoggerFactory instance in use
*/

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");
}
1
2
3
4
5
6
7

private final static void performInitialization() {
bind(); //实际的绑定操作
if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
versionSanityCheck(); //做一下版本兼容性检测
}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
private final static void bind() {
try {
Set<URL> staticLoggerBinderPathSet = null;
// skip check under android, see also
// http://jira.qos.ch/browse/SLF4J-328
if (!isAndroid()) { //安卓项目有个bug,跳过对安卓的check.
staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet(); //找到所有可能的Binder
reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);//如果Binder的数量大于1,则将所有的Binder都打印出来
}
// the next line does the binding
StaticLoggerBinder.getSingleton(); //执行绑定
INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION; //修改初始化动作的状态
reportActualBinding(staticLoggerBinderPathSet); //打印最终绑定的Binder,和前面打印的所有Binder结合可以更方便的debug.
fixSubstituteLoggers();
replayEvents();
// release all resources in SUBST_FACTORY
SUBST_FACTORY.clear();
} catch (NoClassDefFoundError ncde) { //如果没有任何实现类。就会使用默认的no-operation logger
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;
}
} catch (java.lang.NoSuchMethodError nsme) {
String msg = nsme.getMessage();
if (msg != null && msg.contains("org.slf4j.impl.StaticLoggerBinder.getSingleton()")) {
INITIALIZATION_STATE = FAILED_INITIALIZATION;
Util.report("slf4j-api 1.6.x (or later) is incompatible with this binding.");
Util.report("Your binding is version 1.5.5 or earlier.");
Util.report("Upgrade your binding to version 1.6.x.");
}
throw nsme;
} catch (Exception e) {
failedBinding(e);
throw new IllegalStateException("Unexpected initialization failure", e);
}
}

bind()方法中主要做的事情就是先找到所有可能的Binder的Set,再在这个Set中挑选一个,作为最终的Binder.首先来看是如何找到所有Binder的:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
// We need to use the name of the StaticLoggerBinder class, but we can't
// reference
// the class itself.

private static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class";

static Set<URL> findPossibleStaticLoggerBinderPathSet() {
// use Set instead of list in order to deal with bug #138
// LinkedHashSet appropriate here because it preserves insertion order
// during iteration
Set<URL> staticLoggerBinderPathSet = new LinkedHashSet<URL>(); //使用LinkedHashSet可以保存Binder被加载的顺序。
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;
}

原来是根据Path = “org/slf4j/impl/StaticLoggerBinder.class”去加载相应的实现类。

翻看log4j和logback的jar包,都能找到相同全路径名的类:

log4j
logback

还有jul的桥接包:

jul

那么这里会有一个问题,如果找到多个实现类,最终会绑定哪一个了?

来看slf4j这段良心备注:

The warning emitted by SLF4J is just that, a warning. Even when multiple bindings are present, SLF4J will pick one logging framework/implementation and bind with it. The way SLF4J picks a binding is determined by the JVM and for all practical purposes should be considered random. As of version 1.6.6, SLF4J will name the framework/implementation class it is actually bound to.

Embedded components such as libraries or frameworks should not declare a dependency on any SLF4J binding but only depend on slf4j-api. When a library declares a compile-time dependency on a SLF4J binding, it imposes that binding on the end-user, thus negating SLF4J’s purpose. When you come across an embedded component declaring a compile-time dependency on any SLF4J binding, please take the time to contact the authors of said component/library and kindly ask them to mend their ways.

大意就是说,如果发现有多个实现类,那么slf4j会打印出warning信息。但是仅仅是warning而已。即使有多个实现类,slf4j也只会挑选其中一个,这个选择取决于JVM和所有其他实际因素,基本算是随机性的。同时,slf4j建议删除多余的实现类,仅仅保留一个。

这里还特别良心的提到,嵌入式的组件(比如libraries和框架等)不应该申明依赖任何slf4j的实现。因为这样相当于强加给了终端用户。如果你要使用的组件做了这样的编译时依赖申明,请花点时间联系作者,让他们优化实现方式。
看到这里,我感觉自己被点名了。。。哈哈哈哈
关于多重绑定的更多细节,请戳这里

静态绑定 & 动态绑定

静态绑定又称编译时绑定,动态绑定又称运行时绑定。
关于其具体的概念和特性,相关的介绍文档已经有很多了,在这里我就直接引用了:

从源码中可以看出slf4j获取实际实现类的方式属于静态绑定:

1
2
3
4
5
6
7
8
9
10
11
/**
* Return the {@link ILoggerFactory} instance in use.
* <p/>
* <p/>
* ILoggerFactory instance is bound with this class at compile time.
*
* @return the ILoggerFactory instance in use
*/

public static ILoggerFactory getILoggerFactory() {
...
}

而在slf4j出现之前,已经有JCL这个日志门面系统了。JCL在绑定实现类的时候,使用的是动态绑定的方式。但是先驱者总是容易踩到坑,而无法迅速的优雅的填好这个坑,就会给后继者可乘之机。Slf4j能从JCL那边扳回一城,很大程度上归功于这个静态绑定的使用。

JCL作为第一个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的官网上也打出了一波对于JCL的动态绑定的嘲讽攻击:详情请戳这里

总结

陆游是个好诗人。

Reference