You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Ralph Goers (Jira)" <ji...@apache.org> on 2023/01/03 01:14:00 UTC
[jira] [Resolved] (LOG4J2-3357) CronExpression.getTimeBefore() calculates incorrect result
[ https://issues.apache.org/jira/browse/LOG4J2-3357?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ralph Goers resolved LOG4J2-3357.
---------------------------------
Fix Version/s: 2.20.0
Resolution: Fixed
> 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
> Assignee: Ralph Goers
> Priority: Critical
> Fix For: 2.20.0
>
>
> 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.10#820010)