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.