某天排查業務問題時,在我司的日志收集平臺上,未能發現相關業務服務介面訪問日志，經過和相關同事確定,發現業務服務未能將介面訪問日志吐到日志收集平臺,由此開啟一段有點漫長的排查之旅，
業務服務是典型的SpringBoot web應用，日志記錄采用slf4j+log4j2組合，
通過application.propertis檔案中logging.config配置項指定了日志組態檔log4j2.xml具體位置，
通過實作org.apache.logging.log4j.core.Appender介面實作自定義的HttpAppender,將介面訪問記錄發送到日志收集平臺，在log4j2.xml組態檔里如下圖
具體管理與日志收集平臺服務連接,發送請求的是類HttpManager,HttpManager的屬性url決定了接收日志資訊的日志收集平臺地址(來源是組態檔中HttpAppender的url屬性)，
所有HttpAppender物件共享同一個HttpManager,按照單例模式創建,合理的做法應是每個HttpAppender有自己單獨的HttpManager，
這會導致在有配置多個HttpAppender的情況下,只有在實體化第一個HttpAppender時，其配置的日志平臺收集服務的地址會生效，其他的通通無效.
合理的辦法是改動HttpAppender源代碼,但是我沒權限，只能從日志組態檔加載方面想辦法,想辦法讓我們指定的日志組態檔生效，
基本情況介紹完畢,下面開始排查之旅，
在和同事確定之后沒有講日志資訊發送到日志收集平臺,憑直覺猜測日志收集平臺地址是否正確，檢查日志組態檔,發現地址配置正確，難道就這樣結束了？不，你已經是一個成熟的程式員了，要學會自己排查問題了，
遇到這種情況時,我看了一下其他服務，相同的配置,卻穩定正常的向日志收集平臺在發送日志，那我就有理由猜測線上服務實際生效的日志收集平臺地址不是我們想要的,但是如何驗證了，
我們如何方便的可以查看線上服務某個類物件的欄位值了,那就要亮出大殺器了，阿里巴巴開源的Arthas，使用arthas的vmtool命令查看jvm行程中的實體物件資料
看到的結果讓人始料未及,線上服務使用的是日志收集平臺的測驗地址，現在問題變成了,是什么原因導致了線上加載了錯誤的配置，
在idea中全域搜索發現,在resources目錄下的log4j2.xml中,含有相同的HtppAppender,url屬性配置成了日志收集平臺的測驗地址，maven打包之后,業務jar中也會含有log4j2.xml檔案，
那接下來要驗證的是jar包里的log4j2.xml是否被加載,如果被加載,這樣算下來就會有兩份位置不同log42.xml檔案被加載，
接下來就是如何進行驗證了，
思路是如果加載了兩份不同的位置的log4j2.xml,那么創建HttpAppender的方法就會被呼叫兩次,如果能追蹤到創建HttpAppender方法的被呼叫路徑,那么排查起來就會輕松些了.
這次還是借助Arthas,通過其stack命令,可以查看指定方法被呼叫的呼叫路徑，
因為SpringBoot應用一起動,便會在SpringApplication的prepareEnvironment方法里觸發日志組態檔加載,等我通過Arthas attach到指定的jvm行程,執行stack命令的時候,日志配置加載已經結束了,為時已晚，
解決辦法是通過在啟動類的main方法里加上一行代碼TimeUnit.SECONDS.sleep(30) 延遲應用的啟動,以便有足夠的時候通過Arthas attach到jvm行程,執行stack命令，結果如下兩張圖
通過上面這兩張圖得知,在LoggingApplicationListener正常加載日志組態檔之前，BootStrapApplicationListener觸發LoggingApplicationListener做了一次日志組態檔加載，
接下來需要分析的是由BootStrapApplicationListener觸發加載的是哪個日志組態檔，
通過分析BootStrapApplicationListener的bootstrapServiceContext方法,其新建的SpringApplication實體物件,讀取的默認組態檔為bootstrap.yml，因為專案并沒有配置bootstrap.yml,導致ConfigFileApplicationListener對Environment進行初始化時,沒有設定logging.config，
沒有設定logging.config 那ConfigFileApplicationListener是從哪里加載日志組態檔了，通過分析代碼，默認的日志配置加載檔案位置由org.springframework.boot.logging.AbstractLoggingSystem#getSelfInitializationConfig方法負責,如下圖
通過上圖可得知主要檢測classpath里是否存在log4j2.xml，logj4j2.json這樣的組態檔，不巧的是服務的jar里存在log4j2.xml,且配置的url是日志收集平臺的測驗地址，那要如何解決了這個問題了，
通過分析BootStrapApplicationListener源代碼,通過在啟動腳本里啟動命令中添加-Dspring.cloud.bootstrap.enabled=false來禁止BootstrapApplicationListener運行.
修改完畢，再次執行vmtool命令檢查日志收集平臺url配置是否正確，結果顯示的還是日志收集平臺測驗地址，那說明還有其他地方觸發加載了jar包內的log4j2.xml檔案，
此時瞥了一眼我們的啟動類,那么大一個Logger在那杵著,之前愣是沒注意，
啟動類xxxApplication被加載的時候,此時會觸發LOGGER的創建,雖然使用的是SLF4J,實際上創建的是log4j2的Logger,由此會觸發針對日志組態檔的加載，經過google搜索,和針對log4j的原始碼分析,如果沒有指定組態檔,默認是會加載classpath下的log4j2.xml檔案，
此時想到的簡單辦法是把LOGGER屬性注釋掉,那么就會避免發生記在jar包內的log4j2.xml檔案,從而只加載服務目錄下的log4j2.xml，
修改完畢,進行第二次驗證，不巧的是，顯示的還是日志收集平臺測驗地址,那說明還是有其他地方觸發加載了jar包內的log4j2.xml檔案，
此時我們的辦法還是和第一次內似,這次我們用的是watch命令，關注的是org.slf4j.LoggerFactory getLogger方法的被呼叫的時候入參，
通過上圖,發現工程依賴的公司封裝的Apollo配置服務的jar包內的ApolloApplicationContextInitializer觸發了Logger的創建，進而觸發加載了jar包內的log4j2.xml，
那這個ApolloApplicationContextInitializer是因為什么原因被觸發了class加載,導致了Logger的創建，通過查看原始碼,ApolloApplicationContextInitializer實作了ApplicationListener介面，SpringApplication在建構式中會收集當前classpath的spring.factories檔案中org.springframework.context.ApplicationListener配置項中的Listener,并實體化，因此導致了ApolloApplicationContextInitializer類的初始化，
到此我們可以做一下總結,業務程式的啟動程序中,按先后順序總共做了三次日志組態檔log4j2.xml的加載，
第一次：由程式啟動類XXXApplication的靜態屬性LOGGER觸發,加載的是業務jar包內log4j2.xml，
第二次: 由org.springframework.cloud.bootstrap.BootstrapApplicationListener觸發,加載的是業務jar包內log4j2.xml
第三次: 由LoggingApplicationListener負載加載application.properties指定的服務目錄下的logj42.xml，
至此，問題的分析與排查可暫時告一段落,接下來的就是如何修復問題,然后進行驗證，辦法就兩條,
1.減少日志組態檔的加載的次數,
2.讓log4j2框架第一次加載日志組態檔時，便加載到正確的日志組態檔，
辦法1. 通過在服務啟動腳本中加入-Dspring.cloud.bootstrap.enable=false,可以避免上面提到的第二次日志檔案加載，
辦法2. 通過分析lo4j2源代碼,在org.apache.logging.log4j.core.config.ConfigurationFactory類中可以發現通過設定名為log4j.configurationFile的sytem property指定要加載的日志組態檔，
方法都已找到,解決方法如下圖所示,綜合了前面提到的兩條辦法，
經過驗證,問題得到解決,介面訪問日志順利吐到日志收集平臺，一個問題的解決之旅也就此結束，
其實事后總結,還是基礎不夠扎實,對日志框架的了解掌握不夠深入，排查分析問題不夠仔細，對啟動類存在的Logger熟視無睹,由此忽略了帶來的日志配置加載問題，
轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/556226.html
標籤：其他
上一篇：C++語言執行標準
下一篇：返回列表