Application should fail to start when an incorrect logback config is provided

[hanswesterbeek]

Reproduction:

• checkout https://github.com/hanswesterbeek/logback-failure-demo
• take a look at src/main/resources/logback-demo.xml and application.properties
• mvn spring-boot:run

Currently, Spring Boot falls back to a default logback configuration. This causes me to believe that my logback configuration is fine while it isn't. In real deployment scenarios, I depend heavily on my logback-config. For instance, it emails me when ERROR-level events occur.

I think the application should not boot at all when I fail to configure logging. I would like it to write the to stderr and crash.

[wilkinsona]

It would appear that it only carries on if you're using a custom name for the logging configuration file. If you use the default (logback.xml) the app fails to start:

Failed to auto configure default logger context
Reported exception:
ch.qos.logback.core.joran.spi.JoranException: Problem parsing XML document. See previously reported errors.
    at ch.qos.logback.core.joran.event.SaxEventRecorder.recordEvents(SaxEventRecorder.java:67)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:134)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
    at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:77)
    at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:152)
    at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85)
    at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
    at org.slf4j.LoggerFactory.bind(LoggerFactory.java:141)
    at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:120)
    at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:331)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:283)
    at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:155)
    at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:132)
    at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:273)
    at org.springframework.boot.SpringApplication.<init>(SpringApplication.java:160)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:957)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:946)
    at demo.LogbackFailureDemoApplication.main(LogbackFailureDemoApplication.java:10)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.springframework.boot.maven.RunMojo$LaunchRunner.run(RunMojo.java:418)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.xml.sax.SAXParseException; lineNumber: 2; columnNumber: 17; Attribute name "tion" associated with an element type "configura" must be followed by the ' = ' character.
    at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1239)
    at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:649)
    at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl.parse(SAXParserImpl.java:333)
    at ch.qos.logback.core.joran.event.SaxEventRecorder.recordEvents(SaxEventRecorder.java:61)
    ... 24 more
09:39:07,678 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
09:39:07,678 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
09:39:07,678 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/Users/awilkinson/dev/tmp/logback-failure-demo/src/main/resources/logback.xml]
09:39:07,710 |-ERROR in ch.qos.logback.core.joran.event.SaxEventRecorder@5ec3c28d - XML_PARSING - Parsing fatal error on line 2 and column 17 org.xml.sax.SAXParseException; lineNumber: 2; columnNumber: 17; Attribute name "tion" associated with an element type "configura" must be followed by the ' = ' character.
    at org.xml.sax.SAXParseException: Attribute name "tion" associated with an element type "configura" must be followed by the ' = ' character.
    at  at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.createSAXParseException(ErrorHandlerWrapper.java:203)
    at  at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.fatalError(ErrorHandlerWrapper.java:177)
    at  at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:441)
    at  at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:368)
    at  at com.sun.org.apache.xerces.internal.impl.XMLScanner.reportFatalError(XMLScanner.java:1436)
    at  at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.scanAttribute(XMLNSDocumentScannerImpl.java:418)
    at  at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.scanStartElement(XMLNSDocumentScannerImpl.java:255)
    at  at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl$NSContentDriver.scanRootElementHook(XMLNSDocumentScannerImpl.java:605)
    at  at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:3138)
    at  at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl$PrologDriver.next(XMLDocumentScannerImpl.java:880)
    at  at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:606)
    at  at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:117)
    at  at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:510)
    at  at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:848)
    at  at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:777)
    at  at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:141)
    at  at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1213)
    at  at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:649)
    at  at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl.parse(SAXParserImpl.java:333)
    at  at ch.qos.logback.core.joran.event.SaxEventRecorder.recordEvents(SaxEventRecorder.java:61)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:134)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
    at  at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:77)
    at  at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:152)
    at  at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85)
    at  at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
    at  at org.slf4j.LoggerFactory.bind(LoggerFactory.java:141)
    at  at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:120)
    at  at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:331)
    at  at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:283)
    at  at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:155)
    at  at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:132)
    at  at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:273)
    at  at org.springframework.boot.SpringApplication.<init>(SpringApplication.java:160)
    at  at org.springframework.boot.SpringApplication.run(SpringApplication.java:957)
    at  at org.springframework.boot.SpringApplication.run(SpringApplication.java:946)
    at  at demo.LogbackFailureDemoApplication.main(LogbackFailureDemoApplication.java:10)
    at  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at  at java.lang.reflect.Method.invoke(Method.java:483)
    at  at org.springframework.boot.maven.RunMojo$LaunchRunner.run(RunMojo.java:418)
    at  at java.lang.Thread.run(Thread.java:745)

[WARNING]
java.lang.reflect.InvocationTargetException
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.springframework.boot.maven.RunMojo$LaunchRunner.run(RunMojo.java:418)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: Could not initialize Logback logging from classpath:logback.xml
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:122)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.reinitialize(LogbackLoggingSystem.java:130)
    at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:60)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:96)
    at org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:213)
    at org.springframework.boot.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:181)
    at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:161)
    at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:142)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:151)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:128)
    at org.springframework.boot.context.event.EventPublishingRunListener.publishEvent(EventPublishingRunListener.java:100)
    at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:59)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:285)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:957)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:946)
    at demo.LogbackFailureDemoApplication.main(LogbackFailureDemoApplication.java:10)
    ... 6 more
Caused by: ch.qos.logback.core.joran.spi.JoranException: Problem parsing XML document. See previously reported errors.
    at ch.qos.logback.core.joran.event.SaxEventRecorder.recordEvents(SaxEventRecorder.java:67)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:134)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
    at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
    at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:77)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:119)
    ... 21 more
Caused by: org.xml.sax.SAXParseException; lineNumber: 2; columnNumber: 17; Attribute name "tion" associated with an element type "configura" must be followed by the ' = ' character.
    at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1239)
    at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:649)
    at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl.parse(SAXParserImpl.java:333)
    at ch.qos.logback.core.joran.event.SaxEventRecorder.recordEvents(SaxEventRecorder.java:61)
    ... 26 more

[hanswesterbeek]

Interesting nuance :) Do you agree it shouldn't carry on, even if the filename is non-default?

[wilkinsona]

I'm not sure… I'd certainly like the behaviour to be consistent.

My initial feeling was that we should do whatever Logback does by default and, having now tried it, I've learned that it carries on when it can't parse its configuration file.

The cause of the different behaviour between logback-whatever.xml and logback.xml is this logic:

private void initializeSystem(ConfigurableEnvironment environment,
            LoggingSystem system) {
    LogFile logFile = LogFile.get(environment);
    String logConfig = environment.getProperty(CONFIG_PROPERTY);
    if (StringUtils.hasLength(logConfig)) {
        try {
            ResourceUtils.getURL(logConfig).openStream().close();
            system.initialize(logConfig, logFile);
        }
        catch (Exception ex) {
            this.logger.warn("Logging environment value '" + logConfig
                    + "' cannot be opened and will be ignored "
                    + "(using default location instead)");
            system.initialize(null, logFile);
        }
    }
    else {
        system.initialize(null, logFile);
    }
}

The exception message suggests that the intent is to only fallback to the default if the file cannot be opened, not to fallback to the default if the custom file is malformed. However, I'm guessing that you may consider a missing file to be incorrect config, and that you'd like it to crash then too?

[hanswesterbeek]

Yep, fail fast, that always gets the attention of whoever was just deploying the new config. The alternative, to keep running silently while the application is configured incorrectly, is pretty bad for me.

To illustrate the issue: I had a typo in my elaborate logback config. For days the application kept running and I missed out on messages. I only noticed that the application was ignoring my logback-config altogether when I was trying to change its config without result.

By the way, I never saw the "..and will be ignored" log-message in my console output. I didn't have WARN-level logging enabled for that class.

[wilkinsona]

By the way, I never saw the "..and will be ignored" log-message in my console output. I didn't have WARN-level logging enabled for that class.

A nice illustration of the dangers of using logging to report a problem with logging configuration. Even if we don't change the fallback behaviour, we should move that to System.err.

[wilkinsona]

Reopening. The new tests have broken the build when LoggingApplicationListenerTests runs before LogbackLoggingSystemTests. Reproduced reliably with this test suite:

@RunWith(Suite.class)
@Suite.SuiteClasses({ LoggingApplicationListenerTests.class,
        LogbackLoggingSystemTests.class })
public class Gh3309 {

}