Logger with mockito in java

Question

I'm trying to verify a logger message with mockito.

However, I can not run my junit class to coverage all lines of code.

Do you know the reason why?

My code:

    public class App {
      private static final Logger LOGGER = Logger.getLogger(App.class);

      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;
    }
}

My JUnit class

import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;

import java.util.ArrayList;
import java.util.List;

import org.apache.log4j.Appender;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.spi.LoggingEvent;
import org.junit.Assert;
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;

@RunWith(MockitoJUnitRunner.class)
public class AppTest {
    private App uut;
    @Mock
    private Appender mockAppender;
    @Captor
    private ArgumentCaptor<LoggingEvent> captorLoggingEvent;

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

        Logger root = Logger.getRootLogger();
        root.addAppender(mockAppender);
        root.setLevel(Level.INFO);
    }

    /**
     * I want to test with over 3 elements.
     */
    @Test
    public void testWithOver3Element() {
        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");
        Assert.assertEquals(4, outputList.size());
        Assert.assertFalse(myList.contains("some value"));

try {
            verify(mockAppender, times(1)).doAppend(captorLoggingEvent.capture());
        } catch (AssertionError e) {
            e.printStackTrace();
        }

        LoggingEvent loggingEvent = captorLoggingEvent.getAllValues().get(0);
        Assert.assertEquals("The list already has {} entries", loggingEvent.getMessage());
        Assert.assertEquals(Level.DEBUG, loggingEvent.getLevel());
    }
}

ERROR:

Wanted but not invoked: mockAppender.doAppend(); -> at AppTest.testWithOver3Element(AppTest.java:52) Actually, there were zero interactions with this mock.

at AppTest.testWithOver3Element(AppTest.java:52) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229) at org.junit.runners.ParentRunner.run(ParentRunner.java:309) at org.mockito.internal.runners.JUnit45AndHigherRunnerImpl.run(JUnit45AndHigherRunnerImpl.java:37) at org.mockito.runners.MockitoJUnitRunner.run(MockitoJUnitRunner.java:62) at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:86) at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:459) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:678) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:382) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:192)

Answer 1

There are a couple of things you could do to improve your code:

1. Switch to slf4j. This will allow you to code to an interface and be agnostic of the logging implementation under the covers (apache log4j in your case).

2. Switching to slf4j will allow you to not have to concatenate strings when passing to the logging framework - example:

   • this statement: LOGGER.debug("The list already has {} entries" + list.size());
   • can be written like this: LOGGER.debug("The list already has {} entries", list.size());

This has the added benefit of making the place holder in the string literal actually work.

3. You are attempting to assert and capture calls to an object indirectly via the the Logging framework. This will be fragile and error prone as you never know what calls will be made internally in the Logging framework. Mock only your direct dependencies.

4. Don't test logging statements. It's not exactly visible behavior of the class and it makes the test fragile and complicated. Plus, treating the logging statements as you would say using an ArrayList (i.e. part of the language) allows them to be fully exercised AND they output info to the console that may be helpful in debugging a failing test. An example of being fragile is, if you change the logging statement to add more info or maybe you add another logging statement to the method, this test could break for no good reason. At the very least don't assert the number of times called as this will be extremely fragile.

All of that said, if you must test the interactions with the Logging framework - here is a modified version of your code that runs and provides the same functionality. This is basically option #3 from the list of improvements -

package com.spring.mockito;

import static org.mockito.Mockito.spy;
import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.when;

import org.apache.log4j.Logger;
import org.junit.Assert;
import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.mockito.Mock;
import org.mockito.Mockito;
import org.mockito.runners.MockitoJUnitRunner;

import java.util.Arrays;
import java.util.List;

@RunWith(MockitoJUnitRunner.class)
public class AppTest {

    // create a mock of the logger
    @Mock
    private Logger logger;

    private App uut;

    // Not needed - dont test something that gets called through something else
    // @Captor
    // private ArgumentCaptor<LoggingEvent> captorLoggingEvent;

    @Before
    public void setup() {
        // spy the class under test so we can override the logger method to return our mock logger
        uut = spy(new App());
        when(uut.logger()).thenReturn(logger);

        // Not needed test with the mock directly.
        // Logger root = Logger.getRootLogger();
        // root.addAppender(mockAppender);
        // root.setLevel(Level.DEBUG);
    }

    /**
     * I want to test with over 3 elements.
     */
    @Test
    public void testWithOver3Element() {
        List<String> myList = Arrays.asList("value 1", "value 2", "value 3", "value 4");

        List<String> outputList = uut.addToListIfSizeIsUnder3(myList, "some value");

        Assert.assertEquals(4, outputList.size());
        Assert.assertFalse(myList.contains("some value"));
        verify(logger, times(1)).debug("The list already has {} entries4");

        // not needed
        // try {
        // verify(mockAppender, times(1)).doAppend(captorLoggingEvent.capture());
        // } catch (AssertionError e) {
        // e.printStackTrace();
        // }
        //
        // LoggingEvent loggingEvent = captorLoggingEvent.getAllValues().get(0);
        // Assert.assertEquals("The list already has {} entries", loggingEvent.getMessage());
        // Assert.assertEquals(Level.DEBUG, loggingEvent.getLevel());
    }

    public static class App {
        private static final Logger LOGGER = Logger.getLogger(App.class);

        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 {
                // if you use slf4j this concatenation is not needed
                logger().debug("The list already has {} entries" + list.size());
            }
            return list;
        }

        // make a package private method for testing purposes to allow you to inject a mock
        Logger logger() {
            return LOGGER;
        }
    }
}

You can also look at packages like PowerMockito for mocking statics - but only if absolutely needed.

Hope this helps.

Answer 2

Your appender isn't getting fired because you've set it to INFO level, but your code is calling LOGGER.debug. DEBUG is a lower level of logging than INFO, so your appender won't see it.

Answer 3

I make it like that to avoid NPE while I check my methods with SLF4J logger

class MyClass{

    public Logger logger = LoggerFactory.getLogger(MyClass.class);
    //other your fields and methods
}


class MyTestClass{
    private MyClass myClass = mock(MyClass.class);
    private Logger log = mock(Logger.class);


    @Before
    public void init() {
        myClass.logger = log;
    }


     @Test
     public void firstTest() {
        doNothing().when(log).debug(any());
     }
}

Answer 4

Your problem is that there are inconsistencies between your testing and your production code.

The test is passing a list with 3 elements, and the production code says that means that the second argument is not added. But your test case expects it to be added!

So the very first thing here is to ensure that your tests really cover the behavior that you have depicted within the production code that you are showing.

Then i am wondering why your test works with a real logger here; I think it would be much easier for you to provide a mocked logger and specify the expected calls for it!

Answer 5

Although a valid answer has already been provided, I want to propose an alternative where you don't need to expose the Logger for mocking and you don't need to use mocking at all. It works for both SLF4J API and Log4J2 API.

See here for the library https://github.com/Hakky54/log-captor

Include in your maven file the reference for the library:

<dependency>
    <groupId>io.github.hakky54</groupId>
    <artifactId>logcaptor</artifactId>
    <version>2.6.1</version>
    <scope>test</scope>
</dependency>

In java code test method you should include this:

LogCaptor logCaptor = LogCaptor.forClass(App.class);

 // do the test logic....

assertThat(logCaptor.getLogs()).contains("Some log to assert");