log4j笔记：升级2.X版本的日志滚动问题

Posted 2020-08-02 落叶维扬

因为slf4j依赖的log4j在流量大的时候总遇到多线程引起的死锁问题，升级到log4j2.x版本。原来的log4j.properties配置文件已经不被log4j2支持了，需要改写为log4j2.xml。在升级的过程中，配置与原先相同，使用异步日志，按小时滚动，却发现配置后日志输出正常，但滚动的功能不正常，查出以下两个问题。

 

1. 日志不按小时滚动

原来的配置如下：

 <RollingRandomAccessFile name="RollingFile" fileName="${backupFilePatch}${fileName}" filePattern="${backupFilePatch}${fileName}.%d{yyyy-MM-dd}.%i" immediateFlush="false">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} %p %c{1}[%L]-%m%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>            
            </Policies>
            <DefaultRolloverStrategy max="120"/>
 </RollingRandomAccessFile>

根据官网的介绍，我理解成了interval=1的时候固定按小时滚动，其实interval的单位是根据filePattern来的，即filePattern配置中的最小单位，所以在yyyy-MM-dd这样的配置中，interval的单位是day，而%i则是interval的序号，日志是按天滚动的。所以将配置改为${backupFilePatch}${fileName}.%d{yyyy-MM-dd.HH}就能按小时滚动了。

 

2. 每小时滚动后，日志不写入新文件，而是写入旧的归档文件。

这个问题更诡异。tomcat启动后，日志是写入log文件的，但是整点日志滚动之后，log归档为log-日期，产生一个新的log文件，但日志还是打入了归档之后的文件log-日期。放置了一天之后，发现更诡异的事情，日志总是写入上一个归档文件。例如，7点的时候，产生一个归档文件log-日期.6，7点到8点的日志都打入了文件6，log文件始终是空的，而8点之后，log归档为log-日期-7，之后的日志都打入文件7，新产生的log文件还是为空。

该问题遍寻不着解法。在某一次整点时，正好刷新了一下，发现log文件有新内容，再刷新又成为上面那种现象了。由此联想到，有可能不只是log4j2在对这个文件进行操作。

 

排查发现，改写log4j2.xml之后，原来的log4j.properties还留在项目里。由于maven层层叠叠的依赖，有几个包引用的是log4j1.x版本，在运行的时候，始终有一个包用的是log4j1.x在打日志，因此加载的是log4j.properties的配置。log4j.properties和log4j2.xml的配置完全相同，写入的也是同一个日志文件。整点的时候，这两个类都对log文件进行归档操作，猜想是log4j2先执行归档，写入新log文件，而这个文件又被log4j1归档，因此后面log4j2的日志都写入了上一个归档文件。

 

将log4j.properties中的日志改为其他名称，问题解决。