1. 程式人生 > >log4j平穩升級到log4j2

log4j平穩升級到log4j2

一、前言

  公司中的專案雖然已經用了很多的新技術了,但是日誌的底層框架還是log4j,個人還是不喜歡用這個的。最近專案再生產環境上由於log4j引起了一場血案,於是決定升級到log4j2。

二、現象

  雖然生產環境有多個結點分散高併發帶來的壓力,但是訊息中心上一週好多接入方接入,導致併發量一下就增多了,導致服務卡死。在堆疊資訊中看到大量的BLOCK異常,如下。

"http-nio-172.17.20.113-28080-exec-6452" #381905 daemon prio=5 os_prio=0 tid=0x00007f49e857e000 nid=0x8427f waiting for monitor entry [0x00007f49c1c75000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.log4j.Category.callAppenders(Category.java:
204) - waiting to lock <0x00000000e5915bd8> (a org.apache.log4j.spi.RootLogger) at org.apache.log4j.Category.forcedLog(Category.java:391) at org.apache.log4j.Category.log(Category.java:856) at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.java:581) at com.cmos.core.logger.DefaultLogger.log(DefaultLogger.java:
385) at com.cmos.core.logger.DefaultLogger.log(DefaultLogger.java:398) at com.cmos.core.logger.DefaultLogger.doLog(DefaultLogger.java:350) at com.cmos.core.logger.DefaultLogger.info(DefaultLogger.java:200) at com.cmos.core.logger.DefaultLogger.info(DefaultLogger.java:195) "http-nio-172.17.20.113-28080-exec-6452" #381905 daemon prio=5 os_prio=0 tid=0x00007f49e857e000 nid=0x8427f waiting for
monitor entry [0x00007f49c1c75000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.log4j.Category.callAppenders(Category.java:204) - waiting to lock <0x00000000e5915bd8> (a org.apache.log4j.spi.RootLogger) at org.apache.log4j.Category.forcedLog(Category.java:391) at org.apache.log4j.Category.log(Category.java:856) at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.java:581) at com.cmos.core.logger.DefaultLogger.log(DefaultLogger.java:385) at com.cmos.core.logger.DefaultLogger.log(DefaultLogger.java:398) at com.cmos.core.logger.DefaultLogger.doLog(DefaultLogger.java:350) at com.cmos.core.logger.DefaultLogger.info(DefaultLogger.java:200) at com.cmos.core.logger.DefaultLogger.info(DefaultLogger.java:195)

三、log4j高併發執行緒block原因

  log4j-1.2.16 Category forcedLog邏輯如下

  

  

  log4j版本1.x中,使用的是synchronized(this)進行同步操作,所有執行緒共用一個Category,而它通過log4j.properties指定。 同一個Category下的執行緒打log時,需要進行全域性同步,因此它的效率會很低,log4j 1.x版不適合高併發的場景。

  為了杜絕這種現象的發生,最好升級到log4j2,或者更換為logback。

四、log4j2和logback選擇

  到底是升級到log4j2呢,還是將底層日誌框架更換為logback呢?

  檢查了一下專案直接使用log4j Logger的情況,發現部分工具類中使用了(這倒沒有問題,可以統一改一下),沒有想到是系統部封裝的框架中居然也直接使用了log4j 的Logger,心裡頓時說了一聲“草尼瑪啊...”。

       既然是這樣的話,肯定不能使用logback了,也不能直接升級成log4j2了。

五、log4j1 如何平滑升級到log4j2

  The Log4j 1.2 Bridge allows applications coded to use Log4j 1.2 API to use Log4j 2 instead.

  1.依賴如下

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-1.2-api</artifactId>
    <version>2.6.2</version>
</dependency>

  我們看一下 log4j-1.2-api-2.6.2 Category forcedLog邏輯如下,並沒有呼叫callAppenders方法。

  

  Log4j2 包含了基於 LMAX Disruptor(高效能執行緒間訊息通訊庫)的下一代 Asynchronous Loggers。在多執行緒環境下,Asynchronous Loggers 的吞吐量是 Log4j1 和 Logback 的 18 倍,而延遲時間也要低一個數量級。

  相信大家已經明白了,log4j-1.2-api-2.6.2橋接的原理就是複寫了log4j-1.2.16相關的類,再輸出日誌的時候呼叫的是log4j2中的方法。

  2.刪除掉 log4j的依賴

  3.將log4j.properties 替換成 log4j2.xml

  log4j.properties內容如下

log4j.rootLogger=INFO,ConsoleAppender,FileAppender

log4j.appender.ConsoleAppender=org.apache.log4j.ConsoleAppender
log4j.appender.ConsoleAppender.layout=org.apache.log4j.PatternLayout

log4j.appender.ConsoleAppender.layout.ConversionPattern=%d %p [%t] %C.%M(%L) | %m%n

log4j.appender.FileAppender=org.apache.log4j.DailyRollingFileAppender

log4j.appender.FileAppender.File=${user.dir}/logs/@logging.file-[email protected]

log4j.appender.FileAppender.DatePattern = '.'yyyy-MM-dd

log4j.appender.FileAppender.layout=org.apache.log4j.PatternLayout

#log4j.appender.FileAppender.layout.ConversionPattern=%-5p %d [%t] %l - %m%n
log4j.appender.FileAppender.layout.ConversionPattern=%d %p [%t] %C.%M(%L) | %m%n

log4j.logger.com.ibatis=debug
log4j.logger.com.ibatis.common.jdbc.SimpleDataSource=debug
log4j.logger.com.ibatis.common.jdbc.ScriptRunner=debug
log4j.logger.com.ibatis.sqlmap.engine.impl.SqlMapClientDelegate=debug
log4j.logger.java.sql.Connection=debug
log4j.logger.java.sql.Statement=debug
log4j.logger.java.sql.PreparedStatement=debug,ConsoleAppender

  對應的log4j2.xml內容如下

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <Properties>
        <Property name="LOG_HOME">${sys:user.dir}/logs</Property>
        <Property name="LOG_FILE">@[email protected]</Property>
    </Properties>
    
    <Appenders>
        <Console name="console_appender" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %p [%t] %C.%M(%L) | %m%n"/>
        </Console>
        <RollingFile  name="file_appender" immediateFlush="true" fileName="${LOG_HOME}/${LOG_FILE}"
                      filePattern="${LOG_HOME}/${LOG_FILE}.%d{yyyy-MM-dd}">
            <PatternLayout>
                <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %p [%t] %C.%M(%L) | %m%n</pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true" interval="1"/>
            </Policies>
            <DefaultRolloverStrategy max="30"/>
        </RollingFile >
    </Appenders>

    <Loggers>
        <logger name="com.ibatis.common.jdbc.SimpleDataSource" level="debug"/>
        <logger name="java.sql.Connection" level="debug"/>
        <logger name="com.ibatis" level="debug"/>
        <logger name="com.ibatis.common.jdbc.ScriptRunner" level="debug"/>
        <logger name="com.ibatis.sqlmap.engine.impl.SqlMapClientDelegate" level="debug"/>
        <logger name="java.sql.Statement" level="debug"/>
        <logger name="java.sql.PreparedStatement" level="debug">
            <appender-ref ref="console_appender"/>
        </logger>
        <Root level="INFO">
            <appender-ref ref="console_appender"/>
            <appender-ref ref="file_appender"/>
        </Root>
    </Loggers>

</configuration>

  如果在springboot專案中配置了 logging.config 屬性,請修改 logging.config=classpath:log4j.properties 為 logging.config=classpath:log4j2.xml

六、springboot 對log4j2的支援

  springboot 日誌系統結構如下。

  

  LoggingSystem是個抽象類,功能如下。

  1. beforeInitialize方法:日誌系統初始化之前需要處理的事情。抽象方法,不同的日誌架構進行不同的處理
  2. initialize方法:初始化日誌系統。預設不進行任何處理,需子類進行初始化工作
  3. cleanUp方法:日誌系統的清除工作。預設不進行任何處理,需子類進行清除工作
  4. getShutdownHandler方法:返回一個Runnable用於當jvm退出的時候處理日誌系統關閉後需要進行的操作,預設返回null,也就是什麼都不做
  5. setLogLevel方法:抽象方法,用於設定對應logger的級別

  可支援的日誌系統配置如下。

  

  AbstractLoggingSystem繼承了LoggingSystem,複寫了initialize方法,如下。
@Override
public void initialize(LoggingInitializationContext initializationContext,
        String configLocation, LogFile logFile) {
    if (StringUtils.hasLength(configLocation)) {
        initializeWithSpecificConfig(initializationContext, configLocation, logFile);
        return;
    }
    initializeWithConventions(initializationContext, logFile);
}

  initializeWithSpecificConfig方法時在你指定日誌配置檔案時(也就是指定了  logging.config 屬性)呼叫。initializeWithConventions方法則是使用預設的配置。

  我們簡單的看一下Log4J2LoggingSystem初始化過程。

  1.預設查詢的配置檔名稱

  

   2.log4j2具體的初始化配置過程

  

  可以發現,log4j2通過LogManager管理著多個LoggerContext,每個LoggerContext管理著不同的logger。

  3.動態設定logger的level

  

  4.沒找到日誌配置檔案的話使用loadDefaults方法載入

  

  5.springboot具體是採用哪一個LoggingSystem是在LoggingApplicationListener中決定的,LoggingApplicationListener是一個ApplicationListener,springboot工程在啟動的時候會被載入。

以下摘自網路
LoggingApplicationListener所做的事情...

1. 讀取配置檔案中"logging."開頭的配置,比如logging.pattern.level, logging.pattern.console等設定到系統屬性中 2. 構造一個LogFile(LogFile是對日誌對外輸出檔案的封裝),使用LogFile的靜態方法get構造,會使用配置檔案中logging.file和logging.path配置構造 3. 判斷配置中是否配置了debug併為true,如果是,設定level的DEBUG,然後繼續檢視是否配置了trace併為true,如果是,設定level的TRACE 4. 構造LoggingInitializationContext,檢視是否配置了logging.config,如有配置,呼叫LoggingSystem的initialize方法並帶上該引數,否則呼叫initialize方法並且configLocation為null 5. 設定一些比如org.springframework.boot、org.springframework、org.apache.tomcat、org.apache.catalina、org.eclipse.jetty、org.hibernate.tool.hbm2ddl、org.hibernate.SQL這些包的log el,跟第3步的level一樣
6. 檢視是否配置了logging.register-shutdown-hook,如配置並設定為true,使用addShutdownHook的addShutdownHook方法加入LoggingSystem的getShutdownHandler

七、spring預設日誌系統

  順便說一下,Spring的日誌預設採用commons-logging。以下摘自網上!

  log4j如何切換到logback?

  
1.將logback-classic和logback-core的jar包引入到工程,將有關log4j的jar包從工程的classpath中移除。

2.確認工程引入了slf4j的jar包,作為日誌的適配。

3.在工程中新建logback.xml檔案,將原來log4j配置檔案(log4j.properties),轉換為logback的對應配置,然後將log4j.properties刪除。

4.將工程中,由於缺失了log4j.jar引起的錯誤進行修正,改為利用logback實現。


可能遇到的問題及解決方案:

1.Log4j轉換到logback後,執行後spring的日誌都以紅字輸出到控制檯,而不受logback控制。

因為Spring的日誌預設採用commons-logging,解決方法是在工程中引入jcl-over-slf4j-1.6.1.jar,這樣就將commons-logging與slf4j對接,再通過logback進行了日誌的統一輸出。

2.切換完成後,啟動工程時會出現java.lang.IllegalAccessError: tried to access field org.slf4j.impl.StaticLoggerBinder.SINGLETON from class org.slf4j.LoggerFactory這個錯誤。

原因是slf4j-api的jar包版本太低,改為slf4j-api-1.6.4.jar即可解決。