[LOG4J2-535] Rolled log files end up in the wrong directory

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

Environment

Ubuntu 12.04 and 13.04, java version "1.7.0_51"

• Assignee: Ralph Goers
• Reporter: Remko Popma
• Created: 11/Feb/14 10:47
• Updated: 07/Jun/14 22:45
• Resolved: 07/Jun/14 22:45

Description

Follow-up for issue LOG4J2-531: the main issue (rolled over archives were overwritten) was resolved but the solution brought to light another issue that is tracked here:

The distribution of the log files into the folders is odd and it feels like there might be a flaw in the timestamp logic in there somewhere still.

Test program to reproduce the issue:

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);
        }
    }
}

Sample configuration for LOG4J2-531:

<?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>

I kicked off the test run at 14:29:11 using my example setup from the first post above more or less as is - but with a more sensible max=99.

The initial folder created was 201402101429 and contained 27 numbered files prefixed TEST-201402101429-. Numbers 1-12 contained 16 log lines each with timestamps 14:29:11,667 to 14:29:59,649, number 13 a single log line with timestamp 14:29:59,899, and numbers 14-27 again contain 16 lines each with timestamps 14:30:00,164 to 14:30:56,155.

The second folder created was 201402101430 and contained 15 numbered files. The first file contained 15 log lines with timestamps 14:30:56,405 to 14:30:59,919. The subsequent files contained 16 log lines each with timestamps 14:31:00,170 to 14:31:56,123.

The third folder created was 201402101431. The first file contained 15 log lines with timestamps 14:31:56,373 to 14:31:59,886. The subsequent files contained 16 log lines each with timestamps from 14:32:00,136 onwards.

So in summary after the first minute the majority of log lines from minute X end up in the folder for minute X-1. The exception are the last file of lines which end up in the correct folder.

---

This happens with longer rollover periods as well:

---

Sample configuration based on that for LOG4J2-531, adjusted to roll every hour and every 64kb (i.e. expect similar number of files per folder):

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

Running this overnight gave a similar pattern, e.g. the folder for 2014021100 contains one file with timestamps 00:59:42,836 to 00:59:59,851, and then 15 others covering timestamps 01:00:00,101 to 01:59:24,196. Only the last file's worth for each hour (the one rotated based on time) is in the correct folder, and the rest (rotated based on size) are in the previous hour's folder.

Issue Links

• is related to: LOG4J2-531 Rolled log files overwritten by RollingFile appender with composite time and size based policies