Thursday, April 16, 2015

LoggerRule: Easy verifying of logging events in jUnit tests with Mockito

Testing logging behavior is a contradictory topic among developers and personally I barely came to a situation where I found it useful. Today however, while I was writing a console application, I came to a situation where specific exceptions shouldn't stop the processing but be logged instead. I didn't have an option to verify the exceptional cases with tests other than effectively verifying if the Exception had been sent to the Logger. After some googling I landed on the Slackhacker's article: Testing logging behaviour in four code lines flat which described exactly what I was looking for:
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.verify;
public class FooTest {
    private Appender appenderMock;
    @Before
    public void setupAppender() {
        appenderMock = mock(Appender.class);
        Logger.getRootLogger().addAppender(appenderMock);
    }
    @After
    public void removeAppender() {
        Logger.getRootLogger().removeAppender(appenderMock);
    }
    @Test
    public void testMethod()  {
        doStuffThatCausesLogging();
        verify(appenderMock).doAppend((LoggingEvent) anyObject());
    }
}
With this code it's really "surprisingly easy to accomplish" this task (thanks Slackhacker!), however I was struggling to agree on the statement that it only requires "four code lines". I didn't like the @Before and @After methods required and the verify line is not strong enough if there are other logging actions in your test case. Considering the necessary boiler plate code for the additional methods and the ArgumentCaptors, we already need much more lines than the promised four.

As I looked at the before and after methods, the first thing that came to my mind to generalize this was using a jUnit rule which at the end resulted in the following class:
import static org.mockito.Mockito.*;

import org.apache.log4j.Appender;
import org.apache.log4j.Logger;
import org.junit.rules.MethodRule;
import org.junit.runners.model.FrameworkMethod;
import org.junit.runners.model.Statement;

public class LoggerRule extends Statement implements MethodRule {

  private Statement base;
  private Appender appender;

  @Override
  public Statement apply(final Statement base, final FrameworkMethod method, final Object target) {
    this.base = base;
    return this;
  }

  @Override
  public void evaluate() throws Throwable {
    appender = mock(Appender.class);
    Logger.getRootLogger().addAppender(appender);
    try {
      base.evaluate();
    } finally {
      Logger.getRootLogger().removeAppender(appender);
    }
  }

  public Appender getAppenderMock() {
    return appender;
  }
}
The usage of the rule would then be as follows:
public class MyLoggingTest {

  @Rule
  public LoggerRule loggerRule = new LoggerRule();

  @Test
  public void myTestMethod() throws Exception {
    doStuffThatCausesLogging();
    final ArgumentCaptor<LoggingEvent> arguments = ArgumentCaptor.forClass(LoggingEvent.class);
    verify(loggerRule.getAppenderMock()).doAppend(arguments.capture());
    assertThat(arguments.getValue().getLevel(), is(Level.WARN));
  }

}

Using some guava utilities, we can add the following methods to the rule to simplify the verifying:

  public LoggingEvent verifyLoggingEvent() {
    final ArgumentCaptor<LoggingEvent> captor = ArgumentCaptor.forClass(LoggingEvent.class);
    verify(appender).doAppend(captor.capture());
    return captor.getValue();
  }

  public LoggingEvent verifyLoggingEventWithLevel(final Level level) {
    final ArgumentCaptor<LoggingEvent> captor = verifyLoggingEvents();
    final LoggingEvent event = Iterables.find(captor.getAllValues(), levelEquals(level), null);
    assertNotNull("No LoggingEvent found for level " + level, event);
    return event;
  }

  public ArgumentCaptor<LoggingEvent> verifyLoggingEvents() {
    final ArgumentCaptor<LoggingEvent> captor = ArgumentCaptor.forClass(LoggingEvent.class);
    verify(appender, atLeast(1)).doAppend(captor.capture());
    return captor;
  }

  public List<LoggingEvent> verifyLoggingEventsWithLevel(final Level level) {
    final ArgumentCaptor<LoggingEvent> captor = verifyLoggingEvents();
    return ImmutableList.copyOf(Iterables.filter(captor.getAllValues(), levelEquals(level)));
  }

  private Predicate<LoggingEvent> levelEquals(final Level level) {
    return new Predicate<LoggingEvent>() {

      @Override
      public boolean apply(final LoggingEvent input) {
        return level.equals(input.getLevel());
      }
    };
  }

Using these methods, verifying becomes just a charm:

public class MyLoggingTest {

  @Rule
  public LoggerRule loggerRule = new LoggerRule();

  private Exception expectedException;

  @Test
  public void myTestMethod() throws Exception {
    doStuffThatCausesLogging();
    // same example as above:
    loggerRule.verifyLoggingEventWithLevel(Level.WARN);
    // assert logged Exception
    final LoggingEvent errorLogEvent = loggerRule.verifyLoggingEventWithLevel(Level.ERROR);
    assertEquals(expectedException, errorLogEvent.getThrowableInformation().getThrowable());
  }

}

I don't know how soon I will need this again, but now I have it just in case... :)

No comments:

Post a Comment