Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-2575

CronExpression.getTimeBefore() returns incorrect result

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 2.11.2
    • Fix Version/s: 2.12.1
    • Component/s: Core
    • Labels:
      None
    • Flags:
      Patch

      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

        1. cronexpression.patch
          1 kB
          Nathan Friess
        2. cronexpressiontest.patch
          2 kB
          Nathan Friess

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              nathan.friess Nathan Friess
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: