I’m becoming a slow convert towards the idea that unit testing is actually a good thing. Especially when you’re building new features. After all, do I really want to click around on a bunch of different screens trying to test things? Hell no. I’m a developer and not a QA guy for a reason. Something that I’ve decided is a not bad thing to test is verify that error messages are being logged out on error conditions. Previously, I’ve been a fan of bubbling errors up to the user level so that they can file meaningful bug reports. Unfortunately, end users don’t seem to be as fond of stack-traces as developer types. Therefore, I’ve started to move towards doing something sorta right in an error condition and logging that something went horribly wrong. In this case, it’s probably a pretty good idea to make sure that the system is going to tell you that tidbit of information. Thankfully, this is extremely easy to do with log4j and Junit Junit. The first step is to follow the log4j instructions on how to get logging to work with your system. In my case, I’m running integration tests in a Spring context so the logging plumbing was already up and running. The next step is building a mock appender object that extends org.apache.log4j.AppenderSkeleton. You need to override append, close, and requiresLayout. My append method simply stores the last item logged in an instance variable. This could be as complicated as needed. I’ve also added a few more functions for management. The final class looks like:
public class TestAppender extends AppenderSkeleton {
private LoggingEvent lastEvent;
@Override
protected void append(LoggingEvent event) {
lastEvent = event;
}
@Override
public void close() {
}
@Override
public boolean requiresLayout() {
return false;
}
public LoggingEvent getLastEvent() {
return lastEvent;
}
public void clearAppender() {
lastEvent = null;
}
}
Next, you need to configure log4j to use this appender in addition to or instead of whatever it’s currently using. If you have a working log4j.properties file, you’ll need to add something like the following:
log4j.appender.test=net.vijedi.logging.test.TestAppender # Output to stdout and the file with WARN being the default log4j.rootLogger=warn, stdout, testThis code snippet assumes that “stdout” is your default logger. Finally it comes time to put this in action. I found the easiest way to do this is to build an abstract test class that all my other tests would extend from. Lets take a look at the relevant bits:
public void setUp() throws Exception {
....
((MockTestLoggingAppender) Logger.getRootLogger()
.getAppender("test")).clearAppender();
}
....
protected void testLogMessageAbsence(Level level, Class clazz, String message) {
LoggingEvent event = getLastEventFromLogger();
if(null != event) {
assertFalse(
clazz.getCanonicalName().equals(
event.getLocationInformation().getClassName() ) &&
level.equals(event.getLevel()) &&
((String) event.getMessage()).contains(message)
);
}
}
protected void testLogMessage(Level level, Class clazz, String message) {
LoggingEvent event = getLastEventFromLogger();
assertNotNull(event);
assertEquals(clazz.getCanonicalName(),
event.getLocationInformation().getClassName());
assertEquals(level, event.getLevel());
assertTrue(((String) event.getMessage()).contains(message));
}
private LoggingEvent getLastEventFromLogger() {
MockTestLoggingAppender mockAppender = (MockTestLoggingAppender)
Logger.getRootLogger().getAppender("test");
return mockAppender.getLastEvent();
}
setUp gets the “test” appender from the root logger and clears the instance variable. This ensures that previous tests don’t effect the current one. Note that the name used here is the same as the one specified in the log4j.properties file. getLastEventFromLogger retrieves the last logged event from the appender. testLogMessage and testLogMessageAbsence check whether or not the last log message matches what was or was not expected.
