[
https://issues.apache.org/jira/browse/LOG4J2-2610?focusedWorklogId=252845&page=com.atlassian.jira.plugin.system.issuetabpanels:worklog-tabpanel#worklog-252845
]
ASF GitHub Bot logged work on LOG4J2-2610:
------------------------------------------
Author: ASF GitHub Bot
Created on: 02/Jun/19 16:33
Start Date: 02/Jun/19 16:33
Worklog Time Spent: 10m
Work Description: JCgH4164838Gh792C124B5 commented on issue #271:
Proposed fix for LOG4J2-2610 rollover issue:
URL: https://github.com/apache/logging-log4j2/pull/271#issuecomment-498046100
Hello @rgoers (**apologies in advance for the long response**).
The **short answer** is _none of the existing test cases actually failed_
due to filesystem tunneling behaviour (was only noted by "manual observation"
with the necessary preconditions).
`RollingAppenderSizeWithTimeTest.testAppender()` was the only test that was
actually failing (which as per discussion above with @carterkozak _actually
appears to be a separate issue_ - where the 1ms sleep in
`RollingFileManager.createFileAfterRollover()` was needed to get the test to
succeed).
When debugging an application that used Log4j2 with a "size-and-time"
rollover strategy, I noted that when the _current log file_ had a
_`creationTime` > 24hrs older than the current date/time_, the rollover behaved
strangely. When the current log file was rolled over the new "xxxx.log" would
"_carry over_" the same >24hrs old `creationTime` as the original file. Then,
later, on the next rollover, it's rolled-over name ("xxxx_CCYY-MM-DD_y.log")
still had the CCCYY-MM-DD represented by the `creationTime` of the original log
file (2 rollovers ago).
Basically you need sufficient _"discontiguous time"_ between the
creationTime of the original file and the actual current system datetime to
observe the behaviour. The amount of time required to observe it depended on
the rollover period.
Due to the conditions required to reproduce it, I didn't initally consider a
test case to try and demonstrate it failing. Instead, I did a manual test set
up using `RollingAppenderSizeWithTimeTest`. I either suppressed the directory
cleanup "`withCleanFoldersRule`" in the test, or used a breakpoint so I could
copy a log file with a "really old" creationTime in place.
Using the new code with Files.setAttribute() that you mentioned, I suppose
you could create an empty file in the test before the appender tries to access
it. Then you could set its creationTime to >24hrs in the past, let the
appender roll it over/create the new .log file and then _confirm by reading its
creationTime attribute that it is using "today's date" as expected_ ?
**Sorry again for the long explanation**, but it really is/was a pain to
reproduce in a "nice" way. :sweat_smile:.
----------------------------------------------------------------
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:
us...@infra.apache.org
Issue Time Tracking
-------------------
Worklog Id: (was: 252845)
Time Spent: 2h 50m (was: 2h 40m)
> 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: 2h 50m
> 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)
