Logcaptor error logs do not contain expected content when reusing instance

[Emprah]

Describe the bug
I use logcaptor in a parameterized test method of a @SpringBootIntegrationTest class to check whether the expected error message was actually logged. I loosely followed the reuse example from the readme (see code snippets below).

For every parameterization, one error message is logged in the sut (verified that via debugger). When looking at the logcaptor.getErrorLogs though, this is not always correctly reflected there.

I tried out some things and it appears as if the following things make a difference:

• Just running the test method vs. running the whole test class
• Reusing the logcaptor instance or creating a new one every time
• Having the logcaptor field as an instance variable vs. making it static

The possible results for the assertion whether the specific error message has been logged are:

• Everything ok
• Assertion fails only for the first parameterized method call
• Assertion fails for all parameterizations

	static field, reuse	non-static field, reuse	static field, no reuse	non-static field, no reuse
ran test method	all fail	first fails	ok	ok
ran test class	all fail	ok	ok	ok

To Reproduce

@SpringBootIntegrationTest
class TestClass {
//    LogCaptor logcaptor;
//    static LogCaptor logcaptor;
//    LogCaptor logcaptor = LogCaptor.forClass(Sut.class);

    @Autowired
    Sut sut;
    
    @BeforeEach
    void beforeEach() {
//        logcaptor = LogCaptor.forClass(Sut.class);
//        logcaptor.clearLogs();
    }

    private static Stream<List<String>> provideParameters() {
        return Stream.of(
                null,
                List.of()
        );
    }

    @ParameterizedTest
    @MethodSource("provideParameters")
    void testMethod(List<String> parameters) {
        CompletableFuture<void> future = sut.doStuff(parameters);
        assertThrows(Exception.class, () -> future.get(10, TimeUnit.SECONDS));
        assertThat(logcaptor.getErrorLogs()).containsExactly("Expected error message");
    }
}

In Sut:

@Async
public CompletableFuture<Void> doStuff(List<String> params) {
    if (params == null || params.isEmpty()) {
        var errorMessage = "Expected error message";
        log.error(errorMessage);
        return CompletableFuture.failedFuture(new Exception(errorMessage));
    }

    try {
        // do stuff
    } catch (Exception e) {
        log.error(e.getMessage(), e);
        return CompletableFuture.failedFuture(e);
    }

    return CompletableFuture.completedFuture(null);
}

Expected behavior
I would have expected logCaptor.getErrorLogs to contain the expected error message no matter how the test method is run and no matter how the lagCaptor is defined and (re)used.

Environmental Data:

• Logcaptor 2.7.0
• junit 5.7.2
• jul-to-slf4j 1.7.32
• slf4j-api 1.7.32
• log4j-to-slf4j 2.14.1
• log4j-api 2.14.1
• Java 16.0.2
• Gradle 7.1.1
• Windows 10

[Hakky54]

Hi @Emprah

Thank for reporting this issue and sharing the detailed code snippets! Could you retry with the latest version and tell me if the issue is still present? The latest version is 2.7.2 and is able to capturing logs within a multi thread setup.

[Emprah]

I tried again with 2.7.2, but no difference unfortunately...

[Hakky54]

I have tried it locally and indeed I am getting the same behaviour which you mentioned. Reusing log captor works and I use it at some other places such as here: unit test example So I was amazed to see this issue.

I tried couple of different scenario's with the code snippet you have shared and I noticed that when I don't use SpringBootIntegrationTest annotation and try static field, with reusing logcaptor it works. So my assumption is that the spring annotation is messing things up for this specific setup. I investigated it but could not found the issue, so I ended up creating a stackoverflow question here: https://stackoverflow.com/questions/70259059/logcaptor-fails-to-capture-when-using-springboottest-annotation

For now I don't have a fix as I am not able to understand why the spring boot annotation messes logcaptor while using it as a static field. So I would suggest to use the following snippet for now till I have more info regarding this issue.

private LogCaptor logcaptor;

@BeforeEach
void setupLogCaptor() {
    logcaptor = LogCaptor.forClass(FooService.class);
}

@AfterEach
void closeLogCaptor() {
    logcaptor.close();
}

You could also use the following setup for the time being:

@SpringBootIntegrationTest
class TestClass {

    private LogCaptor logcaptor;
    private Sut sut;

    @Autowired
    TestClass(Sut sut) {
        this.sut = sut;
        this.logcaptor = LogCaptor.forClass(Sut.class);
    }
    
    @BeforeEach
    void beforeEach() {
        logcaptor.clearLogs();
    }

    private static Stream<List<String>> provideParameters() {
        return Stream.of(
                null,
                List.of()
        );
    }

    @ParameterizedTest
    @MethodSource("provideParameters")
    void testMethod(List<String> parameters) {
        CompletableFuture<void> future = sut.doStuff(parameters);
        assertThrows(Exception.class, () -> future.get(10, TimeUnit.SECONDS));
        assertThat(logcaptor.getErrorLogs()).containsExactly("Expected error message");
    }
}

or the following snippet:

@SpringBootIntegrationTest
class TestClass {

    private LogCaptor logcaptor;

    @Autowired    
    private Sut sut;

    @PostConstruct
    void init() {
        logcaptor = LogCaptor.forClass(Sut.class);
    }
    
    @BeforeEach
    void beforeEach() {
        logcaptor.clearLogs();
    }

    private static Stream<List<String>> provideParameters() {
        return Stream.of(
                null,
                List.of()
        );
    }

    @ParameterizedTest
    @MethodSource("provideParameters")
    void testMethod(List<String> parameters) {
        CompletableFuture<void> future = sut.doStuff(parameters);
        assertThrows(Exception.class, () -> future.get(10, TimeUnit.SECONDS));
        assertThat(logcaptor.getErrorLogs()).containsExactly("Expected error message");
    }
}

[Hakky54]

I got a reply on this issue from someone on stackoverflow and he mentioned the following:

The problem in the failing test is that the class variable logcaptor is created before the test application context is created. During the bootstrapping of the test application context, Spring Boot will completely configure logback from scratch. This causes the appender that was added in LogCaptor::forClass to get lost.

In the successful @SpringBootTest tests, the appender is added in a much later stage of the context lifecycle.

You can get the test to pass when you take any of the two passing @SpringBootTest tests and execute them together as long as the failing test is not executed first. That's because the Spring test framework will not bootstrap a new context but re-use the context of the first test that was run. You can get the test back to failing if you annotate its class with @DirtiesContext(classMode = ClassMode.BEFORE_CLASS) because then again a new context will be created after the class variable logcaptor is assigned.

I'm afraid that there is little one can do about this. This comment on github by the Spring Boot team is about a similar problem: spring-projects/spring-boot#19323 (comment)

source: https://stackoverflow.com/a/70310499/6777695

This issue is exactly the same as this one: spring-projects/spring-boot#19323 (comment) So I am not able to fix this on my side as it is a spring-boot related issue. So my advice would be to initialise LogCaptor after spring-boot has initialised the application context. This can be done by adding LogCaptor either in the BeforeAll, BeforeEach, Constructor, PostConstruct or in the test method.

So I am closing this issue as it is spring-boot related. Thank you for sharing this issue as it gave me more insight of how spring-boot is working and how LogCaptor is behaving in different kind of setups. I appreciate your investigation for the different scenario's 😊

[Emprah]

Sorry for the late answer, i was quite busy - but just wanted to return the thank you for the follow up :)

[hoangbnc]

@Hakky54 maybe you could introduce something like resetCaptor (that reassigns internally) so we can just do

@BeforeEach
void setupLogCaptor() {
  logCaptor.resetCaptor();
}

for such cases?

[Hakky54]

Hi @hoangbnc

Thank you for the suggestion, however this won't solve the root issue which is causing this different behavior. Adding a reset function and calling that in the before each is not different than just initializing it at that level. I think the ideal solution for this kind of use case or rather generic use case when using spring with junit 4 or 5 would be creating a junit-extension for logcaptor which would take away all of the verbosity for creating, resetting and disposal of logcaptor in the different test phases such as before all, before each, after each and after all.