Test Logging

How do you test (in a unittest) that a method writes the log statements you expect it to write?

Apparantly being able to do that is not a very common requirement - at least Google wasn't it's normal helpful self when I asked it how to, and frankly I never needed it myself. Before now, that is.

AbstractInterruptibleChannel.close() throws one of those pesky checked IOExceptions, which you always have to write a lot of verbose and error-prone code to "handle", and which you really can't do anything about anyway.

Code working with two IO channels normally looks something like this:

AbstractInterruptibleChannel c1, c2;
try {
    // Open and use channels c1 and c2
} catch (IOException ioe) {
    // Display or log errormessage or whatever
} finally {
    try {
        c1.close();
    } catch (IOException e) {
        logger.error("Failed to close a channel.", e);
    }
    try {
        c2.close();
    } catch (IOException e) {
        logger.error("Failed to close a channel.", e);
    }
}

I would much rather have something like this:

AbstractInterruptibleChannel c1, c2;
try {
    // Open and use channels c1 and c2
} catch (IOException ioe) {
    // Display or log errormessage or whatever
} finally {
    closeChannels(c1, c2);
}

Therefore I wrote a small utility method to close IO Channels and encapsulate the try/catch hassle normally associated with that:

public static void closeChannels(AbstractInterruptibleChannel... channels) {
    for (AbstractInterruptibleChannel channel : channels) {
        if (channel == null) continue;
        try {
            channel.close();
        } catch (Exception e) {
            logger.error("Failed to close channel.", e);
        }
    }
}

It suppresses errors - if an Exception occurs it will be logged, but otherwise silently ignored. And now we are finally getting to what I really wanted to write about. I wanted to verify that the method acually logs an error message when it fails to close a channel.
That sounds like something which should be very easy to do. It's not hard, but not exactly obvious either. As mentioned earlier I first tried Google without result. The SLF4J. and Logback manuals didn't have any examples exactly matching my needs either, but based on the Logback documentation I did manage to write a Filter to capture whatever was logged during executon of the test. It took quite a bit of code though, and after Ceki Gülcü (the author of Logback) pointed out that there are applicaple examples in the Logback code I dropped the Filter idea and used Logbacks ListAppender instead:

public void testCloseChannels() { 
    // Capture log entries from FileUtil 
    Logger logger = (Logger) LoggerFactory.getLogger(FileUtil.class); 
    logger.setAdditive(false); 
    ListAppender<LoggingEvent> listAppender = new ListAppender<LoggingEvent>(); 
    listAppender.start(); 
    logger.addAppender(listAppender); 
    // Close a mix of normal, broken and completely missing channels 
    closeChannelse(null, new UnclosableChannelStub(), null, new ChannelStub(), new ChannelStub()); 
    // Restore normal logging 
    logger.detachAppender(listAppender); 
    logger.setAdditive(true); 
    // Perform checks 
    assertEquals("Exactly 1 failure should have been logged.", 1, listAppender.list.size()); 
} 

Now the test works exactly as I wanted.

For a while I have wanted to take a closer look at Hamcrest and, to avoid doing any real work, I decided to further refine the test to use Hamcrest matchers to perform the same test.

The following is an example of a Matcher which matches LoggingEvents with a particular message text.

public class LoggingEventMatchers {

    /**
     * Does the LoggingEvent have a particular message?
     */
    @Factory
    public static TypeSafeMatcher&lt;LoggingEvent&gt; message(String message) {
        return new MessageMatcher(message);
    }


    /**
     * Matcher to check if an LoggingEvent has a particular message.
     *
     * @author Claus Nielsen
     */
    private static class MessageMatcher extends TypeSafeMatcher&lt;LoggingEvent&gt; {

        private final String theMessage;

        /**
         * Constructor.
         * 
         * @param theMessage
         *            The predicate evaluates to true for LoggingEvents
         *            with this message.
         */
        private MessageMatcher(String theMessage) {
            this.theMessage = theMessage;
        }

        @Override
        public boolean matchesSafely(LoggingEvent event) {
            return theMessage.equals(event.getMessage());
        }

        @Override
        public void describeTo(Description description) {
            description.appendText("the message ").appendValue(theMessage);
        }

    }


}

In addition to writing a set of matchers similar to the one above, I moved the logger configuration code to a seperate class called LogCapturingTestTemplate, and now the test itself is as simple as this:

 public void testErrorLoggedForUnclosableChannels() {
 // Capture logging events while closing come Channels.
 final CapturedLoggingEvents loggingEvents = new LogCapturingTestTemplate(FileUtil.class) {
  protected void monitorThis() {
   closeChannels(null, c1, new UnclosableChannelStub(), null, c2);
  }
 }.execute();
  assertThat(loggingEvents.getEvents(), hasItem(
   allOf(level(ERROR), message(FileUtil.FAILED_TO_CLOSE_CHANNEL))
  ));
 }

This test is actually far more specific. Where the previous version only checked that exactly one entry was logged during the call to closeChannels, this test checks that an ERROR message with a specific message is logged.
Full source code for both the test and the Hamcrest-style matchers is part of the clanie-core project (version 0.0.1). The source is available in the Git repository, and both binary builds, source, javadoc and project documentation can be found in the Maven repository.