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!

Advertisements

8 thoughts on “Testing logging behaviour in four code lines flat

  1. Hi,

    this almost worked for me! It seems when the test runs with a log4j.xml in the classpath, the asserts cause an error for some reason.

    Its fine in my ide though. Any ideas why?

  2. i have 3 tests altogether asserting logging:

    ——————————————————————————-
    Test set: com.acme.cmsweb.web.velocity.ContentRendererHelperImplTest
    ——————————————————————————-
    Tests run: 4, Failures: 3, Errors: 0, Skipped: 0, Time elapsed: 0.221 sec <<< FAILURE!
    shouldReturnNullWhenXmlToTransformCreatorThrowsException(com.acme.cmsweb.web.velocity.ContentRendererHelperImplTest) Time elapsed: 0.022 sec <<< FAILURE!
    Wanted but not invoked:
    appenderMock.doAppend();
    -> at com.acme.cmsweb.web.velocity.ContentRendererHelperImplTest.shouldReturnNullWhenXmlToTransformCreatorThrowsException(ContentRendererHelperImplTest.java:90)
    Actually, there were zero interactions with this mock.

    at com.acme.cmsweb.web.velocity.ContentRendererHelperImplTest.shouldReturnNullWhenXmlToTransformCreatorThrowsException(ContentRendererHelperImplTest.java:90)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.junit.internal.runners.TestMethod.invoke(TestMethod.java:59)
    at org.junit.internal.runners.MethodRoadie.runTestMethod(MethodRoadie.java:98)
    at org.junit.internal.runners.MethodRoadie$2.run(MethodRoadie.java:79)
    at org.junit.internal.runners.MethodRoadie.runBeforesThenTestThenAacmeers(MethodRoadie.java:87)
    at org.junit.internal.runners.MethodRoadie.runTest(MethodRoadie.java:77)
    at org.junit.internal.runners.MethodRoadie.run(MethodRoadie.java:42)
    at org.junit.internal.runners.JUnit4ClassRunner.invokeTestMethod(JUnit4ClassRunner.java:88)
    at org.junit.internal.runners.JUnit4ClassRunner.runMethods(JUnit4ClassRunner.java:51)
    at org.junit.internal.runners.JUnit4ClassRunner$1.run(JUnit4ClassRunner.java:44)
    at org.junit.internal.runners.ClassRoadie.runUnprotected(ClassRoadie.java:27)
    at org.junit.internal.runners.ClassRoadie.runProtected(ClassRoadie.java:37)
    at org.junit.internal.runners.JUnit4ClassRunner.run(JUnit4ClassRunner.java:42)
    at org.mockito.internal.runners.JUnit44RunnerImpl.run(JUnit44RunnerImpl.java:35)
    at org.mockito.runners.MockitoJUnitRunner.run(MockitoJUnitRunner.java:59)
    at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62)
    at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
    at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
    at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338)
    at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)

    shouldReturnNullWhenXsltLocatorThrowsException(com.acme.cmsweb.web.velocity.ContentRendererHelperImplTest) Time elapsed: 0.004 sec <<< FAILURE!
    Wanted but not invoked:
    appenderMock.doAppend();
    -> at com.acme.cmsweb.web.velocity.ContentRendererHelperImplTest.shouldReturnNullWhenXsltLocatorThrowsException(ContentRendererHelperImplTest.java:104)
    Actually, there were zero interactions with this mock.

    at com.acme.cmsweb.web.velocity.ContentRendererHelperImplTest.shouldReturnNullWhenXsltLocatorThrowsException(ContentRendererHelperImplTest.java:104)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.junit.internal.runners.TestMethod.invoke(TestMethod.java:59)
    at org.junit.internal.runners.MethodRoadie.runTestMethod(MethodRoadie.java:98)
    at org.junit.internal.runners.MethodRoadie$2.run(MethodRoadie.java:79)
    at org.junit.internal.runners.MethodRoadie.runBeforesThenTestThenAacmeers(MethodRoadie.java:87)
    at org.junit.internal.runners.MethodRoadie.runTest(MethodRoadie.java:77)
    at org.junit.internal.runners.MethodRoadie.run(MethodRoadie.java:42)
    at org.junit.internal.runners.JUnit4ClassRunner.invokeTestMethod(JUnit4ClassRunner.java:88)
    at org.junit.internal.runners.JUnit4ClassRunner.runMethods(JUnit4ClassRunner.java:51)
    at org.junit.internal.runners.JUnit4ClassRunner$1.run(JUnit4ClassRunner.java:44)
    at org.junit.internal.runners.ClassRoadie.runUnprotected(ClassRoadie.java:27)
    at org.junit.internal.runners.ClassRoadie.runProtected(ClassRoadie.java:37)
    at org.junit.internal.runners.JUnit4ClassRunner.run(JUnit4ClassRunner.java:42)
    at org.mockito.internal.runners.JUnit44RunnerImpl.run(JUnit44RunnerImpl.java:35)
    at org.mockito.runners.MockitoJUnitRunner.run(MockitoJUnitRunner.java:59)
    at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62)
    at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
    at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
    at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338)
    at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)

    shouldReturnNullWhenXmlTransformerThrowsException(com.acme.cmsweb.web.velocity.ContentRendererHelperImplTest) Time elapsed: 0.004 sec <<< FAILURE!
    Wanted but not invoked:
    appenderMock.doAppend();
    -> at com.acme.cmsweb.web.velocity.ContentRendererHelperImplTest.shouldReturnNullWhenXmlTransformerThrowsException(ContentRendererHelperImplTest.java:119)
    Actually, there were zero interactions with this mock.

    at com.acme.cmsweb.web.velocity.ContentRendererHelperImplTest.shouldReturnNullWhenXmlTransformerThrowsException(ContentRendererHelperImplTest.java:119)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.junit.internal.runners.TestMethod.invoke(TestMethod.java:59)
    at org.junit.internal.runners.MethodRoadie.runTestMethod(MethodRoadie.java:98)
    at org.junit.internal.runners.MethodRoadie$2.run(MethodRoadie.java:79)
    at org.junit.internal.runners.MethodRoadie.runBeforesThenTestThenAacmeers(MethodRoadie.java:87)
    at org.junit.internal.runners.MethodRoadie.runTest(MethodRoadie.java:77)
    at org.junit.internal.runners.MethodRoadie.run(MethodRoadie.java:42)
    at org.junit.internal.runners.JUnit4ClassRunner.invokeTestMethod(JUnit4ClassRunner.java:88)
    at org.junit.internal.runners.JUnit4ClassRunner.runMethods(JUnit4ClassRunner.java:51)
    at org.junit.internal.runners.JUnit4ClassRunner$1.run(JUnit4ClassRunner.java:44)
    at org.junit.internal.runners.ClassRoadie.runUnprotected(ClassRoadie.java:27)
    at org.junit.internal.runners.ClassRoadie.runProtected(ClassRoadie.java:37)
    at org.junit.internal.runners.JUnit4ClassRunner.run(JUnit4ClassRunner.java:42)
    at org.mockito.internal.runners.JUnit44RunnerImpl.run(JUnit44RunnerImpl.java:35)
    at org.mockito.runners.MockitoJUnitRunner.run(MockitoJUnitRunner.java:59)
    at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62)
    at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
    at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
    at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338)
    at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)

  3. If you use a log4j.xml file for your unit tests, you have to update the root logger level with the expected level.

    Otherwise you will have the following error :
    Actually, there were zero interactions with this mock.

  4. Pingback: Checking Logging in Unit Tests @ Autodidacticism

  5. Pingback: Testing logging behaviour sans Mockito « Slackhacker

  6. Pingback: Test log4j logging – add appender to root | Dawei's space

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

w

Connecting to %s