記一次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屬性，即可在建立日誌時寫入日誌檔案頭。從而很好的規避日誌記錄到錯誤的檔案中的問題。