java日志框架

现有体系

下图是现有Java日志体系的一个示意

上图不是非常精准,但是能够比较清晰地展示现有Java日志体系的主体架构。Java日志体系大体可以分为三个部分:日志门面接口、桥接器、日志框架具体实现。

Java日志框架有很多种,最简单的是Java自带的java.util.logging,而最经典的是log4j,后来又出现了一个比log4j性能更好的logback,其他的日志框架就不怎么常用了。应用程序直接使用这些具体日志框架的API来满足日志输出需求当然是可以的,但是由于各个日志框架之间的API通常是不兼容的,这样做就使得应用程序丧失了更换日志框架的灵活性。

比直接使用具体日志框架API更合理的选择是使用日志门面接口。日志门面接口提供了一套独立于具体日志框架实现的API,应用程序通过使用这些独立的API就能够实现与具体日志框架的解耦,这跟JDBC是类似的。最早的日志门面接口是commons-logging,但目前最受欢迎的是slf4j。

日志门面接口本身通常并没有实际的日志输出能力,它底层还是需要去调用具体的日志框架API的,也就是实际上它需要跟具体的日志框架结合使用。由于具体日志框架比较多,而且互相也大都不兼容,日志门面接口要想实现与任意日志框架结合可能需要对应的桥接器,就好像JDBC与各种不同的数据库之间的结合需要对应的JDBC驱动一样。

需要注意的是,前面说过,上图并不精准,这只是主要部分,实际情况并不总是简单的“日志门面接口—>桥接器—>日志框架”这一条单向线。实际上,独立的桥接器有时候是不需要的,而且也并不是只有将日志门面API转调到具体日志框架API的桥接器,也存在将日志框架API转调到日志门面API的桥接器。

说白了,所谓“桥接器”,不过就是对某套API的伪实现。这种实现并不是直接去完成API所声明的功能,而是去调用有类似功能的别的API。这样就完成了从“某套API”到“别的API”的转调。如果同时存在A-to-B.jar和B-to-A.jar这两个桥接器,那么可以想象当应用程序开始调用A或者B的API时,会发生什么事。这就是最开始引出的那个stack overflow异常的基本原理。

slf4j的转接绑定

上面只是从整体上大概说了下Java现有日志体系,进一步了解一下slf4j与具体日志框架的桥接情况。

slf4j桥接到具体日志框架

下图来自slf4j官网文档Binding with a logging framework at deployment time

可以看到slf4j与具体日志框架结合的方案有很多种。当然,每种方案的最上层(绿色的应用层)都是统一的,它们向下都是直接调用slf4j提供的API(浅蓝色的抽象API层),依赖slf4j-api.jar。然后slf4j API向下再怎么做就非常自由了,几乎可以使用所有的具体日志框架。注意图中的第二层是浅蓝色的,看左下角的图例可知这代表抽象日志API,也就是说它们不是具体实现。如果像左边第一种方案那样下层没有跟任何具体日志框架实现相结合,那么日志是无法输出来的(这里不确定是否可能会默认输出到标准输出)。
图中第三层明显就不如第一、二层那么整齐划一了,因为这里已经开始涉及到了具体的日志框架。
首先看第三层中间的两个湖蓝色块,这是适配层,也就是桥接器。左边的slf4j-log4j12.jar桥接器看名字就知道是slf4j到log4j的桥接器,同样,右边的slf4j-jdk14.jar就是slf4j到Java原生日志实现的桥接器了。它们的下一层分别是对应的日志框架实现,log4j的实现代码是log4j.jar,而jul实现代码已经包含在了JVM runtime中,不需要单独的jar包。
再看第三层其余的三个深蓝色块。它们三个也是具体的日志框架实现,但是却不需要桥接器,因为它们本身就已经直接实现了slf4j API。slf4j-simple.jar和slf4j-nop.jar这两个不用多说,看名字就知道一个是slf4j的简单实现,一个是slf4j的空实现,平时用处也不大。而logback之所以也实现了slf4j API,据说是因为logback和slf4j出自同一人之手,这人同时也是log4j的作者。
第三层所有的灰色jar包都带有红框,这表示它们都直接实现了slf4j API,只是湖蓝色的桥接器对slf4j API的实现并不是直接输出日志,而是转去调用别的日志框架的API。

其它日志框架API转调回slf4j

如果只存在上面这些从sfl4j到其他日志框架的桥接器,可能还不会出什么问题。但是实际上还有另外一类桥接器,它们的作用跟上面的恰好相反,它们将其它日志框架的API转调到slf4j的API上。下图来自slf4j官网文档Bridging legacy APIs

上图展示了目前为止能安全地从别的日志框架API转调回slf4j的所有三种情形。
以左上角第一种情形为例,当slf4j底层桥接到logback框架的时候,上层允许桥接回slf4j的日志框架API有log4j和jul。jcl虽然不是什么日志框架的具体实现,但是它的API仍然是能够被转调回slf4j的。要想实现转调,方法就是图上列出的用特定的桥接器jar替换掉原有的日志框架jar。需要注意的是这里不包含logback API到slf4j API的转调,因为logback本来就是slf4j API的实现。

看完三种情形以后,会发现几乎所有其他日志框架的API,包括jcl的API,都能够随意的转调回slf4j。但是有一个唯一的限制就是转调回slf4j的日志框架不能跟slf4j当前桥接到的日志框架相同。这个限制就是为了防止A-to-B.jar跟B-to-A.jar同时出现在类路径中,从而导致A和B一直不停地互相递归调用,最后堆栈溢出。目前这个限制并不是通过技术保证的,仅仅靠开发者自己保证,这也是为什么slf4j官网上要强调所有合理的方式只有上图的三种情形。

循环依赖造成 stack overflow

Detected both log4j-over-slf4j.jar AND slf4j-log4j12.jar on the class path, preempting StackOverflowError.

Detected both jcl-over-slf4j.jar AND slf4j-jcl.jar on the class path, preempting StackOverflowError.

原文

best practice

总是使用Log Facade,而不是具体Log Implementation

使用 Log Facade 可以方便的切换具体的日志实现。而且,如果依赖多个项目,使用了不同的Log Facade,还可以方便的通过 Adapter 转接到同一个实现上。如果依赖项目使用了多个不同的日志实现,就麻烦的多了。

只添加一个 Log Implementation依赖

毫无疑问,项目中应该只使用一个具体的 Log Implementation,建议使用 Logback 或者Log4j2。如果有依赖的项目中,使用的 Log Facade不支持直接使用当前的 Log Implementation,就添加合适的桥接器依赖。

具体的日志实现依赖应该设置为optional和使用runtime scope

在项目中,Log Implementation的依赖强烈建议设置为runtime scope,并且设置为optional。例如项目中使用了 SLF4J 作为 Log Facade,然后想使用 Log4j2 作为 Implementation,那么使用 maven 添加依赖的时候这样设置:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>${log4j.version}</version>
<scope>runtime</scope>
<optional>true</optional>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-slf4j-impl</artifactId>
<version>${log4j.version}</version>
<scope>runtime</scope>
<optional>true</optional>
</dependency>

设为optional,依赖不会传递,这样如果你是个lib项目,然后别的项目使用了你这个lib,不会被引入不想要的Log Implementation 依赖;

Scope设置为runtime,是为了防止开发人员在项目中直接使用Log Implementation中的类,而不适用Log Facade中的类。

如果有必要, 排除依赖的第三方库中的Log Impementation依赖

第三方库的开发者未必会把具体的日志实现或者桥接器的依赖设置为optional,然后你的项目继承了这些依赖——具体的日志实现未必是你想使用的,比如他依赖了Log4j,你想使用Logback,这时就很尴尬。另外,如果不同的第三方依赖使用了不同的桥接器和Log实现,也极容易形成环。

这种情况下,推荐的处理方法,是使用exclude来排除所有的这些Log实现和桥接器的依赖,只保留第三方库里面对Log Facade的依赖。

比如阿里的JStorm就没有很好的处理这个问题,依赖jstorm会引入对Logback和log4j-over-slf4j的依赖,如果你想在自己的项目中使用Log4j或其他Log实现的话,就需要加上excludes:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
<dependency>
<groupId>com.alibaba.jstorm</groupId>
<artifactId>jstorm-core</artifactId>
<version>2.1.1</version>
<exclusions>
<exclusion>
<groupId>org.slf4j</groupId>
<artifactId>log4j-over-slf4j</artifactId>
</exclusion>
<exclusion>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
</exclusion>
</exclusions>
</dependency>

避免为不会输出的log付出代价

Log库都可以灵活的设置输出界别,所以每一条程序中的log,都是有可能不会被输出的。这时候要注意不要额外的付出代价。

先看两个有问题的写法:

1
2
logger.debug("start process request, url: " + url);
logger.debug("receive request: {}", toJson(request));

第一条是直接做了字符串拼接,所以即使日志级别高于debug也会做一个字符串连接操作;第二条虽然用了SLF4J/Log4j2 中的懒求值方式来避免不必要的字符串拼接开销,但是toJson()这个函数却是都会被调用并且开销更大。

推荐的写法如下:

1
2
3
4
5
6
logger.debug("start process request, url:{}", url); // SLF4J/LOG4J2
logger.debug("receive request: {}", () -> toJson(request)); // LOG4J2
logger.debug(() -> "receive request: " + toJson(request)); // LOG4J2
if (logger.isDebugEnabled()) { // SLF4J/LOG4J2
logger.debug("receive request: " + toJson(request));
}

日志格式中最好不要使用行号,函数名等字段

原因是,为了获取语句所在的函数名,或者行号,log库的实现都是获取当前的stacktrace,然后分析取出这些信息,而获取stacktrace的代价是很昂贵的。如果有很多的日志输出,就会占用大量的CPU。在没有特殊需要的情况下,建议不要在日志中输出这些这些字段。

最后, log中不要输出稀奇古怪的字符!
部分开发人员为了方便看到自己的log,会在log语句中加上醒目的前缀,比如:

1
logger.debug("========================start process request=============");

虽然对于自己来说是方便了,但是如果所有人都这样来做的话,那log输出就没法看了!正确的做法是使用grep 来看只自己关心的日志。