记一次log4j日志写到错误文件的问题

背景

项目采用log4j2记录日志，其中WARN级别日志单独记录，日志文件采用RollingFileAppender，每天一个日志文件。

问题现象

在10月20号的日志文件中，发现了一条10月22日生成的日志文件，导致排查问题时漏看了一条日志。

代码分析

通过查看log4j相关资料，发现RollingFileAppender在记录日志前，会进行一次是否切换文件的判断。

    @Override
    public void append(final LogEvent event) {
        getManager().checkRollover(event);
        super.append(event);
    }

    public synchronized void checkRollover(final LogEvent event) {
        if (triggeringPolicy.isTriggeringEvent(event)) {
            rollover();
        }
    }

checkRollover会进行是否切换文件判断，并进行文件切换，triggeringPolicy使用策略模式实现。在RollingFileAppender里，使用的是TimeBasedTriggeringPolicy，该实现按配置的时间表达式进行日志切换和回滚。
isTriggeringEvent方法中代码如下

    @Override
    public boolean isTriggeringEvent(final LogEvent event) {
        // 该方法对文件大小进行了判断，如果之前文件没有内容，则不会切换文件。
        if (manager.getFileSize() == 0) {
            return false;
        }
        final long nowMillis = event.getTimeMillis();
        if (nowMillis >= nextRolloverMillis) {
            nextRolloverMillis = ThreadLocalRandom.current().nextLong(0, 1 + maxRandomDelayMillis)
                    + manager.getPatternProcessor().getNextTime(nowMillis, interval, modulate);
            return true;
        }
        return false;
    }

if (manager.getFileSize() == 0) 该判断会进行空文件判断，如果文件是空，则不会切换文件，也即是该bug产生的原因。

问题原因分析

bug产生的过程如下
1. 系统在20号启动，启动后log4j会自动创建一个空文件，如WARN.log
2. 20号和21号均没有WARN日志产生。
3. 22号产生一个WARN日志，日志记录前，先进行是否更换文件判断，由于文件内容为空，所以判断不需要切换文件，日志记录在WARN.log文件中。
4. 第二条WARN日志产生时，文件中有内容，于是进行nextRolloverMillis的判断，但文件是20号生产，并且文件按天切换，所以判断时nowMillis >= nextRolloverMillis 满足条件，triggeringPolicy.isTriggeringEvent
方法返回true，进行rollover()操作，切换文件。
5. 切换文件时，会根据上一次切换时间生成文件名，于是会将WARN.log变化为WARN.log-2017-10-20。并且该文件中有一条22号生成的日志。

问题解决方式

从问题原因中可以发现，在不修改log4j源码的情况下，只需要保证日志文件不为空，即可规避该问题。在rollover的代码中发现以下代码片段

public synchronized void rollover() {
        if (!hasOutputStream()) {
            return;
        }
        if (rollover(rolloverStrategy)) {
            try {
                size = 0;
                initialTime = System.currentTimeMillis();
                createFileAfterRollover();
            } catch (final IOException e) {
                logError("Failed to create file after rollover", e);
            }
        }
    }
    protected void createFileAfterRollover() throws IOException  {
        setOutputStream(createOutputStream());
    }protected void setOutputStream(final OutputStream os) {
        final byte[] header = layout.getHeader();
        if (header != null) {
            try {
                os.write(header, 0, header.length);
                this.outputStream = os; // only update field if os.write() succeeded
            } catch (final IOException ioe) {
                logError("Unable to write header", ioe);
            }
        } else {
            this.outputStream = os;
        }
    }

文件切换完毕，创建新的文件流时会执行os.write(header, 0, header.length)方法，即会先写入文件头，通过查看layout.getHeader,发现只需在log4j的PatternLayout节点中，配置header属性，即可在创建日志时写入日志文件头。从而很好的规避日志记录到错误的文件中的问题。