Oct 21 2009

No more excuses: junit testing log messages

Category: java, tutorial — giordano scalzo @ 7:46 pm

Althought I’m a straight adept of Tdd, sometime I can’t resist the temptation to write some production code without a test, above all if I have to implement some cross cutting behaviours, as could be logging .

In project I worked on lately, a request was to manage some bad situations logging something at error level and go process next item; the temptation to implement it and check running the program was very appeliling, but my green wrist band and RailsConf 09 keynote by Uncle Bob I watched recentely, helped me resist.
So I started searching, tried somenthing, and, finally, I came up with a neat solution.

Given this simple object

package biz.scalzo.prod;

import org.apache.log4j.Logger;

public class LoggingObject {
	private static Logger log = Logger.getLogger(LoggingObject.class);

	public void starts() {
		log.info("I'm starting");
	}
}

we want to test if it writes log.
To achieve this, we can use a simple custom appender, that records all messages in a list:

package biz.scalzo.test;

import java.util.ArrayList;
import java.util.List;
import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.PatternLayout;
import org.apache.log4j.spi.LoggingEvent;

public class RecordingAppender extends AppenderSkeleton {
	private static List<String> messages = new ArrayList<String>();
	private static RecordingAppender appender = new RecordingAppender();

	private RecordingAppender() {
		super();
	}

	public static RecordingAppender appender(PatternLayout patternLayout) {
		appender.setLayout(patternLayout);
		appender.clear();
		return appender;
	}

	protected void append(LoggingEvent event) {
		messages.add(layout.format(event));
	}

	public void close() {
	}

	public boolean requiresLayout() {
		return true;
	}

	public static String[] messages() {
		return (String[]) messages.toArray(new String[messages.size()]);
	}

	private void clear() {
		messages.clear();
	}
}

With that, writing our test is a piece of cake:

package biz.scalzo.test;

import org.apache.log4j.ConsoleAppender;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.PatternLayout;
import org.junit.Before;
import org.junit.Test;
import static org.junit.Assert.*;

import biz.scalzo.prod.LoggingObject;

public class ALoggingObject {

	private LoggingObject loggingObj;

	@Before
	public void setUp() {
		loggingObj = new LoggingObject();
		configureLog();
	}

	private boolean logContains(String expected) {
		String actual[] = RecordingAppender.messages();
		for (String log : actual) {
			if (log.contains(expected))
				return true;
		}
		return false;
	}

	private void configureLog() {
		Logger rootLogger = Logger.getRootLogger();
		rootLogger.removeAllAppenders();
		rootLogger.setLevel(Level.INFO);
		rootLogger.addAppender(new ConsoleAppender(new PatternLayout(
				"%d [%t] %-5p %c{1} - %m%n")));
		rootLogger.addAppender(RecordingAppender.appender(new PatternLayout(
				"%-5p - %m%n")));
	}

	@Test
	public void shouldLogWhenStarts() {
		loggingObj.starts();
		assertTrue(logContains("I'm starting"));
	}

}

Neat, simple and clear: no more excuses to not test logging!

Technorati Tags: , ,

Tags: , ,

4 Responses to “No more excuses: junit testing log messages”

  1. Andrea Cerisara says:
    October 22nd, 2009 4:07 pm

    Correct me if I’m wrong, but it seems to me that LoggingObject is a business object: in that case I would probably extract the logging functionality to an interface and test it through an interaction test with some kind of test double.

  2. giordano scalzo says:
    October 22nd, 2009 5:39 pm

    mmm
    in fact RecordingAppender it’s just a kind of test double ;-)
    I agree with you, that injecting that responsibility should be more clear.

    Thanks for your suggestion

  3. Andrea Cerisara says:
    October 22nd, 2009 9:15 pm

    That’s true, but you have a static dependency that, in my opinion, makes hard to test your object. Just a thought anyway :-)

  4. Andrea Cerisara says:
    October 22nd, 2009 9:36 pm

    To clarify myself, for example (without interface, using an object seam):

    in LoggingObject

    protected Logger logger()
{
    return Logger.getLogger(LoggingObject.class);
}

public void starts()
{
    logger().info("I'm starting");
}

    in ALoggingObject

    private Logger logger;

@Before
public void setUp()
{
    logger = mock(Logger.class);
    loggingObject = new LoggingObject()
    {
        @Override
        public Logger logger()
        {
            return logger;
        }
    };
}

@Test
public void shouldLogWhenStarts()
{
    loggingObj.starts();
    verify(logger).info("I'm starting");
}

Leave a Reply