Petr Valenta created LOG4J2-3357:
------------------------------------
Summary: CronExpression.getTimeBefore() calculates incorrect result
Key: LOG4J2-3357
URL: https://issues.apache.org/jira/browse/LOG4J2-3357
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.17.1
Reporter: Petr Valenta
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:
{code:java}
... while (prevFireTime.compareTo(targetDateNoMs) >= 0);{code}
Configuration example:
{code:java}
...
<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>{code}
Adding some extra debugging, we can see the behaviour:
1. targetDate in first second (1/20/22 0:00:00):
{code:java}
[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
...{code}
2. same cron with targetDate in second second (1/20/22 0:00:01):
{code:java}
[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
...{code}
You can see the difference in value prevFireTime. This issue may be related to
LOG4J2-2575.
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
