megster.net

Nathan Russell

Nathan Russell

Unit testing log4j method calls with jUnit and mockito

June 6, 2014, by admin, category java

Quite often we’ll write java code with an else or catch block, and will simply write a log4j logging statement within it. Consider the following method (deliberately simple and pointless for the purpose of this post)


public List<String> addToListIfSizeIsUnder3(final List<String> list, final String value) {
    if (list == null) {
        LOGGER.error("A null list was passed in");
        return null;
    }
    if (list.size() < 3) {
        list.add(value);
    } else {
        LOGGER.debug("The list already has {} entries", list.size());
    }
    return list;
}

Writing a set of unit tests for this method should be pretty easy – we can call the method passing in a null list and assert we get a null back, we can pass in a list with less than 2 elements and assert we get a a list with 1 more element, and we can pass in a list with 4 elements and assert that the list we get back still only has 4 elements. Something like this:


private MyClass uut;

@Before
public void setup() {
    uut = new MyClass();
}
@Test
public void whenIPassInANullListIExpectANullBack() {
    assertNull(uut.addToListIfSizeIsUnder3(null, "some value");
}
@Test
public void whenIPassInAListWithLessThan3ElementsIExpectToGetMyNewValueAdded() {
    List<String> myList = new ArrayList<String>();
    myList.add("value 1");
    List<String> outputList = uut.addToListIfSizeIsUnder3(myList, "some value");
    assertEquals(2, outputList.size());
    assertTrue(myList.contains("some value"));
}
@Test
public void whenIPassInAListWithMoreThan3ElementsIExpectNothingToBeAddedToIt() {
    List<String> myList = new ArrayList<String>();
    myList.add("value 1");
    myList.add("value 2");
    myList.add("value 3");
    myList.add("value 4");
    List<String> outputList = uut.addToListIfSizeIsUnder3(myList, "some value");
    assertEquals(4, outputList.size());
    assertFalse(myList.contains("some value"));
}

That’s all well and good, but how do we 100% assert that the code went into the else block? And what if we needed to assert that the parameters passed into the debug method were the correct values? If we could mock the log4j logger, we could assert how many times the debug method was called and with what parameters. But with mockito we can’t mock or replace static members of the class being tested. So how do we do this?

Fortunately mockito does allow us to mock an appender, and provides an ArgumentCaptor which allows us to capture the values logged. We can simply write our unit test as follows:


@RunWith(MockitoJUnitRunner.class)
public class MyTest {

	private MyClass uut;
	@Mock
	private Appender mockAppender;
	@Captor
	private ArgumentCaptor<LoggingEvent> captorLoggingEvent;

	@Before
	public void setup() {
		uut = new MyClass();

		Logger root = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
		root.addAppender(mockAppender);
		root.setLevel(Level.INFO);
	}
	@Test
	public void whenIPassInAListWithMoreThan3ElementsIExpectNothingToBeAddedToItAndALogEntryToBeWritten() {
		List<String> myList = new ArrayList<String>();
		myList.add("value 1");
		myList.add("value 2");
		myList.add("value 3");
		myList.add("value 4");
		List<String> outputList = uut.addToListIfSizeIsUnder3(myList, "some value");
		assertEquals(4, outputList.size());
		assertFalse(myList.contains("some value"));

		verify(mockAppender, times(1)).doAppend(captorLoggingEvent.capture());
		LoggingEvent loggingEvent = captorLoggingEvent.getAllValues().get(0);
		assertEquals("The list already has {} entries", loggingEvent.getMessage());
		assertEquals("The list already has 4 entries", loggingEvent.getFormattedMessage());
		assertEquals(Level.DEBUG, loggingEvent.getLevel());
	}
}

This is a really good way of being able to prove 100% code coverage (if you need to, but that’s a whole other discussion!), but also a good way of being able to prove the actual values written to the log. What if the else block and log statement looked a bit more like this:


...
} else {
    LOGGER.debug("something logged for policy {}", (policy.id != null ? policy.id : "with no id") );
}

Without being able to capture the values logged, you would not be able to prove test coverage of the ternary operator in the log statement.

4 Comments

  1. Dan Faiers |

    Very helpful post.

    I had to make one small change to this by replacing:
    Logger root = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
    with:
    Logger root = Logger.getRootLogger();

    Reply

So, what do you think ?