日志框架冲突分析


2/14/2015 JavaSE

*注: 下文中的 “桥接”、“转调”、“绑定” 等词基本都是同一个概念. *

log4j-over-slf4j 和 slf4j-log4j12 是跟 Java 日志系统相关的两个 jar 包, 当它们同时出现在 classpath 下时, 就可能会引起堆栈溢出异常. 异常信息大致如下(摘自 slf4j 官网文档 Detected both log4j-over-slf4j.jar AND slf4j-log4j12.jar on the class path, preempting StackOverflowError):

Exception  in thread "main" java.lang.StackOverflowError at java.util.Hashtable.containsKey(Hashtable.java:306) 
    at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:36) 
    at org.apache.log4j.LogManager.getLogger(LogManager.java:39) 
    at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:73) 
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:249) 
    at org.apache.log4j.Category.init>(Category.java:53) 
    at org.apache.log4j.Logger..init>(Logger.java:35) 
    at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:39) 
    at org.apache.log4j.LogManager.getLogger(LogManager.java:39) 
    at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:73) 
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:249) 
    at org.apache.log4j.Category..init>(Category.java:53) 
    at org.apache.log4j.Logger..init>(Logger.java:35) 
    at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:39) 
    at org.apache.log4j.LogManager.getLogger(LogManager.java:39) subsequent lines omitted...
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

现有日志体系

分析这个异常出现的具体原因之前, 有必要先快速了解一下现有的 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 官网上要强调所有合理的方式只有上图的三种情形.

到这里, 在开始所展示的那个异常的原理基本已经清楚了. 此外, 通过上图还可以看出可能会出现类似异常的组合不仅仅是 log4j-over-slf4j 和 slf4j-log4j12, slf4j 官网还指出了另外一对: jcl-over-slf4j.jar 和 slf4j-jcl.jar

代码示例

前面的分析都是理论上的, 实际代码中即便同时使用了 log4j-over-slf4j 和 slf4j-log4j12, 也未必一定会出现异常. 下面的代码调用 slf4j 的 API 输出日志, slf4j 底层桥接到 log4j:

package test;  
  
public class HelloWorld {  
    public static void main(String[] args) {  
        org.apache.log4j.BasicConfigurator.configure();  
        org.slf4j.Logger logger = org.slf4j.LoggerFactory  
                .getLogger(HelloWorld.class);  
        logger.info("Hello World");  
    }  
}  
1
2
3
4
5
6
7
8
9
10

配置 classpath 上的 jar 包为(注意 log4j 在 log4j-over-slf4j 之前):

在这种情况下运行测试程序是能够正常输出日志的, 不会出现 stack overflow 异常. 但是如果调整 classpath 上的 jar 顺序为:

再运行测试程序就出现类似于本文最开始的 stack overflow 异常了, 可以看到明显的周期性重复:

序列图分析

上图是堆栈溢出的详细调用过程序列图. 从调用 1 开始, 依次调用 1.1、1.1.1…… 最后到了 1.1.1.1.1.1(图中最后一个调用)的时候, 发现它跟 1 是完全一样的, 那么后续的过程就是完全一样的重复了.

需要特别说明的是最开始的导火索并不只有图中所示的 LoggerFactory.getLogger() 一种, 应用程序中能够触发堆栈溢出异常的直接调用还有好几种其它的, 比如前面示例代码中触发异常的实际上是第一条语句 org.apache.log4j.BasicConfigurator.configure(), 但后续的互相无限递归调用过程基本都是跟上图相同的过程.

Last Updated: 7/3/2019, 6:17:56 PM