Slf4JBridgeHandler.uninstall called too early in context close, swallowing JUL log output.

[sijskes]

Behavior

JUL logging output in @PreDestroy methods is swallowed, not logged.

Expected behavior

JUL logging output in @PreDestroy methods logged.

Description

LogbackLoggingSystem.cleanup() -> Slf4JLoggingSystem.cleanup() -> Slf4JBridgeHandler.uninstall()

is called before @PreDestroy methods.

therefore JUL logging in @PreDestroy is swallowed, not logged.

This is because the uninstall was registered as a SmartLifeCycle, in LoggingApplicationListener.onApplicationPreparedEvent.

And SmartLifeCycle.stop() is called early in the AbstractApplicationContext.doClose(), before the destroyBeans().

Versions

• spring-boot-2.6.13.jar / spring-boot-2.7.7.jar
• jul-to-slf4j-1.7.36.jar

Context

• WAR deployment
• Apache Tomcat Version 9.0.53

Misc

There are multiple call paths reaching LoggingApplicationListener.cleanupLoggingSystem(). Also one for onContextClosedEvent(). but this contains shortcut code for exactly this scenario. So it looks like the SmartLifeCycle shutdown route is intentional, but unclear to me why the shutdown of Slf4JBridgeHandler should happen so early in the shutdown.

[wilkinsona]

This behaviour was improved in 45ad155 but it sounds like it didn't go far enough for your needs. I'm not sure if we'll be able to improve things further, but we can take a look. To help us to do so, please provide a complete yet minimal sample that reproduces the problem. You can share such a sample with us by pushing it to a separate repository on GitHub or by zipping it up and attaching it to this issue.

Please note that Spring Boot 2.6.x is no longer eligible for open source support. Any fix for this issue will only be made in 2.7.x at the earliest.

[sijskes]

When it turns out that it might not be easy to fix this in AbstractApplicationContext.doClose(), we could discuss the need of calling the Slf4JLoggingSystem.removeJdkLoggingBridgeHandler() in Slf4JLoggingSystem.cleanup(). All it does is removing a reference from the JUL logging handlers lists, no listener calling or cleaning resources (so it looks).

It would be easily fixed by adding a property which shortcuts this behaviour, but i'm not familiar with how easy this is perceived in the whole spring project.

I will try to bump the version to a higher level, this will take some time. If this doesnt fix things, i will build minimal sample.

[sijskes]

upgraded tot spring boot 2.7.6.

what stands out here, that although Slf4JLoggingSystem decides not to install SLF4JBridgeHandler in configureJdkLoggingBridgeHandler() it still decides to uninstall it. That to me seems asymmetric.

So any change of handling SLF4JBridgeHandler in the class derived from SpringBootServletInitializer is impossible.

[sijskes]

logbugdemo.zip

minimal example demonstrating this bug

[sijskes]

stackdump of preDestroy();

stackdump of cleanup();

proposed changes:

• do not shutdown logging subsystem, that you did not start yourself. (re: Slf4JLoggingSystem)
• shutdown logging at the latest moment (re: AbstractApplicationContext)

The first one is the most fundamental one, if applied it allows you to control the logging bridge at application level.

[sijskes]

when deployed with tomcat the Slf4JLoggingSystem.isJulUsingASingleConsoleHandlerAtMost() returns false dependent on the logging configuration used in the tomcat server.