Change the time of delay to fix a flaky test
What is the purpose of this PR
- This PR fixes a flaky test caused by the non-determinism of the amount of time that
delayingListAppendercan wait to receive the message fromasyncAppenderBase - In other words, the test may randomly fail or pass when run on a slow enough machine.
Reproduce the test failure
-
Run test
AsyncAppenderBaseTest#workerShouldStopEvenIfInterruptExceptionConsumedWithinSubappenderfor many times with a slow enough machine -
To reproduce the failure more often, add
Thread.sleep(100);between line 103(asyncAppenderBase.doAppend(0);) and 104(asyncAppenderBase.stop();) in fileAsyncAppenderBaseTest.javato simulate a slow machine.
Expected result:
- The test should run successfully regardless of the amount of execution time between line 103 and line 104.
Actual result:
-
We can get the stack trace of the test failure:
java.lang.AssertionError at org.junit.Assert.fail(Assert.java:92) at org.junit.Assert.assertTrue(Assert.java:43) at org.junit.Assert.assertTrue(Assert.java:54) at ch.qos.logback.core.AsyncAppenderBaseTest.workerShouldStopEvenIfInterruptExceptionConsumedWithinSubappender(AsyncAppenderBaseTest.java:106) 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:45) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20) at org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:62)
Why the test fails
For DelayingListAppender:
public void append(E e) {
try {
Thread.sleep(delay);
} catch (InterruptedException ie) {
// consume InterruptedException
interrupted = true;
}
super.append(e);
}
It only catches interrupted exception for "delay" milliseconds. If this exception comes after the deadline (when the machine is too slow), the variable interrupted remains false, and the test will fail.
Fix
Set delayingListAppender.delay to its maximum(i.e., the timeout of the unit test workerShouldStopEvenIfInterruptExceptionConsumedWithinSubappender).