How to intercept SLF4J (with logback) 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...?

Farkas

Answer 1

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());
    ...
}

NOTE: Use ILoggingEvent if you do not get any output - see the comment section for the reasoning.

Gupton

Note, if you are using logback classic + slf4j you need to use ILoggingEvent instead of LoggingEvent. That's what worked for me. – Changchangaris

@Evgeniy Dorofeev Could you please show how to configure logback-test.xml? – Lovesick

I assume you need to clear events after each test execution. – Saltwater

@Lovesick You can use the one mentioned [here] (logback.qos.ch/manual/configuration.html) in sample0.xml. Don't forget to change the appender to your implementaion – Bostwick

@EvgeniyDorofeev can you help me with this ? #48551583 – Womankind

The problem with writing a custom appender is that you won't see the logs on the console anymore because you cannot extend AppenderBase and OutputStreamAppender at the same time – Eggett

which package should I import AppenderBase from? – Bullen

How do u add it to the logback.xml – Koph

Do we still need to add start() and stop() after adding testAppender in the logback-test.xml? I tried calling TestAppender.start() and TestAppender.stop() but it has no effect! The TestAppender seem to be always running – Clyde

this is how to configure logback-test.xml with TestAppender class <configuration> <appender name="testAppender" class="fullClassPath.TestAppender"/> <root level="DEBUG"> <appender-ref ref="testAppender"/> </root> <root level="ERROR"> <appender-ref ref="testAppender"/> </root> <root level="INFO"> <appender-ref ref="testAppender"/> </root> </configuration> – Clyde

Answer 2

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::getFormattedMessage, ILoggingEvent::getLevel)
          .containsExactly(Tuple.tuple("start", Level.INFO), Tuple.tuple("finish", Level.INFO));

Shannan

Thank you so much! This is exactly what I was looking for! – Arithmomancy

I am getting ClassCastException for Logger fooLogger = (Logger) LoggerFactory.getLogger(Foo.class);. I am using LoggerFactory of org.slf4j.LoggerFactory and Logger of ch.qos.logback.classic.Logger – Descend

@Hiren What is exactly the error message associated to ? – Shannan

@Hiren If you use JUnit 5, make sure to not accidentally import org.junit.platform.commons.logging.LoggerFactory, which is what happened to me. – Foresight

Important to note that instead of ILoggingEvent::getMessage you should use ILoggingEvent::getFormattedMessage If your log contains a parameter value. Otherwise your assert will fail as the value will be missing. – Salpingitis

@Robert Mason thanks for the feedback. It could help others – Shannan

@Shannan I use Apache Log4jLogger which cannot be casted to Logback Logger, is there any way to resolve that? – Medarda

if you are using SLF4J this solution will end up raising SLF4J: Class path contains multiple SLF4J bindings. warning as you have both SLF4J and logback.classic – Eggett

@Shannan please have a look on my question https://mcmap.net/q/152937/-how-to-verify-with-unit-test-that-error-stack-is-printed-in-the-log-file/504807 – Cookbook

it also doesn't work for me due to: > java.lang.ClassCastException: class org.slf4j.simple.SimpleLogger cannot be cast to class ch.qos.logback.classic.Logger (org.slf4j.simple.SimpleLogger and ch.qos.logback.classic.Logger are in unnamed module of loader 'app') in that place (Logger) LoggerFactory.getLogger() – Virility

Answer 3

With JUnit5

private ListAppender<ILoggingEvent> logWatcher;

@BeforeEach
void setup() {
  logWatcher = new ListAppender<>();
  logWatcher.start();
  ((Logger) LoggerFactory.getLogger(MyClass.class)).addAppender(logWatcher);
}

Note: MyClass.class - should be your Prod class, you expect the log output from

use: (AssertJ example)

@Test
void myMethod_logs2Messages() {

  ...
  int logSize = logWatcher.list.size();
  assertThat(logWatcher.list.get(logSize - 2).getFormattedMessage()).contains("EXPECTED MSG 1");
  assertThat(logWatcher.list.get(logSize - 1).getFormattedMessage()).contains("EXPECTED MSG 2");
}

destroy:

Detach is recommended, for a better performance:

@AfterEach
void teardown() {
  ((Logger) LoggerFactory.getLogger(MyClass.class)).detachAndStopAllAppenders();
}

imports:

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

---

credits to: @davidxxx's answer. See it for import ch.qos.logback... details: https://mcmap.net/q/151347/-how-to-intercept-slf4j-with-logback-logging-via-a-junit-test

Fawcette

Finally a simple solution that works just fine. Thanks ! – Septemberseptembrist

It looks promising. But I then get Class path contains multiple SLF4J providers. warning, and an java.lang.ClassCastException: org.slf4j.simple.SimpleLogger cannot be cast to ch.qos.logback.classic.Logger error. I try to run mvn dependency:tree to disable slf4j provider, but it fails. :-/ – Militarism

I ran into issues trying this. It says that logWatcher needs to be an appender – Rachelrachele

did u use the same imports as the answer lists? import ch.qos.logback.core.read.ListAppender; – Fawcette

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();
    }
}

Imparipinnate

Thanks for this alternative answer! It looks very useful and I will quite-likely try this approach as well in the future! Unfortunately, I have already accepted the other answer which is also correct. – Farkas

Complete example using lidalia's slf4j-test package can be found here: github.com/jaegertracing/jaeger-client-java/pull/378/files – Formidable

This solution works fine if you are not using Spring. If you use Spring, it will throw a class not found exception (JoranConfigurator). – Cither

Answer 5

A simple solution could be to mock the appender with Mockito (for example)

MyClass.java

@Slf4j
class MyClass {
    public void doSomething() {
        log.info("I'm on it!");
    }
}

MyClassTest.java

import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.containsString;
import static org.hamcrest.Matchers.is;
import static org.mockito.Mockito.verify;         

@RunWith(MockitoJUnitRunner.class)
public class MyClassTest {    

    @Mock private Appender<ILoggingEvent> mockAppender;
    private MyClass sut = new MyClass();    

    @Before
    public void setUp() {
        Logger logger = (Logger) LoggerFactory.getLogger(MyClass.class.getName());
        logger.addAppender(mockAppender);
    }

    @Test
    public void shouldLogInCaseOfError() {
        sut.doSomething();

        verify(mockAppender).doAppend(ArgumentMatchers.argThat(argument -> {
            assertThat(argument.getMessage(), containsString("I'm on it!"));
            assertThat(argument.getLevel(), is(Level.INFO));
            return true;
        }));

    }

}

NOTE: I'm using assertion rather than returning false as it makes code and (possible) error easier to read, but it won't work if you have multiple verifications. In that case you need to return boolean indicating if the value is as expected.

Thirtythree

does this work if I am using the lombok.extern.slf4j anntations like Slf4j? how do you mock or spy the logger if its not even an object in my clases? i.e. log.error is used just by providing the annotation Slf4j on my class... – Hoxha

@ennth It should work because you're injecting the mock wirh the static method LoggerFactory.getLogger().addAppender(mockAppender). Which works in the same way when you're creating the logger with Lombok – Thirtythree

Having same not working problem. What are the 'imports' for classes Logger and LoggerFactory? Why are the static imports listed and the others are not? – Hying

@DirkSchumacher I had the same confusion, it works with the following imports: 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.Appender; – Peristome

Answer 6

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.

Rog

Answer 7

I would recommend a simple, reusable spy implementation that can be included in a test as JUnit rule:

public final class LogSpy extends ExternalResource {

    private Logger logger;
    private ListAppender<ILoggingEvent> appender;

    @Override
    protected void before() {
        appender = new ListAppender<>();
        logger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); // cast from facade (SLF4J) to implementation class (logback)
        logger.addAppender(appender);
        appender.start();
    }

    @Override
    protected void after() {
        logger.detachAppender(appender);
    }

    public List<ILoggingEvent> getEvents() {
        if (appender == null) {
            throw new UnexpectedTestError("LogSpy needs to be annotated with @Rule");
        }
        return appender.list;
    }
}

In your test, you'd activate the spy in the following way:

@Rule
public LogSpy log = new LogSpy();

Call log.getEvents() (or other, custom methods) to check the logged events.

Epa

In order for this to work, you need to import ch.qos.logback.classic.Logger; instead of import org.slf4j.LoggerFactory; otherwise addAppender() is not available. It took me a while to figure this out. – Selfexcited

Doesn't work for me. It looks as if the rule is not applied correctly: while debugging i found before() and after() never reached, thus the appender is never created/attached and the UnexpectedTestError fires. Any ideas what i'm doing wrong? Does the rule need to be placed into a certain package? Also, pls add the import section to your answer, as some of the objects/interfaces have ambiguous names. – Amberambergris

Answer 8

This is an alternative using lambdas that makes the log capturing logic reusable among tests (encapsulating its implementation) and doesn't require @BeforeEach/@AfterEach (in some of the proposed solutions the appender is not detached, which can lead to memory leaks).

Code under test:

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

public class MyService {

    private static final Logger LOG = LoggerFactory.getLogger(MyService.class);


    public void doSomething(String someInput) {
        ...
        LOG.info("processing request with input {}", someInput);
        ...
    }
}

Interceptor helper:

package mypackage.util

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

import java.util.List;

public class LogInterceptor {

    public static List<ILoggingEvent> interceptLogs(Class<?> klass, Runnable runnable) {
        final Logger logger = (Logger) LoggerFactory.getLogger(klass);
        final ListAppender<ILoggingEvent> listAppender = new ListAppender<>();
        listAppender.start();
        logger.addAppender(listAppender);
        try {
            runnable.run();
            return listAppender.list;
        } finally {
            logger.detachAppender(listAppender);
        }
    }
}

Test suite:

import static mypackage.util.LogInterceptor.interceptLogs;

public class MyServiceTest {

  private MyService myService; 
  ...

  @Test
  void doSomethingLogsLineWithTheGivenInput() {
        List<ILoggingEvent> logs = interceptLogs(
                myService.getClass(),
                () -> myService.doSomething("foo")
        );

        assertThat(logs).isNotEmpty();
        ILoggingEvent logEntry = logs.get(0);
        assertThat(logEntry.getFormattedMessage()).isEqualTo("Processing request with input foo");
        assertThat(logEntry.getLevel()).isEqualTo(Level.INFO);
  }

}

Hudnut

Answer 9

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.

Alidia

Answer 10

The class that I wanted to log has a lombok @Slf4j annotation on it, and I did as follows.

Testee class

@Slf4j
@Service
public class TesteeService {
   Mono<ResponseEntity<HttpStatus>> sendRequest(RequestDto requestDto) {
       ...logs an ERROR sometimes...
   }
}

Created a new class

public class MemoryLogAppender extends AppenderBase<ILoggingEvent> {
    private final List<LogEvent> list = new ArrayList<>();
    private final PatternLayoutEncoder encoder;
    
    public MemoryLogAppender(LoggerContext loggerContext, String pattern) {
        super.setContext(loggerContext);
        this.encoder = new PatternLayoutEncoder();
        this.encoder.setContext(loggerContext);
        encoder.setPattern(pattern);
        encoder.start();
    }
    
    
    @Override
    protected void append(ILoggingEvent event) {
        String msg = new String(encoder.encode(event));
        LogEvent logEvent = new LogEvent(msg, event.getLevel(), event.getLoggerName());
        list.add(logEvent);
    }
    
    /**
     * Search for log message matching given regular expression.
     *
     * @param regex Regex to match
     * @return matching log events
     */
    public List<MemoryLogAppender.LogEvent> matches(String regex) {
        return this.list.stream()
            .filter(event -> event.message.matches(regex))
            .collect(Collectors.toList());
    }
}

Test class

class TestClass {
    private static MemoryLogAppender logAppender;
    
    @BeforeAll
    static void beforeAll() {
        logAppender = new MemoryLogAppender((LoggerContext) LoggerFactory.getILoggerFactory(), "%-5level: %message");
        logAppender.start();
    }
    
    @AfterAll
    static void afterAll() {
        logAppender.stop();
    }
    
    ...
    ...

    @Test
    void bad_reference() throws Exception {
        ResponseEntity<HttpStatus> response = testeeService.sendRequest(requestDto).block();

        assertThat(logAppender.search("This reference is bad."))
            .hasSize(1);

        assertTrue(response.getStatusCode().is4xxClientError());
    }
}

Fireworks

Answer 11

Approach using custom appender

Unit test:

package org.example;

import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.containsInAnyOrder;

import java.util.List;

import org.junit.Test;
import org.slf4j.LoggerFactory;

import ch.qos.logback.classic.Logger;


public class LoggerTest {

    @Test
    public void logDifferentData() {
        Logger logger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
        CaptureLogsAppender captureLogsAppender = new CaptureLogsAppender();

        logger.addAppender(captureLogsAppender);
        captureLogsAppender.start();

        // you can call service.doSomeWork() here to collect logs from particular service
        LoggerFactory.getLogger("org.example.LoggerTest").debug("message1");
        LoggerFactory.getLogger("org.example.LoggerTest").debug("message2");

        captureLogsAppender.stop();
        logger.detachAppender(captureLogsAppender);

        List<String> logs = captureLogsAppender.getLogs();

        assertThat(logs, containsInAnyOrder("message1", "message2"));
    }
}

Custom Appender that intercepts calls to Logback:

package org.example;

import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.AppenderBase;
import java.util.ArrayList;
import java.util.List;

public class CaptureLogsAppender extends AppenderBase<ILoggingEvent> {
    private List<String> logs = new ArrayList<>();

    @Override
    protected void append(ILoggingEvent eventObject) {
        eventObject.prepareForDeferredProcessing();
        logs.add(eventObject.getFormattedMessage());
    }

    public List<String> getLogs() {
        return logs;
    }
}

Pileate

Answer 12

As this is something I do in many tests, I have written a helper class to do this without much boilerplate:

Junit Test

  @Test

  void testHello() {

    final List<ILoggingEvent> logs = TestUtil.captureLogs(() -> {

      MySerive.sayHello();

    }, Level.INFO);

   

    Assertions.assertEquals(1, logs.size());

    Assertions.assertEquals("Hello World!", logs.get(0).getMessage());

  }

TestUtil Class

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;

import org.slf4j.LoggerFactory;



import java.util.List;



public class TestUtil {



  @FunctionalInterface

  public interface RunnerWithLogCapture<T extends Throwable> {

    void run() throws T;

  }



  public static <T extends Throwable> List<ILoggingEvent> captureLogs(final RunnerWithLogCapture<T> testCode,

                                                final Level level) throws T {

    final Logger logger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);

    logger.setLevel(level);

    final ListAppender<ILoggingEvent> listAppender = new ListAppender<>();

    listAppender.start();

    logger.addAppender(listAppender);

    try {

      testCode.run();

      final List<ILoggingEvent> logsList = listAppender.list;

      return logsList;

    } finally {

      logger.detachAppender(listAppender);
      listAppender.stop();

    }

  }

}

Jepson

Answer 13

I was unable to run with logback (got no records caught), but this way worked for me:

List<LogRecord> list = new ArrayList<>();

java.util.logging.Logger.getLogger("SQL-logger").addHandler(new Handler() {
    @Override
    public void publish(LogRecord record) {
        list.add(record);
    }

    @Override
    public void flush() {
    }

    @Override
    public void close() throws SecurityException {
    }
});

assertThat(callSqlExcutor()).isNotZero();
assertThat(list.stream().map(LogRecord::getMessage).filter(m -> m.startsWith("select ")).count()).isNotZero();

Shafting