[
https://issues.apache.org/jira/browse/LOG4J2-2610?focusedWorklogId=261090&page=com.atlassian.jira.plugin.system.issuetabpanels:worklog-tabpanel#worklog-261090
]
ASF GitHub Bot logged work on LOG4J2-2610:
------------------------------------------
Author: ASF GitHub Bot
Created on: 17/Jun/19 00:37
Start Date: 17/Jun/19 00:37
Worklog Time Spent: 10m
Work Description: carterkozak commented on issue #271: Proposed fix for
LOG4J2-2610 rollover issue:
URL: https://github.com/apache/logging-log4j2/pull/271#issuecomment-502499719
You're right, I set the status logger level too early and failed to record
anything while the test was running.
I was not able to reproduce a failure with trace enabled, but the one
iteration failed when I set the level to debug:
```
2019-06-16 20:35:27,626 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:27,626 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:27,627 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-27-626.log,
renameEmptyFiles=false]
2019-06-16 20:35:27,627 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:27.627-0400
2019-06-16 20:35:27,628 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:27,628 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:27,628 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-27-628.log,
renameEmptyFiles=false]
2019-06-16 20:35:27,629 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:27.629-0400
2019-06-16 20:35:27,629 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:27,629 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:27,630 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-27-629.log,
renameEmptyFiles=false]
2019-06-16 20:35:27,630 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:27.630-0400
2019-06-16 20:35:28,132 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,132 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,133 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-28-132.log,
renameEmptyFiles=false]
2019-06-16 20:35:28,133 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:28.133-0400
2019-06-16 20:35:28,133 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,134 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,134 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-28-134.log,
renameEmptyFiles=false]
2019-06-16 20:35:28,134 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:28.134-0400
2019-06-16 20:35:28,134 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,134 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,134 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-28-134.log,
renameEmptyFiles=false]
2019-06-16 20:35:28,135 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:28.135-0400
2019-06-16 20:35:28,640 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,640 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,640 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-28-640.log,
renameEmptyFiles=false]
2019-06-16 20:35:28,641 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:28.640-0400
2019-06-16 20:35:28,641 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,642 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,642 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-28-642.log,
renameEmptyFiles=false]
2019-06-16 20:35:28,642 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:28.642-0400
2019-06-16 20:35:28,643 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,643 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:28,643 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-28-643.log,
renameEmptyFiles=false]
2019-06-16 20:35:28,644 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:28.643-0400
2019-06-16 20:35:29,146 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,147 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,147 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-29-147.log,
renameEmptyFiles=false]
2019-06-16 20:35:29,147 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:29.147-0400
2019-06-16 20:35:29,148 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,148 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,149 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-29-148.log,
renameEmptyFiles=false]
2019-06-16 20:35:29,149 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:29.149-0400
2019-06-16 20:35:29,150 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,150 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,150 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-29-150.log,
renameEmptyFiles=false]
2019-06-16 20:35:29,150 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:29.150-0400
2019-06-16 20:35:29,653 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,653 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,653 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-29-653.log,
renameEmptyFiles=false]
2019-06-16 20:35:29,654 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:29.654-0400
2019-06-16 20:35:29,655 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,655 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,655 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-29-655.log,
renameEmptyFiles=false]
2019-06-16 20:35:29,655 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:29.655-0400
2019-06-16 20:35:29,656 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,656 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:29,656 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-29-656.log,
renameEmptyFiles=false]
2019-06-16 20:35:29,657 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:29.656-0400
2019-06-16 20:35:30,158 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,158 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,158 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-30-158.log,
renameEmptyFiles=false]
2019-06-16 20:35:30,159 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:30.159-0400
2019-06-16 20:35:30,160 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,160 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,160 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-30-160.log,
renameEmptyFiles=false]
2019-06-16 20:35:30,161 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:30.160-0400
2019-06-16 20:35:30,161 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,161 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,161 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-30-161.log,
renameEmptyFiles=false]
2019-06-16 20:35:30,162 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:30.162-0400
2019-06-16 20:35:30,663 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,663 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,663 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-30-663.log,
renameEmptyFiles=false]
2019-06-16 20:35:30,664 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:30.664-0400
2019-06-16 20:35:30,664 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,664 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,664 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-30-664.log,
renameEmptyFiles=false]
2019-06-16 20:35:30,665 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:30.665-0400
2019-06-16 20:35:30,665 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,665 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:30,665 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-30-665.log,
renameEmptyFiles=false]
2019-06-16 20:35:30,666 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:30.665-0400
2019-06-16 20:35:31,171 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,172 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,172 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-31-172.log,
renameEmptyFiles=false]
2019-06-16 20:35:31,172 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:31.172-0400
2019-06-16 20:35:31,173 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,173 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,173 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-31-173.log,
renameEmptyFiles=false]
2019-06-16 20:35:31,174 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:31.174-0400
2019-06-16 20:35:31,174 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,174 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,175 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-31-174.log,
renameEmptyFiles=false]
2019-06-16 20:35:31,175 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:31.175-0400
2019-06-16 20:35:31,677 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,677 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,677 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-31-677.log,
renameEmptyFiles=false]
2019-06-16 20:35:31,677 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:31.677-0400
2019-06-16 20:35:31,678 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,678 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,678 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-31-678.log,
renameEmptyFiles=false]
2019-06-16 20:35:31,678 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:31.678-0400
2019-06-16 20:35:31,679 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,679 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,679 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-31-679.log,
renameEmptyFiles=false]
2019-06-16 20:35:31,679 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:31.679-0400
2019-06-16 20:35:31,680 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,680 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:31,680 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-31-680.log,
renameEmptyFiles=false]
2019-06-16 20:35:31,680 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:31.680-0400
2019-06-16 20:35:32,186 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:32,187 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:32,187 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-32-187.log,
renameEmptyFiles=false]
2019-06-16 20:35:32,188 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:32.187-0400
2019-06-16 20:35:32,188 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:32,189 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:32,189 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-32-189.log,
renameEmptyFiles=false]
2019-06-16 20:35:32,189 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:32.189-0400
2019-06-16 20:35:32,190 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:32,190 main DEBUG Formatting file name.
useCurrentTime=false, currentFileTime=0, prevFileTime=0
2019-06-16 20:35:32,190 main DEBUG RollingFileManager executing synchronous
FileRenameAction[target/rolling-size-test/rolling.log to
target/rolling-size-test/rollingtest-2019-06-167T20-35-32-190.log,
renameEmptyFiles=false]
2019-06-16 20:35:32,190 main DEBUG Now writing to
target/rolling-size-test/rolling.log at 2019-06-16T20:35:32.190-0400
2019-06-16 20:35:32,191 main DEBUG Stopping
LoggerContext[name=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderSizeWithTimeTest),
org.apache.logging.log4j.core.LoggerContext@35cabb2a]...
2019-06-16 20:35:32,191 main DEBUG Shutting down RollingFileManager
target/rolling-size-test/rolling.log
2019-06-16 20:35:32,192 main DEBUG Shutting down RollingFileManager
target/rolling-size-test/rolling.log
2019-06-16 20:35:32,192 main DEBUG All asynchronous threads have terminated
2019-06-16 20:35:32,192 main DEBUG RollingFileManager shutdown completed
with status true
2019-06-16 20:35:32,192 main DEBUG Shut down RollingFileManager
target/rolling-size-test/rolling.log, all resources released: true
2019-06-16 20:35:32,192 main DEBUG Appender RollingFile stopped with status
true
2019-06-16 20:35:32,192 main DEBUG Stopped
XmlConfiguration[location=/Volumes/git/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-size-with-time.xml]
OK
2019-06-16 20:35:32,192 main DEBUG Stopped
LoggerContext[name=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderSizeWithTimeTest),
org.apache.logging.log4j.core.LoggerContext@35cabb2a] with status true
java.lang.AssertionError: Log messages lost : 32
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.assertTrue(Assert.java:41)
at
org.apache.logging.log4j.core.appender.rolling.RollingAppenderSizeWithTimeTest.testAppender(RollingAppenderSizeWithTimeTest.java:113)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.apache.logging.log4j.junit.LoggerContextRule$1.evaluate(LoggerContextRule.java:123)
at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.junit.runners.Suite.runChild(Suite.java:128)
at org.junit.runners.Suite.runChild(Suite.java:27)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at
com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
at
com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
at
com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
at
com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
```
----------------------------------------------------------------
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: 261090)
Time Spent: 4h 20m (was: 4h 10m)
> 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: 4h 20m
> 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)
