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 {
} catch (IOException ioe) {
} 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 {
} catch (IOException ioe) {
} 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() {
Logger logger = (Logger) LoggerFactory.getLogger(FileUtil.class);
logger.setAdditive(false);
ListAppender<LoggingEvent> listAppender = new ListAppender<LoggingEvent>();
listAppender.start();
logger.addAppender(listAppender);
closeChannelse(null, new UnclosableChannelStub(), null, new ChannelStub(), new ChannelStub());
logger.detachAppender(listAppender);
logger.setAdditive(true);
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 {
@Factory
public static TypeSafeMatcher<LoggingEvent> message(String message) {
return new MessageMatcher(message);
}
@author
private static class MessageMatcher extends TypeSafeMatcher<LoggingEvent> {
private final String theMessage;
@param
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() {
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.