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-web@

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">@logging.file-web@</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即可解决。