JAW Speak

Jonathan Andrew Wolter

Archive for the ‘operations’ tag

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.

Written by Jonathan

June 21st, 2009 at 8:17 pm

Posted in code, java, testability

Tagged with , ,