1.3.0.M2 : Logback appender runtime errors now block the application startup

[jceloi]

Hello,

Upgrading from 1.3.0.M1 to 1.3.0.M2, I've seen that a logback configuration error now block the application startup whereas it had no impact on the startup previously.

Is this a design change or a side effect of the logback extensions integration ?

Example (the Timer already cancelled comes from a custom appender that fails) :

015-07-15 11:23:37.294 ERROR 31902 --- [  restartedMain] o.s.boot.SpringApplication               : **Application startup failed**

java.lang.IllegalStateException: Logback configuration error detected: 
ERROR in ch.qos.logback.core.joran.spi.Interpreter@24:16 - RuntimeException in Action for tag [appender] java.lang.IllegalStateException: Timer already cancelled.
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:141)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.reinitialize(LogbackLoggingSystem.java:169)
    at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:64)
    at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:49)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:102)
    at org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:211)
    at org.springframework.boot.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:189)
    at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:169)
    at org.springframework.boot.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:150)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:163)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:136)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:119)
    at org.springframework.boot.context.event.EventPublishingRunListener.publishEvent(EventPublishingRunListener.java:111)
    at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:65)
    at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:53)
    at org.springframework.boot.SpringApplication.doRun(SpringApplication.java:307)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:273)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:971)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:960)
    at xxxx.XXApplication.main(KioskApiApplication.java:15)
    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.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)

[snicoll]

Hey, this is on purpose, please check the release notes

[jceloi]

Precision : the logback file is correct and is not malformed. It's the appender that fails.

So the impact is a bit wider that what is explained in the release notes, isn't it ?

[snicoll]

I am not sure. Isn't it failing anyway? Or are you saying it's a temporary glitch?

[jceloi]

The logger is failing to start, but is properly configured and declared in the logback configuration file.

It is a poor design of this custom logger that can fail if a remote log repository (flume in this case) is not up.

This logger should be corrected / improved of course, but I'm a bit surprised that a legit, well-formed logback configuration file can lead to an application startup crash. From what I see in the LogbackLoggingSystem class, I do clearly understand the

catch (Exception ex) {
            throw new IllegalStateException("Could not initialize Logback logging from "
                    + location, ex);
        }

part but isn't the

if (errors.length() > 0) {
            throw new IllegalStateException("Logback configuration error "
                    + "detected: \n" + errors);
        }

part a bit too hard ?

[jceloi]

By too hard I mean : isn't the LogbackLoggingSystem validation stronger that logback's, as an error on an appender might not be blocking the others on logback's side. It's more tolerant to fault.

[wilkinsona]

I don't think it's too hard. All that the first catch block verifies is that the XML is legal. The second checks that the configuration actually makes sense from Logback's perspective. It will, for example, catch a typo in the class name of an appender. The intention is to guarantee, as far as we can, that if your app has started then it will produce the expected logging.

The specific error that you're seeing looks very similar to #3472 (in both cases the problem occurs beneath LogbackLoggingSystem.reinitialize). You might like to try with a 1.3.0 snapshot, or using logback-spring.xml rather than logback.xml.

[jceloi]

Indeed using the logback-spring.xml changes the behaviour of my appender and the error does not occur. Thanks for the pointer !

And OK for the design choice. I might have to adapt to that but I can understand the reason for it.