[LOG4J2-1906] DirectWriteRolloverStrategy not properly creating files

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.8.2
• Fix Version/s: 3.0.0, 2.11.2
• Assignee: Ralph Goers
• Reporter: João Santos
• Created: 10/May/17 14:50
• Updated: 04/Mar/19 16:14
• Resolved: 03/Feb/19 06:29

Description

The DirectWriteRolloverStrategy is not properly determining the filename of the new log file after the rollover happens.

With the following configuration:

        <RollingFile name="ApplicationLog" filePattern="application.log.%d{yyyy-MM-dd-HH-mm}">
            <PatternLayout>
                <Pattern>%m%n</Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy />
            </Policies>
            <DirectWriteRolloverStrategy />
        </RollingFile>

What is happening is, for instance:

• application starts at 09h35m30s
• at instant 09h35m55s a new log is written the rollover is set to happen at 09h36m00s, log line is written to application.log.2017-05-10-09-35 - OK
• at instant 09h36m05s a new log is written and the rollover is triggered, after the rollover logs are written to application.log.2017-05-10-09-35 - Not OK
• at instant 09h37m05s a new log is written and the rollover is triggered, after the rollover logs are written to application.log.2017-05-10-09-36 - Not OK

This seems to be happening because DirectWriteRolloverStrategy.getCurrentFileName (when being called from createFileAfterRollover) is calling the PatternProcessor.formatFileName and telling it to use the currentTime. However, currentFileTime is zero, and it will fallback to the prevFileTime to determine the filename, which is wrong as it will be one minute before current time.

It should probably either use the nextFileTime (while debugging I could see that it was set to the correct time, the minute I expect the file to rollover), or use the System time.