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>

Reply via email to