How to intercept SLF4J logging via a JUnit test?

Question

Is it possible to somehow intercept the logging (SLF4J + logback) and get an InputStream (or something else that is readable) via a JUnit test case...?

Answer 1

The Slf4j API doesn't provide such a way but Logback provides a simple solution.

You can use ListAppender : a whitebox logback appender where log entries are added in a public List field that we could use to make our assertions.

Here is a simple example.

Foo class :

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Foo {

    static final Logger LOGGER = LoggerFactory.getLogger(Foo .class);

    public void doThat() {
        logger.info("start");
        //...
        logger.info("finish");
    }
}

FooTest class :

import org.slf4j.LoggerFactory;
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.read.ListAppender;

public class FooTest {

    @Test
    void doThat() throws Exception {
        // get Logback Logger 
        Logger fooLogger = (Logger) LoggerFactory.getLogger(Foo.class);

        // create and start a ListAppender
        ListAppender<ILoggingEvent> listAppender = new ListAppender<>();
        listAppender.start();

        // add the appender to the logger
        fooLogger.addAppender(listAppender);

        // call method under test
        Foo foo = new Foo();
        foo.doThat();

        // JUnit assertions
        List<ILoggingEvent> logsList = listAppender.list;
        assertEquals("start", logsList.get(0)
                                      .getMessage());
        assertEquals(Level.INFO, logsList.get(0)
                                         .getLevel());

        assertEquals("finish", logsList.get(1)
                                       .getMessage());
        assertEquals(Level.INFO, logsList.get(1)
                                         .getLevel());
    }
}

You can also use Matcher/assertion libraries as AssertJ or Hamcrest.

With AssertJ it would be :

import org.assertj.core.api.Assertions;

Assertions.assertThat(listAppender.list)
          .extracting(ILoggingEvent::getMessage, ILoggingEvent::getLevel)
          .containsExactly(Tuple.tuple("start", Level.INFO), Tuple.tuple("finish", Level.INFO));

Answer 2

You can create a custom appender

public class TestAppender extends AppenderBase<LoggingEvent> {
    static List<LoggingEvent> events = new ArrayList<>();

    @Override
    protected void append(LoggingEvent e) {
        events.add(e);
    }
}

and configure logback-test.xml to use it. Now we can check logging events from our test:

@Test
public void test() {
    ...
    Assert.assertEquals(1, TestAppender.events.size());
    ...
}

Answer 3

I had problems when testing logs line like: LOGGER.error(message, exception).

The solution described in http://projects.lidalia.org.uk/slf4j-test/ tries to assert as well on the exception and it is not easy (and in my opinion worthless) to recreate the stacktrace.

I resolved in this way:

import org.junit.Test;
import org.slf4j.Logger;
import uk.org.lidalia.slf4jext.LoggerFactory;
import uk.org.lidalia.slf4jtest.TestLogger;
import uk.org.lidalia.slf4jtest.TestLoggerFactory;

import static org.assertj.core.api.Assertions.assertThat;
import static org.assertj.core.groups.Tuple.tuple;
import static uk.org.lidalia.slf4jext.Level.ERROR;
import static uk.org.lidalia.slf4jext.Level.INFO;


public class Slf4jLoggerTest {

    private static final Logger LOGGER = LoggerFactory.getLogger(Slf4jLoggerTest.class);


    private void methodUnderTestInSomeClassInProductionCode() {
        LOGGER.info("info message");
        LOGGER.error("error message");
        LOGGER.error("error message with exception", new RuntimeException("this part is not tested"));
    }





    private static final TestLogger TEST_LOGGER = TestLoggerFactory.getTestLogger(Slf4jLoggerTest.class);

    @Test
    public void testForMethod() throws Exception {
        // when
        methodUnderTestInSomeClassInProductionCode();

        // then
        assertThat(TEST_LOGGER.getLoggingEvents()).extracting("level", "message").contains(
                tuple(INFO, "info message"),
                tuple(ERROR, "error message"),
                tuple(ERROR, "error message with exception")
        );
    }

}

This has as well the advantage to not having depend on Hamcrest matchers library.

Answer 4

You can use slf4j-test from http://projects.lidalia.org.uk/slf4j-test/. It replaces the entire logback slf4j implementation by it's own slf4j api implementation for tests and provides an api to assert against logging events.

example:

<build>
  <plugins>
    <plugin>
      <artifactId>maven-surefire-plugin</artifactId>
      <configuration>
        <classpathDependencyExcludes>
          <classpathDependencyExcludes>ch.qos.logback:logback-classic</classpathDependencyExcludes>
        </classpathDependencyExcludes>
      </configuration>
    </plugin>
  </plugins>
</build>

public class Slf4jUser {

    private static final Logger logger = LoggerFactory.getLogger(Slf4jUser.class);

    public void aMethodThatLogs() {
        logger.info("Hello World!");
    }
}

public class Slf4jUserTest {

    Slf4jUser slf4jUser = new Slf4jUser();
    TestLogger logger = TestLoggerFactory.getTestLogger(Slf4jUser.class);

    @Test
    public void aMethodThatLogsLogsAsExpected() {
        slf4jUser.aMethodThatLogs();

        assertThat(logger.getLoggingEvents(), is(asList(info("Hello World!"))));
    }

    @After
    public void clearLoggers() {
        TestLoggerFactory.clear();
    }
}

Answer 5

Although creating a custom logback appender is a good solution, it is only the first step, you will eventually end up developing/reinventing slf4j-test, and if you go a bit further: spf4j-slf4j-test or other frameworks that I don't know of yet.

You will eventually need to worry about how many events you keep in memory, fail unit tests when a error is logged (and not asserted), make debug logs available on test failure, etc...

Disclaimer: I am the author of spf4j-slf4j-test, I wrote this backend to be able to better test spf4j, which is a good place to look at for examples on how to use spf4j-slf4j-test. One of the main advantages I achieved was reducing my build output (which is limited with Travis), while still having all the detail I need when failure happens.