排查log4j不输出日志到文件的问题

问题描述

项目使用Spring Boot框架，在pom文件中添加了如下配置：

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.36</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-simple</artifactId>
    <version>1.7.30</version>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>

使用SLF4J的API进行日志输出，并且也明确配置了log4j2写日志文件。

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

private Logger log = LoggerFactory.getLogger(TestController.class);

但是在项目代码中输出的日志信息始终不输出到文件中，只在控制台输出。
一开始我以为是log4j的配置问题：只输出到控制台，不输出到文件，但是反复确认配置没问题。

解决步骤

由于这是一个新介入的老项目，一开始并没有从“配置依赖可能有问题”这个角度去考虑，另外一点就是项目的启动日志太多了，在启动的时候很快就产生许多信息，把关键的的错误信息错过了。
后来经过反复查看启动日志才发现，原来是因为项目中同时添加了slf4j-simple配置，项目启动时默认加载它作为日志实现。因此，log4j2的配置就不生效了。

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/D:/.m2/repository/org/slf4j/slf4j-simple/1.7.30/slf4j-simple-1.7.30.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/D:/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.3/log4j-slf4j-impl-2.13.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.SimpleLoggerFactory]  // 这里是关键日志，明确了项目启动时加载的日志实现
[restartedMain] INFO org.apache.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-8080"]
[restartedMain] INFO org.apache.catalina.core.StandardService - Starting service [Tomcat]
[restartedMain] INFO org.apache.catalina.core.StandardEngine - Starting Servlet engine: [Apache Tomcat/9.0.44]
[restartedMain] INFO org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/] - Initializing Spring embedded WebApplicationContext

定位到是因为同时加载了slf4j-simple的缘故，只要去除该依赖即可。
虽然已经解决了问题，但同时也不禁让我疑惑，难道Slf4j会优先加载slf4j-simple吗？带着这个疑问，继续追踪一下源码。

原因追踪

追踪slf4j-api的源码发现，当classpath路径存在slf4j-simple时，是一定会优先加载其中的org.slf4j.impl.StaticLoggerBinder类的。
也就是说，当slf4j-simple存在classpath下时，总是优先使用它作为slf4j-api的默认实现；此时，即使同时配置了log4j，也无法使用log4j进行日志输出。
详细源码解读如下：

// slf4j-api.jar
// org.slf4j.LoggerFactory
public final class LoggerFactory {
    private static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class";

    // bind()方法是绑定日志实现的入口
    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()) {
                staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
                reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
            }
            // 这一句是最关键的，当classpath路径下存在slf4j-simple时，总是会优先加载slf4j-simple中定义的StaticLoggerBinder
            // the next line does the binding
            StaticLoggerBinder.getSingleton();
            INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            reportActualBinding(staticLoggerBinderPathSet);
        } catch (NoClassDefFoundError ncde) {
            // 省略部分代码...
        }
    }

    // 在findPossibleStaticLoggerBinderPathSet()方法中加载slf4j接口的日志实现类
    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>();
        try {
            ClassLoader loggerFactoryClassLoader = LoggerFactory.class.getClassLoader();
            Enumeration<URL> paths;
            // 使用类加载器加载类定义
            // 有意思的是在slf4j-simple和log4j-slf4j-impl包中都同时存在org.slf4j.impl.StaticLoggerBinder类
            // 所以当使用路径“org/slf4j/impl/StaticLoggerBinder.class”加载类时，会同时把2个类都加载出来
            // 但是只会使用slf4j-simple中的StaticLoggerBinder
            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;
    }
}

另外：当使用logback作为slf4j的日志实现组件时，不再允许依赖其他日志实现组件，即：logback-classic不能与slf4j-simple或log4j-slf4j-impl共存，
这是因为在加载logback时了做了检查：

private LoggerContext getLoggerContext() {
    ILoggerFactory factory = StaticLoggerBinder.getSingleton().getLoggerFactory();
    // 判断加载的日志工厂类是否为logback的LoggerContext，如果不是则抛出异常
    Assert.isInstanceOf(LoggerContext.class, factory,
            () -> String.format(
                    "LoggerFactory is not a Logback LoggerContext but Logback is on "
                            + "the classpath. Either remove Logback or the competing "
                            + "implementation (%s loaded from %s). If you are using "
                            + "WebLogic you will need to add 'org.slf4j' to "
                            + "prefer-application-packages in WEB-INF/weblogic.xml",
                    factory.getClass(), getLocation(factory)));
    return (LoggerContext) factory;
}

如果使用logback作为slf4j的日志实现组件，则只允许添加slf4j-api和logback-classic依赖，此时如果还添加了slf4j-simple或log4j-slf4j-impl依赖，则项目无法启动。
添加如下配置时启动正常：

<!-- 使用loback作为slf4j的日志实现组件 -->
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.36</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.10</version>
</dependency>

同时添加logback和log4j2时启动失败：

<!-- logback无法与log4j2共存 -->
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.36</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.10</version>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>

报错信息如下：

# “/D:/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.3/log4j-slf4j-impl-2.13.3.jar”是本地Maven仓库路径
Caused by: java.lang.IllegalArgumentException: LoggerFactory is not a Logback LoggerContext but Logback is on the classpath. Either remove Logback or the competing implementation (class org.apache.logging.slf4j.Log4jLoggerFactory loaded from file:/D:/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.3/log4j-slf4j-impl-2.13.3.jar). If you are using WebLogic you will need to add 'org.slf4j' to prefer-application-packages in WEB-INF/weblogic.xml: org.apache.logging.slf4j.Log4jLoggerFactory

同时添加loback和slf4j-simple时启动失败：

<!-- logback无法与slf4j-simple共存 -->
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.36</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.10</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-simple</artifactId>
    <version>1.7.30</version>
</dependency>

报错信息如下：

# “/D:/.m2/repository/org/slf4j/slf4j-simple/1.7.30/slf4j-simple-1.7.30.jar”是本地Maven仓库路径
Caused by: java.lang.IllegalArgumentException: LoggerFactory is not a Logback LoggerContext but Logback is on the classpath. Either remove Logback or the competing implementation (class org.slf4j.impl.SimpleLoggerFactory loaded from file:/D:/.m2/repository/org/slf4j/slf4j-simple/1.7.30/slf4j-simple-1.7.30.jar). If you are using WebLogic you will need to add 'org.slf4j' to prefer-application-packages in WEB-INF/weblogic.xml: org.slf4j.impl.SimpleLoggerFactory

但是！slf4j-simple和log4j-slf4j-impl是可以共存的，但是优先只会使用slf4j-simple作为slf4j的日志实现。
如下配置不会导致项目启动失败：

<!-- slf4j-simple可以与log4j-slf4j-impl共存，但是优先使用slf4j-simple -->
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-simple</artifactId>
    <version>1.7.30</version>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>

最后总结

在使用Spring Boot框架时，默认使用的日志实现组件是logback，如果需要使用其他日志实现组件（如：log4j2），需要做2步：
第一，排除默认对spring-boot-starter-logging模块的依赖。

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
    <exclusions>
        <exclusion>
            <!-- 排除Spring Boot默认使用的日志依赖 -->
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>

第二，明确引入对log4j2的依赖配置。

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>

同时，需要确定在项目启动的classpath路径下有对应log4j2的配置文件存在，如：classpath:log4j2.xml。
如下是log4j2的简单配置示例。

<?xml version="1.0" encoding="UTF-8"?>
<configuration status="warn" debug="true" packages="qs.config">
    <Properties>
        <!-- 配置日志文件输出目录 ${sys:user.home} -->
        <Property name="LOG_HOME">${sys:user.home}/test-springboot-simple</Property>
        <property name="PATTERN">%d{MM-dd HH:mm:ss.SSS} [%t-%L] %-5level %logger{36} - %msg%n</property>
    </Properties>

    <appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <ThresholdFilter level="DEBUG" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="[%d{HH:mm:ss.SSS}] %-5level %class{36} %L %M - %msg%xEx%n"/>
        </Console>

        <RollingFile name="RollingFileInfo" fileName="${LOG_HOME}/info.log" filePattern="${LOG_HOME}/$${date:yyyy-MM}/info-%d{yyyy-MM-dd}-%i.log">
            <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
                <SizeBasedTriggeringPolicy size="100MB"/>
            </Policies>
        </RollingFile>
    </appenders>

    <loggers>
        <root level="info">
            <appender-ref ref="RollingFileInfo"/>
            <appender-ref ref="Console"/>
        </root>
    </loggers>
</configuration>

【参考】
https://blog.csdn.net/death05/article/details/83618878 log4j日志不输出的问题