Log stack trace properly when context initialization fails

[vojtapol]

Stack trace is logged as one line when an exception happens during context initialization. This makes it difficult to read and it can not be formatted by log patterns.

I am using default Spring Boot configuration with no logging properties set.

To reproduce:
Add this line in any bean constructor: if (true) throw new RuntimeException();

Result:

2018-08-23 10:49:10.778  WARN 21110 --- [  restartedMain] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'redacted' defined in file [/redacted/path/to/file]: Unsatisfied dependency expressed through constructor parameter 0; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'redacted' defined in file [/redacted/path/to/file]: Unsatisfied dependency expressed through constructor parameter 0; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'graphQLSchemaBuilder' defined in file [/redacted/path/to/file]: Unsatisfied dependency expressed through constructor parameter 1; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'redacted' defined in file [/redacted/path/to/file]: Bean instantiation via constructor failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [/redacted/path/to/file]: Constructor threw exception; nested exception is java.lang.RuntimeException
2018-08-23 10:49:10.779  INFO 21110 --- [  restartedMain] o.s.s.c.ThreadPoolTaskScheduler          : Shutting down ExecutorService 'taskScheduler'

I even tracked down the commit that caused this issue:
spring-projects/spring-framework@cdf6eb9

I propose to revert this commit. I have never seen exceptions being duplicated in my logs before.

[snicoll]

I have never seen exceptions being duplicated in my logs before.

I am not sure I understand what you mean by that. This issue tracker is not the right place to discuss a Spring Framework change though.

[vojtapol]

It's a reaction to:

This is particularly obvious with Spring Boot applications where a simple startup failure results in multiple stack-traces.
https://jira.spring.io/browse/SPR-13663

The commit was fixing a (for me) non-existent issue and made investigating initialization failures more difficult.

Since the issue mentioned Spring Boot I reported it here but I can move it to Spring Framework if you think that's better.

[snicoll]

That issue is 3 years old, I am not following. We always prefer issues over code in text or basic description. I've created an empty project with what you have indicated and I got the following:

2018-08-23 17:14:02.760  INFO 21305 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication on leo.lan with PID 21305 (/Users/snicoll/Downloads/test-exception/target/classes started by snicoll in /Users/snicoll/Downloads/test-exception)
2018-08-23 17:14:02.765  INFO 21305 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2018-08-23 17:14:03.276  WARN 21305 --- [           main] s.c.a.AnnotationConfigApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'demoService' defined in file [/Users/snicoll/Downloads/test-exception/target/classes/com/example/demo/DemoService.class]: Instantiation of bean failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [com.example.demo.DemoService]: Constructor threw exception; nested exception is java.lang.RuntimeException
2018-08-23 17:14:03.303  INFO 21305 --- [           main] ConditionEvaluationReportLoggingListener : 

Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2018-08-23 17:14:03.319 ERROR 21305 --- [           main] o.s.boot.SpringApplication               : Application run failed

org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'demoService' defined in file [/Users/snicoll/Downloads/test-exception/target/classes/com/example/demo/DemoService.class]: Instantiation of bean failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [com.example.demo.DemoService]: Constructor threw exception; nested exception is java.lang.RuntimeException
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateBean(AbstractAutowireCapableBeanFactory.java:1264) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1158) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:538) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:498) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:320) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:318) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:199) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:829) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:865) ~[spring-context-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:548) ~[spring-context-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:785) [spring-boot-2.1.0.BUILD-SNAPSHOT.jar:2.1.0.BUILD-SNAPSHOT]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:418) [spring-boot-2.1.0.BUILD-SNAPSHOT.jar:2.1.0.BUILD-SNAPSHOT]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:337) [spring-boot-2.1.0.BUILD-SNAPSHOT.jar:2.1.0.BUILD-SNAPSHOT]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1269) [spring-boot-2.1.0.BUILD-SNAPSHOT.jar:2.1.0.BUILD-SNAPSHOT]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1257) [spring-boot-2.1.0.BUILD-SNAPSHOT.jar:2.1.0.BUILD-SNAPSHOT]
	at com.example.demo.DemoApplication.main(DemoApplication.java:10) [classes/:na]
Caused by: org.springframework.beans.BeanInstantiationException: Failed to instantiate [com.example.demo.DemoService]: Constructor threw exception; nested exception is java.lang.RuntimeException
	at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:186) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:87) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateBean(AbstractAutowireCapableBeanFactory.java:1256) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	... 16 common frames omitted
Caused by: java.lang.RuntimeException: null
	at com.example.demo.DemoService.<init>(DemoService.java:13) ~[classes/:na]
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_144]
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_144]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_144]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_144]
	at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:174) ~[spring-beans-5.1.0.BUILD-SNAPSHOT.jar:5.1.0.BUILD-SNAPSHOT]
	... 18 common frames omitted

Please share a minimal sample (github repo or link) that reproduces the problem.

[vojtapol]

Thanks, your output helped. I tracked my issue all the way to method SpringApplication::reportFailure where the logger is supposed to log the error. My application hits the line but nothing is printed in the console. The logger reference is an instance of class Jdk14Logger but in a demo project when the same line is hit the instance of logger is of class Log4JLog. And the stack trace is printed in the console just like in your case.

I guess there must be something wrong with my logging configuration so we can close this. Let me know if you have any ideas what could cause this issue.

[phillipuniverse]

Came across this issue and found that this occurs when commons-beanutils is on the classpath. This transitively brings in commons-logging, and causes startup-related exception messages to only look like this:

2019-02-05 02:49:02.828  WARN 70219 --- [  restartedMain] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'someBean' defined in file ... Bean instantiation via factory method failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [com.mycompany.SomeBean]: Factory method 'factoryMethod' threw exception; nested exception is java.lang.IllegalArgumentException: The Real Exception Cause

and no stack trace. Indeed, as @vojtapol reported, in SpringApplication::reportFailure it was sending the exception log to a Jdk14Logger.

This caused me to come across #12457 and sure enough, I had commons-beanutils on my classpath transitively bringing in commons-logging. I excluded it like this:

 <dependency>
    <groupId>commons-beanutils</groupId>
    <artifactId>commons-beanutils</artifactId>
    <version>1.9.3</version>
    <exclusions>
        <exclusion>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>

And I am now getting full stack traces in my logs.

Also relevant: that issue seems to indicate that this is fixed in Spring Boot 2.1, I am targeting Boot 2.0.6.

[nathan818fr]

Also came across this issue.

For me, commons-logging was included by commons-validator so I excluded it like this:

<dependency>
  <groupId>commons-validator</groupId>
  <artifactId>commons-validator</artifactId>
  <exclusions>
    <exclusion>
      <groupId>commons-logging</groupId>
      <artifactId>commons-logging</artifactId>
    </exclusion>
  </exclusions>
</dependency>

But despite that I still not getting full stack traces in my logs (even if the debugger showed that the logger was correct this time)...

In fact my project uses async log4j logger and logs were not flush at shutdown... So the process exited before printing the exception. I fixed it by flushing the logger on shutdown:

System.setProperty("Log4jContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
Runtime.getRuntime().addShutdownHook(new Thread(() -> {
    LoggerContext LoggerContext = LogManager.getContext();
    if (LoggerContext instanceof AsyncLoggerContext) {
        ((AsyncLoggerContext) LoggerContext).stop();
    }
}));

(not caused by spring but I prefer to comment here in case it would help someone else)