曹工改bug--此次，我遇到了一個難纏的棧溢出bug，仍是日誌相關的，真的難

時間  2019-12-27
標籤 bug 此次 遇到 一個 難纏 溢出 仍是 日誌 相關 简体版
原文   原文鏈接

前言

前幾天，在linux上部署一個war包應用時，tomcat直接起不來，查看tomcat的日誌，catalina.out裏沒啥特別的，可是查看localhost日誌，發現棧溢出了。html

[root@localhost logs]# vim localhost.2019-12-26.log 

26-Dec-2019 16:27:31.811 INFO [localhost-startStop-1] org.apache.catalina.core.ApplicationContext.log No Spring WebApplicationInitializer types detected on classpath
26-Dec-2019 16:27:31.855 SEVERE [localhost-startStop-1] org.apache.catalina.core.StandardContext.listenerStart Exception sending context initialized event to listener instance of class [org.springframework.web.context.ContextLoaderListener]
 java.lang.StackOverflowError
        at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:58)
        at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
        at org.apache.log4j.Category.<init>(Category.java:57)
        at org.apache.log4j.Logger.<init>(Logger.java:37)
        at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:43)
        at org.apache.log4j.LogManager.getLogger(LogManager.java:45)
        at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:66)
        at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
        at org.apache.log4j.Category.<init>(Category.java:57)
        at org.apache.log4j.Logger.<init>(Logger.java:37)
        at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:43)
        at org.apache.log4j.LogManager.getLogger(LogManager.java:45)
        at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:66)
        at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
        at org.apache.log4j.Category.<init>(Category.java:57)
        at org.apache.log4j.Logger.<init>(Logger.java:37)
        at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:43)
        at org.apache.log4j.LogManager.getLogger(LogManager.java:45)
        at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:66)
        at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
        at org.apache.log4j.Category.<init>(Category.java:57)
        at org.apache.log4j.Logger.<init>(Logger.java:37)
        at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:43)
        at org.apache.log4j.LogManager.getLogger(LogManager.java:45)
        at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:66)
        at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
        at org.apache.log4j.Category.<init>(Category.java:57)
        at org.apache.log4j.Logger.<init>(Logger.java:37)

當時腦子昏得很，所幸搜索引擎上找到了解決辦法，java

https://www.jb51.net/article/143486.htmmysql

後邊呢，忙着改bug，沒時間細想，但總感受仍是有點糊里糊塗的。今天完全排查了一下，清晰多了。linux

slf4j與其餘日誌的關係

slf4j，通俗來講，只是一個api類型的jar包，沒有定義實現；具體的日誌實現框架有哪些呢，主要有log4j、logback，你們能夠看看下面這個圖（懶得本身畫了，從前面那個連接裏拿的）：git

這種接口和實現的關係，在軟件設計裏，就是爲了對上層提供統一的編程入口，好比，咱們寫日誌，只須要使用slf4j裏的接口和類，而不用直接使用log4j/logback等，方便替換；這個相似於java的spi機制，好比，java官方定義jdbc接口，各廠商實現jdbc接口，提供出本身的驅動包，好比mysql-driver、oracle-driver等。web

slf4j如何尋找自身的實現

在spi裏，java.util.ServiceLoader經過尋找當前線程類加載器路徑下的META-INF/services/接口的全名來尋找實現類；面試

在slf4j裏，則是經過以下機制，你們能夠查看下面的源碼：redis

https://gitee.com/ckl111/all-simple-demo-in-work/tree/master/slf4j-log4j-stackoverflow-demo/slf4j-no-binderspring

這個工程裏，咱們只添加了以下的maven依賴：sql

<dependencies>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.25</version>
        </dependency>

    </dependencies>

測試代碼也很簡單：

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Test {

    public static void main(String[] args) {
        Logger logger = LoggerFactory.getLogger(Test.class);
        logger.info("hahha");
    }
}

output以下：

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.

只要關注第一行便可，load class org.slf4j.impl.StaticLoggerBinder失敗了。這個類，就是slf4j-api和slf4j-api的實現之間的粘合劑。

畫個圖：

我圖裏說了，兩個包內，都是有org.slf4j.impl.StaticLoggerBinder這個類的，我不騙你們，你們能夠看下面這個module的源碼：

https://gitee.com/ckl111/all-simple-demo-in-work/tree/master/slf4j-log4j-stackoverflow-demo/slf4j-multi-binder

pom依賴主要有：

<dependencies>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.24</version>
        </dependency>
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>1.2.3</version>
            <scope>compile</scope>
        </dependency>

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-log4j12</artifactId>
            <version>1.7.25</version>
        </dependency>

    </dependencies>

這裏面有slf4j的多個實現，logback和slf4j-log4j。一樣的測試類，此時會輸出：

SLF4J: Class path contains multiple SLF4J bindings.
//這裏在logback-classic-1.2.3.jar包裏找到了包名和類名全匹配的類
SLF4J: Found binding in [jar:file:/D:/soft/Repo_backup/ch/qos/logback/logback-classic/1.2.3/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
//在slf4j-log4j12也找到了
SLF4J: Found binding in [jar:file:/D:/soft/Repo_backup/org/slf4j/slf4j-log4j12/1.7.25/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]

因此，slf4j-api的作法其實很原始，你曉得噻，classpath下一般有不少jar包，這裏，slf4j-api就是去classpath下找全類名匹配org.slf4j.impl.StaticLoggerBinder的class文件，找到幾個算幾個，一個沒有就報錯，多了就警告，而後隨便選一個（實際上是看哪一個class在前面）。

核心代碼：

slf4j-api包內：org.slf4j.LoggerFactory#bind
private final static void bind() {
        try {
            //經過classLoader.getResources(org/slf4j/impl/StaticLoggerBinder.class)查找class文件
            Set<URL> staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
            //若是有多個，警告一下
            reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
            ...
            // StaticLoggerBinder就是前面說了半天的那個類，在slf4j-api裏是不存在的，若是整個classpath下都沒有，但這裏又去調用其靜態方法，會直接拋異常NoClassDefFoundError，被catch住；
            // 若是存在呢，就會使用classloader加載StaticLoggerBinder，但這個順序無法保證，假設有logback-classic和slf4j-log4j兩個實現，就看類加載器先加載哪一個了
            StaticLoggerBinder.getSingleton();
            INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            reportActualBinding(staticLoggerBinderPathSet);
            fixSubstituteLoggers();
            replayEvents();
            // release all resources in SUBST_FACTORY
            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;
            }
        }
    }

你們能夠看個人註釋，

StaticLoggerBinder就是前面說了半天的那個類，在slf4j-api裏是不存在的，若是整個classpath下都沒有，但這裏又去調用其靜態方法，會直接拋異常NoClassDefFoundError，被catch住；

若是存在呢，就會使用classloader加載StaticLoggerBinder，但這個順序無法保證，假設有logback-classic和slf4j-log4j兩個實現，就看類加載器先加載哪一個了

我這裏說了一點，存在多個實現的時候，先加載哪一個，後加載哪一個，全看classloader。

你們能夠實際測一下，通常來講，在windows下和linux下，會有不一樣的表現的，坑吧，誰讓你進了這充滿bug的行業呢，不少很奇怪的問題，都是classloader在不一樣OS下，獲取到的jar包順序不一樣致使的：

public class Test {

    public static void main(String[] args) throws NoSuchMethodException, InvocationTargetException, IllegalAccessException {
        Logger logger = LoggerFactory.getLogger(Test.class);
        logger.info("hahha");
        //打印jar包的加載順序
        ClassLoader loader = Test.class.getClassLoader();
        Method getURLs = loader.getClass().getMethod("getURLs");
        getURLs.setAccessible(true);
        URL[] o = (URL[]) getURLs.invoke(loader);
        for (URL url : o) {
            System.out.println(url);
        }
    }
}

問題真相揭祕

回到問題，我仔細研究了一夜，在本地復現了問題，可參考module測試代碼：

https://gitee.com/ckl111/all-simple-demo-in-work/tree/master/slf4j-log4j-stackoverflow-demo/slf4j-log4j-cycle-reference-exclude-log4j-in-pom

這個module裏，pom依賴以下：

堆棧，發現大概是這樣的，圖小能夠單獨tab頁查看：

我這裏也有對堆棧的文字解釋：

at org.apache.log4j.Category. (Category.java:57) log4j-over-slf4j
at org.apache.log4j.Logger. (Logger.java:37) log4j-over-slf4j包，已經死循環了
at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:43) log4j-over-slf4j包
at org.apache.log4j.LogManager.getLogger(LogManager.java:45) log4j-over-slf4j，這個LogManager是log4j包裏的，由於log4j-over-slf4j是一個log4j的冒充者，因此它也有這個類
at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:66) slf4j-log4j12,實現了slf4j，進行了static bind的
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358) slf4j-api
at org.apache.log4j.Category. (Category.java:57) log4j-over-slf4j
at org.apache.log4j.Logger. (Logger.java:37) log4j-over-slf4j

關於log4j-over-slf4j，可進一步閱讀：

https://blog.csdn.net/john1337/article/details/76152906

揭祕過程揭祕

真相可能足夠簡單，可是在找真相的過程反而更難一些，由於這個包，其實在windows下跑是沒問題的，在linux有問題，魔幻？

並不魔幻。由於這個war包裏，原本是log4j依賴的：

<dependency>
      <groupId>log4j</groupId>
      <artifactId>log4j</artifactId>
    </dependency>

至關於：log4j-over-slf4j 和 log4j 共存，咱們說了，log4j-over-slf4j裏，提供了log4j的類，包名和類名都同樣，誰知道先加載哪個呢？誰知道，windows下先加載哪一個，linux下先加載哪一個呢？這個就是要靠運氣的時候了，因此是偶現。

不信你把咱們上面測試的module裏，照下面這樣操做，windows下，立馬就行了

以前不記得采用這種方式來驗證，爲此，還專門定義了一個自定義classloader，先加載slf4j-log4j jar包，再代理給parent，可參考：

https://gitee.com/ckl111/all-simple-demo-in-work/tree/master/slf4j-log4j-stackoverflow-demo/slf4j-log4j-cycle-reference-custom-classloader

總結

這個問題仍是比較有意思的，我也尚未徹底弄懂，但大概瞭解了。

關於classloader在windows和linux下的不一樣表現的問題，可參考：

https://stackoverflow.com/questions/17324975/library-load-order-different-on-two-machines

https://stackoverflow.com/questions/2179858/how-to-find-which-jars-and-in-what-order-are-loaded-by-a-classloader

博主以前也寫了一篇, 關於這個的：

了不起，我可能發現了Jar 包衝突的祕密

關於日誌，博主以前還寫了一篇：

面試題：應用中不少jar包，好比spring、mybatis、redis等等，各自用的日誌系統各異，怎麼用slf4j統一輸出？（上）

本次博客的相關代碼：

https://gitee.com/ckl111/all-simple-demo-in-work/tree/master/slf4j-log4j-stackoverflow-demo

你們有問題請留言，你們以爲有幫助，請點贊哦，這個也是對個人鼓勵。

謝謝你們！

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程