作者：Sharehub
來(lái)源：blog.xiaohansong.com/JAVA-log-confict-solve.html
前言
Java 有很多的日志框架可以選擇，當(dāng)同一個(gè)項(xiàng)目中出現(xiàn)多種日志框架時(shí)就很容易出現(xiàn)日志框架沖突的問(wèn)題，導(dǎo)致日志打印不出來(lái)。本文將以一次典型的日志沖突排查問(wèn)題為例，提供排查步驟和思路，最后分析日志框架沖突的原因。
一般行文思路都是先講 Why，再講 How，這里我顛倒了，因?yàn)橐话阌龅絾?wèn)題的時(shí)候我們對(duì)問(wèn)題背后的根本原因是一無(wú)所知的，如果我們已經(jīng)知道問(wèn)題的原因，那么問(wèn)題也就迎刃而解了。
因此我希望先復(fù)現(xiàn)我當(dāng)時(shí)在對(duì)日志框架了解不多的情況下排查問(wèn)題的思路和步驟，如何在面對(duì)未知問(wèn)題找到破題思路是非常重要的技能。
一次典型的日志沖突排查
問(wèn)題背景
在 A 工程中，日志框架配置選用了 Log4j2，master 分支上日志打印正常，但開(kāi)發(fā)分支增加了代碼之后日志打印不出來(lái)。項(xiàng)目的依賴(lài)中包含了 Log4j2、Logback 等日志框架。
排查思路與過(guò)程
排查問(wèn)題的時(shí)候首先必須要有明確的思路，即大膽假設(shè)，小心求證，不能像無(wú)頭蒼蠅一樣亂試。從問(wèn)題的現(xiàn)象看，直覺(jué)上可以得出幾個(gè)假設(shè)：
- 服務(wù)器環(huán)境有問(wèn)題
- 開(kāi)發(fā)分支的 Log4j2 配置有問(wèn)題
接下來(lái)就是驗(yàn)證假設(shè)，首先多申請(qǐng)幾臺(tái)機(jī)器部署項(xiàng)目分支，發(fā)現(xiàn)問(wèn)題仍然存在，可以排除第一個(gè)假設(shè)。其次找到另一個(gè)工程 B 跟 A 工程對(duì)比 Log4j2 的配置，也沒(méi)有發(fā)現(xiàn)明細(xì)的差異，可以排除第二個(gè)假設(shè)。
在已有假設(shè)都驗(yàn)證失敗的情況下，需要收集更多的信息作出判斷，接下來(lái)就是要用對(duì)照實(shí)驗(yàn)收集信息。于是我分別斷點(diǎn)了 A 和 B 兩個(gè)工程，觀察它們?nèi)罩緦?shí)體的類(lèi)型是否一致。結(jié)果發(fā)現(xiàn)兩者的日志實(shí)體類(lèi)型不一樣，A 的日志實(shí)現(xiàn)是 Logback，B 的日志實(shí)現(xiàn)是 Log4j2，很明顯 A 打印不出日志是因?yàn)槿罩緦?shí)體不對(duì)，但是兩者都是用的同一個(gè) LoggerFactory 創(chuàng)建 Logger 的。
從對(duì)照實(shí)驗(yàn)的結(jié)果來(lái)看，可以得出一個(gè)假設(shè)：依賴(lài)沖突導(dǎo)致了 A 運(yùn)行時(shí)使用日志實(shí)體不是 Log4j2。
至此我們已經(jīng)找到了問(wèn)題的大致方向，接下來(lái)就是要排包。排包一般有兩種思路：
- 暴力求解：把所有可能沖突的日志包排掉，一個(gè)個(gè)試。
- 精準(zhǔn)爆破：利用類(lèi)加載的信息判斷運(yùn)行時(shí)加載的具體是哪個(gè) jar
暴力求解的方式太花費(fèi)時(shí)間了，所以我用的第二種方式。
獲取日志實(shí)體的方式如下：
privatestaticfinalLoggerLOGGER=LoggerFactory.getLogger(xxx.class);
LoggerFactory 的代碼如下：
從代碼上可以發(fā)現(xiàn)，getLog方法是來(lái)自父類(lèi)LogFactory，當(dāng)我去嘗試獲取LogFactory的實(shí)現(xiàn)時(shí)候，發(fā)現(xiàn)竟然有 3 個(gè) jar 中都有同樣包名的LogFactory實(shí)現(xiàn)。于是我斷點(diǎn)了 A 和 B 工程的代碼，用 IDEA 的運(yùn)行代碼功能執(zhí)行以下命令獲取LogFactory的加載信息。
結(jié)果發(fā)現(xiàn) B 工程使用是spring-jcl，A 使用的是jcl-over-slf4j，然后排除掉 A 中jcl-over-slf4j，問(wèn)題解決。
上面的排查過(guò)程中，關(guān)鍵的地方有兩點(diǎn)：
- 定位到問(wèn)題的根源是類(lèi)加載沖突，確定排查方向。
- 通過(guò)斷點(diǎn)獲取沖突類(lèi)的加載信息，快速定位到?jīng)_突的 jar。
為什么日志框架會(huì)沖突
問(wèn)題至此就解決了，但是還有一個(gè)更深入的問(wèn)題沒(méi)有解決：為什么同時(shí)存在多個(gè)日志框架的時(shí)候就會(huì)出現(xiàn)沖突呢？在解決完問(wèn)題之后，我深入研究了日志框架的歷史和設(shè)計(jì)，發(fā)現(xiàn)原來(lái)這跟日志框架的實(shí)現(xiàn)機(jī)制有關(guān)系。
日志框架的歷史
首先要從日志框架的發(fā)展歷史開(kāi)始說(shuō)起。
- 首先登場(chǎng)是Java Util Log，簡(jiǎn)稱(chēng)JUL，是JDK 中自帶的 log 功能。雖然是官方自帶的，JUL 的使用卻不廣泛，主要是因?yàn)楣δ鼙容^簡(jiǎn)單，不好用。
- 然后Log4j 1.x就登場(chǎng)了：它是 Gülcü 設(shè)計(jì)實(shí)現(xiàn)的日志框架，設(shè)計(jì)非常優(yōu)秀，是非常廣泛使用的框架。
- Commons Logging：簡(jiǎn)稱(chēng) JCL，是 Apache 的項(xiàng)目。JCL 是一個(gè) Log Facade，只提供 Log API，不提供實(shí)現(xiàn)，用 Adapter 來(lái)使用 Log4j 或者 JUL 作為 Log Implementation。目的是統(tǒng)一日志接口規(guī)范，適配多種日志實(shí)現(xiàn)。
- SLF4J/Logback：SLF4J(The Simple Logging Facade for Java) 和 Logback 也是 Gülcü 創(chuàng)立的項(xiàng)目，其創(chuàng)立主要是為了提供更高性能的實(shí)現(xiàn)。其中，SLF4j 是類(lèi)似于JCL 的Log Facade，Logback 是類(lèi)似于Log4j 的 Log Implementation。這老哥覺(jué)得 JCL 的接口設(shè)計(jì)不好，所以重新設(shè)計(jì)了一套。
- Log4j2：維護(hù) Log4j 的人為了不讓 Log4j 的用戶(hù)被 SLF4J/Logback 搶走，所以搞出了新的日志框架。Log4j2 和 Log4j1.x 并不兼容，設(shè)計(jì)上很大程度上模仿了 SLF4J/Logback，性能上也獲得了很大的提升。Log4j2 也做了 Facade/Implementation 分離的設(shè)計(jì)，分成了 log4j-api 和 log4j-core。
至此我們已經(jīng)有了三個(gè)的 Log 接口和四個(gè) Log 實(shí)現(xiàn)，果然程序員真的是愛(ài)造輪子。出現(xiàn)這么多框架之后，有人開(kāi)始搞各個(gè)框架之間的橋接，你兼容我，我兼容你，如下圖所示。
因?yàn)楹芏?jar 使用的日志框架不同，所以經(jīng)常會(huì)出現(xiàn)引入 jar 包之后導(dǎo)致日志類(lèi)沖突，前面我們排查的那個(gè)問(wèn)題就是因?yàn)橐肓?jcl-over-slf4j 的橋接包。
動(dòng)態(tài)加載日志實(shí)現(xiàn)
前面我們提到日志框架分為日志接口和日志實(shí)現(xiàn)，只要我們代碼中使用的是日志接口（JCL、SLF4J），我們可以隨時(shí)替換日志的實(shí)現(xiàn)。
SLF4J 加載日志實(shí)現(xiàn)的方式
SLF4J 加載日志實(shí)現(xiàn)分為兩個(gè)步驟：
- 獲取 ILoggerFactory 日志工廠
- 根據(jù) ILoggerFactory 獲取 Logger
SLF4J 要求日志實(shí)現(xiàn) jar 包都要實(shí)現(xiàn) StaticLoggerBinder 這個(gè)類(lèi)，而且要放在指定目錄：org/slf4j/impl/StaticLoggerBinder.class，SLF4J 的LoggerFactory會(huì)去掃描所有 jar 包中的這個(gè)地址，參考下面的代碼。
雖然它掃描了多個(gè)日志實(shí)現(xiàn)，但實(shí)際上同名類(lèi) JVM 只能存在一個(gè)，它這里掃描的目的是為了打印日志告訴用戶(hù)有多少個(gè)日志實(shí)現(xiàn)在依賴(lài)包中。下面的代碼返回的是最終使用的日志實(shí)現(xiàn)。
你可能要問(wèn)了，同時(shí)存在多個(gè)日志實(shí)現(xiàn)類(lèi)的時(shí)候，到底是用的是哪個(gè)？答案很簡(jiǎn)單，因?yàn)?SLF4J 利用了靜態(tài)類(lèi)來(lái)加載日志工程，實(shí)際上就是讓 JVM 決定使用哪個(gè)類(lèi)：哪個(gè)被先加載到 JVM 中就用哪個(gè)。為了搞清楚這個(gè)問(wèn)題的答案，我特地去看了URLClassPath加載類(lèi)的實(shí)現(xiàn)，它就是按照 jar 加入到 URLClassPath的順序遍歷掃描，找到第一個(gè)符合條件的就返回。
JCL 加載日志實(shí)現(xiàn)的方式
相比 SLF4J 比較任性的加載方式（依賴(lài) JVM 加載類(lèi)的順序），JCL 提供了更多的配置能力，可以指定使用哪一個(gè)日志工程類(lèi)。
類(lèi)似的，JCL 也分為兩個(gè)步驟加載日志實(shí)現(xiàn)：
- 獲取 LogFactory 日志工廠類(lèi)
- 根據(jù) LogFactory 獲取 Logger
首先是獲取 LogFactory：
- 先從系統(tǒng)屬性中讀取系統(tǒng)屬性System.getProperty("org.apache.commons.logging.LogFactory")
- 使用 Java 的 SPI 機(jī)制，來(lái)搜尋對(duì)應(yīng)的實(shí)現(xiàn)：META-INF/services/org.apache.commons.logging.LogFactory，這里就不對(duì) SPI 進(jìn)行過(guò)多介紹了，簡(jiǎn)單來(lái)說(shuō)就是搜尋哪些 jar 包中含有搜尋含有上述文件，該文件中指明了對(duì)應(yīng)的 LogFactory 實(shí)現(xiàn)
- 從 commons-logging 的配置文件中 commons-logging.properties 尋找org.apache.commons.logging.LogFactory的值
- 最后還沒(méi)找到的話(huà)，使用默認(rèn)的org.apache.commons.logging.impl.LogFactoryImpl
找到 LogFactory 之后就根據(jù) LogFactory 獲取 Logger，這個(gè)根據(jù)不同的 LogFactory 實(shí)現(xiàn)有不同的方式。前面我遇到那個(gè)問(wèn)題就是因?yàn)轭?lèi)沖突導(dǎo)致使用了 SLJ4J 的 LogFactory ，加載了錯(cuò)誤的 Logger。
總結(jié)
開(kāi)發(fā)過(guò)程中總會(huì)遇到奇奇怪怪的問(wèn)題，有無(wú)處下手的感覺(jué)時(shí)先穩(wěn)住心態(tài)，按照大膽假設(shè)，小心求證的方式進(jìn)行排查，實(shí)在沒(méi)有思路往往是因?yàn)榛A(chǔ)還不扎實(shí)。
像這次日志打印不出來(lái)的問(wèn)題，如果了解日志框架的加載實(shí)現(xiàn)，很容易就能定位到問(wèn)題；差一點(diǎn)的像我不了解日志框架的實(shí)現(xiàn)，但是我可以根據(jù)之前對(duì)類(lèi)加載機(jī)制的了解也能解決問(wèn)題；如果對(duì)類(lèi)加載機(jī)制不了解，那基本上是無(wú)解了。
因此，要把問(wèn)題當(dāng)做學(xué)習(xí)機(jī)會(huì)，不光要解決問(wèn)題，還要深挖背后的原理，做好總結(jié)，這樣才能為解決更多的問(wèn)題打下扎實(shí)基礎(chǔ)。
