SpringBoot Describe quirks of JUL and Log4j2 in the javadoc of OutputCaptureExtension

Hi, I ran into this problem below:

For each test, it passes. But if I run the test class, it always failed on the 2nd. Any ideas?

Thanks

import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;
import org.springframework.boot.logging.AbstractLoggingSystemTests;
import org.springframework.boot.test.system.CapturedOutput;
import org.springframework.boot.test.system.OutputCaptureExtension;

import java.util.logging.Logger;

import static org.assertj.core.api.Assertions.assertThat;

@ExtendWith(OutputCaptureExtension.class)
public class TestCapture extends AbstractLoggingSystemTests {
    static Logger LOG=Logger.getLogger(TestCapture.class.getName());


    @Test
    void test(CapturedOutput output) {
        System.out.println("ok");
        LOG.warning("error");
        assertThat(output).contains("ok");
        assertThat(output).contains("error");

    }

    @Test
    void test2(CapturedOutput output) {
        LOG.info("not ok");
        LOG.warning("type 1 error");
        assertThat(output).contains("not");
        assertThat(output).contains("type 1");
    }

}


**Comment From: philwebb**

We've seen issues relating to log configuration in the past, for example https://github.com/spring-projects/spring-boot/issues/27902#issuecomment-916275464.

Can you please share a sample application that replicates the issue so we can see exactly how your logs are being configured.

**Comment From: jianlinshi**

Thanks for the quick response. I didn't use log4j.  The code above is able to replicate the issue.

**Comment From: philwebb**

Although the snippet above might replicate the issue, it would be best if we could have a sample application. That way we know that we're aligned on logging configurations and dependency versions.

**Comment From: jianlinshi**

https://github.com/jianlinshi/nlp-etl-runner

**Comment From: philwebb**

Thanks for the sample. The problem is with `java.util.logging.StreamHandler` which is caching the `output` `OutputStream`. With a `ConsoleHandler` the output is a `OutputStreamWriter` wrapping `System.err`.

Our `OutputCaptureExtension` works by replacing `System.err` when the test runs. If you run one test at a time things are fine, but when you run both tests the second one doesn't fetch `System.err` again so the captured output is sent to the wrong place.

To get things working, you can add the following to your tests:

```java
@AfterEach
void reset() throws Exception {
    LogManager.getLogManager().readConfiguration();
}

That will force all handles to get closed so the next run will capture the correct System.err.

Comment From: philwebb

Flagging for team attention to see if we should try and do this automatically in the OutputCaptureExtension. I'm not sure we should because the extension really shouldn't know about any specific loggers.

Comment From: jianlinshi

Awesome! Thanks

Comment From: wilkinsona

I don't think we should do this automatically, but I think it would be worth mentioning it in the javadoc. We could also mention the need for follow=true when configuring a Log4j2 console appender.

Comment From: coltongoates

@wilkinsona can you briefly explain why follow=true is required for compatibility with Log4j2?

Comment From: wilkinsona

Without follow=true the same problem happens. Log4j2 gets hold of System.out and System.err once and then caches them. This means that it does not use the replacements configured by OutputCaptureExtension and its output is then not captured.

Comment From: fokion

same issue happening when you run tests in parallel and you have Logback and Sl4j setup in your project. In some cases the test method will have a captured output with dirty context and the assertion will fail. Will try to create a test scenario to share here

Comment From: edigu

@fokion Did the latest fix address the issue for you? I am also not using log4j and app uses log back, if my tests runs after any test that involves @SpringBootTest the my unit test that involves output capture extension fails because output is empty. When I run the test alone it passes.

I have lombok’s @Slf4j on my test subject and adding quirks mentioned above did not help at all. Also interesting that sometimes my tests are passing on CI, they are flaky now. I am suspecting that either a class loading order changes the behaviour or a delay happens somewhere else that causes assertion failure before the log entry arrives to the console through the appender.