Log4j2 Mocking with Mockito and JUnit

Note: if you want to see how to intercept actual logging calls, then keep reading. If you want a quick and easy way to see what appears in logs that also go to System.out then there’s an easier, though less powerful, way.

Background

This is an update to the very helpful work done here.

I too have needed to put my own appender into a unit test so I can see that the right things are being logged. Depending on the logging framework you’re using, the ability to do that seems to vary greatly.

Here’s my solution, with some annotations to show how it works.

Note: after the release of a later version of LOG4J, this solution stopped working – there’s an update after this initial simple implementation.

import java.io.IOException;

import org.apache.logging.log4j.core.Appender;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.Logger;
import org.junit.After;
import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.mockito.ArgumentCaptor;
import org.mockito.Captor;
import org.mockito.Mock;
import org.mockito.runners.MockitoJUnitRunner;

import static org.junit.Assert.*;
import static org.mockito.Mockito.*;

/**
 * Tests that depend on being able to capture log output
 * Inspired by logging mocking on http://www.megster.net/2014/unit-testing-log4j-method-calls-with-junit-and-mockito
 *
 */
@RunWith(MockitoJUnitRunner.class)
public class ExceptionLoggerTest {
  @Mock
  private Appender mockAppender;

  @Captor
  private ArgumentCaptor<LogEvent> captorLoggingEvent;

  private Logger logger;

  @Before
  public void setup() {
    // prepare the appender so Log4j likes it
    when(mockAppender.getName()).thenReturn("MockAppender");
    when(mockAppender.isStarted()).thenReturn(true);
    when(mockAppender.isStopped()).thenReturn(false);

    logger = (Logger)LogManager.getLogger(ExceptionLogger.class);
    logger.addAppender(mockAppender);
    logger.setLevel(Level.INFO);
  }

  @After
  public void tearDown() {
    // the appender we added will sit in the singleton logger forever
    // slowing future things down - so remove it
    logger.removeAppender(mockAppender);
  }

  @Test
  public void loggingIsCaptured() {
    logger.error("What an error");
    verifyErrorMessages("What an error");
  }

  @Test
  public void noBleedBetweenLogCaptures() {
    logger.error("What an oopsie");
    verifyErrorMessages("What an oopsie");
  }

  @Test
  public void nothingLogged() {
    verifyErrorMessages();
  }

  // handy function to inspect the messages sent to the logger
  private void verifyErrorMessages(String ... messages) {
    verify(mockAppender, times(messages.length))
      .append(captorLoggingEvent.capture());

    int i=0;
    for(LogEvent loggingEvent:captorLoggingEvent.getAllValues()) {
      assertEquals(messages[i++], 
        loggingEvent.getMessage().getFormattedMessage());
    }
  }
}

Big thanks to the original poster for setting me in the right direction and for this article on StackOverflow explaining how to hack into LOG4J2 at runtime to put appenders in.

So How Did It Stop Working?

At some point log4j in their wisdom started using mutable objects to represent logging events. This probably is the flyweight pattern in action and is not a bad thing unless you’re using Mockito to remember all the invocation parameters, in which case mutable objects suck.

So, rather than use ArgumentCaptor on Mockito Mocks, there are two options:

1. Create a handmade mock for the Appender – I’ve done this and it’s easy and works – follow the things I mocked in the above example to make your own behave correctly with log4j
2. Use a Mockito Answer to capture the inbound logging events

In either case, you need to take a copy of the log event, not the reference to the mutable one. LogEvent.toImmutable is the solution

Here’s a possible annotated solution in Java 8:

// imports as before

@RunWith(MockitoJUnitRunner.class)
public class ExceptionLoggerTest {
  @Mock
  private Appender mockAppender;

  private List<LogEvent> capturedEvents = new ArrayList<>();

  private Logger logger;

  @Before
  public void setup() {
    // prepare the appender so Log4j likes it
    when(mockAppender.getName()).thenReturn("MockAppender");
    when(mockAppender.isStarted()).thenReturn(true);
    when(mockAppender.isStopped()).thenReturn(false);

    // when append is called, convert the event to 
    // immutable and add it to the event list
    doAnswer(answerVoid((LogEvent event) -> 
                 capturedEvents.add(event.toImmutable()))
      .when(mockAppender).append(any());

    logger = (Logger)LogManager.getLogger(ExceptionLogger.class);
    logger.addAppender(mockAppender);
    logger.setLevel(Level.INFO);
  }

  @After /** as before */

  @Test
  public void loggingIsCaptured() {
    logger.error("What an error");
    verifyErrorMessages("What an error");
  }

  // inspecting messages involves just using the list of captured events
  private void verifyErrorMessages(String ... messages) {
    assertThat(capturedEvents.size(), is(messages.length));

    int i=0;
    for(LogEvent loggingEvent:capturedEvents) {
      assertEquals(messages[i++], 
        loggingEvent.getMessage().getFormattedMessage());
    }
  }
}

Advertisement