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:
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:
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:
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:
// 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.
/**
* Does the LoggingEvent have a particular message?
*/
@Factory
public static TypeSafeMatcher<LoggingEvent> 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<LoggingEvent> {
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:
// 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.