Unit testing with static dependencies, e.g. Logger

Submitted by kofa on Tue, 05/28/2013 - 22:26

John Lonergan (not verified)

Tue, 12/01/2015 - 16:53

Adding a setter where a final would be more appropriate or idiomatic seems like a workaround though less severe than the ones mentioned earlier.

The better solution IMHO i dependency injection of ILoggerFactory and leave the field as final.
This pattern has wider benefits when it testing or even suppressing logging. By factory di one is able intercept those getLogger calls without resorting to class loader hell.

don fong (not verified)

Tue, 12/06/2016 - 23:22

thanks for sharing these learned lessons from yourself and your colleagues.

Or, the road to hell is paved with good intentions.

A colleague of mine was recently writing a unit test. At one point, he wanted to determine what log message the component under test generated. The component was similar to this (source is on GitHub):

@Service
public class AuthenticationService {
    private final static Logger LOGGER = LoggerFactory.getLogger(AuthenticationService.class);
    ...
    public AuthenticationResult authenticate(String userId, String password) {
        AuthenticationResult result;
        ...
        LOGGER.info("Result of authenticating {}: {}", userId, result);
        return result;
    }
}

In order to observe parameters passed to the Logger, he needed to inject his own Logger object. As the Logger instance is obtained from LoggerFactory, he decided to use PowerMock and stub the static call. He came up with something like this:

@RunWith(PowerMockRunner.class)
@PrepareForTest({ LoggerFactory.class })
public class AuthenticationServiceTest1 {
    private Logger logger;
    ...
    @Before
    public void setUp() throws Exception {
        logger = mock(Logger.class);
        PowerMockito.spy(LoggerFactory.class);
        PowerMockito.doReturn(logger).when(LoggerFactory.class, "getLogger",
                AuthenticationService.class);
    }

    @Test
    public void testSuccessEvenIfFirstFailed() {
        AuthenticationResult result = authenticateWith(FAILED, SUCCESSFUL);
        assertThat(result, is(SUCCESSFUL));
        assertLogContains(USER, SUCCESSFUL);
    }

    private void assertLogContains(String user, AuthenticationResult result) {
        // to make test less fragile, ignore order of parameters (userId and authentication result)
        ArgumentCaptor param1Captor = ArgumentCaptor
                .forClass(Object.class);
        ArgumentCaptor param2Captor = ArgumentCaptor
                .forClass(Object.class);
        verify(logger).info(anyString(), param1Captor.capture(),
                param2Captor.capture());
        List logParams = Arrays.asList(param1Captor.getValue(),
                param2Captor.getValue());
        assertTrue(logParams.contains(user));
        assertTrue(logParams.contains(result));
    }
    ...
}

Simple enough. Imagine his surprise, when he ran the test, and got:

Wanted but not invoked:
logger.info(
    <any>,
    <Capturing argument>,
    <Capturing argument>
);
-> at org.kovacstelekes.AuthenticationServiceTest1.assertLogContains(AuthenticationServiceTest1.java:73)
Actually, there were zero interactions with this mock.
    at org.kovacstelekes.AuthenticationServiceTest1.assertLogContains(AuthenticationServiceTest1.java:73)
    at org.kovacstelekes.AuthenticationServiceTest1.testSuccessEvenIfFirstFailed(AuthenticationServiceTest1.java:52)
    at ...

Why is that? The test is very simple: we create a Logger mock, set up LoggerFactory to return it, and run the test. However, you should note that LOGGER is a static, final field of AuthenticationService. This means it's initialised as soon as the class is loaded - before we had our chance to hook into LoggerFactory. The solution was pretty simple: instead of a test-level setup method (annotated with @Before), a class-level method should be used. This way, we can hook into LoggerFactory before AuthenticationService is loaded, and can inject our mock into the final static field.

The 'fixed' code is like this (actual code on GitHub):

@RunWith(PowerMockRunner.class)
@PrepareForTest({ LoggerFactory.class })
public class AuthenticationServiceTest2 {
    private static Logger logger;

    @BeforeClass
    public static void setUp() throws Exception {
        logger = mock(Logger.class);
        PowerMockito.spy(LoggerFactory.class);
        PowerMockito.doReturn(logger).when(LoggerFactory.class, "getLogger",
                AuthenticationService.class);
    }
    ...
}

Note that logger is now static, and setUp is a static method, annotated with @BeforeClass instead of @Before.

The test runs, So far, so good; let's add more tests! (GitHub)

    @Test
    public void testSuccessEvenIfFirstFailed() {
        AuthenticationResult result = authenticateWith(FAILED, SUCCESSFUL);

        assertThat(result, is(SUCCESSFUL));
        assertLogContains(USER, SUCCESSFUL);
    }

    @Test
    public void testBlockedStopsProcessing() {
        AuthenticationResult result = authenticateWith(BLOCKED, SUCCESSFUL);

        assertThat(result, is(BLOCKED));
        assertLogContains(USER, BLOCKED);
    }

    @Test
    public void testSuccessfulStopsProcessing() {
        AuthenticationResult result = authenticateWith(SUCCESSFUL, FAILED);

        assertThat(result, is(SUCCESSFUL));
        assertLogContains(USER, SUCCESSFUL);
    }

    @Test
    public void testNoProvidersMeansFailed() {
        AuthenticationResult result = authenticateWith();

        assertThat(result, is(FAILED));
        assertLogContains(USER, FAILED);
    }

When we run this, we get failures, such as:

org.mockito.exceptions.verification.TooManyActualInvocations: 
logger.info(
    <any>,
    <Capturing argument>,
    <Capturing argument>
);
Wanted 1 time:
-> at org.kovacstelekes.AuthenticationServiceTest3.assertLogContains(AuthenticationServiceTest3.java:99)
But was 2 times. Undesired invocation:
-> at org.kovacstelekes.AuthenticationService.authenticate(AuthenticationService.java:36)
    at org.kovacstelekes.AuthenticationServiceTest3.assertLogContains(AuthenticationServiceTest3.java:99)
    at org.kovacstelekes.AuthenticationServiceTest3.testBlockedStopsProcessing(AuthenticationServiceTest3.java:62)
    ...

Again, why? Remember that our Logger mock is static, and we use the same instance in all test methods. This means log messages keep accumulating in it. Again, no warning bells went off in my head, although they should have. Instead, I started googling, and found that 'luckily', with 1.8, Mockito allows you to reset a mock. The only thing that needs to change is to reset the mock before each run - easily done using @Before: (GitHub)

    @Before
    public void resetLogger() {
        reset(logger);
    }

So, I went to write this blog post, and showed it to one of the lead developers here. He said I should definitely not publish this. I was baffled. It took some explaining on his part, and thinking on mine, to realise that what I've done was a "junior's solution", as another of my experienced colleagues calls this way of coding: instead of realising something is off with the whole design, I just kept adding more and more code, more powerful tools/libraries, more tricks, until I got the thing going. What I should have done is to realise that the static dependency should not be worked around - it should be eliminated. To see what I mean, check out the real solution (GitHub: TestableAuthenticationService, TestableAuthenticationServiceTest):

@Service
public class TestableAuthenticationService {
    private Logger logger = LoggerFactory
            .getLogger(TestableAuthenticationService.class);
    ...
    void setLogger(Logger theLogger) {
        logger = theLogger;
    }
    ...
}
public class TestableAuthenticationServiceTest {

    private Logger logger;

    private TestableAuthenticationService service = new TestableAuthenticationService();

    private static final String USER = "user";
    private static final String DUMMY_PASSWORD = "";

    @Before
    public void setUp() throws Exception {
        logger = mock(Logger.class);
        service.setLogger(logger);
    }
    ...
}

The changes are:

Logger is no longer static final
It does not waste resources, the logger framework will cache loggers, and keep a single instance for each name (derived from the class name)
It still has a reasonable default, be can now be modified via a package-private setter, which is accessible to the related test case.
Look ma, no PowerMock!
Since the static reference has been eliminated, we no longer need to jump through hoops, we can replace the logger just like any other dependency.

I must admit I've made a fool of myself, and led my colleagues down a dangerous path. I was the one who standardised on the private static final Logger = LoggerFactory.getLogger(Whatever.class); pattern, I've even come up with an Eclipse editor template to avoid having to type it all the time. So, here's the new template, if you're interested:

private org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(${enclosing_type}.class);

void setLogger(org.slf4j.Logger logger) {
    this.logger = logger;
}