log4j-over-slf4j與slf4j-log4j12共存stack overflow異常分析
注:下文中的“橋接”、“轉調”、“繫結”等詞基本都是同一個概念。
Exceptionin thread "main" java.lang.StackOverflowError
at java.util.Hashtable.containsKey(Hashtable.java:306)
at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:36)
at org.apache.log4j.LogManager.getLogger(LogManager.java:39)
at org.slf4j .impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:73)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:249)
at org.apache.log4j.Category.<init>(Category.java:53)
at org.apache.log4j.Logger..<init>(Logger.java:35)
at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory .java:39)
at org.apache.log4j.LogManager.getLogger(LogManager.java:39)
at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:73)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:249)
at org.apache.log4j.Category..<init>(Category.java:53)
at org.apache.log4j.Logger ..<init>(Logger.java:35)
at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:39)
at org.apache.log4j.LogManager.getLogger(LogManager.java:39)
subsequent lines omitted...
現有日誌體系
分析這個異常出現的具體原因之前,有必要先快速瞭解一下現有的Java日誌體系。下圖是現有Java日誌體系的一個示意:
上圖不是非常精準,但是能夠比較清晰地展示現有Java日誌體系的主體架構。Java日誌體系大體可以分為三個部分:日誌門面介面、橋接器、日誌框架具體實現。
Java日誌框架有很多種,最簡單的是Java自帶的java.util.logging,而最經典的是log4j,後來又出現了一個比log4j效能更好的logback,其他的日誌框架就不怎麼常用了。應用程式直接使用這些具體日誌框架的API來滿足日誌輸出需求當然是可以的,但是由於各個日誌框架之間的API通常是不相容的,這樣做就使得應用程式喪失了更換日誌框架的靈活性。
比直接使用具體日誌框架API更合理的選擇是使用日誌門面介面。日誌門面介面提供了一套獨立於具體日誌框架實現的API,應用程式通過使用這些獨立的API就能夠實現與具體日誌框架的解耦,這跟JDBC是類似的。最早的日誌門面介面是commons-logging,但目前最受歡迎的是slf4j。
日誌門面介面本身通常並沒有實際的日誌輸出能力,它底層還是需要去呼叫具體的日誌框架API的,也就是實際上它需要跟具體的日誌框架結合使用。由於具體日誌框架比較多,而且互相也大都不相容,日誌門面介面要想實現與任意日誌框架結合可能需要對應的橋接器,就好像JDBC與各種不同的資料庫之間的結合需要對應的JDBC驅動一樣。
需要注意的是,前面說過,上圖並不精準,這只是主要部分,實際情況並不總是簡單的“日誌門面介面-->橋接器-->日誌框架”這一條單向線。實際上,獨立的橋接器有時候是不需要的,而且也並不是只有將日誌門面API轉調到具體日誌框架API的橋接器,也存在將日誌框架API轉調到日誌門面API的橋接器。
說白了,所謂“橋接器”,不過就是對某套API的偽實現。這種實現並不是直接去完成API所宣告的功能,而是去呼叫有類似功能的別的API。這樣就完成了從“某套API”到“別的API”的轉調。如果同時存在A-to-B.jar和B-to-A.jar這兩個橋接器,那麼可以想象當應用程式開始呼叫A或者B的API時,會發生什麼事。這就是最開始引出的那個stack overflow異常的基本原理。
slf4j的轉接繫結
上面只是從整體上大概說了下Java現有日誌體系,還看無法詳細說明問題所在,需要進一步瞭解一下slf4j與具體日誌框架的橋接情況。
slf4j橋接到具體日誌框架
可以看到slf4j與具體日誌框架結合的方案有很多種。當然,每種方案的最上層(綠色的應用層)都是統一的,它們向下都是直接呼叫slf4j提供的API(淺藍色的抽象API層),依賴slf4j-api.jar。然後slf4j API向下再怎麼做就非常自由了,幾乎可以使用所有的具體日誌框架。注意圖中的第二層是淺藍色的,看左下角的圖例可知這代表抽象日誌API,也就是說它們不是具體實現。如果像左邊第一種方案那樣下層沒有跟任何具體日誌框架實現相結合,那麼日誌是無法輸出來的( 這裡不確定是否可能會預設輸出到標準輸出 )。
圖中第三層明顯就不如第一、二層那麼整齊劃一了,因為這裡已經開始涉及到了具體的日誌框架。
首先看第三層中間的兩個湖藍色塊,這是適配層,也就是橋接器。左邊的slf4j-log4j12.jar橋接器看名字就知道是slf4j到log4j的橋接器,同樣,右邊的slf4j-jdk14.jar就是slf4j到Java原生日誌實現的橋接器了。它們的下一層分別是對應的日誌框架實現,log4j的實現程式碼是log4j.jar,而jul實現程式碼已經包含在了JVM runtime中,不需要單獨的jar包。
再看第三層其餘的三個深藍色塊。它們三個也是具體的日誌框架實現,但是卻不需要橋接器,因為它們本身就已經直接實現了slf4j API。slf4j-simple.jar和slf4j-nop.jar這兩個不用多說,看名字就知道一個是slf4j的簡單實現,一個是slf4j的空實現,平時用處也不大。而logback之所以也實現了slf4j API,據說是因為logback和slf4j出自同一人之手,這人同時也是log4j的作者。
第三層所有的灰色jar包都帶有紅框,這表示它們都直接實現了slf4j API,只是湖藍色的橋接器對slf4j API的實現並不是直接輸出日誌,而是轉去呼叫別的日誌框架的API。
其它日誌框架API轉調回slf4j
如果只存在上面這些從sfl4j到其他日誌框架的橋接器,可能還不會出什麼問題。但是實際上還有另外一類橋接器,它們的作用跟上面的恰好相反,它們將其它日誌框架的API轉調到slf4j的API上。下圖來自slf4j官網文件 Bridging legacy APIs :
上圖展示了目前為止能安全地從別的日誌框架API轉調回slf4j的所有三種情形。
以左上角第一種情形為例,當slf4j底層橋接到logback框架的時候,上層允許橋接回slf4j的日誌框架API有log4j和jul。jcl雖然不是什麼日誌框架的具體實現,但是它的API仍然是能夠被轉調回slf4j的。要想實現轉調,方法就是圖上列出的用特定的橋接器jar替換掉原有的日誌框架jar。需要注意的是這裡不包含logback API到slf4j API的轉調,因為logback本來就是slf4j API的實現。
看完三種情形以後,會發現幾乎所有其他日誌框架的API,包括jcl的API,都能夠隨意的轉調回slf4j。 但是有一個唯一的限制就是轉調回slf4j的日誌框架不能跟slf4j當前橋接到的日誌框架相同。 這個限制就是為了防止A-to-B.jar跟B-to-A.jar同時出現在類路徑中,從而導致A和B一直不停地互相遞迴呼叫,最後堆疊溢位。目前這個限制並不是通過技術保證的,僅僅靠開發者自己保證,這也是為什麼slf4j官網上要強調所有合理的方式只有上圖的三種情形。
到這裡,在開始所展示的那個異常的原理基本已經清楚了。此外,通過上圖還可以看出可能會出現類似異常的組合不僅僅是log4j-over-slf4j和slf4j-log4j12,slf4j官網還指出了另外一對: jcl-over-slf4j.jar和slf4j-jcl.jar
程式碼示例
前面的分析都是理論上的,實際程式碼中即便同時使用了log4j-over-slf4j和slf4j-log4j12,也未必一定會出現異常。下面的程式碼呼叫slf4j的API輸出日誌,slf4j底層橋接到log4j:
package test;
public class HelloWorld {
public static void main(String[] args) {
org.apache.log4j.BasicConfigurator.configure();
org.slf4j.Logger logger = org.slf4j.LoggerFactory
.getLogger(HelloWorld.class);
logger.info("Hello World");
}
}
配置classpath上的jar包為(注意log4j在log4j-over-slf4j之前):
在這種情況下執行測試程式是能夠正常輸出日誌的,不會出現stack overflow異常。但是如果調整classpath上的jar順序為:
再執行測試程式就出現類似於本文最開始的stack overflow異常了,可以看到明顯的週期性重複:
序列圖分析
上圖是堆疊溢位的詳細呼叫過程式列圖。從呼叫1開始,依次呼叫1.1、1.1.1……最後到了1.1.1.1.1.1(圖中最後一個呼叫)的時候,發現它跟1是完全一樣的,那麼後續的過程就是完全一樣的重複了。
需要特別說明的是最開始的導火索並不只有圖中所示的LoggerFactory.getLogger()一種,應用程式中能夠觸發堆疊溢位異常的直接呼叫還有好幾種其它的,比如前面示例程式碼中觸發異常的實際上是第一條語句org.apache.log4j.BasicConfigurator.configure(),但後續的互相無限遞迴呼叫過程基本都是跟上圖相同的過程。