[
https://issues.apache.org/jira/browse/LOG4J2-2741?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Carter Kozak resolved LOG4J2-2741.
----------------------------------
Fix Version/s: 2.13.1
Resolution: Duplicate
> 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
> Fix For: 2.13.1
>
> Attachments: CronExpressionTest.java
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> 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)
