search

spring-projects / spring-framework

Spring Framework
https://spring.io/projects/spring-framework
Apache License 2.0
56.24k stars 37.98k forks source link

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

Closed spring-projects-issues closed 6 years ago

spring-projects-issues commented 6 years ago

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:

Referenced from: commits https://github.com/spring-projects/spring-framework/commit/519195cf66d6a5e4b6657093a22d691d2908e0b3, https://github.com/spring-projects/spring-framework/commit/1611ce7180b985084e60abc116f32d5db886808d

Backported to: 4.3.13

spring-projects-issues commented 6 years ago

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 commented 6 years ago

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 commented 6 years ago

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 commented 6 years ago

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 commented 6 years ago

Terence Mill commented

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

spring-projects-issues commented 6 years ago

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.