[LOG4J2-3168] RollingFileAppender: Overwritting rotated log file when using zip

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 2.13.3
• Fix Version/s: 2.15.0
• Component/s: Appenders

Environment

Windows 10 + java 1.8.0_201

• Assignee: Unassigned
• Reporter: Markus Ke
• Created: 27/Sep/21 07:46
• Updated: 25/Nov/21 08:19
• Resolved: 21/Nov/21 00:11

Description

We use log4j2 for logging and have observed the phenomenon that when using zipping, existing logs are overwritten when rotating logs.

The used LogConfig:

<Configuration  name="base">
    <Appenders>
        <Console name="console">
            <JSONLayout compact="true" eventEol="true" locationInfo="true"/>
        </Console>
        <RollingFile name="file" append="true">
            <fileName>./file.log</fileName>
            <filePattern>./file.%d{yyyyMMdd'T'HHmmssZ}.%i.log.zip</filePattern>
            <PatternLayout pattern="%d{HH:mm:ss,SSS} [%15.15t] %-5p %30.30c@%-4L %x - %m%n" />
            <Policies>
                <OnStartupTriggeringPolicy/>
                <SizeBasedTriggeringPolicy size="15 MB" />
            </Policies>
            <DefaultRolloverStrategy>
                <Delete basePath="./">
                    <IfFileName glob="file.*.log.zip">
                        <IfLastModified age="7d"/>
                    </IfFileName>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
        <!-- Just for testing to verify if the log files get lost by zipping them-->
        <RollingFile name="file-unzipped-bug-verification" append="true">
            <fileName>./file-fallback.log</fileName>
            <filePattern>./file-fallback.%d{yyyyMMdd'T'HHmmssZ}.%i.log</filePattern>
            <PatternLayout pattern="%d{HH:mm:ss,SSS} [%15.15t] %-5p %30.30c@%-4L %x - %m%n" />
            <Policies>
                <OnStartupTriggeringPolicy/>
                <SizeBasedTriggeringPolicy size="15 MB" />
            </Policies>
            <DefaultRolloverStrategy>
                <Delete basePath="./">
                    <IfFileName glob="./file-fallback.*.log">
                        <IfLastModified age="7d"/>
                    </IfFileName>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>        
    </Appenders>

    <Loggers>
        <Logger name="org.example.project" level="debug"/>
        <Root level="info">
            <AppenderRef ref="console" />
            <AppenderRef ref="file" />
            <AppenderRef ref="file-unzipped-bug-verification" />			
        </Root>
    </Loggers>
</Configuration>

It turns out that at any point in time, the rotation behavior changes and the last time stamp of the log is no longer used as the file name, but the first.

This results in the following circumstance:

• file.20210914T144224+0200.1.log
  • first line:

    13:50:21,789 [lt-executor-194] DEBUG StreamHandler@68 [] - RPC stream completed

• • last line:

    14:42:24,974 [D_2400_supply-1] DEBUG ActionDispatcher@291 [] - Waiting at action ...

• file.20210914T155051+0200.1.log
  • first line:

    15:50:51,988 [ mc-exe-10] DEBUG ResourceSchedule@215 [] - discarding MutexReservation

• • last line:

    16:03:27,839 [ool-58-thread-1] DEBUG Repository@111 [] - Repository@1d41309 changed, publishing updates

Another file between these times does not exist.

We verified this by adding a second appender without zipping, which contained all logs. The files `./file-fallback.XXXXXXXXX.log` contain all logs