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

问题描述

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

    org.slf4j
    slf4j-api
    1.7.36


    org.slf4j
    slf4j-simple
    1.7.30


    org.springframework.boot
    spring-boot-starter-log4j2

使用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 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 findPossibleStaticLoggerBinderPathSet() {
        // use Set instead of list in order to deal with bug #138
        // LinkedHashSet appropriate here because it preserves insertion order
        // during iteration
        Set staticLoggerBinderPathSet = new LinkedHashSet();
        try {
            ClassLoader loggerFactoryClassLoader = LoggerFactory.class.getClassLoader();
            Enumeration 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依赖，则项目无法启动。
添加如下配置时启动正常：

    org.slf4j
    slf4j-api
    1.7.36


    ch.qos.logback
    logback-classic
    1.2.10

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

    org.slf4j
    slf4j-api
    1.7.36


    ch.qos.logback
    logback-classic
    1.2.10


    org.springframework.boot
    spring-boot-starter-log4j2

报错信息如下：

# “/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时启动失败：

    org.slf4j
    slf4j-api
    1.7.36


    ch.qos.logback
    logback-classic
    1.2.10


    org.slf4j
    slf4j-simple
    1.7.30

报错信息如下：

# “/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的日志实现。
如下配置不会导致项目启动失败：

    org.slf4j
    slf4j-simple
    1.7.30


    org.springframework.boot
    spring-boot-starter-log4j2

最后总结

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

    org.springframework.boot
    spring-boot-starter-web
    
        
            
            org.springframework.boot
            spring-boot-starter-logging
        
    

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

    org.springframework.boot
    spring-boot-starter-log4j2

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

<?xml version="1.0" encoding="UTF-8"?>

    
        
        ${sys:user.home}/test-springboot-simple
        %d{MM-dd HH:mm:ss.SSS} [%t-%L] %-5level %logger{36} - %msg%n
    

    
        
            
            
        

        
            
            
            
                
                
            
        
    

    
        
            
            
        
    

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