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:
Comment From: romanstrobl
I believe the issue is related to these commits: https://github.com/spring-projects/spring-boot/commit/0679d4369cc99f4e26655a65398ae995fc6a36b0 https://github.com/spring-projects/spring-boot/commit/844782b20bf1de0ca22b031fd2874a55a483044e
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.
Comment From: 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
Comment From: 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).
Comment From: wilkinsona
This needs to be revisited as it has resulted in JUL-based logging being written to System.err during shutdown.
Comment From: steowens
Spring boot logging is still borked up. If you use log4j you will get duplicate log entries whenever you leverage logging.level.package... in application.yml and there doesn't seem to be any way in configuration to turn off additivity. It should be turned off by default.
Comment From: bclozel
The comment above has been reported in #31032 as it should.