排查log4j不輸出日誌到檔案的問題

nuccch發表於2022-02-18

問題描述

專案使用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-simplelog4j-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-apilogback-classic依賴,此時如果還新增了slf4j-simplelog4j-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>

同時新增logbacklog4j2時啟動失敗:

<!-- 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

同時新增lobackslf4j-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-simplelog4j-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日誌不輸出的問題

相關文章