排查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-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日誌不輸出的問題

log4j不輸出日誌錯誤分析
2013-11-13
記一次log4j日誌寫到錯誤檔案的問題
2017-11-01
Java日誌輸出問題
2016-12-07
Java
Spring按業務模組輸出日誌到不同的檔案
2022-05-06
Spring
日誌檔案問題
2012-02-01
華為 MATE7 除錯 LOCAT 日誌不輸出問題
2015-06-22
除錯
log4j日誌輸出級別(轉)
2022-01-04
Hibernate 使用log4j輸出日誌
2013-12-14
log4j日誌檔案配置
2017-11-29
使用log4j列印異常堆疊到日誌檔案
2020-11-15
操作日誌記錄(包括輸出至自定義日誌檔案)
2020-10-16
Log4j輸出到指定日誌檔案
2012-11-29
使用Log4j輸出日誌至資料庫
2010-08-07
資料庫
Checkpoint not complete 日誌檔案問題
2011-09-16
log4j中將日誌插入到資料庫中遇到的問題^_^
2003-12-31
資料庫
python怎麼將列印輸出日誌檔案
2021-09-11
Python
jaxb輸出xml檔案的中文問題？
2003-08-12
XML
Laravel 日誌檔案許可權問題
2021-05-14
Laravel
聯機日誌檔案損壞問題
2014-01-02
MySQL資料庫中的日誌檔案---(4)配置日誌檔案輸出路徑
2011-10-10
MySql資料庫
log4j自定義輸出多個檔案
2009-12-07
Java - 自動配置log4j的日誌檔案路徑
2019-08-06
Java
【Go語言探險】線上奇怪日誌問題的排查
2020-08-29
Go
Laravel 中輸出 SQL 語句的到 log 日誌
2017-08-23
LaravelSQL
Nginx訪問日誌、Nginx日誌切割、靜態檔案不記錄日誌和過期時間
2017-11-07
Nginx
記一次線上報錯日誌問題排查
2021-04-01
logrus hook輸出日誌到本地磁碟
2018-09-30
Hook
（定時）任務輸出重定向到日誌
2021-10-25
log4j將日誌輸出到資料庫
2010-08-07
資料庫
[問題]多個檔案寫入日誌報錯
2020-07-30
24【線上日誌分析】之Tomcat的支援log4j,日誌輸出為json格式
2017-03-31
TomcatJSON
SpringBoot通過yml和xml檔案配置日誌輸出
2019-04-01
Spring BootXML
C語言log日誌管理-支援檔案與終端輸出
2018-11-17
C語言
使apache的日誌檔案裡不記錄圖片檔案
2017-11-12
Apache
(OAF)jdeveloper整合log4j並將日誌輸出到指定檔案並寫入資料庫
2016-10-27
Developer資料庫
日誌檔案和歸檔日誌檔案的關係以及如何切換日誌
2014-08-04
PowerShell輸出內容到檔案
2013-09-06
日誌檔案太大，壓縮後，限制檔案的大小，但出現日誌檔案已經滿的告警
2007-07-08

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

問題描述

解決步驟

原因追蹤

最後總結

相關文章