You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@logging.apache.org by Volkan Yazıcı <vo...@gmail.com> on 2020/08/26 07:47:40 UTC
Time-sensitive tests
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?
Re: Time-sensitive tests
Posted by Matt Sicker <bo...@gmail.com>.
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ı <vo...@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 <bo...@gmail.com>
Re: Time-sensitive tests
Posted by Ralph Goers <ra...@dslextreme.com>.
You probably need to look at the logic of the tests. Some of these expect a certain number of files or records in each file and that may not always be the case in the first or last interval.
Ralph
> On Aug 26, 2020, at 12:47 AM, Volkan Yazıcı <vo...@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?