log4j日誌不輸出的問題
今天伺服器上報錯，想先去看一下日誌進行排查，結果發現日誌很久都沒有輸出過了。從上午排查到下午，剛剛解決，因此記錄一下，但現在也只是知其然，並不知其所以然，所以如果大家有什麼想法請在下方評論。
先說一下環境，伺服器是linux，專案是執行在tomcat下的Spring專案，日誌用的是log4j。
首先，從10月13號開始便沒有新的日誌檔案了。假設日誌名為log.txt（如果你設定了DailyRollingFileAppender，那麼你當天的日誌檔案就是log.txt），先備份該檔案到其他目錄下，然後刪除該檔案，重新啟動tomcat。這是為了確認你的log4j配置是否有問題，因為這是最容易出錯的地方。很遺憾，我不是這裡出的問題，因為專案重啟後，日誌檔案又重新生成了，但很奇怪的是，日誌檔案是空的
感覺自己碰上了很神奇的問題，因此我在自己的本地進行除錯，啟動專案後發現，正常的專案啟動日誌是有的：
15:13:48:0253 INFO [RMI TCP Connection(3)-127.0.0.1] -Root WebApplicationContext: initialization completed in 18479 ms
但我自己的一些日誌輸出是不顯示的，比如：
private static final Logger log = LoggerFactory.getLogger(MyDomain.class);
log.info("show info log" show info log這句話就不列印，現在證明，我的日誌配置沒有問題，伺服器也找到了我的日誌檔案，但應該是我自己的Logger是不對應正確的日誌輸出的，因為我的console(控制檯)有顯示。
接下來，我就是開始看原始碼了。先是LoggerFactory.getLogger(Class<?> clazz)方法：
public static Logger getLogger(Class<?> clazz) {
Logger logger = getLogger(clazz.getName());
if (DETECT_LOGGER_NAME_MISMATCH) 好吧，沒什麼用，看不出我的logger變成了，繼續看getLogger(String name)方法：
public static Logger getLogger(String name) {
ILoggerFactory iLoggerFactory = getILoggerFactory();
return iLoggerFactory.getLogger(name);
}
這時我在return iLoggerFactory.getLogger(name);這行打了斷點，我看到了這樣的東西：
為什麼我的iLoggerFactory是用的logback中的實現？其實也是怪我自己大意，我其實依賴了一個基於Spring Boot的專案(雖然我只是用了裡面的一些domain類，但因為設計不當，還沒有把這些domain類單獨提成一個_專案)，而Spring Boot中一般預設就依賴的logback。通過gradle檢視專案的依賴樹，也證實了我的這一猜想(./gradlew 子專案名稱:dependencies):
| +--- org.springframework.boot:spring-boot-starter-web:2.0.2.RELEASE
| | +--- org.springframework.boot:spring-boot-starter:2.0.2.RELEASE
| | | +--- org.springframework.boot:spring-boot:2.0.2.RELEASE
| | | | +--- org.springframework:spring-core:5.0.6.RELEASE (*)
| | | | \--- org.springframework:spring-context:5.0.6.RELEASE (*)
| | | +--- org.springframework.boot:spring-boot-autoconfigure:2.0.2.RELEASE
| | | | \--- org.springframework.boot:spring-boot:2.0.2.RELEASE (*)
| | | +--- org.springframework.boot:spring-boot-starter-logging:2.0.2.RELEASE
| | | | +--- ch.qos.logback:logback-classic:1.2.3
| | | | | +--- ch.qos.logback:logback-core:1.2.3
| | | | | \--- org.slf4j:slf4j-api:1.7.25
接下來就好辦了，你排除掉ch.qos.logback的依賴就可以了，在你的build.gradle中增加：
configurations {
compile.exclude group: 'ch.qos.logback'
}
這個時候你再重新除錯一下看看：
完美，現在是log4j中的實現，得到了我想要的操作。當然了，既然我知道之前專案中的slf4j是logback實現了，那麼我自然也可以換成logback的配置，但這就需要我將專案換成用Spring Boot啟動，這個改動有點大，如果以後有必要的話，我再將這個exclude刪除，換成Spring Boot的形式。
這次Spring Boot幫我們預設啟用的是logback，那麼有沒有什麼簡單方法可以知道呢？如果你的專案出現了以下的日誌輸出，說明你的專案當前有不止一個SLF4J的實現元件：
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/project.war/WEB-INF/lib/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/project.war/WEB-INF/lib/slf4j-log4j12-1.7.21.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 [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
因為在org.slf4j.LoggerFactory的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()) {
// 查詢你的當前專案有幾個slf4j的實現
staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
// 如果多餘一個就列印
reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
}
// the next line does the binding
// 這個是具體選了哪一個實現（重點關注）
StaticLoggerBinder.getSingleton();
INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
reportActualBinding(staticLoggerBinderPathSet);
fixSubstituteLoggers();
replayEvents();
// release all resources in SUBST_FACTORY
SUBST_FACTORY.clear();
} catch (NoClassDefFoundError ncde) {
String msg = ncde.getMessage();
if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;
Util.report("Failed to load class \"org.slf4j.impl.StaticLoggerBinder\".");
Util.report("Defaulting to no-operation (NOP) logger implementation");
Util.report("See " + NO_STATICLOGGERBINDER_URL + " for further details.");
} else {
failedBinding(ncde);
throw ncde;
}
} catch (java.lang.NoSuchMethodError nsme) {
String msg = nsme.getMessage();
if (msg != null && msg.contains("org.slf4j.impl.StaticLoggerBinder.getSingleton()")) {
INITIALIZATION_STATE = FAILED_INITIALIZATION;
Util.report("slf4j-api 1.6.x (or later) is incompatible with this binding.");
Util.report("Your binding is version 1.5.5 or earlier.");
Util.report("Upgrade your binding to version 1.6.x.");
}
throw nsme;
} catch (Exception e) {
failedBinding(e);
throw new IllegalStateException("Unexpected initialization failure", e);
}
}
特別要注意的是StaticLoggerBinder.getSingleton();這行程式碼，StaticLoggerBinder在logback-classic和slf4j-log4j12這兩個jar包各有一個，因此，Spring boot是自動選擇logback-classic（雖然我在本地執行的時候還是預設進入的slf4j-log4j12，但是會提醒我Source code does not match the bytecode，因此我判斷依舊進的是logback-classic），所以只要把logback給exclude掉，就解決了這個問題。
現在看問題，更加關注原始碼，因為這可以讓我們更加快速定位問題，並且也能據此大致猜出其解決方案。希望大家能一起看看原始碼，如果你有什麼發現，可以在下方留言，我將和你一起討論。
有興趣的話可以看看我的私人部落格，說不定會有意外的驚喜。