False assertions when running tests in parallel

[MosheElisha]

Hi,

First, I would like to thank you for this project. It is nicely implemented and very useful.

I would like to report an issue when running the tests in parallel with the following properties:

junit.jupiter.execution.parallel.enabled = true
junit.jupiter.execution.parallel.mode.default = concurrent

Attaching a small project to reproduce - parallel-tests.zip

If I uncomment the @Execution(ExecutionMode.SAME_THREAD) on the ParallelTest class or use @ResourceLock("LogCapturer") on both test methods, everything works.

Run the tests by executing:

mvn clean test

BTW - I used Flogger which uses slf4j to log4j2

Thanks!

[netmikey]

After digging into this a bit, I'm afraid parallel execution won't work for logunit because of the very nature of how logging frameworks work.

Let me explain: logunit works by injecting its own appender, configured with all loggers specified in the LogCapturer.create() call, into the logging framework's configuration before a test method. Those loggers and the appender are removed from the logging framework after that test method, re-added for the next one and so on. This ensures a clean context for each test, even though the logging framework, by nature, is global. Indeed, since logging frameworks are not instantiated per-thread, or even per-test-method but globally for the VM, running logunit in parallel will constantly overwrite the logging framework's configuration, destroying logunit's own context.

The first solution that comes to mind would be redesigning Logunit so that the injection of its appenders and loggers would be handled globally, using some mapping between logger/appender and the test method who asked for them. However, even if we implemented this, you still couldn't tell what test method a specific log message came from. It's like a printer that would be getting print jobs from several computers at the same time: even if it manages to print each page correctly, you couldn't tell what computer a specific page came from just by looking at the page.

Here's an example: Let's say you have 2 test methods, each in its own test class and a unit under test like this:

public class Tested {
  private Logger log = LoggerFactory.getLogger(Tested.class);
  public void doSomething(int arg) {
    if(arg > 0) {
      log.info("positive");
    }
  }
}

public class ParallelTest1 {
  @RegisterExtension
  LogCapturer logCapturer = LogCapturer.create().captureForType(Tested.class);
  public void testZero() {
    new Tested().doSomething(0);
    logCapturer.assertDoesNotContain("positive");
  }
}

public class ParallelTest2 {
  @RegisterExtension
  LogCapturer logCapturer = LogCapturer.create().captureForType(Tested.class);
  public void testPositive() {
    new Tested().doSomething(1);
    logCapturer.assertContains("positive");
  }
}

Now, if both of your tests ParallelTest1 and ParallelTest2 are started concurrently by JUnit, your log file will contain:

10:08:57.563 [ForkJoinPool-1-worker-2] INFO  com.example.Tested - positive

Logunit would have no way of knowing what test method emitted this log entry. So depending on timing (did someone say race condition?), testZero() would either fail or succeed because testZero()'s logCapturer could contain the "positive" log event from testPositive().

---

I guess my advice would be: if logging is so important that you have to cover it in your tests, and if you absolutely need to run them in parallel, then a solution might be to encapsulate the critical log messages into an interface with an implementation delegating to your log framework at runtime, mocking that interface in test and run your expectations on those mocks.

Something like this setup:

public interface CriticalLog {
  public void accountDeleted(int id);
}

public class CriticalLogImpl {
  private Logger log = LoggerFactory.getLogger(CriticalLogImpl.class);
  public void accountDeleted(int id) {
    log.warn("Account " + id + " deleted.");
  }
}

public class AccountController {
  private CriticalLog log; // use e.g. injection
  public void deleteAccount(int id) {
    // ... do something ...
    log.accountDeleted(id);
  }
}

public class AccountControllerTest {
  public void testAccountDeletion(@Mock CriticalLog logMock) {
    AccountController tested = new AccountController();
    tested.setCritialLog(logMock);
    tested.deleteAccount(3);
    Mockito.verify(logMock).accountDeleted(3);
  }
}

Hope this helps!

[MosheElisha]

Thank you, @netmikey for digging into this issue! I assumed it won't be easy / possible.

There are very few tests in which I need to test the logger. I will go with the approach of using a @ResourceLock. That is completely acceptable for me.

Thank again!