排查log4j不輸出日誌到文件的問題
- 2022 年 2 月 18 日
- 筆記
- Framework/Logging, 踩過的坑
問題描述
項目使用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 //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
// //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>
【參考】
//blog.csdn.net/death05/article/details/83618878 log4j日誌不輸出的問題
