Description
The method getTimeBefore(targetDate) of org.apache.logging.log4j.core.util.CronExpression incorrectly returns the targetDate argument instead of one time increment before targetDate when running in OpenJDK 1.8.0_191.
When CronTiggeringPolicy calls this method the targetDate object contains a time with milliseconds, but prevFireTime is always computed with zero milliseconds which causes the comparison at line 1586:
... while (prevFireTime.compareTo(targetDate) >= 0);
to be false on the first time through the loop and so targetDate (with zero milliseconds) is returned.
Configuration example:
<RollingFile name="my_log" fileName="/var/log/my.log" filePattern="/var/log/my.log.%d{yyyy-MM-dd}"> <PatternLayout pattern="[%d{EEE MMM dd HH:mm:ss yyyy}] [%p] %x [%X{user}] %m{nolookups}%n" /> <CronTriggeringPolicy schedule="0 0 0 * * ?" evaluateOnStartup="true" /> </RollingFile>
Adding some extra debugging, we can see the behaviour:
DEBUG StatusLogger getTimeBefore(targetDate=2019-03-22T00:00:00.002-0600 DEBUG StatusLogger in loop preFireTime=2019-03-22T00:00:00.000-0600 DEBUG StatusLogger return 2019-03-22T00:00:00.000-0600
Sometimes the file rolling will run at exactly zero milliseconds and getTimeBefore() will correctly returns the previous day in the above example, masking this issue during those runs. I marked this issue as critical because in combination with FileRenameAction's procedure of replacing existing files, log files will be lost at seemingly random rolls when this method returns the current date on one run, but then reverts back to the previous date on the next run, causing a filename collision.
A patch is attached. This issue may be related to LOG4J2-2246 since that bug mentions issues with milliseconds in Date objects as well, but I have not investigated that part of the file rolling code.
Attachments
Attachments
Issue Links
- is duplicated by
-
LOG4J2-2741 Log files are (sometimes) overwritten during rolling when using CronTriggeringPolicy
-
- Resolved
-