Testing and Handling Logging in Java

Logging is a great way to communicate the systems past steps and state for debugging. Often, they are the last resort to get an idea about what is happening in a remote system.
But, not all is shiny. Usually, the log entries are printed onto the console and to a file. The later one is no problem, however, the first one can be a pain point.
How? Assuming you have an application with a good suit of unit tests. Say a couple of hundreds so that the output of running the tests does not fit on one screen any more. Now, when you run the tests, you get a few lines for each test and a bunch of logging informations. This is called noise. It gets even worse if the output is laced with exception stack traces. Sure, there are cases were you want to test error conditions and those will cause exceptions in return. However, consider yourself new to a team and you just setup a new sandbox, a good corporate citizen as you are, you run all the tests before you pick up your first user story to work on. But, what is this? The screen is scattered with exceptions in the test output. I would be scared and would assume that I did something wrong during setup. The noise drowns out the real state of the system -- a build system should communicate the health of the system in a unambiguous way. This is a risk which can be avoided easily.

Logging -- which was added to Java 1.4 -- allows you to add a filter. With that filter you can intercept and decide which logs to actually log.
Also, you have to make sure to use the same logger as the one you want to suppress. Just use the same string as identifier for both. I usually use the name of the class from the class object itself.

Logger LOG = Logger.getLogger(Example.class.getName());

once you have the logger instance, you add a filter which deals with the log record and suppresses its logging.

logger.setFilter(new Filter()
{
 public boolean isLoggable(LogRecord logRecord) {
   if (logRecord.getLevel().intValue() == Level.SEVERE.intValue()) {
        // deal with log record
   }
   return false; // suppress logging  }
});

Here the code for a small Example

public class Example {
  private static final Logger LOG = Logger.getLogger(Example.class.getName());
  public void foo() {
    LOG.info("entering");
    try {
      willFail();
    } catch (Exception e) {
      LOG.logp(Level.SEVERE, Example.class.getName(),
               "foo", "something bad happened", e);
    }
    LOG.info("exiting");
  } 
  private void willFail() throws Exception {
    throw new Exception("ERROR MSG");
  }
}

And here the matching test

public class ExamleTest extends TestCase {
  private Example example;
  private Logger logger;
  private List logRecords;

 protected void setUp() throws Exception {
   example = new Example();
   logger = Logger.getLogger(Example.class.getName());
   logRecords = new ArrayList();
 }

 public void testFooLogsSevereIfFailure() {
   logger.setFilter(new Filter()
   {
     public boolean isLoggable(LogRecord logRecord) {
       if (logRecord.getLevel().intValue() == Level.SEVERE.intValue()) {
         logRecords.add(logRecord);
       }
       return false;
   }});

   example.foo();

   assertEquals(1, logRecords.size());
   assertEquals("something bad happened", logRecords.get(0).getMessage());
   assertEquals("ERROR MSG", logRecords.get(0).getThrown().getMessage());
 }

 public void testFooLogsEntryAndExit() {
   logger.setFilter(new Filter()
   {
     public boolean isLoggable(LogRecord logRecord) {
       if (logRecord.getLevel().intValue() == Level.INFO.intValue()) {
         logRecords.add(logRecord);
       }
       return false;
   }});

   example.foo();

   assertEquals(2, logRecords.size());
   assertEquals("entering", logRecords.get(0).getMessage());
   assertEquals("exiting", logRecords.get(1).getMessage());
 }
}

With this you remove the noise from running your tests as this

ExamleTest,testFooLogsSevereIfFailure
May 5, 2008 9:50:18 PM Example foo
INFO: entering
May 5, 2008 9:50:18 PM Example foo
SEVERE: something bad happened
java.lang.Exception: ERROR MSG
 at Example.willFail(Example.java:20)
 at Example.foo(Example.java:11)
 at ExamleTest.testFooLogsSevereIfFailure(ExamleTest.java:33)
 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:585)
 at junit.framework.TestCase.runTest(TestCase.java:164)
 at junit.framework.TestCase.runBare(TestCase.java:130)
 at junit.framework.TestResult$1.protect(TestResult.java:106)
 at junit.framework.TestResult.runProtected(TestResult.java:124)
 at junit.framework.TestResult.run(TestResult.java:109)
 at junit.framework.TestCase.run(TestCase.java:120)
 at junit.textui.TestRunner.doRun(TestRunner.java:121)
 at com.intellij.rt.execution.junit.IdeaTestRunner.doRun(IdeaTestRunner.java:65)
 at junit.textui.TestRunner.doRun(TestRunner.java:114)
 at com.intellij.rt.execution.junit.IdeaTestRunner.startRunnerWithArgs(IdeaTestRunner.java:24)
 at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:118)
 at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:40)
May 5, 2008 9:50:18 PM Example foo
INFO: exiting

Process finished with exit code 0

becomes that

Process finished with exit code 0

The second line shows you that the tests passed (exit code 0) with no errors. All you need to know. No noise!
Best of all, you now actually test a specific exception to be thrown if a certain condition occurs. So, if a fellow programmer removes the exception with or without intention you get at least a raised finger in form of a failing test. That should lead to a conversation which again makes sure that the situation is resolved accordingly. Agile is about communication!

Note: This applies only for the JDK logger. log4j does not feature a filter which can be modified at runtime. I haven't spent lots of time investigating, but as of now I did not discover a work around. Drop me a line if you figured that one out ;)