Describe quirks of JUL and Log4j2 in the javadoc of OutputCaptureExtension

[jianlinshi]

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

}

[philwebb]

We've seen issues relating to log configuration in the past, for example #27902 (comment).

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

[jianlinshi]

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

[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.

[jianlinshi]

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

[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:

@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.

[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.

[jianlinshi]

Awesome! Thanks

[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.

[coltongoates]

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

[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.

[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

[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.