Mocking Logger and LoggerFactory with PowerMock and Mockito
I have the following Logger I want to mock out, but to validate log entries are getting called, not for the content.
private static Logger logger =
LoggerFactory.getLogger(GoodbyeController.class);
I want to Mock ANY class that is used for LoggerFactory.getLogger() but I could not find out how to do that. This is what I ended up with so far:
@Before
public void performBeforeEachTest() {
PowerMockito.mockStatic(LoggerFactory.class);
when(LoggerFactory.getLogger(GoodbyeController.class)).
thenReturn(loggerMock);
when(loggerMock.isDebugEnabled()).thenReturn(true);
doNothing().when(loggerMock).error(any(String.class));
...
}
I would like to know:
- Can I Mock the static
LoggerFactory.getLogger()to work for any class? - I can only seem to run
when(loggerMock.isDebugEnabled()).thenReturn(true);in the@Beforeand thus I cannot seem to change the characteristics per method. Is there a way around this?
Edit findings:
I thought I tried this already and it didnt work:
when(LoggerFactory.getLogger(any(Class.class))).thenReturn(loggerMock);
But thank you, as it did work.
However I have tried countless variations to:
when(loggerMock.isDebugEnabled()).thenReturn(true);
I cannot get the loggerMock to change its behavior outside of @Before but this only happens with Coburtura. With Clover, the coverage shows 100% but there is still an issue either way.
I have this simple class:
public ExampleService{
private static final Logger logger =
LoggerFactory.getLogger(ExampleService.class);
public String getMessage() {
if(logger.isDebugEnabled()){
logger.debug("isDebugEnabled");
logger.debug("isDebugEnabled");
}
return "Hello world!";
}
...
}
Then I have this test:
@RunWith(PowerMockRunner.class)
@PrepareForTest({LoggerFactory.class})
public class ExampleServiceTests {
@Mock
private Logger loggerMock;
private ExampleServiceservice = new ExampleService();
@Before
public void performBeforeEachTest() {
PowerMockito.mockStatic(LoggerFactory.class);
when(LoggerFactory.getLogger(any(Class.class))).
thenReturn(loggerMock);
//PowerMockito.verifyStatic(); // fails
}
@Test
public void testIsDebugEnabled_True() throws Exception {
when(loggerMock.isDebugEnabled()).thenReturn(true);
doNothing().when(loggerMock).debug(any(String.class));
assertThat(service.getMessage(), is("Hello null: 0"));
//verify(loggerMock, atLeast(1)).isDebugEnabled(); // fails
}
@Test
public void testIsDebugEnabled_False() throws Exception {
when(loggerMock.isDebugEnabled()).thenReturn(false);
doNothing().when(loggerMock).debug(any(String.class));
assertThat(service.getMessage(), is("Hello null: 0"));
//verify(loggerMock, atLeast(1)).isDebugEnabled(); // fails
}
}
In clover I show 100% coverage of the if(logger.isDebugEnabled()){ block.
But if I try to verify the loggerMock:
verify(loggerMock, atLeast(1)).isDebugEnabled();
I get zero interactions.
I also tried PowerMockito.verifyStatic(); in @Before but that also has zero interactions.
This just seems strange that Cobertura shows the if(logger.isDebugEnabled()){ as being not 100% complete, and Clover does, but both agree the verification fails.
Solution 1:
EDIT 2020-09-21: Since 3.4.0, Mockito supports mocking static methods, API is still incubating and is likely to change, in particular around stubbing and verification. It requires the mockito-inline artifact. And you don't need to prepare the test or use any specific runner. All you need to do is :
@Test
public void name() {
try (MockedStatic<LoggerFactory> integerMock = mockStatic(LoggerFactory.class)) {
final Logger logger = mock(Logger.class);
integerMock.when(() -> LoggerFactory.getLogger(any(Class.class))).thenReturn(logger);
new Controller().log();
verify(logger).warn(any());
}
}
The two inportant aspect in this code, is that you need to scope when the static mock applies, i.e. within this try block. And you need to call the stubbing and verification api from the MockedStatic object.
@Mick, try to prepare the owner of the static field too, eg :
@PrepareForTest({GoodbyeController.class, LoggerFactory.class})
EDIT1 : I just crafted a small example. First the controller :
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class Controller {
Logger logger = LoggerFactory.getLogger(Controller.class);
public void log() { logger.warn("yup"); }
}
Then the test :
import org.junit.Test;
import org.junit.runner.RunWith;
import org.powermock.core.classloader.annotations.PrepareForTest;
import org.powermock.modules.junit4.PowerMockRunner;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import static org.mockito.Matchers.any;
import static org.mockito.Matchers.anyString;
import static org.mockito.Mockito.verify;
import static org.powermock.api.mockito.PowerMockito.mock;
import static org.powermock.api.mockito.PowerMockito.mockStatic;
import static org.powermock.api.mockito.PowerMockito.when;
@RunWith(PowerMockRunner.class)
@PrepareForTest({Controller.class, LoggerFactory.class})
public class ControllerTest {
@Test
public void name() throws Exception {
mockStatic(LoggerFactory.class);
Logger logger = mock(Logger.class);
when(LoggerFactory.getLogger(any(Class.class))).thenReturn(logger);
new Controller().log();
verify(logger).warn(anyString());
}
}
Note the imports ! Noteworthy libs in the classpath : Mockito, PowerMock, JUnit, logback-core, logback-clasic, slf4j
EDIT2 : As it seems to be a popular question, I'd like to point out that if these log messages are that important and require to be tested, i.e. they are feature / business part of the system then introducing a real dependency that make clear theses logs are features would be a so much better in the whole system design, instead of relying on static code of a standard and technical classes of a logger.
For this matter I would recommend to craft something like= a Reporter class with methods such as reportIncorrectUseOfYAndZForActionX or reportProgressStartedForActionX. This would have the benefit of making the feature visible for anyone reading the code. But it will also help to achieve tests, change the implementations details of this particular feature.
Hence you wouldn't need static mocking tools like PowerMock. In my opinion static code can be fine, but as soon as the test demands to verify or to mock static behavior it is necessary to refactor and introduce clear dependencies.
Solution 2:
Somewhat late to the party - I was doing something similar and needed some pointers and ended up here. Taking no credit - I took all of the code from Brice but got the "zero interactions" than Cengiz got.
Using guidance from what jheriks amd Joseph Lust had put I think I know why - I had my object under test as a field and newed it up in a @Before unlike Brice. Then the actual logger was not the mock but a real class init'd as jhriks suggested...
I would normally do this for my object under test so as to get a fresh object for each test. When I moved the field to a local and newed it in the test it ran ok. However, if I tried a second test it was not the mock in my test but the mock from the first test and I got the zero interactions again.
When I put the creation of the mock in the @BeforeClass the logger in the object under test is always the mock but see the note below for the problems with this...
Class under test
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class MyClassWithSomeLogging {
private static final Logger LOG = LoggerFactory.getLogger(MyClassWithSomeLogging.class);
public void doStuff(boolean b) {
if(b) {
LOG.info("true");
} else {
LOG.info("false");
}
}
}
Test
import org.junit.AfterClass;
import org.junit.BeforeClass;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.powermock.core.classloader.annotations.PrepareForTest;
import org.powermock.modules.junit4.PowerMockRunner;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import static org.mockito.Mockito.*;
import static org.powermock.api.mockito.PowerMockito.mock;
import static org.powermock.api.mockito.PowerMockito.*;
import static org.powermock.api.mockito.PowerMockito.when;
@RunWith(PowerMockRunner.class)
@PrepareForTest({LoggerFactory.class})
public class MyClassWithSomeLoggingTest {
private static Logger mockLOG;
@BeforeClass
public static void setup() {
mockStatic(LoggerFactory.class);
mockLOG = mock(Logger.class);
when(LoggerFactory.getLogger(any(Class.class))).thenReturn(mockLOG);
}
@Test
public void testIt() {
MyClassWithSomeLogging myClassWithSomeLogging = new MyClassWithSomeLogging();
myClassWithSomeLogging.doStuff(true);
verify(mockLOG, times(1)).info("true");
}
@Test
public void testIt2() {
MyClassWithSomeLogging myClassWithSomeLogging = new MyClassWithSomeLogging();
myClassWithSomeLogging.doStuff(false);
verify(mockLOG, times(1)).info("false");
}
@AfterClass
public static void verifyStatic() {
verify(mockLOG, times(1)).info("true");
verify(mockLOG, times(1)).info("false");
verify(mockLOG, times(2)).info(anyString());
}
}
Note
If you have two tests with the same expectation I had to do the verify in the @AfterClass as the invocations on the static are stacked up - verify(mockLOG, times(2)).info("true"); - rather than times(1) in each test as the second test would fail saying there where 2 invocation of this. This is pretty pants but I couldn't find a way to clear the invocations. I'd like to know if anyone can think of a way round this....
Solution 3:
In answer to your first question, it should be as simple as replacing:
when(LoggerFactory.getLogger(GoodbyeController.class)).thenReturn(loggerMock);
with
when(LoggerFactory.getLogger(any(Class.class))).thenReturn(loggerMock);
Regarding your second question (and possibly the puzzling behavior with the first), I think the problem is that logger is static. So,
private static Logger logger = LoggerFactory.getLogger(GoodbyeController.class);
is executed when the class is initialized, not the when the object is instantiated. Sometimes this can be at about the same time, so you'll be OK, but it's hard to guarantee that. So you set up LoggerFactory.getLogger to return your mock, but the logger variable may have already been set with a real Logger object by the time your mocks are set up.
You may be able to set the logger explicitly using something like ReflectionTestUtils (I don't know if that works with static fields) or change it from a static field to an instance field. Either way, you don't need to mock LoggerFactory.getLogger because you'll be directly injecting the mock Logger instance.
Solution 4:
I think you can reset the invocations using Mockito.reset(mockLog). You should call this before every test, so inside @Before would be a good place.
Solution 5:
Use explicit injection. No other approach will allow you for instance to run tests in parallel in the same JVM.
Patterns that use anything classloader wide like static log binder or messing with environmental thinks like logback.XML are bust when it comes to testing.
Consider the parallelized tests I mention , or consider the case where you want to intercept logging of component A whose construction is hidden behind api B. This latter case is easy to deal with if you are using a dependency injected loggerfactory from the top, but not if you inject Logger as there no seam in this assembly at ILoggerFactory.getLogger.
And its not all about unit testing either. Sometimes we want integration tests to emit logging. Sometimes we don't. Someone's we want some of the integration testing logging to be selectively suppressed, eg for expected errors that would otherwise clutter the CI console and confuse. All easy if you inject ILoggerFactory from the top of your mainline (or whatever di framework you might use)
So...
Either inject a reporter as suggested or adopt a pattern of injecting the ILoggerFactory. By explicit ILoggerFactory injection rather than Logger you can support many access/intercept patterns and parallelization.