日志文件内容部分丢失的问题

以你之姓@ 2022-08-31 15:28 141阅读 0赞

### 起因 ###

我做了一个模块，会统计某个用户的接口调用次数，调用次数是会累加并持久化到mysql，并且每次接口调用的具体结果，都会记录在日志中。

前几天我根据日志进行接口调用次数统计，发现和mysql中记录的次数不一致，并且相差很大。于是便开始进行了排查。

### 排查 ###

首先为了确认是否是我的统计逻辑出了问题。我动态地观察了日志输出和mysql调用次数数据的变化情况。每次观察10s，发现10s内日志中新增的关键字数量，和mysql调用次数的增加数量是一致的。多次观察，均未发现问题。则说明统计数据的逻辑是正确的。

后来，我想起之前偶发的一个问题：测试同学在发起了请求之后，我在应用日志中没有找到对应的日志。于是我观察了多个日期的日志文件，发现都是从18点之后才开始有日志。按理说应该记录了0点到24点的全部日志信息才对。并且全部的日志文件都是从18点开始才有日志。于是我怀疑，日志中的部分内容丢失了。那么为什么会丢失呢。

在我检查日志的配置文件时，注意到`RollingRandomAccessFile`设置的滚动更新的触发时间是每6小时触发一次。于是联系到前面观察的，日志都是从18点后才开始有，18点到24点就是一天中的最后那6个小时。于是，问题清晰了一点。貌似是前面时间产生的日志都被丢失了。

我原先的`log4j2.xml`配置文件如下

<?xml version="1.0" encoding="UTF-8"?>
    <Configuration status="DEBUG">
        <Properties>
            <Property name="rewrite">true</Property>
            <Property name="file.root.path">logs</Property>
            <property name="filePattern">${date:yyyy-MM-dd}</property>
            
            <Property name="pattern-layout">%d{yyyy-MM-dd HH:mm:ss.SSS} %p %t %c [%X{cid}] - %m%n</Property>
        </Properties>
        <Appenders>
            <Console name="Console" target="SYSTEM_OUT" follow="true">
                <PatternLayout pattern="${pattern-layout}" />
            </Console>
            <RollingRandomAccessFile name="Console-File" fileName="${file.root.path}/console.log" filePattern="${file.root.path}/console-%d{yyyy-MM-dd}.log">
                <PatternLayout pattern="${pattern-layout}"/>
                <CronTriggeringPolicy schedule="0 0 0/6 * * ?" evaluateOnStartup="true"/>
            </RollingRandomAccessFile>
        </Appenders>
    
        <Loggers>
            <Root level="info">
                <AppenderRef ref="Console"/>
                <AppenderRef ref="Console-File"/>
            </Root>
        </Loggers>
    </Configuration>

我查了谷歌百度，看了log4j2的官方文档。最后定位到的问题是。在`RollingRandomAccessFile`的 `filePatten`中，我设置的是 `${file.root.path}/console-%d{yyyy-MM-dd}.log`，而根据日志的`rollOver`配置(那个cron表达式)，每6个小时，log4j2都会将当前的`console.log`文件按照上面的`pattern`进行重命名，并把新产生的日志写入到新的`console.log`。

于是，真相大白了。由于文件名的重复，导致前6个小时的日志文件被后6个小时的重名文件给覆盖掉了。

正确的 `filePattern` 应该加上一个计数器`%i`

`${file.root.path}/console-%d{yyyy-MM-dd}-%i.log`

这样才能保证每次滚动更新时的文件名不重复

另外，当使用 `%i` 时，还有一个属性 `max`，如下

当不配置这个属性时，log4j2默认的配置是7，即同一天内最多滚动产生7个日志文件（计数器从1到7），若超过了7个日志文件，则会删除最旧的文件，此时也会导致部分的日志文件丢失，需要注意  
最后修改后正确的`log4j2.xml`如下

<?xml version="1.0" encoding="UTF-8"?>
    <Configuration status="DEBUG">
        <Properties>
            <Property name="rewrite">true</Property>
            <Property name="file.root.path">logs</Property>
            <property name="filePattern">${date:yyyy-MM-dd}</property>
            
            <Property name="pattern-layout">%d{yyyy-MM-dd HH:mm:ss.SSS} %p %t %c [%X{cid}] - %m%n</Property>
        </Properties>
        <Appenders>
            <Console name="Console" target="SYSTEM_OUT" follow="true">
                <PatternLayout pattern="${pattern-layout}" />
            </Console>
            <RollingRandomAccessFile name="Console-File" fileName="${file.root.path}/console.log" filePattern="${file.root.path}/console-%d{yyyy-MM-dd}-%i.log">
                <PatternLayout pattern="${pattern-layout}"/>
                <Policy>
                    <CronTriggeringPolicy schedule="0 0 0 * * ?" evaluateOnStartup="true"/> 
                    <SizeBasedTriggeringPolicy size="250 MB"/>
                </Policy>
            </RollingRandomAccessFile>
        </Appenders>
    
        <Loggers>
            <Root level="info">
                <AppenderRef ref="Console"/>
                <AppenderRef ref="Console-File"/>
            </Root>
        </Loggers>
    </Configuration>

参考链接：

*  `log4j2`官方文档：[https://logging.apache.org/log4j/2.x/manual/appenders.html\#DefaultRolloverStrategy][https_logging.apache.org_log4j_2.x_manual_appenders.html_DefaultRolloverStrategy]
 *  [http://tonfay.cn/articles/2019/10/15/1571120117603.html][http_tonfay.cn_articles_2019_10_15_1571120117603.html]

[https_logging.apache.org_log4j_2.x_manual_appenders.html_DefaultRolloverStrategy]: https://logging.apache.org/log4j/2.x/manual/appenders.html#DefaultRolloverStrategy
[http_tonfay.cn_articles_2019_10_15_1571120117603.html]: http://tonfay.cn/articles/2019/10/15/1571120117603.html