Living the startup life in Atlanta, GA.

Pollen season in Atlanta. It sucks. No one can build a successful startup here because they are too busy sneezing.

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, test

This 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.

I’ve finally started getting my Lullaby project moving foward. The fact is, since I decided to move my CD’s into mp3′s, I haven’t had a solid way to control what’s playing on my music system without walking over the the Mac in the other room. Hopefully Lullaby will be able to solve that problem.

Of course, this program is becoming harder to write than I thought it would be. Fortunately, I have a lot of music, which makes a system like this useful. Unfortunately, it’s come from a lot of different sources and been ripped from cd from a lot of different computers. Which means that all the edge cases for parsing ID3 tags become exposed and since the ruby-mp3info library is not entirely rock-solid, and I’m far from the greatest Ruby dev ever, getting past them hasn’t been all that easy.

It’s almost to the point where the program can scan through a list of directories and populate the database. Which is much farther that I’ve gotten before. Of course, there are still some architectural decisions that I’m not really sure I’m qualified to answer. Such as, how to make an interface, or a set of interfaces that will work well on the mylo (or smartphone), Wii, and the laptop? What’s the best way to create the controllers to handle these cases? I can only hope that the Ruby refactoring tools get up to spec before I need to use them!