I recently added the following test to ensure any runtime exceptions thrown during multi-threaded report generation were being logged correctly.
1 public void testExceptionHandling() { 2 CloverExecutor executor = CloverExecutors.newCloverExecutor(10, "CLOVER-EXCEPTION-TEST"); 3 Logger logger = Logger.getInstance(); 4 try { 5 RecordingLogger bufferLogger = new RecordingLogger(); 6 Logger.setInstance(bufferLogger); 7 8 executor.submit(new ExceptionCallable()); 9 10 assertTrue(bufferLogger.contains(runtimeException)); 11 assertTrue(bufferLogger.contains(runtimeException.getMessage())); 12 } catch (Exception e) { 13 fail("Exception thrown, which should have been caught and logged." + e); 14 } finally { 15 Logger.setInstance(logger); 16 } 17}
RecordingLogger is a test utility class that stores any log messages in a list. The #contains methods return true if the given argument was logged during execution.
This test initially failed and not because I was doing TDD 😉 The assertion on line 10 was throwing an AssertionFailedError.
Can you spot the bug?
Bugger.
Instead of diving into the debugger, I had a look at the code coverage of the RecordingLogger class:
#find is a method that gets called by #contains to do the actual lookup in the list.
Viewing the coverage made it clear that the buffer was empty for both calls to #find.
This lead me to the reason why the test was failing – the executor did not have enough time to fire up its thread, pop my Callable on the queue and execute it.
The one line fix was easy:
executor.awaitTermination(1000, TimeUnit.MILLISECONDS);
Viewing code coverage often provides enough insight into the cause of a failing test and is a cheap alternative to adding printlns or firing up the debugger. During testing, I think of it as a “static debugger”. In fact, when stepping through the above code in a debugger, the test passes.