Hi... I have run into an odd issue trying to troubleshoot an issue within my application. I was wanting to see some debug output so I setup my logback.xml file but no matter what I did I couldn't get debug output to show. Eventually I created the below code block to validate what logback.xml was being used. At the initial startup the log context is great and uses my configured logback information. Unfortunately after the spring context has been loaded and the application is running the log context has changed to the default spring boot logback configuration. How can I correct this or is this an issue with spring boot?
@ComponentScan
@EnableAutoConfiguration
public class Application {
public static void main(String[] args) {
LoggerContext loggerContext = ((ch.qos.logback.classic.Logger) log).getLoggerContext();
URL mainURL = ConfigurationWatchListUtil.getMainWatchURL(loggerContext);
log.info("Logback used '{}' as the configuration file.", mainURL);
Level level = loggerContext.getLogger(Logger.ROOT_LOGGER_NAME).getLevel();
log.info("Root logger level is: {}", level);
SpringApplication.run(Application.class, args);
URL mainUrlAfter = ConfigurationWatchListUtil.getMainWatchURL(loggerContext);
log.info("Logback used '{}' as the configuration file.", mainUrlAfter);
Level levelAfter = loggerContext.getLogger(Logger.ROOT_LOGGER_NAME).getLevel();
log.info("Root logger level is: {}", levelAfter);
}
}
output
2014-01-07 15:25:44.983 INFO --- [ main] com.testapp.Application : Logback used 'file:/C:/Development/Workspaces/git/testapp/target/classes/logback.xml' as the configuration file.
2014-01-07 15:25:44.988 INFO --- [ main] com.testapp.Application : Root logger level is: DEBUG
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v0.5.0.BUILD-SNAPSHOT)
2014-01-07 15:25:45.394 INFO 11708 --- [ main] com.testapp.Application : Starting Application on TESTMACHINE with PID 11708 (C:\Development\Workspaces\git\testapp\target\classes started by sclark)
2014-01-07 15:25:45.429 INFO 11708 --- [ main] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@10d4159f: startup date [Tue Jan 07 15:25:45 PST 2014]; root of context hierarchy
...
2014-01-07 15:25:50.688 INFO 11708 --- [ main] com.testapp.Application : Started Application in 5.52 seconds (JVM running for 6.053)
2014-01-07 15:25:50.689 INFO 11708 --- [ main] com.testapp.Application : Logback used 'jar:file:/C:/Development/Repo/org/springframework/boot/spring-boot/0.5.0.BUILD-SNAPSHOT/spring-boot-0.5.0.BUILD-SNAPSHOT.jar!/org/springframework/boot/logging/logback/logback.xml' as the configuration file.
2014-01-07 15:25:50.689 INFO 11708 --- [ main] com.testapp.Application : Root logger level is: INFO
Comment From: ShawnTuatara
Got a bit more details... I did a StatusPrinter.print(loggerContext) at the end and this is the output:
16:37:52,375 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
16:37:52,376 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
16:37:52,376 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Development/Workspaces/git/testapp/target/classes/logback.xml]
16:37:52,451 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
16:37:52,476 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word clr with class [org.springframework.boot.logging.logback.ColorConverter]
16:37:52,476 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word wex with class [org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter]
16:37:52,476 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
16:37:52,480 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE]
16:37:52,503 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
16:37:52,568 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
16:37:52,568 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[ROOT]
16:37:52,569 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.http] to TRACE
16:37:52,569 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
16:37:52,571 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@e5d1aef - Registering current configuration as safe fallback point
16:37:52,786 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@17850c5a - URL [jar:file:/C:/Development/Repo/org/springframework/boot/spring-boot/0.5.0.BUILD-SNAPSHOT/spring-boot-0.5.0.BUILD-SNAPSHOT.jar!/org/springframework/boot/logging/logback/logback.xml] is not of type file
16:37:52,788 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
16:37:52,789 |-INFO in ch.qos.logback.core.joran.util.ConfigurationWatchListUtil@1fedf4c6 - Adding [jar:file:/C:/Development/Repo/org/springframework/boot/spring-boot/0.5.0.BUILD-SNAPSHOT/spring-boot-0.5.0.BUILD-SNAPSHOT.jar!/org/springframework/boot/logging/logback/base.xml] to configuration watch list.
16:37:52,789 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@17850c5a - URL [jar:file:/C:/Development/Repo/org/springframework/boot/spring-boot/0.5.0.BUILD-SNAPSHOT/spring-boot-0.5.0.BUILD-SNAPSHOT.jar!/org/springframework/boot/logging/logback/base.xml] is not of type file
16:37:52,792 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word clr with class [org.springframework.boot.logging.logback.ColorConverter]
16:37:52,792 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word wex with class [org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter]
16:37:52,792 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
16:37:52,792 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE]
16:37:52,793 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
16:37:52,794 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
16:37:52,796 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
16:37:52,802 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
16:37:52,812 |-INFO in ch.qos.logback.core.rolling.FixedWindowRollingPolicy@3f61038a - No compression will be used
16:37:52,819 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: /tmp/spring.log
16:37:52,819 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [/tmp/spring.log]
16:37:52,821 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
16:37:52,821 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[ROOT]
16:37:52,821 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
16:37:52,821 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.validator.internal.util.Version] to WARN
16:37:52,821 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.coyote.http11.Http11NioProtocol] to WARN
16:37:52,821 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.crsh.plugin] to WARN
16:37:52,821 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.tomcat.util.net.NioSelectorPool] to WARN
16:37:52,822 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.catalina.startup.DigesterFactory] to ERROR
16:37:52,822 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
16:37:52,822 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@7a2f7987 - Registering current configuration as safe fallback point
16:37:53,034 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@42d3ccbc - URL [jar:file:/C:/Development/Repo/org/springframework/boot/spring-boot/0.5.0.BUILD-SNAPSHOT/spring-boot-0.5.0.BUILD-SNAPSHOT.jar!/org/springframework/boot/logging/logback/logback.xml] is not of type file
16:37:53,037 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
16:37:53,037 |-INFO in ch.qos.logback.core.joran.util.ConfigurationWatchListUtil@1fedf4c6 - Adding [jar:file:/C:/Development/Repo/org/springframework/boot/spring-boot/0.5.0.BUILD-SNAPSHOT/spring-boot-0.5.0.BUILD-SNAPSHOT.jar!/org/springframework/boot/logging/logback/base.xml] to configuration watch list.
16:37:53,037 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@42d3ccbc - URL [jar:file:/C:/Development/Repo/org/springframework/boot/spring-boot/0.5.0.BUILD-SNAPSHOT/spring-boot-0.5.0.BUILD-SNAPSHOT.jar!/org/springframework/boot/logging/logback/base.xml] is not of type file
16:37:53,040 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word clr with class [org.springframework.boot.logging.logback.ColorConverter]
16:37:53,040 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word wex with class [org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter]
16:37:53,040 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
16:37:53,041 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE]
16:37:53,041 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
16:37:53,042 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
16:37:53,043 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
16:37:53,043 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
16:37:53,044 |-INFO in ch.qos.logback.core.rolling.FixedWindowRollingPolicy@5f266cea - No compression will be used
16:37:53,044 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: /tmp/spring.log
16:37:53,044 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [/tmp/spring.log]
16:37:53,045 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
16:37:53,045 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[ROOT]
16:37:53,045 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
16:37:53,045 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.validator.internal.util.Version] to WARN
16:37:53,045 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.coyote.http11.Http11NioProtocol] to WARN
16:37:53,045 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.crsh.plugin] to WARN
16:37:53,045 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.tomcat.util.net.NioSelectorPool] to WARN
16:37:53,045 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.catalina.startup.DigesterFactory] to ERROR
16:37:53,045 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
16:37:53,045 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@53b8a773 - Registering current configuration as safe fallback point
Based on this it looks like logback picked up the workspace configuration but it was overwritten twice by the spring boot's configuration.
Comment From: ShawnTuatara
My workaround for now is
LoggerContext loggerContext = ((ch.qos.logback.classic.Logger) log).getLoggerContext();
URL mainURL = ConfigurationWatchListUtil.getMainWatchURL(loggerContext);
log.info("Logback used '{}' as the configuration file.", mainURL);
Level level = loggerContext.getLogger(Logger.ROOT_LOGGER_NAME).getLevel();
log.info("Root logger level is: {}", level);
SpringApplication.run(Application.class, args);
JoranConfigurator joranConfigurator = new JoranConfigurator();
joranConfigurator.setContext(loggerContext);
loggerContext.reset();
try {
joranConfigurator.doConfigure(mainURL);
} catch (JoranException e) {
e.printStackTrace();
}
Comment From: dsyer
Just for clarity, what do you actually need to do? Just a custom logback.xml?
What you are seeing might be a windows problem. Any chance you can try your original code on a different platform, just to confirm?
Comment From: ShawnTuatara
Yah I just want to have my logback.xml to be used once the Spring application context has been loaded. Trying it now on another platform.
Comment From: ShawnTuatara
Same result from a CentOS box. I even created the full jar package that spring boot uses and ran it as a java -jar.
2014-01-08 09:37:28.058 INFO --- [ main] com.testapp.Application : Logback used 'jar:file:/media/workspaces/git/testapp/target/testapp-0.0.1-SNAPSHOT.jar!/logback.xml' as the configuration file.
2014-01-08 09:37:28.069 INFO --- [ main] com.testapp.Application : Root logger level is: DEBUG
...
2014-01-08 09:37:45.663 INFO 32162 --- [ main] com.testapp.Application : Started Application in 16.927 seconds (JVM running for 23.258)
2014-01-08 09:37:45.665 INFO 32162 --- [ main] com.testapp.Application : Logback used 'jar:file:/media/workspaces/git/testapp/target/testapp-0.0.1-SNAPSHOT.jar!/lib/spring-boot-0.5.0.BUILD-SNAPSHOT.jar!/org/springframework/boot/logging/logback/logback.xml' as the configuration file.
2014-01-08 09:37:45.666 INFO 32162 --- [ main] com.testapp.Application : Root logger level is: INFO
Comment From: dsyer
I think that fixed it (there was certainly a problem). Can you try again with a snapshot (just add a logback.xml and verify that it works)?
Comment From: ShawnTuatara
Looks good. Sorry for the delayed response on testing it. Thanks for looking into this.
2014-01-21 11:40:49.862 INFO --- [ main] com.testapp.Application : Logback used 'file:/C:/Development/Workspaces/git/testapp/target/classes/logback.xml' as the configuration file.
2014-01-21 11:40:49.867 INFO --- [ main] com.testapp.Application : Root logger level is: DEBUG
...
2014-01-21 11:40:55.038 INFO 4844 --- [ main] .s.b.c.e.j.JettyEmbeddedServletContainer : Jetty started on port: 8080
2014-01-21 11:40:55.040 INFO 4844 --- [ main] com.testapp.Application : Started Application in 5.001 seconds (JVM running for 5.508)
2014-01-21 11:40:55.040 INFO 4844 --- [ main] com.testapp.Application : Logback used 'file:/C:/Development/Workspaces/git/testapp/target/classes/logback.xml' as the configuration file.
2014-01-21 11:40:55.040 INFO 4844 --- [ main] com.testapp.Application : Root logger level is: DEBUG
Comment From: RobHK
Hello,
Is this fix in a released version please? I am having the same issue using the spring-boot-starter-parent.
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>1.2.4.RELEASE</version>
</parent>
Comment From: wilkinsona
As confirmed above this issue was fixed in 1.0.0.RC1. If you believe you've found a similar problem, please open a new issue with a description and details of how to recreate it.
Comment From: RobHK
OK thanks I'll check my config again. On 22 Jun 2015 11:21, "Andy Wilkinson" notifications@github.com wrote:
As confirmed above https://github.com/spring-projects/spring-boot/issues/196#issuecomment-32955229 this issue was fixed in 1.0.0.RC1. If you believe you've found a similar problem, please open a new issue with a description and details of how to recreate it.
— Reply to this email directly or view it on GitHub https://github.com/spring-projects/spring-boot/issues/196#issuecomment-114058978 .
Comment From: MalathiBoggavarapu
Thanks a ton for reporting this issue. I am facing this issue today and was pissed off. Fortunately i found your post and realized what the actual issue is. But this issue is closed and seems like it is resolved. But i still face the same issue with spring-boot-starter latest 2.7.1.
Comment From: wilkinsona
@MalathiBoggavarapu We're not aware of any problems with logback.xml in Spring Boot 2.7. If you believe you've found one then please open a new issue with a description of it and details of how to recreate it.