[jira] [Closed] (LOG4J2-2575) CronExpression.getTimeBefore() returns incorrect result

["Nathan Friess (JIRA)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/LOG4J2-2575?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Nathan Friess closed LOG4J2-2575.
---------------------------------

Closing.

> CronExpression.getTimeBefore() returns incorrect result
> -------------------------------------------------------
>
>                 Key: LOG4J2-2575
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-2575
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Core
>    Affects Versions: 2.11.2
>            Reporter: Nathan Friess
>            Priority: Critical
>             Fix For: 2.12.1
>
>         Attachments: cronexpression.patch, cronexpressiontest.patch
>
>
> 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:
> {code:java}
>   ... while (prevFireTime.compareTo(targetDate) >= 0);{code}
> to be false on the first time through the loop and so targetDate (with zero milliseconds) is returned.
>  
> Configuration example:
> {code:java}
> <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>{code}
>  
> Adding some extra debugging, we can see the behaviour:
>  
> {noformat}
> 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{noformat}
> 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.
>  
>  
>  



--
This message was sent by Atlassian JIRA
(v7.6.14#76016)