-Dlogback.configurationFile=logback.xml ignored when running Spring-Boot

spring logback spring-boot
Andrew Harmel-Law picture Andrew Harmel-Law · Feb 12, 2014 · Viewed 62.3k times · Source

We have a spring-boot 1.0.RC1 application, with logback configured for logging and a logback.xml file in src/test/resources. When we run spring-boot from maven, the logback file seems to be seen and respected. (That's our required logging format after the spring-boot logo)

D:\Users\myName\My Projects\Work\my-co\my-app\src\my-app\my-app-camel>mvn  clean spring-boot:run -Dlogback.statusListenerClass=ch.qos.logback.core.status.OnConsoleStatusListener -Dlogback.configurationFile=src/test/resources/logback.xml

<snip/>

[INFO] --- spring-boot-maven-plugin:0.5.0.M7:run (default-cli) @ my-app-camel ---
06:41:56,011 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [src/test/resources/logback.xml] at [file:/D:/Users/myName/My%20Projects/Work/my-co/my-app/src/my-app/my-app-camel/src/test/resources/logback.xml]
06:41:56,150 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
06:41:56,170 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 5 seconds
06:41:56,171 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[D:\Users\myName\My Projects\Work\my-co\my-app\src\my-app\my-app-camel\src\test\resources\logback.xml]] every 5 seconds.
06:41:56,172 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
06:41:56,223 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
06:41:56,233 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
06:41:56,276 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
06:41:56,389 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [me.moocar.logbackgelf.GelfAppender]
06:41:56,398 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [GELF]
06:41:56,567 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.my-co.my-app.] to DEBUG
06:41:56,568 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [com.my-co.my-app.] to false
06:41:56,569 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[com.my-co.my-app.]
06:41:56,571 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.] to DEBUG
06:41:56,572 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.] to false
06:41:56,572 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[org.]
06:41:56,573 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
06:41:56,574 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
06:41:56,574 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
06:41:56,578 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@4ffdcca5 - Registering current configuration as safe fallback point

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::            (v1.0.0.RC1)

06:41:57.436 [com.my-co.my-app.Application.main()] INFO  com.my-co.my-app.Application - Starting Application on MY-LAPTOP-HOSTNAME with PID 7812 (started by myName)
06:41:57.952 [com.my-co.my-app.Application.main()] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/spring/camel-server.xml]

<etc./>

However, when we remove a rogue logback.xml file which snuck into src/java/resources and re-run with everything else unchanged (making sure we clean to remove the one in target too):

D:\Users\myName\My Projects\Work\my-co\my-app\src\my-app\my-app-camel>mvn  clean spring-boot:run -Dlogback.statusListenerClass=ch.qos.logback.core.status.OnConsoleStatusListener -Dlogback.configurationFile=src/test/resources/logback.xml

<snip/>

[INFO]
[INFO] <<< spring-boot-maven-plugin:1.0.0.RC1:run (default-cli) @ my-app-camel <<<
[INFO]
[INFO] --- spring-boot-maven-plugin:1.0.0.RC1:run (default-cli) @ my-app-camel ---
06:53:59,598 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [src/test/resources/logback.xml] at [file:/D:/Users/myName/My%20Projects/Work/my-co/my-app/src/my-app/my-app-camel/src/test/resources/logback.xml]
06:53:59,736 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
06:53:59,755 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 5 seconds
06:53:59,756 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[D:\Users\myName\My Projects\Work\my-co\my-app\src\my-app\my-app-camel\src\test\resources\logback.xml]] every 5 seconds.
06:53:59,757 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
06:53:59,806 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
06:53:59,817 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
06:53:59,858 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
06:53:59,971 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [me.moocar.logbackgelf.GelfAppender]
06:53:59,980 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [GELF]
06:54:00,144 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.my-co.my-app.] to DEBUG
06:54:00,144 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [com.my-co.my-app.] to false
06:54:00,145 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[com.my-co.my-app.]
06:54:00,148 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.] to DEBUG
06:54:00,148 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.] to false
06:54:00,149 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[org.]
06:54:00,150 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
06:54:00,150 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
06:54:00,151 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
06:54:00,154 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@54c1f582 - Registering current configuration as safe fallback point

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::            (v1.0.0.RC1)

2014-02-12 06:54:01.023  INFO 5240 --- [lication.main()] com.my-co.my-app.Application          : Starting Application on MY-LAPTOP-HOSTNAME with PID 5240 (started by myName)
2014-02-12 06:54:01.564  INFO 5240 --- [lication.main()] o.s.b.f.xml.XmlBeanDefinitionReader      : Loading XML bean definitions from class path resource [META-INF/spring/camel-server.xml]

<etc./>

You'll notice that the logging format after spring-boot starts is different from the first output. However, logback (prior to Spring-Boot starting) reports it's seen the logback.xml in src/test/resources, just like it did the first time.

For interest, our logback.xml (which was in both src/java/resources and src/test/resources is as follows:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="5 seconds">

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{40} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="GELF" class="me.moocar.logbackgelf.GelfAppender">
        <facility>logback-gelf-test</facility>
        <graylog2ServerHost>XXX.XXX.XXX.XXX</graylog2ServerHost>
        <graylog2ServerPort>NNNNN</graylog2ServerPort>
        <useLoggerName>true</useLoggerName>
        <useThreadName>true</useThreadName>
        <useMarker>true</useMarker>
        <graylog2ServerVersion>0.9.6</graylog2ServerVersion>
        <chunkThreshold>1000</chunkThreshold>
        <messagePattern>%m%rEx</messagePattern>
        <shortMessagePattern>%.-100(%m%rEx)</shortMessagePattern>
        <additionalField>ipAddress:_ip_address</additionalField>
        <additionalField>requestId:_request_id</additionalField>
        <staticAdditionalField>_node_name:www013</staticAdditionalField>
        <includeFullMDC>true</includeFullMDC>
    </appender>

    <logger name="com.my-co.my-app." level="DEBUG" additivity="false">
        <appender-ref ref="STDOUT" />
    </logger>

    <logger name="org." level="DEBUG" additivity="false">
        <appender-ref ref="STDOUT" />
    </logger>

    <root level="INFO">
        <appender-ref ref="STDOUT" />
        <!--<appender-ref ref="GELF" />-->
    </root>

</configuration>

So in summary, it seems (though I might be wrong) that when a logback.xml is bundled with my spring-boot app it is seen and used (i.e. in src/java/resources), but when we don't bundle, then despite logback's best efforts it's ignored.

As for fixing this, we're stumped. We're guessing that there is something somewhere in our spring-boot jar which is somehow taking precedence, or turning off logback, or stepping in and telling logback to ignore what it's just been told and to use another default.

Alternatively we're being dumb, but can't see it. All help gratefully received.

Answer

Dave Syer picture Dave Syer · Feb 12, 2014

The default strategy assumes that if you don't have a logback.xml (or one of the other standard file names) in the classpath then you must be happy with the defaults (see LogbackLoggingSystem for details). Spring Boot tries to unify the external configuration switches for common logging sytems, so it looks in logging.config (it didn't know about logback.configurationFile). You could use that instead (i.e. logging.config=file:./src/test/resources/logback.xml), or make sure your config file is on the classpath.

Related questions

spring boot, logback and logging.config property

I am implement logging in a spring boot project with logback library. I want to load different logging configuration files according to my spring profiles (property 'spring.pofiles.active'). I have 3 files : logback-dev.xml, logback-inte.xml and logback-prod.xml. I …

Read More
Spring Boot - no log file written (logging.file is not respected)

I use Spring Boot and want it to write log output to a file. According to the docs, this is simply done by setting logging.file=filename.log While the console output works fine, filename.log is not created. Also, …

Read More
Spring Boot logging pattern

I have a problem with configuration on Logback in a Spring Boot application. I want my consoleAppender to look like the default Spring Boot console appender. How to inherit pattern from Spring Boot default console appender? Below is my consoleAppender …

Read More