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 2022/05/17 05:58:00 UTC
[jira] [Commented] (LOG4J2-3357) CronExpression.getTimeBefore() calculates incorrect result
[ https://issues.apache.org/jira/browse/LOG4J2-3357?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17537955#comment-17537955 ]
Ralph Goers commented on LOG4J2-3357:
-------------------------------------
Well, the problem is that the logic for getTimeBefore is working correctly. It did indeed calculate the time the file should have rolled based on the provided time. Will need to think about how to best address this.
> 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
>
> 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.7#820007)