You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "ASF GitHub Bot (Jira)" <ji...@apache.org> on 2019/12/20 16:24:00 UTC
[jira] [Work logged] (LOG4J2-2741) Log files are (sometimes)
overwritten during rolling when using CronTriggeringPolicy
[ https://issues.apache.org/jira/browse/LOG4J2-2741?focusedWorklogId=361719&page=com.atlassian.jira.plugin.system.issuetabpanels:worklog-tabpanel#worklog-361719 ]
ASF GitHub Bot logged work on LOG4J2-2741:
------------------------------------------
Author: ASF GitHub Bot
Created on: 20/Dec/19 16:23
Start Date: 20/Dec/19 16:23
Worklog Time Spent: 10m
Work Description: ahr-huber commented on pull request #323: LOG4J2-2741 - Fix race condition in computation of prevFireTime in Cr…
URL: https://github.com/apache/logging-log4j2/pull/323
…onTriggeringPolicy
There was a race condition in the computation of prevFireTime - which is used as time
for the file pattern - could be wrong which lead to the possibility of overwriting files,
because a file name could be generated twice. The cause was CronExpression.getPrevFireTime()
needs a Date in the interval (prevFireTime, currentFireTime], but the Date provided was
created at or after the currentFireTime.
Fixed by using the exact currentFireTime as provided by the scheduler.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Issue Time Tracking
-------------------
Worklog Id: (was: 361719)
Remaining Estimate: 0h
Time Spent: 10m
> 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
>
> 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)