Details
Major Description
I have a log4j config that uses RollingFileAppender with TimeBasedTriggeringPolicy to create one logfile per minute (well in reality it’s actually one logfile per day, but testing/reproducing the described behaviour is easier when you don’t have to wait an entire day for the logfile rolling to occur, and the bug described here applies to both rolling per day and rolling per minute).
I would expect that each logfile contains only log entries written within the same minute that’s suggested by its filename, for example:
- Logfile app.2018-03-21_10-00.log contains log messages starting with timestamp 2018-03-21 10:00
- Logfile app.2018-03-21_10-01.log contains log messages starting with timestamp 2018-03-21 10:01
- Logfile app.2018-03-21_10-02.log contains log messages starting with timestamp 2018-03-21 10:02
- …
However that’s not the case: When I start the application, the first logfile created contains log messages from both the minute suggested by its filename and the next minute, and all subsequent logfiles contain messages that are off by 1 minute compared to the logfile name. For example, let’s say I start the app on 2018-03-21 10:00:01 Then the logfiles contain the following messages:
- Logfile app.2018-03-21_10-00.log contains log messages starting with timestamp 2018-03-21 10:00 and 2018-03-21 10:01
- Logfile app.2018-03-21_10-01.log contains log messages starting with timestamp 2018-03-21 10:02
- Logfile app.2018-03-21_10-02.log contains log messages starting with timestamp 2018-03-21 10:03
- …
I’m using the following log4j configuration
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn">
<Appenders>
<RollingFile name="app_log" filePattern="logs/app.%d{yyyy-MM-dd_HH-mm}.log">
<PatternLayout>
<Pattern>%d{DEFAULT} - %m%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy modulate="true"/>
</Policies>
</RollingFile>
</Appenders>
<Loggers>
<Root level="info">
<AppenderRef ref="app_log" level="info"/>
</Root>
</Loggers>
</Configuration>