RocketMQ-LogAppender填坑記
問題背景：最近做的一個項目需要把日誌輸出到RocketMQ進行集中查看，使用的技術框架是Log4j2搭配RocketMQ官方提供的Log4j2 appender
將Log4j2 appender、RocketMQ client及其他相關依賴添加之後，在Log4j2配置文件中添加RocketMQ appender配置，Demo如下：
運行時候報如下警告：
經排查發現是由於RocketMQ client中的ClientLogger類默認會載入一個自定義的log4j2配置文件:
找不到這個文件，就會使用默認的Log4j2配置，默認配置是在Console中輸出Error級別的日誌，Log4j2中配置類AbstractConfiguration中告警代碼如下：
同時發現其提供了一個開關配置來判斷是否載入自定義Log4j2配置文件：
也就是說在程序啟動時將這個system property屬性配置為false就可以讓rocketmq client不去載入自定義配置。由於我的項目是spring boot項目，可以在main方法入口設置這個property：
如果是非Spring boot項目，則可以在java啟動命令時，追加-Dkey=value的方式來配置system property。
配置這個屬性之後重新啟動應用，又報了另外一個錯誤：
可以看到一個異常堆棧，而且在異常堆棧之前有兩個ERROR日誌輸出，初步判斷這個異常應該與這兩個ERROR日誌有某種聯繫。看這個ERROR日誌的大概意思是配置文件中的rocketmqAppender被遞歸調用了。據此判斷，應該是rocketmqAppender在初始化過程中本身又有打日誌的行為，造成遞歸調用。根據日誌中列印的MQ相關信息發現找到其中一個類，確實獲取了logger:
這裡的logger名稱也確實與輸出的日誌信息對應上了。找到了這個錯誤原因，接下來就是在日誌輸出時，讓RocketMQ client本身的logger不再依賴rocketmqAppender，在log4j2配置文件中增加相應Logger配置：
在後續排查問題過程中發現RocketMQ官方提供的client包中有一個demo配置就是這麼乾的：
可是官方文檔並沒有提及這一點，我這還花了好長時間才自己琢磨出來，這實在是坑，不過也怪自己沒有先全局找一下rockemq_client_log4j2.xml這個文件。
配置修改之後，再次重啟應用，結果又報了新的錯誤：
分析一下，這裡的問題大概是這樣，當調用rocketmqAppender發送消息時，它底層依賴的那個Producer已經被關閉了。打開這個DefaultMQProducerImpl類源碼，發現其提供了一個shutdown方法用來將自身狀態置為SHUTDOWN_ALREADY：
那接下來就在這裡設置一個斷點，看哪裡會調用這個shutdown方法：
可以看到是有外層方法調用了RocketmqLog4j2Appender的stop方法，這裡會將底層的Producer shutdown掉：
順著堆棧一層層往上查看，發現Log4j2的LoggerContext在進行配置過程中，會將前一次的配置給stop掉：
大概判斷出這裡的log4j2配置被執行了二次載入。
在RocketMQLog4j2Appender的構造方法上打斷點，然後往堆棧上層調用查看：
從堆棧可以看出是spring boot中的LoggingApplicationListener在啟動時載入了log4j2。斷點通過一下，被之前的shutdown方法中斷點攔截到，也就是第二次log4j2載入的堆棧：
可以看到還是在之前的spring boot啟動方法中，剛才是listeners.starting()調用觸發的log4j2載入，這一次是prepareEnviroment()調用。至此問題基本明了，就是spring boot啟動過程中產生了兩次的log4j2載入，而log4j2本身會對前一次configuration進行stop操作。
不過在排查問題過程中，同事陳偉幫忙分析的時候發現一個問題，當項目中添加spring-boot-starter-log4j2依賴之後，log4j2的載入調用堆棧與我不加這個依賴時，並不一樣。
這個是不加spring-boot-starter-log4j2依賴時的堆棧：
下邊這個是加了依賴之後的堆棧，紅線標出的cinit調用是多出來的：
這一調用其實是靜態欄位初始化：
可以看到在這裡得到了一個Log4jLoggerFactory，由此開始了Log4j2的載入過程。放過斷點在一句上打斷點看這個Log4jLoggerFactory是怎麼來的：
可以看到這個StaticLoggerBinder最終返回的是個Log4jLoggerfactory,然後這個類的getLogger實際上調用了繼承自Log4j2的getLogger方法：
就這樣接著開始了一次Log4j2載入過程。
那麼問題來了，為什麼加了spring-boot-starter-log4j2就走這個載入過程呢?
在排查getFactory()方法過程中發現其載入了這個文件，全局搜索一下，發現這個文件在jcl-over-slf4j的包下面：
這個就是java commons logging與slf4j的橋接包，就是在SLF4JLogFactory中載入了Log4j2。當項目添加spring-boot-starter-log4j2的時候會將jcl-over-slf4j的包傳遞依賴進來，就走了這個新的堆棧調用流程。至此問題分析完成。
接下來要考慮的是怎樣解決。回顧一下，問題的根源是Log4j2初始化了兩次，第二次初始化時候，會將前一次Configuration stop掉，進而調用了底層的RocketMQAppender的stop方法，而它的stop方法中又會將producer給shutdown。那麼解決方法就是可以從兩方面入手：
第一種方法：避免兩將載入Log4j2配置文件，其實在Spring Boot中是可以修改Log的配置文件的，其官方文檔有如下描述：
也就是說加個」-spring」,spring boot也可以默認處理，而且特彆強調一句，你要使用默認文件名不加這個後綴，它無法完全控制log的初始化。看來Spring boot開發人員也知道此處有坑，只是沒有詳細說明。
第二種方法：就是在RocketMQAppender的方法中不要將Producer給shutdown掉，通過其源碼來看，那個Producer針對同一個mqserver及group來說，只會產生唯一一個實例，shutdown之後就絕種了。
最後特別感謝同事陳偉協助解決問題，這個問題分析了好幾天，在他的幫忙下很快就找出原因並解決掉了。
TAG:MasterCoder |