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

起因

我做了一个模块，会统计某个用户的接口调用次数，调用次数是会累加并持久化到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>
        <!-- 使用 slf4j 的 MDC 机制, 实现 contextId 的记录 -->
        <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，如下

<DefaultRolloverStrategy max="7"/>

当不配置这个属性时，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>
        <!-- 使用 slf4j 的 MDC 机制, 实现 contextId 的记录 -->
        <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
• http://tonfay.cn/articles/2019/10/15/1571120117603.html