如果把工作看作是一個遇到問題-解決問題的過程,那麼在拿一份薪水的同時,我們也需要多問一下自己:在解決問題的過程中,我們學到了什麼?
很多人可能會抱怨,自己是初級碼農,天天寫CRUD,接觸不到架構、接觸不到複雜場景。那麼如何實現從初級到中級再到高級的躍遷?它實際暗含在每一天的積累中。首先要學會發現問題,在解決之餘,留一些時間給自己溯源、復盤,就能給自己帶來一些進步,而這些細微的提升,正是充實和豐富自己知識網絡的絕佳機會。
事情的起因,在使用slf4j作為日誌框架時,當一段代碼拋出異常,進行異常捕獲之後,日誌中卻沒有列印相應的調用棧。
首先來看看這段代碼:
try{
int i = 1 / 0;
} catch (Exception reqEx) {
LOGGER.error("xxx about:{}, cause:{}", ip, reqEx);
}
你覺得它會輸出哪些東西?
在檢查日誌時,我們發現,這段代碼在捕獲異常之後,在有些機器上執行結果會列印出exception的異常棧,有些機器上則只會單純地把reqEx當做一個普通對象,列印 toString信息,不會列印出異常棧。
測試發現,如上代碼在logback下,會輸出棧異常信息:
xxx about:10.10.10.10, cause:{}
java.lang.ArithmeticException: / by zero
at com.zzc.test.dubbo.ProviderBootStrap.main(ProviderBootStrap.java:32)
可以看到儘管有兩個{},但是最後一個參數如果是 Throwable類型的話,則優先當做 Throwable處理,會列印出異常棧信息。
但是相同的代碼在log4j下,輸出情況則有所區別:
xxx about:10.10.10.10, cause: java.lang.ArithmeticException: / by zero
可以看到,log4j下會優先選擇滿足佔位符,儘管最後一個參數是異常類型,則也進行了 toStirng輸出,而異常的 toString並不會將異常棧一起輸出。
為什麼會這樣呢?這就需要先給大家普及一下slf4j相關的門面模式(也稱為外觀模式)的知識了,像slf4j的官網所說的一樣
The Simple Logging Facade for Java (SLF4J) serves as a simple facade or abstraction for various logging frameworks, such as java.util.logging, logback and log4j. SLF4J allows the end-user to plug in the desired logging framework at deployment time. Note that SLF4J-enabling your library/application implies the addition of only a single mandatory dependency, namely slf4j-api-2.0.0-alpha2-SNAPSHOT.jar.
翻譯成中文就可以這麼理解:slf4j為多種多樣的日誌框架(比如logging, logback and log4j)充當門面或抽象化的接口,本身並沒有具體實現如何進行日誌地列印以及日誌列印的格式這些細節。需要具體的日誌框架來實現並執行。
先從概念上了解一下:門面模式(Facade Pattern),外部與一個子系統的通信必須通過一個統一的外觀對象進行,為子系統中的一組接口提供一個一致的界面,外觀模式定義了一個高層接口,這個接口使得這一子系統更加容易使用。門面模式又稱為外觀模式,它是一種對象結構型模式。為了具體說明這個門面模式是如何工作的,這裡寫了一個簡單例子,讓我們根據這個例子看看這裡面的學問。
上面所說的「高層接口」指的就是slf4j,而子系統則是諸如logging, logback and log4j這種具體實現。
為了更加直觀地理解門面模式,舉一個通俗易懂的例子:
一般的醫院都會分為掛號、門診、化驗、收費、取藥等。病人要想治好自己的病(相當於一個客戶端想要實現自己的功能)就要和醫院的各個部門打交道。首先,病人需要掛號,然後門診,如果醫生要求化驗的話,病人就要去化驗,然後再回到門診室,最後拿藥,經過一系列複雜的過程後才能完成看病的過程。如下圖所示:
解決這種不便的方式就是引入門面模式。如果我們在醫院設立一個接待員的話,病人只負責和接待員接觸,由接待員負責與醫院的各個部門打交道,如下圖所示:
相較於醫院,現在很多的體檢機構,都有這種「專門的接待員」,本質就是門面模式。
為了具體說明門面模式在slf4j中是如何工作的,這裡寫了一個簡單例子,讓我們根據這個例子看看這裡面的學問。
private static final Logger LOGGER = LoggerFactory.getLogger(Main.class);
public static void main(String[] args) {
LOGGER.info("Hello,World");
}
如上程序,所以大家很可能在運行的時候發現,調用了 LOGGER.info方法但是沒有任何日誌列印出來,並且控制臺上還出現了如下的警告。
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
debug發現, LOGGER.info調用的是 org.slf4j.helpers.NOPLogger#info,但是這是一個空實現。這種情況往往就是大家只引入了slf4j-api這個門面的jar包,但是沒告訴SLF4J如何去列印日誌,所以slf4j採用了默認空實現的方式。那這些異常又是怎麼回事呢?
我們進入源碼看看是如何根據 LoggerFactory.getLogger是如何獲取到對應的 Logger的。以下代碼都來自於slf4j1.7.29版本。
跟入源碼首先會去拿對應的 LoggerFactory,這是個全局單例的對象。
public static Logger getLogger(String name) {
ILoggerFactory iLoggerFactory = getILoggerFactory();
return iLoggerFactory.getLogger(name);
}
繼續跟到 org.slf4j.LoggerFactory#getILoggerFactory方法中,
public static ILoggerFactory getILoggerFactory() {
if (INITIALIZATION_STATE == UNINITIALIZED) {
synchronized (LoggerFactory.class) {
if (INITIALIZATION_STATE == UNINITIALIZED) {
INITIALIZATION_STATE = ONGOING_INITIALIZATION;
performInitialization();
}
}
}
switch (INITIALIZATION_STATE) {
case SUCCESSFUL_INITIALIZATION:
return StaticLoggerBinder.getSingleton().getLoggerFactory();
case NOP_FALLBACK_INITIALIZATION:
return NOP_FALLBACK_FACTORY;
case FAILED_INITIALIZATION:
throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
case ONGOING_INITIALIZATION:
// support re-entrant behavior.
// See also http://jira.qos.ch/browse/SLF4J-97
return SUBST_FACTORY;
}
throw new IllegalStateException("Unreachable code");
}
可以看到當 if(INITIALIZATION_STATE==UNINITIALIZED),即當第一次獲取時,此時處於未初始化時,則首先調用 performInitialization進行初始化。(這裡還用了雙重檢測避免多線程下重複初始化)
performInitialization方法隨後調用核心方法 bind,可以看到該方法的catch塊中看到了我們熟悉的那段警告。
private final static void bind() {
try {
Set<URL> staticLoggerBinderPathSet = null;
if (!isAndroid()) { // 非安卓應用
staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
}
StaticLoggerBinder.getSingleton();
INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
reportActualBinding(staticLoggerBinderPathSet);
fixSubstituteLoggers(); // 這個方法我們後面會說到
replayEvents(); // 同上
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;
}
}
....省略
}
對於非安卓應用,會調用 findPossibleStaticLoggerBinderPathSet,該方法是重中之重,從名字來看,該方法會去尋找所有可能的 StaticLoggerBinder類路徑, Failedto loadclass"org.slf4j.impl.StaticLoggerBinder".我們在警告中也看到過該類的身影,所以此類就是關鍵所在了。
private static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class";
static Set<URL> findPossibleStaticLoggerBinderPathSet() {
Set<URL> staticLoggerBinderPathSet = new LinkedHashSet<URL>();
try {
ClassLoader loggerFactoryClassLoader = LoggerFactory.class.getClassLoader();
Enumeration<URL> paths;
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;
}
可以看到,該方法會去當前應用的classpath下去找所有的 org/slf4j/impl/StaticLoggerBinder.class並且返回。(2.0版本以上用了SPI機制去發現,具體看https://github.com/qos-ch/slf4j/blob/master/slf4j-api/src/main/java/org/slf4j/LoggerFactory.java)。
搜索了一下,當前程序應用果然找不到該類,所以就會有了應用啟動的時候那段警告,並且降級到 org.slf4j.helpers.NOPLogger的空實現了。我們再去其他日誌正常列印的應用下搜索下該類,可以看到:
幾個你經常看到伴隨著 slf4j-api這個jar包一起引入的jar中都會有這個類的存在,且如果發現某一個應用有多個 org/slf4j/impl/StaticLoggerBinder類,則會列印出類似 Foundbindingin[jar:file:/Users/xxx/.m2/repository/org/slf4j/slf4j-log4j12/1.7.25/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]這樣的警告,並且按照類加載順序選擇最靠前的一個進行使用。
問題所在看到這裡,大家可能就明白了,為啥平常在使用日誌的時候,除了引入slf4j-api這個jar包之外,還會引入其他的諸如log4j、logback這類的jar包。簡而言之,就是slf4j提供了一個日誌的標準,各大廠家都去遵循標準來進行具體的實現。儘管實現可能有細小的差異,就像我上面說的那個問題在log4j和logback下的行為並不完全一致,所以在日常寫代碼中,也儘可能地需要遵循標準方式進行列印日誌,例如最初的那個起因的代碼,我們只需要改成 LOGGER.error("xxx about:{}, cause:",ip,reqEx);即可以在任何實現下都列印出異常棧信息了,即異常不需要去匹配 {}佔位符。
一個優秀設計這裡額外需要說到的一個設計,感興趣的讀者可以看一下,不感興趣可以跳過看下一段。
在 caseONGOING_INITIALIZATION:的情況下,此時是因為其他線程已經在初始化LoggerFactory了,為了避免阻塞等待初始化,當其他線程發現有線程已經在初始化時則會返回一個 SUBST_FACTORY,該對象是 SubstituteLoggerFactory類型,在其上調用 getLogger會返回一個臨時的 SubstituteLogger。
SubstituteLogger是一個裝飾者類,所有方法的調用都會交給真正的Logger對象進行處理,如 info方法所示:
public void info(String msg, Throwable t) {
delegate().info(msg, t);
}
delegate方法的處理也很容易理解,當 delegate為空時,則判斷 createdPostInitialization是否為真,為真則返回 NOP_LOGGER,否則通過 getEventRecordingLogger返回一個 EventRecodingLogger,該Logger會將所有日誌包裝成事件,放到對應的隊列中緩存。
private volatile Logger _delegate;
Logger delegate() {
if(_delegate != null) {
return _delegate;
}
if(createdPostInitialization) {
return NOPLogger.NOP_LOGGER;
} else {
return getEventRecordingLogger();
}
}
_delegate對象在另一個線程初始化 LoggerFactory完成之後,調用 org.slf4j.LoggerFactory#fixSubstituteLoggers方法進行注入。
而之前緩存的日誌事件也會由該初始化線程調用 org.slf4j.LoggerFactory的 replayEvents方法由真正的Logger進行重放。
這個設計點使得多線程在初始化 LoggerFactory的時候不會阻塞對方,並且也不會影響在初始化結束之前的日誌記錄。
Java日誌框架的混亂歷史看到這裡,有心的讀者肯定會有這麼一個疑惑,為什麼Java日誌框架需要一個門面標準,而不是統一一個類庫的實現標準?
首先來看看歷史的車輪:
Java日誌框架的發展歷史
log4j是Java社區最早的日誌框架,推出後一度成為Java的事實日誌標準,據說Apache曾建議Sun把log4j加入到Java標準庫中,但是被Sun拒絕。
在Java1.4中,Sun在標準庫中推出了自己的日誌框架java.util.logging,功能相對簡陋。
雖然logging相對簡陋,但還是有類庫採用了它,這就出現了同一個項目中同時使用log4j和logging要維護兩套配置的問題,Apache試圖解決這個問題,推出了JCL日誌門面(接口),定義了一套日誌接口,底層實現支持log4j和logging,但是並沒有解決多套配置的問題。
log4j的主力開發Ceki Gülcü由於某些原因離開了Apache,創建了slf4j日誌門面(接口),並實現了性能比log4j性能更好的logback(如果Ceki Gülcü沒有離開Apache,這應該就是log4j2的codebase了)
Apache不甘示弱,成立了不兼容log4j 1.x的log4j2項目,引入了logback的特性(還酸酸地說解決了logback架構上存在的問題),但目前採用率不是很高。
當你在開發一個新項目,進行日誌框架選型時,儘量避免採用單一的實現,更好的方式是使用門面模式,秉承面向接口編程的思想。這樣做有什麼好處呢?尤其是當你的代碼是以SDK的形式提供給他人的,假如你的SDK中寫死了logback,而調用方使用的是log4j,那麼就會產生衝突;而如果你使用的是門面,就能與具體實現解耦。
下面這張圖就展示了slf4j門面是如何配合其他具體實現框架工作的。其中可以看到,在面對log4j和logging時,slf4j需要一個額外的適配層來進行適配,這是因為log4j和logging比較老,當初的設計就不是面向門面的。
這是我準備在2020年持續更新的一個系列
致力於用一種新方式講解編程
難度會逐漸上升
希望得到你的關注和轉發
我和啾啾感激不盡🙏