Monthly Archives: December 2010

Checking Logging in Unit Tests

Update – I’ve written a new post here to do the same unit testing with Logback and not just Log4J

Logging is often a second class citizen in programming and one of the reasons is that logging is a pain to unit test. The simplest and most naive way of testing logging is to run a test, log to a file and then “grep” the log for the expected message. Earlier this week I stumbled across this which showed an awesomely simple way to unit test logging. I wrote up a simple version that takes advantage of some of the syntactical sugar of the Mockito framework that runs out of the box for my current team. So here it is.

package com.bloodredsun;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

/**
 * @author Martin Anderson
 * based on example from http://slackhacker.com/
 */
public class ExampleThatLogs {

    private static final Log LOG =
        LogFactory.getLog(ExampleThatLogs.class);

    public String concat(String a, String b) {
        LOG.info("String a:" + a + ", String b:" + b);
        return a+b;
    }
}
package com.bloodredsun;

import org.apache.log4j.Appender;
import org.apache.log4j.Level;
import org.apache.log4j.LogManager;
import org.apache.log4j.spi.LoggingEvent;
import org.junit.After;
import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.mockito.ArgumentCaptor;
import org.mockito.Mock;
import org.mockito.runners.MockitoJUnitRunner;

import static org.hamcrest.CoreMatchers.is;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertThat;
import static org.mockito.Mockito.verify;

/**
 * @author Martin Anderson
 */
@RunWith(MockitoJUnitRunner.class)
public class ExampleThatLogsTest {

    @Mock
    private Appender mockAppender;
    @Captor
    private ArgumentCaptor captorLoggingEvent;

    @Before
    public void setup() {
        LogManager.getRootLogger().addAppender(mockAppender);
    }

    @After
    public void teardown() {
        LogManager.getRootLogger().removeAppender(mockAppender);
    }

    @Test
    public void shouldConcatAndLog() {
        //given
        ExampleThatLogs example = new ExampleThatLogs();
        //when
        String result = example.concat("foo", "bar");
        //then
        assertEquals("foobar", result);

        verify(mockAppender).doAppend(captorLoggingEvent.capture());
        LoggingEvent loggingEvent = captorLoggingEvent.getValue();
        //Check log level
        assertThat(loggingEvent.getLevel(), is(Level.INFO));
        //Check the message being logged
        assertThat(loggingEvent.getRenderedMessage(), 
            is("String a:foo, String b:bar"));
    }
}

Playing with JRebel

The London Java Community does more than a few cool things: meetups in the pub, coding dojos, training events, monthly draws and almost impossibly is run a a sane recruiter who actually knows how to deal with IT people. I throw my name into the hat for the prize draws every now and then and last month was my luck was in since I won a JRebel license (for those of you who don’t know JRebel allows the hot deploy of Java code changes and a load more).

Now not only is this a full license rather than being fobbed off with a time-limited trial but it also includes the Enteprise add-on. What makes it even better is that last week I was talking to one of the top techies at my current contract about using JRebel in a development environment so now I get to see exactly how it works. I’m all about the value added 🙂

Come back for an update in the next few weeks.