Testing logging behaviour sans Mockito

The most popular post in this somewhat dormant blog is Testing logging behaviour in four code lines flat. The approach described there relies on everyones favourite unit testing mocking swiss army knife – Mockito. To achieve the purpose of unit testing logging Mockito is however not a required drink, some simple Log4j coding goes a long way:

import org.apache.log4j.SimpleLayout;
import org.apache.log4j.WriterAppender;
import static org.hamcrest.CoreMatchers.is;
import org.junit.Test;
import static org.junit.Assert.assertThat;

public class FooTest {

  @Test
  public void testMethod() {

    StringWriter stringWriter = new StringWriter();

    Logger.getRootLogger().addAppender(new WriterAppender(new SimpleLayout(), stringWriter));

    doStuffThatCausesLogging();

    assertThat(stringWriter.toString(), is("WARN - doh\n"));
  }
}

The code is still acceptable and quite compact. However the expressive niceties Mockito provides are lost and making assertions about logging levels, timestamps and multiple logging invocations takes a lof of cruft. Hence I really see few reasons for this approach if Mockito is available.

Testing logging behaviour in four code lines flat

Update: Testing logging without Mockito is also viable.

Adding assertions for logging behaviour to my unit tests have been a long standing item om my ToDo list. This imperfection have been a nagging thorn in my side since it obvious that logging is a critical aspect (no AOP pun intended) of any commercial system of importance. But I thought that it must be hard and boring work to add tests for logging. To be honest I’m no fan of boring work. Recently I finally got around to take a shot at it and found it surprisingly easy to accomplish in a mavenized Spring project with the help of the everyone’s favorite Java mocking library: Mockito.

Originally I though I had to modify all the classes under test to accept a log4j Logger as constructor argument and mock that logger in the unit test. This would have required quite a lot of code rewrite since most classes in the project simply use:

Logger.getLogger(this.getClass())

to get access to a logger instance. Also I don’t like the idea to “pollute” the constructors with additional arguments, most classes had just enough dependencies passed in that way as it were.

Next up was an idea to write a custom log4j Appender and add a log4j.properties to src/test/resources with:

log4j.rootLogger=ERROR,TESTAPPENDER
log4j.appender.TESTAPPENDER=com.my.fantastic.MockedAppender

The main problem with this approach is that MockedAppender instance would be shared by all unit tests, forcing manual (ugly!) resets of its state between test invocations.

Then I discovered that log4j provides an API for dynamic Appender configuration at runtime! What it all boiled down to became surprisingly succinct when some Mockito magic was applied. In fact only four code lines (ignoring imports, and other noise) bought me the capability to make assertions about the logging behavior of the code under test!

import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.verify;
public class FooTest {
	private Appender appenderMock;
	@Before
	public void setupAppender() {
		appenderMock = mock(Appender.class);
		Logger.getRootLogger().addAppender(appenderMock);
	}
	@After
	public void removeAppender() {
		Logger.getRootLogger().removeAppender(appenderMock);
	}
	@Test
	public void testMethod()  {
		doStuffThatCausesLogging();
		verify(appenderMock).doAppend((LoggingEvent) anyObject());
	}
}

Using Mockito’s handy ArgumentCaptor class it’s dead simple to make stronger assertions, with regard to for instance the level the message was logged at:

		ArgumentCaptor arguments = ArgumentCaptor.forClass(LoggingEvent.class);
		verify(appenderMock).doAppend(arguments.capture());
		assertThat(arguments.getValue().getLevel(), is(Level.WARN));

Ergo – I have no longer any excuse for settling for anything less than comprehensive unit tests, adding tests for logging is actually quite trivial using modern tools!