Not Waving But …

I do hate it when I’ve been dense. I hate it even more when I have been smugly dense.

I have always had a thing about applications producing to much logging. Generally a production log line should only be produced if it is needed. That is if someone is going to look at it and take action on it or it is going to be part of an audit trail of some kind. I get quite worked up about the issue (a developer on my team once deployed an application that produced several Gigabytes of logging a day; “just in case”.)

Anyway, a couple of days ago, I had just related to Steve Freeman that in another project a previous developer had developed a rather byzantine Java logging framework that required a logging API to be passed in to all classes. I was sitting back waiting for the inevitable “yeah, what an idiot” response when Steve actually said “sounds like a good idea”.

Huh?

“Well”, continued Steve [this is from memory], “passing in the API allows you to test the log output of the class and, as logging is part of the class API it should be tested. If it is important that that line is produced you should test it. If it isn’t then you shouldn’t produce it.”

DOH! There we are, very succinct and to the point. If your production system produces it you should test it. Completely obvious in retrospect, and it may help solve the over logging problem most teams seem to have too.

I still don’t like passing around logging interfaces so the below should help test log lines in a log4j world. It only works for log4j under Java 5+ but shouldn’t be hard to retrofit to pre Java 5 and other log frameworks. You could make it more “Mocky” if you want.
It comes unwarranted as fit for any purpose, it is not thread safe, it won’t play well with existing logging configuration and I’m sorry about the formatting (I haven’t found a lightweight way of doing pretty code in Wordpress yet.) but hey, you get what you pay for.

LogRecorder.java

import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.Level;
import org.apache.log4j.PropertyConfigurator;
import org.apache.log4j.spi.LoggingEvent;

import java.util.ArrayList;
import java.util.List;
import java.util.Properties;

/**
* The responsibility of this class is to hook into the logging framework, capture
* messages written to the logger and make them available to a test.
*

* The logging framework instantiates its own appender skeleton so the LogRecorder
* stores the LoggingEvents in a singleton (static) list.
*/
public class LogRecorder extends AppenderSkeleton {
private static List logEvents = new ArrayList();protected void append(LoggingEvent event) {
if (Level.DEBUG_INT < event.getLevel().toInt()) { // Do not record debug lines
logEvents.add(event);
}
}

public void close() {
}

public boolean requiresLayout() {
return false;
}

public static List getLoggedEvents() {
return logEvents;
}

/**
* This should be called in the setUp / @BeforeMethod method
*/
public static void setupLogging() {
logEvents.clear();

Properties logProps = new Properties();

logProps.put("log4j.appender.RECORDER", "LogRecorder");
logProps.put("log4j.rootCategory", "DEBUG, RECORDER");

PropertyConfigurator.configure(logProps);
}
}
LoggingTest.java

import org.apache.log4j.Logger;
import org.apache.log4j.Level;
import org.apache.log4j.spi.LoggingEvent;
import org.testng.Assert;
import org.testng.annotations.BeforeMethod;
import org.testng.annotations.Test;

import java.util.List;

public class LoggingTest {
private List loggedEvents;

@BeforeMethod
public void setUp() {
LogRecorder.setupLogging();
loggedEvents = LogRecorder.getLoggedEvents();
}

@Test
public void testLogInfo() {
LoggedClass logged = new LoggedClass();
logged.infoLog(”test”);
Assert.assertEquals(Level.INFO, loggedEvents.get(0).getLevel());
Assert.assertEquals(”test”, loggedEvents.get(0).getMessage());
}

@Test
public void testLogMultiple() {
LoggedClass logged = new LoggedClass();
logged.debugLog(”debug line”);
logged.infoLog(”info line”);
logged.warnLog(”warn line”);
Assert.assertEquals(2, loggedEvents.size());
Assert.assertEquals(Level.INFO, loggedEvents.get(0).getLevel());
Assert.assertEquals(”info line”, loggedEvents.get(0).getMessage());
Assert.assertEquals(Level.WARN, loggedEvents.get(1).getLevel());
Assert.assertEquals(”warn line”, loggedEvents.get(1).getMessage());
}

@Test
public void testDoNotLogDebug() {
LoggedClass logged = new LoggedClass();
logged.debugLog(”test”);
assert loggedEvents.isEmpty();
}

@Test
public void testLoggingException() {
LoggedClass logged = new LoggedClass();
logged.throwException();
Assert.assertEquals(Level.WARN, loggedEvents.get(0).getLevel());
Assert.assertEquals(”Exception”, ((Exception)loggedEvents.get(0).getMessage()).getLocalizedMessage());
}
}

class LoggedClass {
public static Logger log = Logger.getLogger(LoggedClass.class);

public void warnLog(String msg) {
log.warn(msg);
}

public void infoLog(String msg) {
log.info(msg);
}

public void debugLog(String msg) {
log.debug(msg);
}

public void throwException() {
Exception e = new Exception(”Exception”);
log.warn(e);
}
}

This entry was posted on Sunday, February 4th, 2007 at 1:54 pm and is filed under Software Development, Process, Java. You can follow any responses to this entry through the RSS 2.0 feed. Both comments and pings are currently closed.