Tuesday, October 2, 2012

Logging Configuration for Testing

I realized this morning that putting the name of the test in the logging frameworks (log4j/slf4j) Mapped Diagnostic Context (MDC) gives great context to every logging statement. I'm not sure why I didn't do this before. Well, I've always had a different log4j (and now slf4j) configuration file sitting in src/test/java to change the level of local classes while executing tests. This configuration almost always goes to the console where the main code will log to a file.
This example uses log4j but slf4j has the same MDC class.
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
  <appender class="org.apache.log4j.ConsoleAppender" name="console">
    <param name="Target" value="System.out" />
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d{ISO8601} %X{testMethod} %-5p %c - %m%n" />;
    </layout>
  </appender>
  <root>
    <priority value="debug" />
    <appender ref="console" />
  </root>
</log4j:configuration>
Then, in Java, you'll need a custom TestWatchman that uses the same string 'testmethod' as seen above inside the french braces %X{testMethod}):
/**
 * This helpfull little thing works in concert with the log4j configuration.
 * There are two steps to it's use:
 * <ol>
 * <li>declare a Rule in your test: @Rule public TestNameMDC testNameMDC = new TestNameMDC();</li>
 * <li>include the %X in the log4j pattern: %X{testMethod}</li>
 * </ol>
 * Note that the 'testMethod' in french braces above must match the {@link #MDC_KEY} defined here.
 *
 */
public class TestNameMDC extends TestWatchman {

  private static final String MDC_KEY = "testMethod";

  @Override public void starting(FrameworkMethod method) {
    MDC.put(MDC_KEY, method.getName());
  }
 
  @Override public void finished(FrameworkMethod method) {
    MDC.remove(MDC_KEY);
  }

  public String getMethodName() {
    return (String)MDC.get(MDC_KEY);
  } 
}