LogBack 日誌等級設定無效，原因竟然是因為這個？！

熬夜不加班發表於2021-05-30

Hello，大家好，我是樓下小黑哥~

最近被公司派去北京出差，本以為是個輕鬆的差事，北京一週遊~

但是沒想到第一天就是九點半下班， 大意了~

好了，回到正題，今天來講下最近除錯專案的時候發現的一個 Logback 日誌級別設定不生效的問題。

問題背景

事情是這樣的，我們的專案是一個 SpringBoot 的工程的，其中日誌框架使用的是 LogBack，配置檔案如下所示：

<configuration scan="true" scanPeriod=" 5 seconds" debug="true">

    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%date [%thread] %-5level %logger{80} - %msg%n</pattern>
        </encoder>
    </appender>

    <logger name="org.springframework" level="DEBUG"/>

    <root level="debug">
        <appender-ref ref="stdout"/>
    </root>

</configuration>

為了方便檢視專案執行的 SQL，這裡我把日誌的級別調整成 DEBUG。

執行的專案，執行結果比較令人驚訝，日誌僅僅輸出了 INFO 日誌，並沒有輸出 DEBUG 日誌。

剛開始還以為 Logback 配置檔案寫的有問題，才導致這個問題。網上找了幾個例子，對比了一下，這類的配置檔案並沒有什麼問題。

於是進行一系列深度排查（令人頭禿），最終終於找到了問題的原因。

問題原因

由於 Logback 的配置 debug=true,專案啟動的時候，將會列印出 Logback 內部日誌資訊，日誌如下：

從這個日誌可以看到，Logback Root 已經設定為 DEBUG。

那為什麼專案啟動之後，DEBUG 就失效了？

不要急，接著往下看。

當 Spring 容器啟動之後，Spring 內部將會發出一些列的 ApplicationEvent，然後這些將會被各類已經註冊的 ApplicationListener監聽。

由於這個專案是一個 SpringBoot 的工程，裡面有一個 LoggingApplicationListener將會監聽 ApplicationEnvironmentPreparedEvent，程式碼如下：

這裡面的邏輯比較簡單，獲取系統配置的日誌級別，levels 值如下：

可以看到這裡 root 對應的值為 info，這裡將會繼續呼叫 Logback 的的方法設定日誌級別，日誌輸出如下：

上面這些日誌級別配置來自其實來自 SpringBoot 的配置檔案 application.properties

總結

最後，總結一下，SpringBoot 專案，如果使用單獨的 LogBack 配置檔案，SpringBoot 的配置檔案 application.properties 配置的 logging.level.root 將會覆蓋的 Logback 配置檔案中的 root 的配置：

<root level="debug">
    <appender-ref ref="stdout"/>
</root>

問題看起來是那麼簡單，排查的過程真的是令人頭禿。

相關文章