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.