DefaultMessageListenerContainer not shutting down

I know there have been other threads about this but none which have helped. I am using tomcat, activemq and using an Message driven pojo via DefaultMessageListenerContainer.

Everything is fine except that tomcat does not shutdown gracefully (the process hangs). If I remove the MDP from spring config everything works fine which means it is definately the MDP hence DefaultMessageListenerContainer. From my debugging I can see that the MDP thread is still hanging around while all most other tomcat threads have stopped.

Has anyone come across this and/or solved it?

Hello,

do you use the Webapplicationcontext with a ServletContextListener in your enviroment ?
Normally when the applicationcontext stops, the defaultmesaagelistenercontainer also stops.

Regards
agim

Not sure what you mean - but in my web.xml I have the following -

<!-- Listeners -->
<listener>
<listener-class>org.springframework.web.context.ContextLoade rListener</listener-class>
</listener>

I can see in the logs that it tries to shutdown but the process doesn't die it seems.

Did you try Spring 2.0.4 and above?

Its a guess. Think through this.

ContextLoaderListener - is an implementation to load the spring context via the web.xml. But it may not be the responsibility of the web container to call the close() or destroy() method on the ApplicationContext that was created by the web container. I dont think it's happening. So you may need to grab the Application context being in a ServletContextListener.destroy() and call applicationContext.close() method. Hopefully that will bring down your Spring beans and will fire the destroy methods on all spring managed beans.

Check it out.

Quote:

---

ContextLoaderListener - is an implementation to load the spring context via the web.xml. But it may not be the responsibility of the web container to call the close() or destroy() method on the ApplicationContext that was created by the web container. I dont think it's happening.

---

I think you're worong, have a look at ContextLoaderLister (destroy method)

Code:

---

public void contextDestroyed(ServletContextEvent event) {
                if (this.contextLoader != null) {
                        this.contextLoader.closeWebApplicationContext(event.getServletContext());
                }
}

---

closeWebbapplicationContext calls close on the applicationcontexts. So normally with the ContextLoaderListener you should be fine with the MEssageListenerContainer.


@alvins

Do you use any (custom ) receiveTimeout in your MessageListenerContainer

regards
agim

Yes I do - 10000 (10sec). But even with that removed - I am seeing the same issue. Below is what I see in the log - the exception is thrown a few seconds after the "INFO: Failed shutdown of Apache Portable Runtime". Haven't tried spring-2.0.4 - will try and see if the issue goes away.

May 14, 2007 3:52:47 PM org.apache.coyote.http11.Http11BaseProtocol destroy
INFO: Stopping Coyote HTTP/1.1 on http-8081
May 14, 2007 3:52:47 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
INFO: Failed shutdown of Apache Portable Runtime

Exception in thread "ActiveMQ Transport: tcp://localhost/127.0.0.1:61616" java.lang.NullPointerException
at org.apache.log4j.LogManager.getLogger(LogManager.j ava:179)
at org.apache.log4j.Logger.getLogger(Logger.java:85)
at org.apache.commons.logging.impl.Log4JLogger.getLog ger(Log4JLogger.java:229)
at org.apache.commons.logging.impl.Log4JLogger.isDebu gEnabled(Log4JLogger.java:239)
at org.apache.activemq.transport.ResponseCorrelator.o nCommand(ResponseCorrelator.java:85)
at org.apache.activemq.transport.TransportFilter.onCo mmand(TransportFilter.java:65)
at org.apache.activemq.transport.WireFormatNegotiator .onCommand(WireFormatNegotiator.java:133)
at org.apache.activemq.transport.InactivityMonitor.on Command(InactivityMonitor.java:122)
at org.apache.activemq.transport.TransportSupport.doC onsume(TransportSupport.java:84)
at org.apache.activemq.transport.tcp.TcpTransport.run (TcpTransport.java:137)
at java.lang.Thread.run(Thread.java:619)

Hi,

another option is to enable debug log. And paste it here.
Normally you should see the log line

"Shutting down message listener container", and a few more.

regards
agim

It is rather long and ugly but you can see that the listener tries to stop (I have split in two posts). That exception being thrown at the end keeps recurring because DMLC is still running.

Code:

---

May 14, 2007 4:19:00 PM org.apache.coyote.http11.Http11BaseProtocol pause
INFO: Pausing Coyote HTTP/1.1 on http-8081
May 14, 2007 4:19:01 PM org.apache.catalina.core.StandardService stop
INFO: Stopping service Catalina
16:19:01,972 DEBUG org.apache.struts.action.ActionServlet - Finalizing this controller servlet
16:19:01,974 DEBUG org.apache.struts.validator.ValidatorPlugIn - Destroying ValidatorPlugin
16:19:01,977  INFO org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/postrlife] - Closing Spring root WebApplicationContext
16:19:01,979  INFO org.springframework.web.context.support.XmlWebApplicationContext - Closing org.springframework.web.context.support.XmlWebApplicationContext@700edc: display name [Root WebApplicationContext]; startup date [Mon May 14 16:17:52 EST 2007]; root of context hierarchy
16:19:01,980 DEBUG org.springframework.web.context.support.XmlWebApplicationContext - Publishing event in context [org.springframework.web.context.support.XmlWebApplicationContext@700edc]: org.springframework.context.event.ContextClosedEvent[source=org.springframework.web.context.support.XmlWebApplicationContext@700edc: display name [Root WebApplicationContext]; startup date [Mon May 14 16:17:52 EST 2007]; root of context hierarchy]
16:19:01,981  INFO org.springframework.beans.factory.support.DefaultListableBeanFactory - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@16237e0: defining beans [dataSource,sessionFactory,jdbcExceptionTranslator,transactionManager,baseHibernateDAO,baseTransactionProxyFactory,musicServiceTarget,musicService,jmsFactory,musicDestination,musicListener,musicListenerContainer,rosterDestination,rosterJmsTemplate,rosterJmsSender,scraperTaskExecutor,scraperExecutor,emailTaskExecutor,emailExecutor]; root of factory hierarchy
16:19:01,982 DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Retrieved dependent beans for bean 'emailTaskExecutor': [emailExecutor]
16:19:01,982 DEBUG org.springframework.beans.factory.support.DisposableBeanAdapter - Invoking destroy() on bean with name 'emailTaskExecutor'
16:19:01,983  INFO org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor - Shutting down ThreadPoolExecutor 'emailTaskExecutor'
16:19:01,983 DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Retrieved dependent beans for bean 'scraperTaskExecutor': [scraperExecutor]
16:19:01,983 DEBUG org.springframework.beans.factory.support.DisposableBeanAdapter - Invoking destroy() on bean with name 'scraperTaskExecutor'
16:19:01,983  INFO org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor - Shutting down ThreadPoolExecutor 'scraperTaskExecutor'
16:19:01,984 DEBUG org.springframework.beans.factory.support.DisposableBeanAdapter - Invoking destroy() on bean with name 'musicListenerContainer'
16:19:01,984 DEBUG org.springframework.jms.listener.DefaultMessageListenerContainer - Shutting down JMS listener container
16:19:01,984 DEBUG org.springframework.jms.listener.DefaultMessageListenerContainer - Waiting for shutdown of message listener invokers
16:19:01,984 DEBUG org.springframework.jms.listener.DefaultMessageListenerContainer - Still waiting for shutdown of 1 message listener invokers
16:19:01,995 DEBUG org.springframework.jms.listener.DefaultMessageListenerContainer - Consumer [ActiveMQMessageConsumer { value=ID:localhost.localdomain-58093-1179123486254-1:1:1:1, started=true }] of session [PooledSession { ActiveMQSession {id=ID:localhost.localdomain-58093-1179123486254-1:1:1,started=true} }] did not receive a message
16:19:05,782 DEBUG org.apache.activemq.transport.InactivityMonitor - Message sent since last write check, resetting flag
16:19:06,877 DEBUG org.apache.activemq.transport.InactivityMonitor - No message sent since last write check, sending a KeepAliveInfo
16:19:06,909 DEBUG org.apache.activemq.transport.InactivityMonitor - Message received since last read check, resetting flag:
16:19:07,725 DEBUG org.springframework.jms.listener.DefaultMessageListenerContainer - Consumer [ActiveMQMessageConsumer { value=ID:localhost.localdomain-58093-1179123486254-1:0:1:1, started=true }] of session [PooledSession { ActiveMQSession {id=ID:localhost.localdomain-58093-1179123486254-1:0:1,started=true} }] did not receive a message
16:19:07,726 DEBUG org.springframework.jms.listener.DefaultMessageListenerContainer - Lowered scheduled invoker count: 0
16:19:07,731 DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Retrieved dependent beans for bean 'sessionFactory': [transactionManager]
16:19:07,738 DEBUG org.springframework.beans.factory.support.DisposableBeanAdapter - Invoking destroy() on bean with name 'sessionFactory'
16:19:07,738  INFO org.springframework.orm.hibernate3.annotation.AnnotationSessionFactoryBean - Closing Hibernate SessionFactory
16:19:07,738  INFO org.hibernate.impl.SessionFactoryImpl - closing
log4j:ERROR Error occured while converting date.
java.lang.NullPointerException
        at java.lang.System.arraycopy(Native Method)
        at java.lang.AbstractStringBuilder.getChars(AbstractStringBuilder.java:328)
        at java.lang.StringBuffer.getChars(StringBuffer.java:201)
        at org.apache.log4j.helpers.AbsoluteTimeDateFormat.format(AbsoluteTimeDateFormat.java:108)
        at java.text.DateFormat.format(DateFormat.java:316)
        at org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:436)
        at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:56)
        at org.apache.log4j.PatternLayout.format(PatternLayout.java:495)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:292)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        at org.apache.log4j.Category.callAppenders(Category.java:187)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.log(Category.java:864)
        at org.apache.commons.logging.impl.Log4JLogger.debug(Log4JLogger.java:110)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:324)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:254)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:871)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:811)
        at java.lang.Thread.run(Thread.java:619)

---

Code:

---

DEBUG org.springframework.jms.listener.DefaultMessageListenerContainer - Consumer [ActiveMQMessageConsumer { value=ID:localhost.localdomain-58093-1179123486254-1:1:1:1, started=true }] of session [PooledSession { ActiveMQSession {id=ID:localhost.localdomain-58093-1179123486254-1:1:1,started=true} }] did not receive a message
log4j:ERROR Error occured while converting date.
java.lang.NullPointerException
        at java.lang.System.arraycopy(Native Method)
        at java.lang.AbstractStringBuilder.getChars(AbstractStringBuilder.java:328)
        at java.lang.StringBuffer.getChars(StringBuffer.java:201)
        at org.apache.log4j.helpers.AbsoluteTimeDateFormat.format(AbsoluteTimeDateFormat.java:108)
        at java.text.DateFormat.format(DateFormat.java:316)
        at org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:436)
        at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:56)
        at org.apache.log4j.PatternLayout.format(PatternLayout.java:495)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:292)
        at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:225)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        at org.apache.log4j.Category.callAppenders(Category.java:187)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.log(Category.java:864)
        at org.apache.commons.logging.impl.Log4JLogger.debug(Log4JLogger.java:110)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:324)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:254)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:871)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:811)
        at java.lang.Thread.run(Thread.java:619)
May 14, 2007 4:19:13 PM org.apache.coyote.http11.Http11BaseProtocol destroy
INFO: Stopping Coyote HTTP/1.1 on http-8081
May 14, 2007 4:19:13 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
INFO: Failed shutdown of Apache Portable Runtime
Exception in thread "ActiveMQ Transport: tcp://localhost/127.0.0.1:61616" java.lang.NullPointerException
        at org.apache.log4j.LogManager.getLogger(LogManager.java:179)
        at org.apache.log4j.Logger.getLogger(Logger.java:85)
        at org.apache.commons.logging.impl.Log4JLogger.getLogger(Log4JLogger.java:229)
        at org.apache.commons.logging.impl.Log4JLogger.isDebugEnabled(Log4JLogger.java:239)
        at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:85)
        at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:65)
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:133)
        at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122)
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:137)
        at java.lang.Thread.run(Thread.java:619)
log4j:ERROR Error occured while converting date.
java.lang.NullPointerException
        at java.lang.System.arraycopy(Native Method)
        at java.lang.AbstractStringBuilder.getChars(AbstractStringBuilder.java:328)
        at java.lang.StringBuffer.getChars(StringBuffer.java:201)
        at org.apache.log4j.helpers.AbsoluteTimeDateFormat.format(AbsoluteTimeDateFormat.java:108)
        at java.text.DateFormat.format(DateFormat.java:316)
        at org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:436)
        at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:56)
        at org.apache.log4j.PatternLayout.format(PatternLayout.java:495)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:292)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        at org.apache.log4j.Category.callAppenders(Category.java:187)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.log(Category.java:864)
        at org.apache.commons.logging.impl.Log4JLogger.trace(Log4JLogger.java:85)
        at org.apache.activemq.transport.InactivityMonitor.writeCheck(InactivityMonitor.java:79)
        at org.apache.activemq.transport.InactivityMonitor.access$100(InactivityMonitor.java:35)
        at org.apache.activemq.transport.InactivityMonitor$2.run(InactivityMonitor.java:57)
        at edu.emory.mathcs.backport.java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:431)
        at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.runAndReset(FutureTask.java:198)
        at edu.emory.mathcs.backport.java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:189)
        at edu.emory.mathcs.backport.java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:213)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
        at java.lang.Thread.run(Thread.java:619)
 DEBUG org.apache.activemq.transport.InactivityMonitor - No message sent since last write check, sending a KeepAliveInfo
log4j:ERROR Error occured while converting date.
java.lang.NullPointerException
        at java.lang.System.arraycopy(Native Method)
        at java.lang.AbstractStringBuilder.getChars(AbstractStringBuilder.java:328)
        at java.lang.StringBuffer.getChars(StringBuffer.java:201)
        at org.apache.log4j.helpers.AbsoluteTimeDateFormat.format(AbsoluteTimeDateFormat.java:108)
        at java.text.DateFormat.format(DateFormat.java:316)
        at org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:436)
        at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:56)
        at org.apache.log4j.PatternLayout.format(PatternLayout.java:495)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:292)
        at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:225)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        at org.apache.log4j.Category.callAppenders(Category.java:187)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.log(Category.java:864)
        at org.apache.commons.logging.impl.Log4JLogger.trace(Log4JLogger.java:85)
        at org.apache.activemq.transport.InactivityMonitor.writeCheck(InactivityMonitor.java:79)
        at org.apache.activemq.transport.InactivityMonitor.access$100(InactivityMonitor.java:35)
        at org.apache.activemq.transport.InactivityMonitor$2.run(InactivityMonitor.java:57)
        at edu.emory.mathcs.backport.java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:431)
        at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.runAndReset(FutureTask.java:198)
        at edu.emory.mathcs.backport.java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:189)
        at edu.emory.mathcs.backport.java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:213)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
        at java.lang.Thread.run(Thread.java:619)
log4j:ERROR Error occured while converting date.

---