一文搞定slf4j、Java日誌那些事兒,我和面試官談笑風生

2021-03-02 寒食君


如果把工作看作是一個遇到問題-解決問題的過程,那麼在拿一份薪水的同時,我們也需要多問一下自己:在解決問題的過程中,我們學到了什麼?

很多人可能會抱怨,自己是初級碼農,天天寫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年持續更新的一個系列

致力於用一種新方式講解編程

難度會逐漸上升

希望得到你的關注轉發

我和啾啾感激不盡🙏

相關焦點

  • slf4j中的橋接器是如何運作的?
    前言在日誌框架slf4j中有一組項目,除了核心的slf4j-api之外,還有slf4j-log4j12、slf4j-jdk14等項目。這一類項目統稱橋接器項目,針對不同的日誌框架有不同的橋接器項目。在使用logback日誌框架時,並沒有針對的橋接器,這是因為logback與slf4j是一個作者所寫,在logback中直接實現了slf4j的SPI機制。但如果使用其他日誌框架,那麼就必須要用到橋機器相關依賴。
  • 架構師之路--談架構師的基本素養和日誌處理
    但是我覺得做人要厚道,決不能肥了自己虧了別人。素養三:廣交朋友  我的技術在朋友圈裡是個小嘍囉。幾個月前給了兩萬塊錢給一個朋友讓他幫我炒股。籤的半年合同,現在怎麼樣了我也沒問。用人不疑,疑人不用。這個朋友我是怎麼認識的呢?我之前就見過他一面,去58面試,他是面試官。我認識一個大牛是58的一個部門領導。之前是同事,我什麼水平其實都清楚。
  • 坑爹代碼 | 這樣的日誌封裝到底是坑爹還是有用呢?
    那麼怎麼用日誌框架才是最佳的實踐呢?下面這段代碼難道真的只是一個無用的封裝嗎?import org.slf4j.Marker;// 當時完全不懂包裝slf4j什麼意思,還以為自己針對市面上的logger進行了封裝處理,上次開會的時候這麼說,我為了logger的時候像andriod能寫個tag,WTF,難道你logger.info('tag:{},xxxxx',tag)這樣不行麼?
  • Java 日誌框架衝突問題排查與總結
    因此我希望先復現我當時在對日誌框架了解不多的情況下排查問題的思路和步驟,如何在面對未知問題找到破題思路是非常重要的技能。一次典型的日誌衝突排查問題背景在 A 工程中,日誌框架配置選用了 Log4j2,master 分支上日誌列印正常,但開發分支增加了代碼之後日誌列印不出來。項目的依賴中包含了 Log4j2、Logback 等日誌框架。
  • Log4j 2.4 發布,最低要求 Java 7 - OSCHINA - 中文開源技術交流社區
    o LOG4J2-1058:  Log4jMarker#contains(String) does not respect org.slf4j.Marker contract. Thanksto Daniel Branzea.
  • 別在Java 代碼裡亂打日誌了,這才是正確的打日誌姿勢!
    本文轉載自【微信公眾號:java進階架構師,ID:java_jiagoushi】經微信公眾號授權轉載,如需轉載與原文作者聯繫使用slf4j使用門面模式的日誌框架,有利於維護和各個類的日誌處理方式統一。實現方式統一使用: Logback框架打日誌的正確方式什麼時候應該打日誌當你遇到問題的時候,只能通過debug功能來確定問題,你應該考慮打日誌,良好的系統,是可以通過日誌進行問題定為的。
  • Java和Groovy正則使用
    相信很多人都對正則有很深的交情,畢竟這玩意功能太強了,幾乎無處不在。
  • 【java】獲取本機IP位址和網卡的MAC地址
    平凡也就兩個字: 懶和惰;成功也就兩個字: 苦和勤;優秀也就兩個字: 你和我。
  • JNPF快速開發平臺-簡單快速高效開發java項目
    使用JNPF開發平臺可以簡單、快速、高效的構建各種類型java項目。 JAVA版介紹 JNPF.java版採用前後端分離,可將代碼直接導入idea運行,也可將前後端代碼利用ngnix分開部署。
  • 五分鐘學會 Java 開發效率神器 Lombok
    @Slf4j自動生成該類的 log 靜態常量,要打日誌就可以直接打,不用再手動 new log 靜態常量了除了 @Slf4j 之外,lombok 也提供其他日誌框架的變種註解可以用,像是 @Log、@Log4j...等,他們都是幫我們創建一個靜態常量 log,只是使用的庫不一樣而已
  • 大型企業JVM性能調優實戰Java垃圾收集器及gcroot
    一個java程序運行,最少有三個類加載器實例,負責不同類的加載。「將class文件加載進JVM的方法區,並在方法區中創建一個java.lang.Class對象作為外界訪問這個類的接口。」實現這一動作的代碼模塊稱為類加載器案例類和類加載器:對於任意一個類,都需要由加載它的類加載器和這個類本身一同確立其在虛擬機中的唯一性。
  • 十分鐘搞懂Java效率工具Lombok使用與原理
    這篇文章是我當初學習 Lombok 覺得非常不錯的一篇文章,原文地址:https://juejin.im/post/5b00517cf265da0ba0636d4b。1 簡介Lombok是一款好用順手的工具,就像Google Guava一樣,在此予以強烈推薦,每一個Java工程師都應該使用它。
  • 我和面試官的博弈:Java 並發編程篇
    還請大家置頂(標星)本公眾號:Java後端,第一時間接收優質博面試中問的頻率很高的一個是分布式,一個就是並發。而JUC(java.util.concurrent)裡的東西是並發編程的基石。上次的面試已經過去一段時間,在一邊努力工作的同時,我也一邊抽出時間準備 Java 並發編程的部分。今天懷著輕鬆愉快的心情,再次踏上我的大廠面試之旅。
  • 面試系列——Java工作6年面試拼多多和阿里經歷附帶面試題
    然後面試官說他們也是這麼做的,所以他說他們的一些操作日誌表有的表已經有分庫分表上萬張了我問面試官的第二個問題是詳情頁的設計,怎麼做的緩存設計?(比如從不同的業務緯度拆分key,更新頻率拆分key)因為我一直想了解一下大公司在庫存和價格這塊有沒有應用緩存這種形式,因為我們之前因為QPS都不算高,價格,庫存都是直接實時查詢數據的,結合兜底方案來解決。所以這二個問題一提,一面面試官覺得我之前有過思考,就讓我進入了二面。
  • 面試總結——Java高級工程師
    尚學堂AD試前面也總結了一和二, 這第三篇可能更偏向於是內心的獨白篇和面試技巧總結吧…..一、獨白之前也面試別人,現在輪到自己找工作,怎麼說呢,每個面試官的看法不一樣,面試的方式就不一樣,比如我面試別人我喜歡問項目中他用到了那些,然後針對用到的技術去問一些問題,或者說對於某些場景的一些技術實現方案是我特別喜歡問的,比如當你的接口服務數據被人截包了,你如何防止數據惡意提交?
  • 面試官是怎麼來考察你對ES搜尋引擎的理解?
    本文轉載自【微信公眾號:java進階架構師,ID:java_jiagoushi】經微信公眾號授權轉載,如需轉載與原文作者聯繫一. 面試官心理分析問這個,其實面試官就是要看看你了解不了解 es 的一些基本原理,因為用 es 無非就是寫入數據,搜索數據。
  • 2017年排名Top 100的Java類庫——在分析了259,885份源碼之後得出的結論
    譯者註:Mockito 是一個強大的用於 Java 開發的模擬測試框架, 通過 Mockito 我們可以創建和配置 Mock 對象, 進而簡化有外部依賴的類的測試.Java中的日誌組建 slf4j 位列第五。這從某個側面體現出目前的開發人員對日誌還是比較情有獨鐘的。同時也看得出Java開發人員對於 java.util.logging 庫的使用率較低。