[轉] log4j-over-slf4j與slf4j-log4j12共存stack overflow異常分析

[From] http://www.tuicool.com/articles/INveIf

 

注：下文中的“橋接”、“轉調”、“綁定”等詞基本都是同一個概念。

log4j-over-slf4j和slf4j-log4j12是跟java日志系統相關的兩個jar包，當它們同時出現在classpath下時，就可能會引起堆棧溢出異常。異常信息大致如下（摘自slf4j官網文檔 Detected both log4j-over-slf4j.jar AND slf4j-log4j12.jar on the class path, preempting StackOverflowError ）：

Exception in 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官網文檔 Binding with a logging framework at deployment time ：

可以看到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()，但后續的互相無限遞歸調用過程基本都是跟上圖相同的過程。