Do not swallow exception cause when context refresh fails [SPR-17549]

[spring-projects-issues]

Jake Robb opened SPR-17549 and commented

I have a bean that is failing to initialize and throwing an exception. The cause of the cause of the cause of that exception is the real, underlying issue.

The exception propagates to AbstractApplicationContext.refresh, at which point it is logged as a warning:

if (logger.isWarnEnabled()) {
   logger.warn("Exception encountered during context initialization - " +
         "cancelling refresh attempt: " + ex);
}

Note that the exception is being string-concatenated (and therefore toString'd), rather than passing the exception itself to the logger. This means that only the exception's type and message get written to the log, which in turn means that I only learn that my bean failed to initialize, but not why. It also means I get no stacktrace.

The fix here is to replace the + with a ,. I'll be submitting a pull request shortly.

---

Affects: 5.0.4, 5.0.11

Issue Links:

• Revisit BeansException warn logging after startup failure [SPR-13663] #18238 Revisit BeansException warn logging after startup failure

[spring-projects-issues]

Juergen Hoeller commented

Note that the exception is being propagated to the caller of refresh(), and that caller (a Servlet container listener or possibly just a programmatic main method) is meant to log the full exception according to its logging rules (possibly in a specific server log file). Our warn log entry is only meant as an additional measure, not logging the full stacktrace in order to avoid a repeated stacktrace for scenarios where the caller also logs the stacktrace in the same sink.

See #18238 for the ticket where we reduced the warn log entry from a full stacktrace to just Exception.toString() a few years ago.

[spring-projects-issues]

Jake Robb commented

Interesting. I got pulled away from this before I had a chance to make the change, and based on your comment, I don't think I will.

I'll have to do some work to replicate the conditions under which I saw the failure, but I have a Spring Boot application which fails to bootstrap and does not ever write the full stacktrace. I've gone through our code, and I believe I've verified that it's not getting swallowed on our end, but I'll get to the bottom of it and be sure.

[jakerobb]

I figured out what's happening!

We're using SLF4J and Logback as our logging framework. For Spring logging to work, we have jcl-over-slf4j in place. Normally, this works great.

My app is a Spring Boot app, currently using Spring Boot 2.0.6. SpringApplication.java has this method, which is logs the exception with the full stacktrace:

private void reportFailure(Collection<SpringBootExceptionReporter> exceptionReporters,
        Throwable failure) {
    try {
        for (SpringBootExceptionReporter reporter : exceptionReporters) {
            if (reporter.reportException(failure)) {
                registerLoggedException(failure);
                return;
            }
        }
    }
    catch (Throwable ex) {
        // Continue with normal handling of the original failure
    }
    if (logger.isErrorEnabled()) {
        logger.error("Application run failed", failure);
        registerLoggedException(failure);
    }
}

The call to logger.error gets invoked correctly, and has all of the correct context on it, but this happens after the ApplicationFailedEvent has been distributed to the ApplicationListeners, including LoggingApplicationListener, which eventually calls Slf4JLoggingSystem.cleanup, which eventually uninstalls the SLF4JBridgeHandler.

As a result, there are no appenders associated with the logger, and nothing gets printed to my log.

Assuming you don't want to go back to logging the full exception stacktrace twice, it seems to me that the path forward is to make it so that reportFailure gets invoked before the ApplicationFailedEvent is sent.

There are also warnings in Logback's StatusManager that never get printed. It probably makes sense to print them out as part of the application failure.

I'm not up to speed on the administrative practices in this project, so I'll defer to someone else to update the labels on this issue. I'm guessing it needs to be moved to the Spring Boot project, too. Please let me know if re-reporting there is desired.

Thanks!

[jakerobb]

I've looked over the latest source in GitHub and determined that the relevant code has not changed in the latest version of Spring Boot.

[snicoll]

@jakerobb what you've described is a Spring Boot issue, see spring-projects/spring-boot#33697. As for the original reporter, there hasn't been an update in years so I am going to close this.