The Art of Test Driven Development: Logging JUnit Test Results

JUnit saves your test results to a file (using XML, plain, brief or failure formatters). If you use Maven, you can convert these files into an HTML report easily. However, that means waiting for a build to complete. If you want to see your test results while a Maven or Ant build is running, you must watch the command line.

In an IDE like Eclipse, you can watch the JUnit view to see tests progress. Wouldn’t it be nice to be able to do whatever you want with tests results on the fly?

What we’ll show you here as an alternative is logging your test results while JUnit runs your tests. This gives you all the power of Log4j to direct test results all over the place, from a simple console, to a database, a JMS queue, or any of the long list of appenders Log4j provides. You can provide your own Log4j appender as well for custom processing.

The basic mechanism that lets us do this is JUnit’s TestWatcher rule. Let’s introduce the TestWatcher with a simple example that logs test results to a StringBuilder. The example dumps the builder’s contents on the console when the test finishes.

package com.garygregory.log4j;

import org.junit.AfterClass;
import org.junit.Assert;
import org.junit.Rule;
import org.junit.Test;
import org.junit.rules.TestWatcher;
import org.junit.runner.Description;

public class StringBuilderTestWatcherTest {
    private static final String EOL = 
        System.getProperty("line.separator");

    private static StringBuilder builder = new StringBuilder();

    @AfterClass
    public static void afterClass() {
        System.out.print(builder);
    }

    @Rule
    public TestWatcher watchman = new TestWatcher() {

        @Override
        protected void failed(Throwable e, Description description) {
            if (description != null) {
                builder.append(description);
            }
            if (e != null) {
                builder.append(' ');
                builder.append(e);
            }
            builder.append(" FAIL");
            builder.append(EOL);
        }

        @Override
        protected void succeeded(Description description) {
            if (description != null) {
                builder.append(description);
            }
            builder.append(" OK");
            builder.append(EOL);
        }
    };

    @Test
    public void testFails() {
        // test
        Assert.fail();
    }

    @Test
    public void testSucceeds() {
        // test
    }
}

In this example, the test class implements the TestWatcher rule directly. JUnit calls each method you annotate with @Test one after the next. JUnit calls the failed() method when a @Test method fails and gives it a description and an exception. JUnit calls the succeeded() method when a @Test method completes normally, no JUnit Assert calls failed, no unexpected exceptions.

The method afterClass() (annotated with JUnit’s @AfterClass) runs after all test methods have run and outputs the contents of the StringBuilder.

The console output is for the StringBuilder example is:

testSucceeds(com.garygregory.log4j.StringBuilderTestWatcherTest) OK
testFails(com.garygregory.log4j.StringBuilderTestWatcherTest) java.lang.AssertionError FAIL

It’s easy to imagine growing and morphing this StringBuilder implementation into all sorts of things: to write the results to a file, with your own format, or send results to a database, and so on.

Instead of going that way though, you should bridge to Log4j and reuse its powerful and rich feature set, which let’s you do all that and much more. The power of Log4j comes from the simplicity of its API combined with rich configurations you create in XML, JSON, or YAML. Log4j 2.4 also provides a programmatic configuration API, but that’s a separate topic.

To log our results to Log4j, we replace the StringBuilder with a Logger:

package com.garygregory.log4j;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.junit.Assert;
import org.junit.Rule;
import org.junit.Test;
import org.junit.rules.TestWatcher;
import org.junit.runner.Description;

public class Log4jTestWatcherTest {

    private static Logger logger = LogManager.getLogger();

    @Rule
    public TestWatcher watchman = new TestWatcher() {

        @Override
        protected void failed(Throwable e, Description description) {
            logger.error(description, e);
        }

        @Override
        protected void succeeded(Description description) {
            logger.info(description);
        }
    };

    @Test
    public void testFails() {
        // test
        Assert.fail();
    }

    @Test
    public void testSucceeds() {
        // test
    }
}

In this example, we still embed an implementation of TestWatcher in the test itself, but this time the methods call on its Logger. When a test fails, we log at the ERROR level, and when a test succeeds, we log at the INFO level.

The console output is for the Log4j example is:

2015-09-14 20:25:57,173 INFO [main][com.garygregory.log4j.Log4jTestWatcherTest] testSucceeds(com.garygregory.log4j.Log4jTestWatcherTest)
2015-09-14 20:25:57,175 ERROR [main][com.garygregory.log4j.Log4jTestWatcherTest] testFails(com.garygregory.log4j.Log4jTestWatcherTest)
java.lang.AssertionError
  at org.junit.Assert.fail(Assert.java:86)
  at org.junit.Assert.fail(Assert.java:95)
  at com.garygregory.log4j.Log4jTestWatcherTest.testFails(Log4jTestWatcherTest.java:32)

The next obvious step is to abstract this TestWatcher in a class:

package com.garygregory.log4j;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.junit.rules.TestWatcher;
import org.junit.runner.Description;

public class Log4jTestWatcher extends TestWatcher {

    private final Logger logger;

    public Log4jTestWatcher() {
        logger = LogManager.getLogger();
    }

    public Log4jTestWatcher(String loggerName) {
        logger = LogManager.getLogger(loggerName);
    }

    @Override
    protected void failed(Throwable e, Description description) {
        logger.error(description, e);
    }

    @Override
    protected void succeeded(Description description) {
        logger.info(description);
    }
}

And reuse it in the test:

package com.garygregory.log4j;

import org.junit.Assert;
import org.junit.Rule;
import org.junit.Test;
import org.junit.rules.TestWatcher;

public class Log4jTestWatcherTest2 {

    @Rule
    public TestWatcher watchman = new Log4jTestWatcher();

    @Test
    public void testFails() {
        // test
        Assert.fail();
    }

    @Test
    public void testSucceeds() {
        // test
    }
}

This is short and sweet, compare it to our first listing!

Boom! All the power of Log4j and JUnit combined.

Happy Coding,
Gary Gregory

Advertisements

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 )

Twitter picture

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

Facebook photo

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

Google+ photo

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

Connecting to %s