logback icon indicating copy to clipboard operation
logback copied to clipboard

Change the time of delay to fix a flaky test

Open miyamura-miyako opened this issue 3 years ago • 0 comments

What is the purpose of this PR

  • This PR fixes a flaky test caused by the non-determinism of the amount of time that delayingListAppender can wait to receive the message from asyncAppenderBase
  • In other words, the test may randomly fail or pass when run on a slow enough machine.

Reproduce the test failure

  • Run test AsyncAppenderBaseTest#workerShouldStopEvenIfInterruptExceptionConsumedWithinSubappender for 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 file AsyncAppenderBaseTest.java to 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).

miyamura-miyako avatar Sep 14 '22 13:09 miyamura-miyako