Early ApplicationContext close call may lead to ApplicationEventMulticaster/LifecycleProcessor access exception [SPR-16149]

[spring-projects-issues]

Terence Mill opened SPR-16149 and commented

Similar things as in #17501 happened again on spring-cloud dalston ( spring framework 4.3.9.RELEASE). Not sure but maybe the change has been introduced from change
spring-cloud dalston SR3 to SR4 (did not happen fopr me before)

java.lang.IllegalStateException: LifecycleProcessor not initialized - call 'refresh' before invoking lifecycle methods via the context: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@624c96df: startup date [Thu Nov 02 08:27:24 CET 2017]; parent: org.springframework.context.annotation.AnnotationConfigApplicationContext@1c5ebbc5
	at org.springframework.context.support.AbstractApplicationContext.getLifecycleProcessor(AbstractApplicationContext.java:427)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:999)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:958)
	at org.springframework.boot.SpringApplication.handleRunFailure(SpringApplication.java:750)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:314)
	at com.myorg.dvd.core.DvdSpringApplication.run(DvdSpringApplication.java:68)
	at com.myorg.dvd.core.DvdSpringApplication.run(DvdSpringApplication.java:37)
	at com.myorg.dvd.cfg.ConfigServerApplication.main(ConfigServerApplication.java:36)
	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:498)
	at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)
 
2017-11-02 08:27:28.425 ERROR [configserver,,,] 13740 --- [  restartedMain] o.s.b.f.s.DefaultListableBeanFactory     : Destroy method on bean with name 'org.springframework.boot.autoconfigure.internalCachingMetadataReaderFactory' threw an exception
 
java.lang.IllegalStateException: ApplicationEventMulticaster not initialized - call 'refresh' before multicasting events via the context: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@624c96df: startup date [Thu Nov 02 08:27:24 CET 2017]; parent: org.springframework.context.annotation.AnnotationConfigApplicationContext@1c5ebbc5
	at org.springframework.context.support.AbstractApplicationContext.getApplicationEventMulticaster(AbstractApplicationContext.java:414)
	at org.springframework.context.support.ApplicationListenerDetector.postProcessBeforeDestruction(ApplicationListenerDetector.java:97)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:253)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:578)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:554)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:961)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:523)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:968)
	at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1030)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1006)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:958)
	at org.springframework.boot.SpringApplication.handleRunFailure(SpringApplication.java:750)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:314)
	at com.myorg.dvd.core.DvdSpringApplication.run(DvdSpringApplication.java:68)
	at com.myorg.dvd.core.DvdSpringApplication.run(DvdSpringApplication.java:37)
	at com.myorg.dvd.cfg.ConfigServerApplication.main(ConfigServerApplication.java:36)
	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:498)
	at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)

---

Affects: 4.3.9

Reference URL: #17501

Issue Links:

• Revisit "ApplicationEventMulticaster not initialized" behavior for early event publication scenarios [SPR-12902] #17501 Revisit "ApplicationEventMulticaster not initialized" behavior for early event publication scenarios

Referenced from: commits 519195c, 1611ce7

Backported to: 4.3.13

[spring-projects-issues]

Juergen Hoeller commented

I assume both of those are 'just' log entries? Even as log entries, we should get rid of them... just double-checking whether they ever bubble up as actual exceptions.

[spring-projects-issues]

Juergen Hoeller commented

We're defensively accessing the ApplicationEventMulticaster and LifecycleProcessor delegates on shutdown now, simply skipping the corresponding steps if they are not initialized yet and therefore not logging any IllegalStateExceptions anymore.

[spring-projects-issues]

Terence Mill commented

Its not just logging, currently the config server boot application is even unable to start

Here is a eureka based app not starting

java.lang.IllegalStateException: LifecycleProcessor not initialized - call 'refresh' before invoking lifecycle methods via the context: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@6b8c9974: startup date [Thu Nov 02 15:48:22 CET 2017]; parent: org.springframework.context.annotation.AnnotationConfigApplicationContext@3450a40b
	at org.springframework.context.support.AbstractApplicationContext.getLifecycleProcessor(AbstractApplicationContext.java:427)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:999)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:958)
	at org.springframework.boot.SpringApplication.handleRunFailure(SpringApplication.java:750)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:314)
	at com.myorg.dvb.core.DvbSpringApplication.run(DvbSpringApplication.java:68)
	at com.myorg.dvb.core.DvbSpringApplication.run(DvbSpringApplication.java:37)
	at com.myorg.dvb.reg.RegistryServerApplication.main(RegistryServerApplication.java:20)
	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:498)
	at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)

java.lang.IllegalStateException: ApplicationEventMulticaster not initialized - call 'refresh' before multicasting events via the context: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@6b8c9974: startup date [Thu Nov 02 15:48:22 CET 2017]; parent: org.springframework.context.annotation.AnnotationConfigApplicationContext@3450a40b
	at org.springframework.context.support.AbstractApplicationContext.getApplicationEventMulticaster(AbstractApplicationContext.java:414)
	at org.springframework.context.support.ApplicationListenerDetector.postProcessBeforeDestruction(ApplicationListenerDetector.java:97)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:253)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:578)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:554)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:961)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:523)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:968)
	at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1030)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1006)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:958)
	at org.springframework.boot.SpringApplication.handleRunFailure(SpringApplication.java:750)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:314)
	at com.myorg.dvb.core.DvbSpringApplication.run(DvbSpringApplication.java:68)
	at com.myorg.dvb.core.DvbSpringApplication.run(DvbSpringApplication.java:37)
	at com.myorg.dvb.reg.RegistryServerApplication.main(RegistryServerApplication.java:20)
	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:498)
	at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)

java.lang.IllegalStateException: ApplicationEventMulticaster not initialized - call 'refresh' before multicasting events via the context: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@6b8c9974: startup date [Thu Nov 02 15:48:22 CET 2017]; parent: org.springframework.context.annotation.AnnotationConfigApplicationContext@3450a40b
	at org.springframework.context.support.AbstractApplicationContext.getApplicationEventMulticaster(AbstractApplicationContext.java:414)
	at org.springframework.context.support.ApplicationListenerDetector.postProcessBeforeDestruction(ApplicationListenerDetector.java:97)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:253)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:578)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:554)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:961)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:523)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:968)
	at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1030)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1006)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:958)
	at org.springframework.boot.SpringApplication.handleRunFailure(SpringApplication.java:750)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:314)
	at com.myorg.dvb.core.DvbSpringApplication.run(DvbSpringApplication.java:68)
	at com.myorg.dvb.core.DvbSpringApplication.run(DvbSpringApplication.java:37)
	at com.myorg.dvb.reg.RegistryServerApplication.main(RegistryServerApplication.java:20)
	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:498)
	at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)

[spring-projects-issues]

Juergen Hoeller commented

So is it the LifecycleProcessor exception bubbling up? I wonder how that can happen since doClose() had a try-catch block around that part, logging an exception. If the config server doesn't start up anymore, it might be for some other reason, with the core shutdown logging just getting in the way there.

In any case, I'll commit my revision along with a few other changes in a few minutes: If for any reason we shut down against a half-initialized context, we are not going to log any spurious IllegalStateExceptions anymore - and as far as I can tell, there is no chance for them to reach user-level code either.

That's all we can do at this level. If the real issue is that a context shutdown is triggered so early in Spring Cloud to begin with, you'll need to raise it with them.

[spring-projects-issues]

Terence Mill commented

Ye, i also think there is some other issue (in best case hidden) behind this one.

[spring-projects-issues]

Juergen Hoeller commented

The current 5.0.2.BUILD-SNAPSHOT contains this revision in the meantime. I'll backport it to 4.3.13 by Monday.