[LOG4J2-531] Rolled log files overwritten by RollingFile appender with composite time and size based policies

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.0-beta9
• Fix Version/s: 2.0-rc1
• Component/s: Appenders

Environment

Ubuntu 12.04 and 13.04, java version "1.7.0_51"

• Assignee: Remko Popma
• Reporter: Geoff Ballinger
• Created: 07/Feb/14 14:27
• Updated: 17/Feb/20 18:00
• Resolved: 09/Feb/14 15:48

Description

We have a system which generates high volume logs which are required to be preserved for audit purposes, and have been having problems with files being unexpectedly overwritten.

We are using a RollingFile appender with day granularity, time based and size based triggering policies, and a rollover strategy with a suitably large max value.

I have created a simple test case with minute granularity to quickly illustrate the problem, which is v. similar to the example given in the documentation:

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class LogTest
{
    private static final Logger logger = LogManager.getLogger("TestLogger");

    public static void main(String[] args) throws Exception
    {
        for (long i=0; ; i+=1) {
            logger.debug("Sequence: " + i);
            Thread.sleep(250);
        }
    }
}

... with a config of:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Appenders>
        <RollingFile name="Test" fileName="logs/test.log" filePattern="logs/test/$${date:yyyyMMddHHmm}/TEST-%d{yyyyMMddHHmm}-%i.log.gz">
            <PatternLayout pattern="%d %p (%t) [%c] - %m%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="1 KB"/>
            </Policies>
            <DefaultRolloverStrategy max="999999"/>
        </RollingFile>
    </Appenders>
    <Loggers>
        <Root level="debug">
            <AppenderRef ref="Test"/>
        </Root>
    </Loggers>
</Configuration>

If this is run as is many of the rollover logfiles have other files written over them and are lost, as can clearly be seen by the gaps in the remaining sequence numbers, and the order the sequence numbers appear in the resulting files.

If the time based policy is removed from the config and it is re-run then all sequence numbers are correctly stored and in the expected order., Without the time based trigger some are carried over into the folder for the next period which is not ideal, though is what we are using at present to avoid data loss.

Issue Links

• is related to: LOG4J2-2784 Rolling stuck at counter 10 by RollingFile appender when counter is zero padded
• relates to: LOG4J2-412 RollingRandomAccessFile appender loses output when fileName/filePattern accesses ${sys:property}
• relates to: LOG4J2-535 Rolled log files end up in the wrong directory