Exception during context refresh swallowed by subsequent LifecycleProcessor exception handling [SPR-10000]

[spring-projects-issues]

Archie Cobbs opened SPR-10000 and commented

My application had a bug causing an exception to be thrown during construction of a bean.

This caused the application context refresh operation to be aborted. However, in the process of aborting the refresh, an additional exception was thrown by AbstractApplicationContext.getLifecycleProcessor().

This second exception got logged to the error log, but the first exception never did.

As a result, it was very difficult to debug what the actual problem was.

The error logs, including the second exception that did get logged, are here (edited for brevity):

2012-11-15 17:27:29,067 [localhost-startStop-1] INFO : Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7dbafc22: defining beans [...]; parent: org.springframework.beans.factory.support.DefaultListableBeanFactory@5697c78b
2012-11-15 17:27:29,551 [localhost-startStop-1] INFO : Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7dbafc22: defining beans [...]; parent: org.springframework.beans.factory.support.DefaultListableBeanFactory@5697c78b
2012-11-15 17:27:29,595 [localhost-startStop-1] INFO : Closing Root WebApplicationContext: startup date [Thu Nov 15 17:27:08 CST 2012]; root of context hierarchy
2012-11-15 17:27:29,607 [localhost-startStop-1] WARN : Exception thrown from LifecycleProcessor on context close
java.lang.IllegalStateException: LifecycleProcessor not initialized - call 'refresh' before invoking lifecycle methods via the context: Root WebApplicationContext: startup date [Thu Nov 15 17:27:08 CST 2012]; root of context hierarchy
        at org.springframework.context.support.AbstractApplicationContext.getLifecycleProcessor(AbstractApplicationContext.java:350)
        at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1038)
        at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:993)
        at org.springframework.context.support.AbstractApplicationContext.destroy(AbstractApplicationContext.java:981)
        at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:211)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:498)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:474)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:509)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:474)
        at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:300)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:225)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:291)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:193)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:609)
        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918)
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:469)
        at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:383)
        at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:283)
        at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:111)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4791)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5285)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:618)
        at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1100)
        at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1618)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
        at java.util.concurrent.FutureTask.run(FutureTask.java:166)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:722)

It appears that the following snippet of code in AbstractBeanFactory (visible in the above stack trace) may be contributing to the problem (but I haven't verified that for sure). Note how the second exception occurs during the call to destroySingleton().

            // Create bean instance.
            if (mbd.isSingleton()) {
                sharedInstance = getSingleton(beanName, new ObjectFactory<Object>() {
                    public Object getObject() throws BeansException {
                        try {
                            return createBean(beanName, mbd, args);
                        }
                        catch (BeansException ex) {
                            // Explicitly remove instance from singleton cache: It might have been put there
                            // eagerly by the creation process, to allow for circular reference resolution.
                            // Also remove any beans that received a temporary reference to the bean.
                            destroySingleton(beanName);
                            throw ex;
                        }
                    }
                });
                bean = getObjectForBeanInstance(sharedInstance, name, beanName, mbd);
            }

Possibly relevant: I have a slightly unusual setup where an outer application context contains a bean which is itself an inner application context:

<bean id="updatesContext" class="org.springframework.context.support.ClassPathXmlApplicationContext">
    <constructor-arg>
        <util:list>
            <value>classpath:updates.xml</value>
        </util:list>
    </constructor-arg>
    <constructor-arg>
        <value>false</value>
    </constructor-arg>
    <constructor-arg>
        <bean factory-bean="applicationContextBean" factory-method="getApplicationContext"/>
    </constructor-arg>
</bean>

The applicationContextBean is a bean that exposes the containing application context. It is set as the parent of the nested context. Note the refresh constructor parameter is false, so the inner application context is not refreshed until afterPropertiesSet().

Bottom line: ideally, secondary exceptions should never occur; but if they do, they should never prevent a primary exception from being logged.

---

Affects: 3.1.2

Attachments:

• SPR-10000.tgz (12.27 kB)

Issue Links:

• Exceptions thrown during AbstractApplicationContext.refresh() not being logged right when they are caught [SPR-12010] #16626 Exceptions thrown during AbstractApplicationContext.refresh() not being logged right when they are caught

Backported to: 3.2.11

[spring-projects-issues]

Juergen Hoeller commented

Something is strange here: doClose shouldn't even proceed when the context is not active, which is a flag only set after a successful refresh... However, if a refresh had been successful, the LifecycleProcessor would have been properly initialized! Going in circles trying to understand what goes wrong here.

There is a solution that I'll probably apply in any case: to simply locally catch and log any exception from a destroySingleton call after a createBean failure. However, I'd like to find out whether there is a deeper issue somewhere in the ApplicationContext instance's lifecycle state handling...

Juergen

[spring-projects-issues]

Juergen Hoeller commented

Oh BTW, congrats on the issue number :-)

[spring-projects-issues]

Juergen Hoeller commented

I'm afraid I can't reproduce the circumstances here: The LifecycleProcessor exception is being locally logged to warn level on context close, not actually thrown to the caller. The original exception should end up getting rethrown from the refresh() call on that nested ApplicationContext, as expected, so it doesn't seem to get swallowed by Spring at all there. Is the exception maybe not properly handled by whoever actually calls refresh() on your nested context?

Juergen

[spring-projects-issues]

Archie Cobbs commented

I'm attaching a test case that reproduces the problem.

FYI, the dellroad-stuff project is located here in case you need to inspect that code.

[spring-projects-issues]

Juergen Hoeller commented

This should be fixed now along with #16626.

Juergen