Critical 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.