I am trying to test a static method that catches exception coming from different sub-calls or from the method itself and does just log the exception messages. By requirements, I cannot change the method implementation. Spying sub-calls is not a option in this case as we want to be consistent over the tests and since some executions throw exceptions from the method body itself, we finally opted to check... the error log messages.
Therefore, I want to mock the logger that will be called from the method, add an answer to the logging call when the logger calls error(...) with a match to a specific message. So far so good in my side. An example of what I do is as follow:
Mockito.doAnswer(new Answer<Void>()
{
@Override
public Void answer(InvocationOnMock invocation) throws Throwable {
Object[] args = invocation.getArguments();
String errorMessage = (String) args[0];
assertTrue(errorMessage.contains(SPECIFIC_MESSAGE));
return null;
}
}).when(logger).error(Matchers.startsWith(GENERIC_PREFIX));
We decided to use PowerMockito to mock the static call and returned our mocked logger from LoggerFactory.getLogger(...)
Logger logger = Mockito.mock(Logger.class);
PowerMockito.mockStatic(LoggerFactory.class);
Mockito.when(LoggerFactory.getLogger(any(Class.class))).thenReturn(logger);
Now comes our problem:
For each test, the value of the message SPECIFIC_MESSAGE to check changes. So we mock a logger for each test, mock the static LoggerFactory call to return the logger and then add our specific answer to our logger.error(...) call for this specific instance. But the first Answer which is added to the logger.error call during our first test seems to override all the other answers. Same execution occurs with each test.
I thought that the problem could come from Mockito that would return a singleton mock but I tested for that and it's not the case. Then I thought my problem could come from my LoggerFactory.getLogger(...) call which would return all the time the same instance of a logger but not the case either. Here is an implementation that shows the same issue I'm having with my code with the related execution log trace.
import java.util.Arrays;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class App
{
public static Logger logger = LoggerFactory.getLogger(App.class);
public static void main(String[] args)
{
logger.error("Error = " + Arrays.toString(args));
}
}
import org.junit.Test;
import org.junit.runner.RunWith;
import org.mockito.Matchers;
import org.mockito.Mockito;
import org.mockito.invocation.InvocationOnMock;
import org.mockito.stubbing.Answer;
import org.powermock.api.mockito.PowerMockito;
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.junit.Assert.*;
@RunWith(PowerMockRunner.class)
@PrepareForTest({LoggerFactory.class})
public class AppTest
{
@Test
public void firstTest()
{
Logger logger = Mockito.mock(Logger.class);
PowerMockito.mockStatic(LoggerFactory.class);
Mockito.when(LoggerFactory.getLogger(any(Class.class))).thenReturn(logger);
Mockito.doAnswer(new Answer<Void>()
{
@Override
public Void answer(InvocationOnMock invocation) throws Throwable {
Object[] args = invocation.getArguments();
String errorMessage = (String) args[0];
System.out.println("Calling from firstTest");
assertTrue(errorMessage.contains("a"));
return null;
}
}).when(logger).error(Matchers.startsWith("Error"));
App.main(new String[]{ "a" });
}
@Test
public void secondTest()
{
Logger logger = Mockito.mock(Logger.class);
PowerMockito.mockStatic(LoggerFactory.class);
Mockito.when(LoggerFactory.getLogger(any(Class.class))).thenReturn(logger);
Mockito.doAnswer(new Answer<Void>()
{
@Override
public Void answer(InvocationOnMock invocation) throws Throwable {
Object[] args = invocation.getArguments();
String errorMessage = (String) args[0];
System.out.println("Calling from secondTest");
assertTrue(errorMessage.contains("b"));
return null;
}
}).when(logger).error(Matchers.startsWith("Error"));
App.main(new String[]{ "b" });
}
}
TRACE:
Calling from firstTest
Calling from firstTest
Any idea why is the second answer not processed? Thanks in advance.
EDIT:
Issue is actually coming from the static method mock. "Then I thought my problem could come from my LoggerFactory.getLogger(...) call which would return all the time the same instance of a logger but not the case either." is actually wrong. It is valid inside my test where calling getLogger(...) returns the logger mock being mocked inside the test but when actually calling the App.main(...) method, the mocked getLogger(...) method call inside main(...) always return the same instance and is not reset between tests as expected. Mockito is supposed to reset between tests per documentation. A mockito's bug or limitation? Troubles related to interactions between Mockito and PowerMockito?
I found a solution which is to prepare the class to static mock at the method level for each test.
Adding @PrepareForTest(LoggerFactory.class)
before signature is actually solving the problem which was that the logger factory mock wasn't being reset between test and therefore the first call Mockito.when(LoggerFactory.getLogger(any(Class.class))).thenReturn(logger);
was always valid and always returning the same logger.