log4j日誌不輸出的問題

  • 2019 年 10 月 3 日
  • 筆記

今天伺服器上報錯,想先去看一下日誌進行排查,結果發現日誌很久都沒有輸出過了。從上午排查到下午,剛剛解決,因此記錄一下,但現在也只是知其然,並不知其所以然,所以如果大家有什麼想法請在下方評論。

先說一下環境,伺服器是linux,項目是運行在tomcat下的Spring項目,日誌用的是log4j。

首先,從10月13號開始便沒有新的日誌文件了。假設日誌名為log.txt(如果你設置了DailyRollingFileAppender,那麼你當天的日誌文件就是log.txt),先備份該文件到其他目錄下,然後刪除該文件,重新啟動tomcat。這是為了確認你的log4j配置是否有問題,因為這是最容易出錯的地方。很遺憾,我不是這裡出的問題,因為項目重啟後,日誌文件又重新生成了,但很奇怪的是,日誌文件是空的,其大小為0.

感覺自己碰上了很神奇的問題,因此我在自己的本地進行調試,啟動項目後發現,正常的項目啟動日誌是有的:

15:13:48:0253  INFO [RMI TCP Connection(3)-127.0.0.1] -Root WebApplicationContext: initialization completed in 18479 ms

但我自己的一些日誌輸出是不顯示的,比如:

private static final Logger log = LoggerFactory.getLogger(MyDomain.class);  log.info("show info log");

show info log這句話就不列印,現在證明,我的日誌配置沒有問題,伺服器也找到了我的日誌文件,但應該是我自己的Logger是不對應正確的日誌輸出的,因為我的console(控制台)有顯示。

接下來,我就是開始看源碼了。先是LoggerFactory.getLogger(Class<?> clazz)方法:

    public static Logger getLogger(Class<?> clazz) {          Logger logger = getLogger(clazz.getName());          if (DETECT_LOGGER_NAME_MISMATCH) {              Class<?> autoComputedCallingClass = Util.getCallingClass();              if (autoComputedCallingClass != null && nonMatchingClasses(clazz, autoComputedCallingClass)) {                  Util.report(String.format("Detected logger name mismatch. Given name: "%s"; computed name: "%s".", logger.getName(),                                  autoComputedCallingClass.getName()));                  Util.report("See " + LOGGER_NAME_MISMATCH_URL + " for an explanation");              }          }          return logger;      }

好吧,沒什麼用,看不出我的logger變成了,繼續看getLogger(String name)方法:

    public static Logger getLogger(String name) {          ILoggerFactory iLoggerFactory = getILoggerFactory();          return iLoggerFactory.getLogger(name);      }

這時我在return iLoggerFactory.getLogger(name);這行打了斷點,我看到了這樣的東西:
iLoggerFactory是logback中的實現

為什麼我的iLoggerFactory是用的logback中的實現?其實也是怪我自己大意,我其實依賴了一個基於Spring Boot的項目(雖然我只是用了裡面的一些domain類,但因為設計不當,還沒有把這些domain類單獨提成一個_項目),而Spring Boot中一般默認就依賴的logback。通過gradle查看項目的依賴樹,也證實了我的這一猜想(./gradlew 子項目名稱:dependencies):

|    +--- org.springframework.boot:spring-boot-starter-web:2.0.2.RELEASE  |    |    +--- org.springframework.boot:spring-boot-starter:2.0.2.RELEASE  |    |    |    +--- org.springframework.boot:spring-boot:2.0.2.RELEASE  |    |    |    |    +--- org.springframework:spring-core:5.0.6.RELEASE (*)  |    |    |    |    --- org.springframework:spring-context:5.0.6.RELEASE (*)  |    |    |    +--- org.springframework.boot:spring-boot-autoconfigure:2.0.2.RELEASE  |    |    |    |    --- org.springframework.boot:spring-boot:2.0.2.RELEASE (*)  |    |    |    +--- org.springframework.boot:spring-boot-starter-logging:2.0.2.RELEASE  |    |    |    |    +--- ch.qos.logback:logback-classic:1.2.3  |    |    |    |    |    +--- ch.qos.logback:logback-core:1.2.3  |    |    |    |    |    --- org.slf4j:slf4j-api:1.7.25

接下來就好辦了,你排除掉ch.qos.logback的依賴就可以了,在你的build.gradle中增加:

configurations {      compile.exclude group: 'ch.qos.logback'  }

這個時候你再重新調試一下看看:
iLoggerFactory是log4j中的實現

完美,現在是log4j中的實現,得到了我想要的操作。當然了,既然我知道之前項目中的slf4j是logback實現了,那麼我自然也可以換成logback的配置,但這就需要我將項目換成用Spring Boot啟動,這個改動有點大,如果以後有必要的話,我再將這個exclude刪除,換成Spring Boot的形式。

這次Spring Boot幫我們默認啟用的是logback,那麼有沒有什麼簡單方法可以知道呢?如果你的項目出現了以下的日誌輸出,說明你的項目當前有不止一個SLF4J的實現組件:

SLF4J: Class path contains multiple SLF4J bindings.  SLF4J: Found binding in [jar:file:/project.war/WEB-INF/lib/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]  SLF4J: Found binding in [jar:file:/project.war/WEB-INF/lib/slf4j-log4j12-1.7.21.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]

因為在org.slf4j.LoggerFactorybind方法中有關於這方面的輸出:

    private final static void bind() {          try {              Set<URL> staticLoggerBinderPathSet = null;              // skip check under android, see also              // http://jira.qos.ch/browse/SLF4J-328              if (!isAndroid()) {                  // 查找你的當前項目有幾個slf4j的實現                  staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();                  // 如果多餘一個就列印                  reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);              }              // the next line does the binding              // 這個是具體選了哪一個實現(重點關注)              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;              }          } catch (java.lang.NoSuchMethodError nsme) {              String msg = nsme.getMessage();              if (msg != null && msg.contains("org.slf4j.impl.StaticLoggerBinder.getSingleton()")) {                  INITIALIZATION_STATE = FAILED_INITIALIZATION;                  Util.report("slf4j-api 1.6.x (or later) is incompatible with this binding.");                  Util.report("Your binding is version 1.5.5 or earlier.");                  Util.report("Upgrade your binding to version 1.6.x.");              }              throw nsme;          } catch (Exception e) {              failedBinding(e);              throw new IllegalStateException("Unexpected initialization failure", e);          }      }

特別要注意的是StaticLoggerBinder.getSingleton();這行程式碼,StaticLoggerBinderlogback-classicslf4j-log4j12這兩個jar包各有一個,因此,Spring boot是自動選擇logback-classic(雖然我在本地運行的時候還是默認進入的slf4j-log4j12,但是會提醒我Source code does not match the bytecode,因此我判斷依舊進的是logback-classic),所以只要把logback給exclude掉,就解決了這個問題。

現在看問題,更加關注源程式碼,因為這可以讓我們更加快速定位問題,並且也能據此大致猜出其解決方案。希望大家能一起看看源程式碼,如果你有什麼發現,可以在下方留言,我將和你一起討論。

有興趣的話可以關注我的公眾號或者頭條號,說不定會有意外的驚喜。