[jira] [Resolved] (LOG4J2-2610) Windows - File creationTime issue for RollingFileAppender, combined time/size policy

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

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

Ralph Goers resolved LOG4J2-2610.
---------------------------------
    Resolution: Fixed

A fix has been applied to both the release-2.x and master branches. Please verify and close.

> Windows - File creationTime issue for RollingFileAppender, combined time/size policy
> ------------------------------------------------------------------------------------
>
>                 Key: LOG4J2-2610
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-2610
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Core
>    Affects Versions: 2.11.2
>         Environment: Windows 10, JDK 7u79, Log4J2 2.11.2
>            Reporter: James Chaplin
>            Priority: Major
>              Labels: pull-request-available
>             Fix For: 2.12.0
>
>          Time Spent: 3h
>  Remaining Estimate: 0h
>
> Hello Apache Log4j Team.
> Recently I encountered a boundary-condition issue with RollingFileAppender on Windows. Due to the nature of the issue it can be difficult to reproduce consistently, but I was able to do so using some files with old creation dates.
> It was reproduced with a configuration like this modified from one of the unit tests:
> {code:xml}
>     <RollingFile name="RollingFile" fileName="target/rolling3/rollingtest.log" filePattern="target/rolling3/rollingtest_%d\{yyyy-MM-dd}_%i_.log"
>       append="true" bufferedIO="true" bufferSize="8192" immediateFlush="true">
>       <PatternLayout pattern="%d\{yyyy-MM-dd-HH-mm-ss} [%level] [%c] %msg%n"/>
>       <Policies>
>         <TimeBasedTriggeringPolicy interval="1" modulate="true" />
>         <SizeBasedTriggeringPolicy size="3500KB" />
>       </Policies>
>       <DefaultRolloverStrategy max="3"/>
>     </RollingFile>
> {code}
> where the +current and rollover files both share the same directory+. It is easier to see when the date/time of the initial log file "rollingtest.log" has a creationTime that is a few days in the past (simulating a gap in processing between logs due to downtime).
> When the rolling append rolls the file over into one matching filePattern, it creates a +new "rollingtest.log" file+ which has a +creationTIme equal to+ the +old file's creationTime+ (instead of the current system time).
> For example if the current date is 2019-05-30 and the old file's creationTime is sometime in 2019-05-28 (2 days previous), after the rollover the newly created "rolingtest.log" will still have a creationTime of 2019-05-28 ... even though it was just re-created on 2019-05-30. This creates some strange behaviour the next time a rollover is processed by the RollingFileAppender (since the current log file appears to be a "2-day-old file" the 2nd rollover filename is incorrect).
> Going through some of the Log4j2 code it doesn't appear to be a direct bug in Log4j2, but rather due to a Windows behaviour called "File System Tunneling" (see blog [https://devblogs.microsoft.com/oldnewthing/20050715-14/?p=34923] for some details).
> While trying to figure out what was happening I also noticed that the unit test RollingAppenderSizeWithTimeTest.+testAppender()+ was +consistently failing+ under Windows too. Since that test involves very rapid rollovers it could be related to the "tunneling" behaviour in Windows or could be something entirely different.
> I've attempted two mitigation fixes for both issues described in this Jira against the code for 2.12.0-SNAPSHOT. A GitHub PR with an initial fix attempt and unit test should follow soon.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)