I always prefer to refactor sleep calls to use count down latches or other concurrency mechanisms due to timing variability like this. Do note that the Clock instance is configurable, so perhaps a test version can be used for that test to artificially advance time step by step?
On Wed, Aug 26, 2020 at 02:47 Volkan Yazıcı <volkan.yaz...@gmail.com> wrote: > I have been trying to fix certain (randomly?) failing tests on both master > > and release-2.x; RollingDirectSizeTimeNewDirectoryTest, > > RollingDirectTimeNewDirectoryTest, etc. to name a few. I suspect the > > hardwiring to the system clock causes this strange behaviour. Consider the > > following RollingDirectTimeNewDirectoryTest failure on Linux build of CI > > run 1030228241 <https://github.com/apache/logging-log4j2/runs/1030228241>: > > > > 2020-08-26T07:14:20.6935332Z [INFO] Running > > > org.apache.logging.log4j.core.appender.rolling.RollingDirectTimeNewDirectoryTest > > 2020-08-26T07:14:22.6924028Z log directory > > (target/rolling-folder-direct) contents: > > 2020-08-26T07:14:22.7012928Z -> target/rolling-folder-direct (4096) > > 2020-08-26T07:14:22.7016056Z -> > > target/rolling-folder-direct/08-26-20-07-14-21 (4096) > > 2020-08-26T07:14:22.7016745Z -> > > target/rolling-folder-direct/08-26-20-07-14-21/processor.log (106000) > > 2020-08-26T07:14:22.7019114Z -> > > target/rolling-folder-direct/08-26-20-07-14-22 (4096) > > 2020-08-26T07:14:22.7019730Z -> > > target/rolling-folder-direct/08-26-20-07-14-22/processor.log (106000) > > 2020-08-26T07:14:22.7020266Z -> > > target/rolling-folder-direct/08-26-20-07-14-20 (4096) > > 2020-08-26T07:14:22.7020811Z total file count: 6 > > 2020-08-26T07:14:22.7266674Z [ERROR] Tests run: 1, Failures: 1, > > Errors: 0, Skipped: 0, Time elapsed: 2.023 s <<< FAILURE! - in > > > org.apache.logging.log4j.core.appender.rolling.RollingDirectTimeNewDirectoryTest > > 2020-08-26T07:14:22.7271597Z [ERROR] streamClosedError Time elapsed: > > 2.016 s <<< FAILURE! > > 2020-08-26T07:14:22.7274708Z java.lang.AssertionError: check failure > > 2020-08-26T07:14:22.7283417Z at > > org.apache.logging.log4j.core.appender.rolling.RollingDirectTimeNewDirect > > ... > > 2020-08-26T07:14:22.7561864Z Caused by: java.lang.AssertionError: > > empty folder: target/rolling-folder-direct/08-26-20-07-14-20 > > 2020-08-26T07:14:22.7562796Z at org.junit.Assert.fail(Assert.java:89) > > 2020-08-26T07:14:22.7563709Z at > org.junit.Assert.assertTrue(Assert.java:42) > > 2020-08-26T07:14:22.7564629Z at > > > org.apache.logging.log4j.core.appender.rolling.RollingDirectTimeNewDirectoryTest.streamClosedError(RollingDirectTimeNewDirectoryTest.java:80) > > 2020-08-26T07:14:22.7565648Z ... 49 more > > > > See the rolling-folder-direct directory dump at the top and notice the > > empty 08-26-20-07-14-20 folder, hence the failure? I think we can resolve > > such flickering behaviours by throwing around more Thread.sleep() calls, > > though I doubt if this is the right way to go. > > > > In my personal RotatingFileOutputStream project > > <https://github.com/vy/rotating-fos>, the employed clock is configurable. > > Via a custom mocked clock, I can implement tests without reaching out to > > system time or Thread.sleep(). Is such a thing possible in Log4j roller as > > well? > > -- Matt Sicker <boa...@gmail.com>