logback Archives

We have been using TestNG to run our tests for a while now. When we initially started, our code was written using Log4J and we were able to configure it to log all the tests to a single file. This made the logs very unwieldy and looking for issues very difficult. Looking at 100+ MB of logs isn’t an easy task. Changing this to rolling files only made the matters worse. So, I started looking for ways to log each test case into a separate file (meaning a test named foo, would be logged to foo.log).

My first attempt was to do this using log4j itself. Log4J doesn’t provide an easy way of doing this. It’s possible if you follow certain conventions in declaring your loggers and how you use MDC, but I wasn’t able to get it working with all my code. On looking a bit further, I found Logback. And SiftingAppender in Logback is just what I needed.

So, using slf4j, logback, MDC and a few simple coding conventions, I was able to get per test log files working. Here’s what you need to do:

Start using SLF4J for your logging. If you are using Log4J, moving from L0g4J to SLF4J is pretty simple
Write functions to set MDC at start of a test and unset it at the end of a test
Update the test cases, such that the MDC set/unset functions are invoked
Configure logback.xml to use the SiftingAppender

I’ll expand a bit more on the above.

Using SLF4J

Starting to use SLF4J or moving to SLF4J from other logging frameworks is pretty straightforward. I didn’t bother using the java application at http://www.slf4j.org/migrator.html and found it much easier to just to regex to do the job. There were some places where log.xxx(object) had to be changed to log.xxx(object.toString()) but that wasn’t a whole lot of pain.

Code to set/unset MDC

Logback’s documentation on MDC is very extensive and explains the concept quite clearly. Essentially using MDC would allow us to share a key/value across a thread hierarchy. Using MDC is as simple as putting a key/value into a Map. This value will be accessible anytime in the thread and any children of that thread. At the beginning of the test, we’ll put <"testname", $test_case_name> as the key/value into the map. At the end of the test, we’ll remove this key. This MDC value would be used by the sifting appender to create logs at runtime. I wrote a simple class to encapsulate this functionality:

package com.nm.examples;
 
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
 
/**
 * Class to handle setting/removing MDC on per test case basis. This helps
 * us log each test case into it's own log file. Please see
 * {@link http://logback.qos.ch/manual/appenders.html#SiftingAppender}
 * and {@link http://logback.qos.ch/manual/mdc.html}
 * @author nullin
 */
public class TestLogHelper
{
  private static final Logger log = LoggerFactory.getLogger(TestLogHelper.class);
  public static final String TEST_NAME = "testname";
 
  /**
   * Adds the test name to MDC so that sift appender can use it and log the new
   * log events to a different file
   * @param name name of the new log file
   * @throws Exception
   */
  public static void startTestLogging(String name) throws Exception {
    MDC.put(TEST_NAME, name);
  }
 
  /**
   * Removes the key (log file name) from MDC
   * @return name of the log file, if one existed in MDC
   */
  public static String stopTestLogging() {
    String name = MDC.get(TEST_NAME);
    MDC.remove(TEST_NAME);
    return name;
  }
}

Update test cases

Now, you just need to make sure that you invoke TestLogHelper.startTestLogging(String testname) as early as possible during the test execution. Eventually, by the end of the test you should invoke TestLogHelper.stopTestLogging() to ensure that no extra logs get logged into this log file.

As we are using TestNG, for us it was a very simple matter of creating a method annotated @BeforeClass or @BeforeMethod as per requirements and put this code in there. For example, I use the following two methods in the base class for all our tests:

   @BeforeClass
   public void testSetUp() throws Exception {
      //start logging to test specific log file
      TestLogHelper.startTestLogging(getTestId());
 
      //
      //Do some setup specific stuff here
      //
   }
 
   @AfterClass
   public void testCleanUp() throws Exception {
      try {
         //
         //Do some cleanup specific stuff here
         //
      } finally {
         //stop test logging to test specific file
         TestLogHelper.stopTestLogging();
      }
      return true;
   }
 
   public String getTestId() {
      return ((testId == null) ? (this.getClass().getName()) : testId);
   }

Configure logback.xml with SiftingAppender

The last part is to configure the logback.xml to use a SiftingAppender. You can look at the documentation for SiftingAppender to see the different examples. Following is a snippet of the configuration that I am using:

   <appender name="RootSiftAppender" class="ch.qos.logback.classic.sift.SiftingAppender">
      <discriminator>
         <Key><strong>testname</strong></Key>
         <DefaultValue><strong>testrun</strong></DefaultValue>
      </discriminator>
      <sift>
         <appender name="FILE-${testname}" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <File>${testname}.log</File>
            <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
               <FileNamePattern><strong>${testname}.%i.log</strong></FileNamePattern>
               <MinIndex>1</MinIndex>
               <MaxIndex>100</MaxIndex>
            </rollingPolicy>
            <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
               <MaxFileSize>5MB</MaxFileSize>
            </triggeringPolicy>
            <layout class="ch.qos.logback.classic.PatternLayout">
               <Pattern>%d{ISO8601} %-5level %C{1} [%M:%L] [%thread] - %msg%n</Pattern>
            </layout>
         </appender>
      </sift>
   </appender>

This configuration says that the test cases would specify the MDC value using a key “testname” and if logback finds no such key, it’ll just log the statements into testrun.log.

And that’s it. You should be good to go.

Tag: logback

Logging tests to separate files

Using SLF4J

Code to set/unset MDC

Update test cases

Configure logback.xml with SiftingAppender