When writing JUnit tests developers often add log statements that can help provide information on test failures. During the initial attempt to find a failure a simple System.out.println() statement is usually the first resort of most developers.

Replacing these System.out.println() statements with log statements is the first improvement on this technique. Using SLF4J (Simple Logging Facade for Java) provides some neat improvements using parameterized messages. Combining SLF4J with JUnit 4 rule implementations can provide more efficient test class logging techniques.

Some examples will help to illustrate how SLF4J and JUnit 4 rule implementation offers improved test logging techniques. As mentioned the inital solution by developers is to use System.out.println() statements. The simple example code below shows this method.

01    import org.junit.Test;
02
03    public class LoggingTest {
04
05      @Test
06      public void testA() {
07        System.out.println(“testA being run…”);
08      }
09
10      @Test
11      public void testB() {
12        System.out.println(“testB being run…”);
13      }
14    }

The obvious improvement here is to use logging statements rather than the System.out.println() statements. Using SLF4J enables us to do this simply whilst allowing the end user to plug in their desired logging framework at deployment time. Replacing the System.out.println() statements with SLF4J log statements directly results in the following code.
view source

01    import org.junit.Test;
02    import org.slf4j.Logger;
03    import org.slf4j.LoggerFactory;
04
05    public class LoggingTest {
06
07      final Logger logger =
08        LoggerFactory.getLogger(LoggingTest.class);
09
10      @Test
11      public void testA() {
12        logger.info(“testA being run…”);
13      }
14
15      @Test
16      public void testB() {
17        logger.info(“testB being run…”);
18      }
19    }

Looking at the code it feels that the hard coded method name in the log statements would be better obtained using the @Rule TestName JUnit 4 class. This Rule makes the test name available inside method blocks. Replacing the hard coded string value with the TestName rule implementation results in the following updated code.

01    import org.junit.Rule;
02    import org.junit.Test;
03    import org.junit.rules.TestName;
04    import org.slf4j.Logger;
05    import org.slf4j.LoggerFactory;
06
07    public class LoggingTest {
08
09      @Rule public TestName name = new TestName();
10
11      final Logger logger =
12        LoggerFactory.getLogger(LoggingTest.class);
13
14      @Test
15      public void testA() {
16        logger.info(name.getMethodName() + ” being run…”);
17      }
18
19      @Test
20      public void testB() {
21        logger.info(name.getMethodName() + ” being run…”);
22      }
23    }

SLF4J offers an improved method to the log statement in the example above which provides faster logging. Use of parameterized messages enable SLF4J to evaluate whether or not to log the message at all. The message parameters will only be resolved if the message will be logged. According to the SLF4J manual this can provide an improvement of a factor of at least 30, in case of a disabled logging statement.

Updating the code to use SLF4J parameterized messages results in the following code.

01    import org.junit.Rule;
02    import org.junit.Test;
03    import org.junit.rules.TestName;
04    import org.slf4j.Logger;
05    import org.slf4j.LoggerFactory;
06
07    public class LoggingTest {
08
09      @Rule public TestName name = new TestName();
10
11      final Logger logger =
12        LoggerFactory.getLogger(LoggingTest.class);
13
14      @Test
15      public void testA() {
16        logger.info(“{} being run…”, name.getMethodName());
17      }
18
19      @Test
20      public void testB() {
21        logger.info(“{} being run…”, name.getMethodName());  }
22      }
23    }

Quite clearly the logging statements in this code don’t conform to the DRY principle.

Another JUnit 4 Rule implementation enables us to correct this issue. Using the TestWatchman we are able to create an implementation that overrides the starting(FrameworkMethod method) to provide the same functionality whilst maintaining the DRY principle. The TestWatchman Rule also enables developers to override methods invoked when the test finishes, fails or succeeds.

Using the TestWatchman Rule results in the following code.

01    import org.junit.Rule;
02    import org.junit.Test;
03    import org.junit.rules.MethodRule;
04    import org.junit.rules.TestWatchman;
05    import org.junit.runners.model.FrameworkMethod;
06    import org.slf4j.Logger;
07    import org.slf4j.LoggerFactory;
08
09    public class LoggingTest {
10
11      @Rule public MethodRule watchman = new TestWatchman() {
12        public void starting(FrameworkMethod method) {
13          logger.info(“{} being run…”, method.getName());
14        }
15      };
16
17      final Logger logger =
18        LoggerFactory.getLogger(LoggingTest.class);
19
20      @Test
21      public void testA() {
22
23      }
24
25      @Test
26      public void testB() {
27
28      }
29    }

And there you have it. A nice test code logging technique using JUnit 4 rules taking advantage of SLF4J parameterized messages.

I would be interested to hear from anyone using this or similar techniques based on JUnit 4 rules and SLF4J.

Reference: http://www.catosplace.net/