Description
The CronTriggeringPolicy with a date pattern as file pattern may overwrite previous log files during rolling. This happens randomly. An example appender definition:
<RollingRandomAccessFile name="mylogfile"
fileName="mylogfile.log"
filePattern="mylogfile.%d{yyyy-MM-dd_HHmmss}.log.zip">
<PatternLayout pattern="%d{ISO8601} %m%n" />
<Policies>
<CronTriggeringPolicy schedule="0 0 0 * * ?"/><!-- triggers at midnight -->
</Policies>
</RollingRandomAccessFile>
In the debug logging we can see that the "prev file time" is set the 17:11 twice.
2019-12-17T17:11:00,001 Log4j2-TF-3-Scheduled-8 DEBUG Setting prev file time to 2019-12-17T17:11:00,000+0100 2019-12-17T17:12:00,000 Log4j2-TF-3-Scheduled-2 DEBUG Setting prev file time to 2019-12-17T17:11:00,000+0100
This bug is reproducible in 2.11.2, but not in 2.11.1. I believe it was introduced with LOG4J2-2542 (https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;a=commitdiff;h=42fe68e;hp=dfced487bdb422c56334922411e10447bdb64969).
When we look at CronTriggeringPolicy.rollover(), then we see that in <=2.11.1 the prevFileTime set on the PatternProcessor was based on the lastRollDate. With 2.11.2 it is based on CronExpression.getPrevFireTime(new Date()). The problem is that CronExpression.getPrevFireTime() returns the wrong date if the method is called with a date created a millisecond after the actual fire time. I attached a simple test that demonstrates this (see CronExpressionTest.java
). In other words if new Date() is called in the same millisecond as the schedule was scheduled to run, then you get the correct previous fire time. But if new Date() is called a millisecond too late, then you get the wrong previous fire time.
My current workaround is to add %i to the file pattern, e.g. mylogfile.%d{yyyy-MM-dd_HHmmss}_%i.log.zip. That way no files are overwritten and I do not lose log files.
I am not sure how to fix this without breaking the fix for LOG4J2-2542. At first glance I see the following starting point for further investigation:
lastRollDate is private to CronTriggeringPolicy, but only the RollingFileManager really knows when the file was last rolled. CronTriggeringPolicy can never know that the log was already rolled by another policy. And it will never know when the log is being rolled concurrently in another thread. Therefore the lastRollDate cannot be correctly determined in CronTriggeringPolicy and has to be part of the RollingFileManager.
FYI, rgoers
Attachments
Attachments
Issue Links
- duplicates
-
LOG4J2-2575 CronExpression.getTimeBefore() returns incorrect result
-
- Closed
-
- links to
