Don’t mock static: test SLF4J Logger with appenders

Most of the time you would like to inject dependencies to your class directly – through the class constructor or by setting required properties via setters. No matter what programming style you prefer you may encounter situation when some dependency cannot or shouldn’t be passed directly to your system under test.

Good example of that kind of situation are loggers – most of the time we want to access them directly via static methods. I will show you ideas how to effectively use SLF4J with Logback in unit tests.

SLF4J stands for Simple Logging Facade for Java

How to test logs?

Logs are important piece of production code – they play primary role in debugging and are useful in analytics. We can test them in few ways:

1. We can read them in console output
2. We can dump logs to file and analyze that file (in production or in integration tests)
3. We can provide test double for logger and test logs in unit test

In the next sections we will focus on the third option – testing logger in unit tests

Why would you test logs?

Let’s suppose that your code encounter very specific race condition. You fixed the bug and now you want to have information in your monitoring services if something like this happens again. Those race conditions may be difficult to reproduce in full environment so instead of clicking through app you write automatic test for that case.

How to mock SLF4J Logger?

SLF4J is default logger added to Spring Boot projects. There are high chances that you are already using it.

Let’s consider the following RestController:

import org.slf4j.Logger;import org.slf4j.LoggerFactory;import org.springframework.http.HttpStatus;import org.springframework.http.ResponseEntity;import org.springframework.web.bind.annotation.*;import java.util.Collections;import java.util.List;import java.util.Map;@RestControllerpublic class Controller {    private final ItemsService service;    private final Logger logger = LoggerFactory.getLogger(Controller.class);    public Controller(ItemsService service) {        this.service = service;    }    @GetMapping    public List<Entity> getAll() {        try {            return service.getAll();        } catch (Exception exception) {            logger.warn("Service.getAll returned exception instead of empty list", exception);            return Collections.emptyList();        }    }}

As you can see, in this case we log warn when service throws exception, but we are not passing that error to client, rather log it for monitoring purposes.

We could try to move logger into constructor parameter and just change it’s implementation for unit tests. That’s not always possible due to several reasons (legacy code, team programming style, etc.). We will try to provide test double for logger without system under test modification – it will stay private final.

How to assert that SLF4J logged warn?

We will:

1. Grab the logger from LoggerFactory
2. Add appender
3. Assert that specific log with desired level Level.Warn was logged and that it contains proper message

To capture logs without messing with XML configurations, we need to add appender to logger.

But wait, org.slf4j.Logger does not have addAppender method! Appenders are supported by ch.qos.logback.classic.Logger!

To ensure which implementation of Logger runs in your test, you may use debugger or just print logger class:

private final Logger logger = LoggerFactory.getLogger(Controller.class);public Controller(ItemsService service) {    this.service = service;    System.out.println((logger.getClass().toString())); //class ch.qos.logback.classic.Logger}

For testing purpose we can cast Logger to it’s underlying implementation:

LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME) as ch.qos.logback.classic.Logger

Now we are ready to add appender to this method. We can use some of built-in appenders such as ListAppender or implement our own:

import ch.qos.logback.classic.spi.ILoggingEventimport ch.qos.logback.core.AppenderBaseclass TestAppender : AppenderBase<ILoggingEvent>() {    private val events: MutableList<ILoggingEvent> = mutableListOf()    fun lastLoggedEvent() = events.lastOrNull()    override fun append(eventObject: ILoggingEvent) {        events.add(eventObject)    }}

Now we can write rest of the test:

import ch.qos.logback.classic.Levelimport ch.qos.logback.classic.Loggerimport io.kotest.assertions.assertSoftlyimport io.kotest.core.spec.style.StringSpecimport io.kotest.matchers.shouldBeimport io.kotest.matchers.string.shouldContainimport org.mockito.kotlin.doThrowimport org.mockito.kotlin.mockimport org.slf4j.LoggerFactoryclass ControllerLoggingTest : StringSpec({    "given service error when get all called then log warn" {        //prepare logging context        val testAppender = TestAppender()        val logger = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME) as ch.qos.logback.classic.Logger        logger.addAppender(testAppender)        testAppender.start()        //setup system under test        val controller = Controller(mock {            on { getAll() } doThrow Exception("Something failed :(")        })        //execute system under test        controller.getAll()        //capture last logged event        val lastLoggedEvent = testAppender.lastLoggedEvent()        require(lastLoggedEvent != null) {            "There are on events appended in TestLogger"        }        //assertion on last logged event fields        assertSoftly {            lastLoggedEvent.level shouldBe Level.WARN            lastLoggedEvent.message shouldContain "Service.getAll returned exception instead of empty list"        }    }})

I’m using here few techniques described in previous articles – read here how to assertSoftly and check here how to use Mockito with Kotlin

Important! If you are not capturing events in appender, ensure you invoked appender.start() method!

To sum things up:

1. Add custom appender to logger
2. Execute system under test normally
3. Assert that something happened in custom appender

Bonus: TestAppender for SLF4J implementation in Java

I highly encourage you to give Kotlin a try in unit tests, but if you are just looking for SLF4J / Logback test in Java, use the following snippets:

import ch.qos.logback.classic.spi.ILoggingEvent;import ch.qos.logback.core.AppenderBase;import java.util.ArrayList;class TestLogAppender extends AppenderBase<ILoggingEvent> {    ArrayList<ILoggingEvent> loggingEvents = new ArrayList<>();    @Override    protected void append(ILoggingEvent eventObject) {        loggingEvents.add(eventObject);    }    ILoggingEvent getLastLoggedEvent() {        if (loggingEvents.isEmpty()) return null;        return loggingEvents.get(loggingEvents.size() - 1);    }}

import ch.qos.logback.classic.Logger;import ch.qos.logback.classic.spi.ILoggingEvent;import org.junit.jupiter.api.Test;import org.mockito.Mockito;import org.slf4j.LoggerFactory;import java.util.List;import static org.junit.jupiter.api.Assertions.assertEquals;import static org.junit.jupiter.api.Assertions.assertNotNull;public class ControllerLoggerTestJava {    @Test    public void given_service_error_when_get_all_called_then_log_warn() throws Exception {        ItemsService service = Mockito.mock(ItemsService.class);        Mockito.when(service.getAll()).thenThrow(new Exception("Something failed :("));        Controller controller = new Controller(service);        TestLogAppender testLogAppender = new TestLogAppender();        Logger logger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);        logger.addAppender(testLogAppender);        testLogAppender.start();        List<Entity> entityList = controller.getAll();        ILoggingEvent lastLoggedEvent = testLogAppender.getLastLoggedEvent();        assertNotNull(lastLoggedEvent);        assertEquals(lastLoggedEvent.getMessage(), "Service.getAll returned exception instead of empty list");    }}

Summary

• check if library you are using supports indirect injection (something like adding Appender)
• try to avoid using static methods with side effects in the first place – if you inject your dependencies directly, you have more control!
• What to do if appender cannot be added to logger? Stay tuned for the next articles in series Mock Static