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

CronExpression.getTimeBefore() calculates incorrect result

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Open
    • Critical
    • Resolution: Unresolved
    • 2.17.1
    • None
    • Core
    • None

    Description

      The method getTimeBefore(targetDate) of org.apache.logging.log4j.core.util.CronExpression incorrectly returns the prevFireTime value sometimes or is called with bad inputs.

      When CronTiggeringPolicy calls this method the targetDate object contains a current time.
      For example, if we have a situation where we want to perform a midnight rollup, the method works differently if the entry time is ... 00:00:00 or ... 00:00:01. This can happen if we have many different logs, all of which we want to roll at the same time (typically midnight). But all "getTimeBefore" won't make it within 1 second. If the targetDate differs at least one second it causes the different comparison result at line:

        ... while (prevFireTime.compareTo(targetDateNoMs) >= 0);

       

      Configuration example:

      ...
      <Properties>
        <Property name="filePath">logs/l4j2_</Property>
        <Property name="fileBackupPath">logs/bck/l4j2_</Property>
        <Property name="fileSuffix">log.bz2</Property>
        <Property name="fileDatePattern">yyyyMMdd</Property>
        <Property name="basicPatternLayout">%d %-5p [%t] - %m%n</Property>
        <Property name="hostname">HOSTNAME</Property>
        <Property name="environment">ENVIRONMENT</Property>
      </Properties>
      ...
      <RollingFile name="UNICommonJavaScriptAppender" fileName="${filePath}uni-javascript.log" filePattern="${fileBackupPath}uni-javascript-%d{${fileDatePattern}}_%i.${fileSuffix}">
        <PatternLayout pattern="${basicPatternLayout}" />
        <Policies>
          <OnStartupTriggeringPolicy />
          <CronTriggeringPolicy schedule="0,5 0 0 * * ?"/>                
          <SizeBasedTriggeringPolicy size="30MB" />                
        </Policies>
        <DefaultRolloverStrategy max="50">
          <Delete basePath="logs/bck" maxDepth="1">
              <IfFileName glob="l4j2_uni-javascript*.${fileSuffix}">
              <IfAny>
                <IfAccumulatedFileSize exceeds="200 MB" />
                <IfAccumulatedFileCount exceeds="25" />
              </IfAny>
            </IfFileName>
          </Delete>
        </DefaultRolloverStrategy>
      </RollingFile>

       

      Adding some extra debugging, we can see the behaviour:
      1. targetDate in first second (1/20/22 0:00:00):

      [1/20/22 0:00:00:018 CET] 00000186 SystemOut     O 2022-01-20 00:00:00,018 Log4j2-TF-3-Scheduled-2 DEBUG PV: CronExpression | getTimeBefore - entering 2022-01-20T00:00:00.018+0100
      [1/20/22 0:00:00:469 CET] 00000186 SystemOut     O 2022-01-20 00:00:00,469 Log4j2-TF-3-Scheduled-2 DEBUG PV: CronExpression | getTimeBefore - result 2022-01-19T00:00:05.000+0100
      [1/20/22 0:00:00:469 CET] 00000186 SystemOut     O 2022-01-20 00:00:00,469 Log4j2-TF-3-Scheduled-2 DEBUG PV: RollingFileManager | rollover entered
      [1/20/22 0:00:00:469 CET] 00000186 SystemOut     O 2022-01-20 00:00:00,469 Log4j2-TF-3-Scheduled-2 DEBUG Setting prev file time to 2022-01-19T00:00:05.000+0100
      [1/20/22 0:00:00:470 CET] 00000186 SystemOut     O 2022-01-20 00:00:00,470 Log4j2-TF-3-Scheduled-2 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1642546805000, prevFileTime=1642546805000
      [1/20/22 0:00:00:470 CET] 00000186 SystemOut     O 2022-01-20 00:00:00,470 Log4j2-TF-3-Scheduled-2 DEBUG Current file: logs/l4j2_ccm-javascript.log
      ...

      2. same cron with targetDate in second second (1/20/22 0:00:01):

      [1/20/22 0:00:01:365 CET] 0000018d SystemOut     O 2022-01-20 00:00:01,365 Log4j2-TF-3-Scheduled-9 DEBUG PV: CronExpression | getTimeBefore - entering 2022-01-20T00:00:01.365+0100
      [1/20/22 0:00:01:365 CET] 0000018d SystemOut     O 2022-01-20 00:00:01,365 Log4j2-TF-3-Scheduled-9 DEBUG PV: CronExpression | getTimeBefore - result 2022-01-20T00:00:00.000+0100
      [1/20/22 0:00:01:365 CET] 0000018d SystemOut     O 2022-01-20 00:00:01,365 Log4j2-TF-3-Scheduled-9 DEBUG PV: RollingFileManager | rollover entered
      [1/20/22 0:00:01:366 CET] 0000018d SystemOut     O 2022-01-20 00:00:01,366 Log4j2-TF-3-Scheduled-9 DEBUG Setting prev file time to 2022-01-20T00:00:00.000+0100
      [1/20/22 0:00:01:366 CET] 0000018d SystemOut     O 2022-01-20 00:00:01,366 Log4j2-TF-3-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1642546805000, prevFileTime=1642633200000
      [1/20/22 0:00:01:366 CET] 0000018d SystemOut     O 2022-01-20 00:00:01,366 Log4j2-TF-3-Scheduled-9 DEBUG Current file: logs/l4j2_uni-perf.log
      ...

       
      You can see the difference in value prevFireTime. This issue may be related to LOG4J2-2575.

      Attachments

        Activity

          People

            rgoers Ralph Goers
            petrvalenta Petr Valenta
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated: