Log4j2 not working with Spring Boot 3.4.2 together with BlockHound

[micopiira]

When upgrading to Spring Boot 3.4.2 our logging stopped completely working.

After narrowing down I figured the problem happens with Spring Boot 3.4.2 when using Log4j2 together with BlockHound.

Here is a minimum reproducer repo: https://github.com/micopiira/spring-boot-log4j2-issue

Spring Boot 3.4.1 with exact same Log4j2 version and BlockHound version works.

Spring Boot 3.4.1:

Spring Boot 3.4.2:

[wilkinsona]

Thanks for the report and for the minimal sample. I assume that something has changed in Spring Boot 3.4.2 that is causing BlockHound to break Log4j2 in some way. Unfortunately, given that this works fine without BlockHound and the way in which BlockHound works, I don't think there's anything we can do about this in Spring Boot. Please raise a BlockHound issue so that they can investigate further.

[wilkinsona]

Re-opening. Thanks to @violetagg's analysis, this has been tracked down to an assumption in StatusConsoleListener#closeNonSystemStream that is faulty when BlockHound is involved. It's only started causing a problem due to #43578.

[nosan]

Thanks for the sample, @micopiira.

StandardOutputIntegration.applyTo(...) replaces the standard OUT and ERR streams with PrintStreamDelegate. During initialization, Log4J2LoggingSystem attempts to reset the StatusLogger.FallbackListener stream (which was previously replaced by BlockHound). This results in PrintStreamDelegate being closed, which in turn delegates the close call to the standard OUT and ERR streams.

One of the options is to revert b6b9237 and fix SampleLog4j2StructuredLoggingApplicationTests.
main...nosan:spring-boot:43963

Meanwhile, you can use this solution reactor/BlockHound#469 (comment)

[violetagg]

Thanks for the sample, @micopiira.

StandardOutputIntegration.applyTo(...) replaces the standard OUT and ERR streams with PrintStreamDelegate. During initialization, Log4J2LoggingSystem attempts to reset the StatusLogger.FallbackListener stream (which was previously replaced by BlockHound). This results in PrintStreamDelegate being closed, which in turn delegates the close call to the standard OUT and ERR streams.

@nosan Please check the screenshot below -> it is not the delegator that closes but the real system stream

One of the options is to revert b6b9237 and fix SampleLog4j2StructuredLoggingApplicationTests. main...nosan:spring-boot:43963

Meanwhile, you can use this solution reactor/BlockHound#469 (comment)

[nosan]

@violetagg

Oh, you're right, my mistake.

// stream = original System.out
// System.out = BlockHound.PrintStreamDelegate

    private static void closeNonSystemStream(final OutputStream stream) {
        // Close only non-system streams
        if (stream != System.out && stream != System.err) {
            try {
                stream.close();
            } catch (IOException error) {
                // We are at the lowest level of the system.
                // Hence, there is nothing better we can do but dumping the failure.
                error.printStackTrace(System.err);
            }
        }
    }

so Log42J closes the original stream.

[eichingertim]

I noticed a similar problem in IntelliJ:

When I upgraded to 3.4.2 and executed a SpringBootTest with OutputCaptureExtension (Log Framework Log4J) the test is marked as "Not started" after some time and produces no log output. However when the tests are run via maven it works fine.

When I downgraded again to 3.4.1 the behavior is back to normal. Can anybody else validate this?

[nosan]

@eichingertim

I've tried the following test with IntelliJ IDEA and 3.4.2:

@SpringBootTest
@ExtendWith(OutputCaptureExtension.class)
class SpringBootLog4j2DemoApplicationTests {

	@Test
	void contextLoads(CapturedOutput output) {
		Assertions.assertThat(output).isNotEmpty();
	}

}

And indeed it does not work for me as well.

This fix main...nosan:spring-boot:gh-43963 resolves both issues.

[eichingertim]

Thanks for validating ;) Are you able to get this into 3.4.3?

[nosan]

I don't make the decision, but it seems likely that the plan is to fix it in 3.4.3. The solution I proposed is just one option—another option is to revert resetFallbackListenerStream changes. There's a good chance that someone on the team might have a better approach or another idea for handling this.