[jira] [Assigned] (LOG4J2-2741) Log files are (sometimes) overwritten during rolling when using CronTriggeringPolicy

["Ralph Goers (Jira)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/LOG4J2-2741?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Ralph Goers reassigned LOG4J2-2741:
-----------------------------------

    Assignee: Ralph Goers

> Log files are (sometimes) overwritten during rolling when using CronTriggeringPolicy
> ------------------------------------------------------------------------------------
>
>                 Key: LOG4J2-2741
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-2741
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Appenders
>    Affects Versions: 2.11.2
>            Reporter: Andreas Huber
>            Assignee: Ralph Goers
>            Priority: Critical
>         Attachments: CronExpressionTest.java
>
>
> The {{CronTriggeringPolicy}} with a date pattern as file pattern may overwrite previous log files during rolling. This happens randomly. An example appender definition:
> {noformat}
> <RollingRandomAccessFile name="mylogfile" 
> 	fileName="mylogfile.log" 
> 	filePattern="mylogfile.%d{yyyy-MM-dd_HHmmss}.log.zip">
> 	<PatternLayout pattern="%d{ISO8601} %m%n" />
> 	<Policies>
> 		<CronTriggeringPolicy schedule="0 0 0 * * ?"/><!-- triggers at midnight -->
> 	</Policies>
> </RollingRandomAccessFile>
> {noformat}
> In the debug logging we can see that the "prev file time" is set the 17:11 twice.
> {noformat}
> 2019-12-17T17:11:00,001 Log4j2-TF-3-Scheduled-8 DEBUG Setting prev file time to 2019-12-17T17:11:00,000+0100
> 2019-12-17T17:12:00,000 Log4j2-TF-3-Scheduled-2 DEBUG Setting prev file time to 2019-12-17T17:11:00,000+0100
> {noformat}
> This bug is reproducible in 2.11.2, but not in 2.11.1. I believe it was introduced with LOG4J2-2542 ([https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;a=commitdiff;h=42fe68e;hp=dfced487bdb422c56334922411e10447bdb64969]).
> When we look at {{CronTriggeringPolicy.rollover()}}, then we see that in <=2.11.1 the {{prevFileTime}} set on the {{PatternProcessor}} was based on the {{lastRollDate}}. With 2.11.2 it is based on {{CronExpression.getPrevFireTime(new Date())}}. The problem is that {{CronExpression.getPrevFireTime()}} returns the wrong date if the method is called with a date created a millisecond after the actual fire time. I attached a simple test that demonstrates this (see [^CronExpressionTest.java]). In other words if {{new Date()}} is called in the same millisecond as the schedule was scheduled to run, then you get the correct previous fire time. But if {{new Date()}} is called a millisecond too late, then you get the wrong previous fire time.
> My current workaround is to add {{%i}} to the file pattern, e.g. {{mylogfile.%d\{yyyy-MM-dd_HHmmss}_%i.log.zip}}. That way no files are overwritten and I do not lose log files.
> I am not sure how to fix this without breaking the fix for LOG4J2-2542. At first glance I see the following starting point for further investigation:
>  {{lastRollDate}} is private to {{CronTriggeringPolicy}}, but only the {{RollingFileManager}} really knows when the file was last rolled. {{CronTriggeringPolicy}} can never know that the log was already rolled by another policy. And it will never know when the log is being rolled concurrently in another thread. Therefore the {{lastRollDate}} cannot be correctly determined in {{CronTriggeringPolicy}} and has to be part of the {{RollingFileManager}}.
> FYI, [~rgoers]



--
This message was sent by Atlassian Jira
(v8.3.4#803005)