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

["James Chaplin (JIRA)" <ji...@apache.org>]

James Chaplin created LOG4J2-2610:
-------------------------------------

             Summary: 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
             Fix For: 2.12.0


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)