JAW Speak

Jonathan Andrew Wolter

Test Driven log4j Logging Code Example

with 3 comments

Reading time: 3 – 4 minutes

Update: Added a snippet so that you can easily assert a message was contained in the logged messages.

Frequently logging is not viewed as “important” by engineers as, say, the logic for refunding a customer’s purchase. The customer’s won’t mind, after all, if we forget to log something right? Maybe so, until there are problems and the operational team supporting your application has very little ability to diagnose problems.

I propose logging should be viewed as another user interface, and thus needs its’ own set of acceptance and unit tests. This makes for more tedious and up front work for development teams — however I want to survive in production without a pager going off, and with fewer late night scrambles to ship patches.

Imagine a class that has logic associated with logging. Below you will see a unit test verifying logging statements are correct. Often logging uses statics, and as Misko has said, statics are a death to testabilty. With Guice you can easily inject loggers automatically for the class under construction. This method gets around most of the issues with static loggers, although I still despise statics everywhere.

This is a basic example, but the point is to understand how to hook into appenders and add/change one to use a test appender.

package com.jawspeak.common.testing;
 
import com.google.common.collect.Lists;
import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.spi.LoggingEvent;
 
import java.util.List;
 
/**
* Use me for spying on test logs and making asserts against them.
*
* Example how to use:
*        final SpyLoggerAppenderForTesting spyAppender = new SpyAppenderForTesting();
*        final Logger logger = Logger.getLogger(MyClass.class.getName());
*        try {
*            logger.addAppender(spyAppender);
*            // do something
*            assertEquals(Lists.newArrayList("Attempted to read such-and-such, but could not: oops"), spyAppender.getMessagesLogged());
*        } finally {
*            logger.removeAppender(spyAppender); // clean up global state
*        }
*/
public class SpyLoggingAppenderForTesting extends AppenderSkeleton {
  private List messages = Lists.newArrayList();
 
  protected void append(LoggingEvent loggingEvent) {
    messages.add(loggingEvent.getRenderedMessage());
  }
 
  public List getMessagesLogged() {
    return messages;
  }
 
  public boolean doMessagesContain(String snippet) {
      boolean isFound = false;
      for (String message : messages) {
          if (message.indexOf(snippet) >= 0) {
              isFound = true;
          }
      }
      return isFound;
  }
 
  public void close() { }
  public boolean requiresLayout() { return false; }
}

Here’s an example test where we make use of it. Note that we didn’t assert the lists are exactly the same, because in this project we were also using aspects to do logging, and depending on if you ran with or without the aspects enabled, a different number of logging messages would be created.

package com.jawspeak.common.utility;
 
import com.google.common.collect.Maps;
import com.jawspeak.common.testing.SpyLoggingAppenderForTesting;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.junit.After;
import static org.junit.Assert.*;
import org.junit.Before;
import org.junit.Test;
 
import java.util.LinkedHashMap;
import java.util.List;
 
public class SessionSizeLoggingTest {
private SpyLoggingAppenderForTesting spyAppender = new SpyLoggingAppenderForTesting();
private Logger logger = Logger.getLogger(SessionSizeLoggingTest.class.getName());
private Level oldLoggingLevel = logger.getLevel();
private SessionSizeLogging sessionSizeLogging = new SessionSizeLogging();
 
  @Before
  public void setUp() {
    logger.addAppender(spyAppender);
    logger.setLevel(Level.TRACE); // set the level in case a log4j.properties or log4j.xml disables this level of logging
  }
 
  @After
  public void tearDown() {
    logger.setLevel(oldLoggingLevel);
    logger.removeAppender(spyAppender);
  }
 
  @Test
  public void logBytesWhenUnprintable() throws Exception {
    LinkedHashMap map = Maps.newLinkedHashMap();
    map.put("key", new String(new byte[] { 1, 31, 127, -97}, "ISO-8859-1"));
    String sessionId = "abc123";
    sessionSizeLogging.logSessionSize(logger, sessionId, map);
    List messagesLogged = spyAppender.getMessagesLogged();
    assertTrue(spyAppender.doMessagesContain("Session Size for session id: " + sessionId + " (approx. total " + (7 + 3 + 1 + 4 + 1) + " bytes)"));
     // or use
    assertTrue(messagesLogged.contains("  key[   3 bytes]                            key  -->  value[   4 bytes] '\\u0001\\u0031\\u0127\\u0159'"));
  }
 
  // .. many more tests
}

This is a trick that I don’t see written about too much, but I recommend it often. And, I’d love to have some readers post enhancements, links, and take testability further with respect to logging.

Bookmark and Share

Written by Jonathan

June 21st, 2009 at 8:17 pm

Posted in code, java, testability

Tagged with , ,

3 Responses to 'Test Driven log4j Logging Code Example'

Subscribe to comments with RSS or TrackBack to 'Test Driven log4j Logging Code Example'.

  1. hi,

    I wonder, why you just didn’t mock the logger. Afterwards you would check whether some collaborations appeared, Mockito.verify(mockLogger).info(Session Size for session id: + sessionId + (approx. total + (7 + 3 + 1 + 4 + 1) + bytes)). I do like this when I have to test some logging. Can you provide cons & prons in those two approaches?

    cheers

    lucas

    20 Dec 09 at 7:58 am

  2. I was doing this trick first in a codebase that didn’t have mockito. (Thus mocking was more verbose, and less friendly).

    Pre-Mockito, I avoided Mocks and built my own test doubles where I could. This way I didn’t have my tests tied to the api-calls of the mocked object, but just made assertions-about-state. This generally meant one up front cost to build the test double (i.e. this one, or an InMemoryRepository, etc.), and then very small incremental costs to use this new test collaborator.

    I still do this in Post-Mockito codebases. Recently I was writing some classpath repository mocking code. It was verbose, and required repeating frequently as boilerplate everywhere I wanted to set up this mock test double. Even when refactored into a parametrized method call, I didn’t like it. Too hard to see the important interactions in my test. So I re-wrote a test double that I only could make state assertions on at the end. Much better, imho.

    Jonathan

    20 Dec 09 at 11:20 am

  3. Hi guys,

    Since your comments where excellent pointers.
    Let me share the following snippet:


    private Appender mockAppender;

    @Before
    public void setupMocksAndTestee() {
    mockAppender = Mockito.mock(AppenderSkeleton.class);
    Logger logger = Logger.getLogger(testee.getClass());
    logger.addAppender(mockAppender);
    logger.setLevel(Level.INFO);
    }

    @Test
    public void infoLogEventReceived() {
    testee.doSomething();

    ArgumentCaptor loggingEventCaptor = ArgumentCaptor.forClass(LoggingEvent.class);
    verify(mockAppender).doAppend(loggingEventCaptor.capture());

    LoggingEvent loggingEvent = loggingEventCaptor.getValue();
    assertEquals(“Expected info log message.”, loggingEvent.getRenderedMessage());
    assertEquals(Level.INFO, loggingEvent.getLevel());
    }

    Grunx

    3 Aug 11 at 2:01 pm

Leave a Reply