Log4j2 Mocking with Mockito and JUnit

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<span 				data-mce-type="bookmark" 				id="mce_SELREST_start" 				data-mce-style="overflow:hidden;line-height:0" 				style="overflow:hidden;line-height:0" 			></span>
	private void verifyErrorMessages(String ... messages) {
		assertThat(capturedEvents.size(), is(messages.length));

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

5 comments

  1. There is no addAppender() method in Logger interface. You have to do that by LogManager. What if I have custom Converter for Masking and i have to create log4j2.xml, how should i name this mocked appender?

    • The version of Logger used in this solution does have that method. Different logging frameworks and versions have different APIs. In our project we had more than one version of log4j and also sl4j. The dependency you need for this logging to work is:

      		  <dependency>
      			<groupId>org.apache.logging.log4j</groupId>
      			<artifactId>log4j-core</artifactId>
      			<version>2.2</version>
      		  </dependency>
      
    • Way late, but just in case it helps someone:

      The reason Ashley’s code works is because he’s casting the Logger *interface* returned by the log manager to the Logger *class* (from the org.apache.logging.log4j.core package). Looking through the source code, that seems currently safe because LogManager always returns a core.Logger or core.AsyncLogger, which is derived from core.Logger.

      Of course, this could break in the future but it works for now, and it’s way simpler than the recommended way at https://logging.apache.org/log4j/2.x/manual/customconfig.html#AddingToCurrent.

  2. Thanks for the post, exactly what I was looking for!

    FYI – Line 31 contains html entities for the less than and greater than symbols.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s