Chatty unit tests

June 27, 2007. Tags [ commons-logging, JUnit, logging, unit test ]

Did I mention this blog is going to be a bit stream-of-consciousness, hopping around from topic to topic? Anyway, wanted to talk today about “chatty” unit tests–unit tests which produce logging output when they run. Most of the time this is due to logging statements from the class under test. Now, most of our Java classes use commons-logging in the following fashion:

public class Thing {
  private static final Log logger =
    LogFactory.getLog(Thing.class);
  // ...
}

This makes sure there’s one logger per class (not per object), which is usually what you want, so that you can control logging (particularly at runtime) on a whole package basis. However, now when you run unit tests against Thing, it might spew out a bunch of log messages (particularly if those messages are at the INFO level, or if you log exceptions to ERROR (you are testing the exception cases in your unit tests, right?)). This not only scrolls a bunch of stuff on the screen you probably don’t care about (especially if it’s for tests that pass), but it also slows your unit tests down with I/O. So, a simple solution is to code it like this:

public class Thing {
  private static final Log defaultLogger =
    LogFactory.getLog(Thing.class);
  private Log logger;
  public Thing() {
    this.logger = defaultLogger;
  }
  public Thing(Log logger) {
    this.logger = logger;
  }
  // ...
}

Now, most of the time your class will behave as before, especially in a Spring/Hibernate world where everything is expected to have a default constructor. However, now in your unit tests you can either:

public void setUp() {
     Log mockLog = EasyMock.createMock(Log.class);
     Thing thing = new Thing(mockLog);
}

especially if you want to actually test the logging. Or, if you just want the unit test to “shut up” while you run it:

public void setUp() {
    Log nullLog = new org.apache.commons.logging.impl.NoOpLog();
    Thing thing = new Thing(nullLog);
}

Note that if a unit test breaks, you can always come back in to setUp and change the call to instantiate the Thing under test to use the default constructor again (and thus bring back more verbose logging).