Testing Log Output Java Spring

Question

I have a spring boot 2 application running on java 10 using SLF4J and logback as the underlying logger.

Given the following spring component:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Service;

@Service
public class MyClass {

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

    public void hello() {
        // more logic...
        LOG.trace("World");
    }
}

And a test which wishes to verify the log output (imagine a more complex scenario where the log would contain variables and context information) or that the fact a log message is produced is deemed to be critical.

import org.junit.Rule;
import org.junit.Test;
import org.springframework.boot.test.rule.OutputCapture;

import static org.hamcrest.Matchers.containsString;

public class MyClassTest {

    private final MyClass myClass = new MyClass();

    @Rule
    public final OutputCapture outputCapture = new OutputCapture();

    @Test
    public void successShouldLogSuccessMessages() {
        myClass.hello();
        outputCapture.expect(containsString("World"));
    }
}

For this test to pass the log level must be set at TRACE. I noticed some unpredictable behaviour where the test would either fail or pass depending on the order in which tests run - see Seemingly Random Test Failure With Maven & Spring Boot 2 When A WebFluxTest Is Introduced

I have explored a few options, none of which seem "ideal" but do work.

1. Provide a log back config file on the test class path which sets the log level to trace for at least this one class.
2. Set the log level of this class to TRACE in a spring application properties class and run the test in a spring context.
3. Create a setup and tear down in the test class which programatically modifies the log level during the test execution and then resets it after.

The solution I have currently is to let Spring do the work of configuring the logger and make the test a spring context test (and to make sure it runs quickly only load the one bean I care about) as follows:

@RunWith(SpringRunner.class)
@SpringBootTest(properties = "spring.profiles.active=test")
@ContextConfiguration(classes = MyClass.class)
public class MyClassTest {

    private final MyClass myClass = new MyClass();

    @Rule
    public final OutputCapture outputCapture = new OutputCapture();

    @Test
    public void successShouldLogSuccessMessages() {
        myClass.hello();
        outputCapture.expect(containsString("World"));
    }
}

Where the content of application-test.properties is:

logging.level.com.example.MyClass=TRACE

This solution works, it does't require me to programmatically play around with loggers or put logback configuration on the classpath which keeps everything quite agnostic to the underlying log framework and keeping logback configuration away from the test classpath also means other tests which don't care about logging aren't picking up the config.

That said, it feels "odd", I've never really seen someone using spring tests this way (to test a single bean with no dependencies and no direct reliance on the context). The test started life as a plan POJO test with no care for spring and it feels more "pure" that it remains that way.

Is there a best practice that applies when trying to test the log outputs of an object via SLF4J?

Answer 1

Your approach is testing what your current logging configuration logs, rather than what is being sent to the logging system.

Instead of an OutputCapture rule, you can intercept the logging by writing your own appender or mocking out the SLF4J implementation. You could even fail the test from within your custom appender if something incorrect gets logged, such as an error. I'd recommend making your own @Rule that adds your own test appender, which can then do whatever custom logic you want of checking matchers or ensuring that the right data gets logged.