93 log4j-slf4j-impl 搭配上 log4j-to-slf4j 导致的 StackOverflow

前言

呵呵最近想要做一个 mongo 低版本的客户端读取高版本的服务端传递过来的数据造成的一个错误的时候, 出现了这样的问题

引入了 mongo-java-driver 之后, 使用相关 api 的时候会触发 com.mongo.internal.connection.BaseCluser 的初始化, 其依赖的 Loggers 间接的依赖的是 org.slf4j.LoggerFactory 来获取 logger

然后启动一个简单的 public static void main, 之后就 StackOverflow 了

稍微看了一下, 是由于 log4j-slf4j-impl 和 log4j-to-slf4j 依赖, 导致的一个比现的一个问题

因此来一个 case 看一下具体的情况

也顺便看了一下 slf4j 和 log4j, 以及他们的一些关联关系, 之前也是稀里糊涂的复制过来直接使用, 没有怎么关注这个

简单的来说 slf4j 是一套接口, 一套约束, 适配了各种实现, slf4j-api.jar 属于接口的约束, log4j-slf4j-impl 属于 log4j 适配 slf4j 系列接口的具体的实现

log4j 是一种具体的日志输出的实现, 和 logback, slf4j-simple, jdk的Logger 都属于具体的 impl

测试用例

依赖如下

        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-slf4j-impl</artifactId>
            <version>2.10.0</version>
        </dependency>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-to-slf4j</artifactId>
            <version>2.13.2</version>
        </dependency>

测试用例

package com.hx.test;


import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/**
 * Test01LoggerStackOverflow
 *
 * @author Jerry.X.He <970655147@qq.com>
 * @version 1.0
 * @date 2021-10-23 12:08
 */
public class Test01LoggerStackOverflow {

    // logger
    public static final Logger LOGGER = LoggerFactory.getLogger(Test01LoggerStackOverflow.class);

    // Test01LoggerStackOverflow
    public static void main(String[] args) {

        LOGGER.error("Hello World");

    }

}

启动之后抛出异常如下, 是在 LoggerFactory.getLogger 的时候

Exception in thread "main" java.lang.StackOverflowError
	at org.apache.logging.log4j.util.StackLocatorUtil.getCallerClass(StackLocatorUtil.java:55)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:42)
	at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:46)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:355)
	at org.apache.logging.slf4j.SLF4JLoggerContext.getLogger(SLF4JLoggerContext.java:39)
	at org.apache.logging.slf4j.Log4jLoggerFactory.newLogger(Log4jLoggerFactory.java:37)
	at org.apache.logging.slf4j.Log4jLoggerFactory.newLogger(Log4jLoggerFactory.java:29)
	at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:52)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:355)
	at org.apache.logging.slf4j.SLF4JLoggerContext.getLogger(SLF4JLoggerContext.java:39)
	at org.apache.logging.slf4j.Log4jLoggerFactory.newLogger(Log4jLoggerFactory.java:37)
	at org.apache.logging.slf4j.Log4jLoggerFactory.newLogger(Log4jLoggerFactory.java:29)
	at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:52)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29)

问题的调试

这个问题我们要关注两个地方, 一个是 LoggerFactory 的选择, 一个是 LoggerContextFactory 的选择

slf4j-simple 里面的实现就相对简单, 直接通过 LoggerFactory 创建 Logger

但是 log4j-slf4j-impl 里面需要实际工作的 Logger 是 log4j 的 Logger, log4j 中构建 Logger 需要构建 LoggerContext, 并基于 LoggerContext 来创建 Logger

LoggerFactory 的选择

首先来看一下 LoggerFactory 的一些初始化的地方

这里获取 Slf4jServiceProvier 是通过 serviceloader 来实现的, 我们这里只能够获取到一个 provider, 这个是 log4j-slf4j-impl 里面的一个具体的实现

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

比如我现在增加一个 slf4j-simple 的一个实现, 那么这里可以获取到两个 Slf4jServiceProvier

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

存在多个 Slf4jServiceProvider 的情况下, 就会输出我们常见的如下日志信息, 并且日志中输出了选择的是哪一个 Slf4jServiceProvider, 选择的规则是选择第一个

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

LoggerContextFactory 的选择

我们来具体看一下 log4j-slf4j-impl 里面 LoggerFactory 创建 Logger 的具体的实现

看这里创建了一个 context, 并使用 context 创建 Logger, 按道理来说, 我们期望这个 context.getLogger 应该是一个具体的创建 Logger 的地方

但是可以看到这里的 context 的到的是一个 Slf4jLoggerContext[是在 log4j-to-slf4j.jar 的包中], 这个 context 里面没有创建 Logger, 而是吧创建 Logger 的业务委托给了 org.slf4j.LoggerFactory, 所以这里就构成了一个没有退出边界的递归, 造成了 StackOverflow

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

我们来看一下正常的的情况下, 可以看到这里获取到的 LoggerContext 是 log4j-core 下面的

然后实际的工作, 也是创建真实的 log4j 的 Logger

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

为什么 log4j-slf4j-impl 和 log4j-to-slf4j 都存在的时候, 会选择到 Slf4jLoggerContext 呢 ?

AbstractLoggerAdapter 中创建 LoggerContext 是委托给了 LogManager

LogManager 中创建 LoggerContext 取决于具体的 factory, 也就是 LoggerContextFactory

ProviderUtil 中使用 servicelaoder 加载对应的 Provider 加载了两个, 一个是 Log4jContextFactory, 一个是 Slf4jLoggerContextFactory, 并且 Slf4jLoggerContextFactory 的优先级比 Log4jContextFactory 要高, 因此优先选择的是 Slf4jLoggerContextFactory

这两个 Provider 分别是来自于 log4j-slf4j-impl 和 log4j-to-slf4j 这两个包中

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16