Duplicate logging in Tomcat console with default settings

[romanstrobl]

Spring boot version: 2.0.2.RELEASE
Last worked in version: 1.5.13.RELEASE
Tomcat version: 9.0.0.0 (also reproducible on older version of Tomcat)
Java version: 1.8.0_121-b13

Messages logged using Logger.getLogger().log() are logged twice into console when application is deployed to Tomcat with default Spring boot configuration (application.properties and logback.xml are missing).

When application is started standalone from console, the issue does not occur and each call of Logger.getLogger().log() causes only one message in console.

I attach a sample project in which the issue can be easily reproduced:
logging-bug.zip

To reproduce the issue, follow these steps:

1. Build the project using mvn package.
2. Deploy created war file to Tomcat in default configuration.
3. Access URL: http://localhost:8080/logging-bug/rest/status
   -> Two log messages are printed in console instead of only one message. See screenshot:

[romanstrobl]

I believe the issue is related to these commits:
0679d43
844782b

Instead of calling SLF4JBridgeHandler.removeHandlersForRootLogger() only the ConsoleHandler is deregistered, however this happens only in case there is one handler attached to the root logger and it is instanceof ConsoleHandler.

This fix will not work for Tomcat in default configuration, because Tomcat by default adds two handlers to the root logger:

• AsyncFileHandler
• ConsoleHandler

So when the application starts, there are actually three handlers on the root logger:

• AsyncFileHandler
• ConsoleHandler
• SLF4JBridgeHandler

Two of these handlers log into console which causes duplicate messages to be printed out.

When the Spring boot application is started standalone from command line, the fix works fine, because the ConsoleHandler is deregistered and replaced by SLF4JBridgeHandler.

[wilkinsona]

Thanks for the analysis.

My current thinking is that we shouldn't be trying to route JUL-based logging into SLF4J and Boot's logging at all when deployed to Tomcat. As things stand, in addition to the duplicate messages, you also get logging for other applications running in the same Tomcat instance or from the Tomcat instance itself appearing in the application's logs. This is particularly obvious when you use the application's file-based logging and enable debug logging for org.apache. Looking a Tomcat's self-hosted docs, served by a separate web application, results in the Boot application's log file containing entries from the docs app similar to the following:

2018-06-19 13:54:41.300 DEBUG 2522 --- [http-nio-8080-exec-8] o.a.c.authenticator.AuthenticatorBase    : Security checking request GET /docs/images/asf-logo.svg

[wilkinsona]

There's a secondary problem that LogbackLoggingSystem installs a LevelChangePropagator so any log levels configured by an individual Spring Boot app are propagated into Tomcat's JUL configuration, potentially affecting multiple applications. I think we should disable this functionality as well when running in Tomcat (or any environment with customised JUL configuration).