Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

DefaultMessageListenerContainer shutdown exceptions with ActiveMQ [SPR-16327] #20874

Open
spring-issuemaster opened this issue Dec 27, 2017 · 3 comments

Comments

@spring-issuemaster
Copy link
Collaborator

@spring-issuemaster spring-issuemaster commented Dec 27, 2017

yael opened SPR-16327 and commented

upon system shutdown we get exceptions from DefaultMessageListenerContainer
happens every time
something here is not closing correctly

27 09:19:29.603  INFO [Thread-11] AnnotationConfigEmbeddedWebApplicationContext:984 : Closing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@68702e03: startup date [Wed Dec 27 09:17:35 IST 2017]; root of context hierarchy
27 09:19:29.607  INFO [Thread-11]       o.s.c.support.DefaultLifecycleProcessor:358 : Stopping beans in phase 2147483647
27 09:19:29.628  WARN [DefaultMessageListenerContainer-1]    org.apache.activemq.jms.pool.PooledSession:121 : Caught exception trying rollback() when putting session back into the pool, will invalidate. javax.jms.IllegalStateException: The Session is closed
javax.jms.IllegalStateException: The Session is closed
	at org.apache.activemq.ActiveMQSession.checkClosed(ActiveMQSession.java:771)
	at org.apache.activemq.ActiveMQSession.rollback(ActiveMQSession.java:596)
	at org.apache.activemq.jms.pool.PooledSession.close(PooledSession.java:118)
	at org.springframework.jms.support.JmsUtils.closeSession(JmsUtils.java:108)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.clearResources(DefaultMessageListenerContainer.java:1207)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1066)
	at java.lang.Thread.run(Thread.java:748)
27 09:19:29.630  WARN [DefaultMessageListenerContainer-1]       o.s.j.l.DefaultMessageListenerContainer:880 : Setup of JMS message listener invoker failed for destination 'test.scan.responses' - trying to recover. Cause: null
27 09:19:29.635  WARN [DefaultMessageListenerContainer-1]    org.apache.activemq.jms.pool.PooledSession:121 : Caught exception trying rollback() when putting session back into the pool, will invalidate. javax.jms.IllegalStateException: The Session is closed
javax.jms.IllegalStateException: The Session is closed
	at org.apache.activemq.ActiveMQSession.checkClosed(ActiveMQSession.java:771)
	at org.apache.activemq.ActiveMQSession.rollback(ActiveMQSession.java:596)
	at org.apache.activemq.jms.pool.PooledSession.close(PooledSession.java:118)
	at org.springframework.jms.support.JmsUtils.closeSession(JmsUtils.java:108)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.clearResources(DefaultMessageListenerContainer.java:1207)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1066)
	at java.lang.Thread.run(Thread.java:748)
27 09:19:29.635  WARN [DefaultMessageListenerContainer-1]       o.s.j.l.DefaultMessageListenerContainer:880 : Setup of JMS message listener invoker failed for destination 'test.realtime.responses' - trying to recover. Cause: The Session is closed
27 09:19:29.636  WARN [DefaultMessageListenerContainer-2]    org.apache.activemq.jms.pool.PooledSession:121 : Caught exception trying rollback() when putting session back into the pool, will invalidate. javax.jms.IllegalStateException: The Session is closed
javax.jms.IllegalStateException: The Session is closed
	at org.apache.activemq.ActiveMQSession.checkClosed(ActiveMQSession.java:771)
	at org.apache.activemq.ActiveMQSession.rollback(ActiveMQSession.java:596)
	at org.apache.activemq.jms.pool.PooledSession.close(PooledSession.java:118)
	at org.springframework.jms.support.JmsUtils.closeSession(JmsUtils.java:108)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.clearResources(DefaultMessageListenerContainer.java:1207)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1066)
	at java.lang.Thread.run(Thread.java:748)
27 09:19:29.647  WARN [Thread-11]     c.c.m.a.connectors.AppServerCommListeners:137 : Shutting down 3 jms listeners.
27 09:19:29.658  WARN [DefaultMessageListenerContainer-1]    org.apache.activemq.jms.pool.PooledSession:121 : Caught exception trying rollback() when putting session back into the pool, will invalidate. javax.jms.IllegalStateException: The Session is closed
javax.jms.IllegalStateException: The Session is closed
	at org.apache.activemq.ActiveMQSession.checkClosed(ActiveMQSession.java:771)
	at org.apache.activemq.ActiveMQSession.rollback(ActiveMQSession.java:596)
	at org.apache.activemq.jms.pool.PooledSession.close(PooledSession.java:118)
	at org.springframework.jms.support.JmsUtils.closeSession(JmsUtils.java:108)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.clearResources(DefaultMessageListenerContainer.java:1207)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1066)
	at java.lang.Thread.run(Thread.java:748)
27 09:19:29.658  WARN [DefaultMessageListenerContainer-1]       o.s.j.l.DefaultMessageListenerContainer:880 : Setup of JMS message listener invoker failed for destination 'test.scan.requests' - trying to recover. Cause: The Session is closed
27 09:19:29.668  WARN [Thread-11]    org.apache.activemq.jms.pool.PooledSession:121 : Caught exception trying rollback() when putting session back into the pool, will invalidate. javax.jms.IllegalStateException: The Session is closed
javax.jms.IllegalStateException: The Session is closed
	at org.apache.activemq.ActiveMQSession.checkClosed(ActiveMQSession.java:771)
	at org.apache.activemq.ActiveMQSession.rollback(ActiveMQSession.java:596)
	at org.apache.activemq.jms.pool.PooledSession.close(PooledSession.java:118)
	at org.springframework.jms.support.JmsUtils.closeSession(JmsUtils.java:108)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.clearResources(DefaultMessageListenerContainer.java:1207)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.access$000(DefaultMessageListenerContainer.java:1032)
	at org.springframework.jms.listener.DefaultMessageListenerContainer.doShutdown(DefaultMessageListenerContainer.java:579)
	at org.springframework.jms.listener.AbstractJmsListeningContainer.shutdown(AbstractJmsListeningContainer.java:237)
	at org.springframework.jms.listener.AbstractJmsListeningContainer.destroy(AbstractJmsListeningContainer.java:177)
	at org.springframework.jms.config.JmsListenerEndpointRegistry.destroy(JmsListenerEndpointRegistry.java:252)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:272)
	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$2.run(AbstractApplicationContext.java:929)
27 09:19:29.671  WARN [Thread-11]    org.apache.activemq.jms.pool.PooledSession:121 : Caught exception trying rollback() when putting session back into the pool, will invalidate. javax.jms.IllegalStateException: The Session is closed
javax.jms.IllegalStateException: The Session is closed
	at org.apache.activemq.ActiveMQSession.checkClosed(ActiveMQSession.java:771)
	at org.apache.activemq.ActiveMQSession.rollback(ActiveMQSession.java:596)
	at org.apache.activemq.jms.pool.PooledSession.close(PooledSession.java:118)
	at org.springframework.jms.support.JmsUtils.closeSession(JmsUtils.java:108)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.clearResources(DefaultMessageListenerContainer.java:1207)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.access$000(DefaultMessageListenerContainer.java:1032)
	at org.springframework.jms.listener.DefaultMessageListenerContainer.doShutdown(DefaultMessageListenerContainer.java:579)
	at org.springframework.jms.listener.AbstractJmsListeningContainer.shutdown(AbstractJmsListeningContainer.java:237)
	at org.springframework.jms.listener.AbstractJmsListeningContainer.destroy(AbstractJmsListeningContainer.java:177)
	at org.springframework.jms.config.JmsListenerEndpointRegistry.destroy(JmsListenerEndpointRegistry.java:252)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:272)
	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$2.run(AbstractApplicationContext.java:929)
27 09:19:29.673  WARN [Thread-11]    org.apache.activemq.jms.pool.PooledSession:121 : Caught exception trying rollback() when putting session back into the pool, will invalidate. javax.jms.IllegalStateException: The Session is closed
javax.jms.IllegalStateException: The Session is closed
	at org.apache.activemq.ActiveMQSession.checkClosed(ActiveMQSession.java:771)
	at org.apache.activemq.ActiveMQSession.rollback(ActiveMQSession.java:596)
	at org.apache.activemq.jms.pool.PooledSession.close(PooledSession.java:118)
	at org.springframework.jms.support.JmsUtils.closeSession(JmsUtils.java:108)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.clearResources(DefaultMessageListenerContainer.java:1207)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.access$000(DefaultMessageListenerContainer.java:1032)
	at org.springframework.jms.listener.DefaultMessageListenerContainer.doShutdown(DefaultMessageListenerContainer.java:579)
	at org.springframework.jms.listener.AbstractJmsListeningContainer.shutdown(AbstractJmsListeningContainer.java:237)
	at org.springframework.jms.listener.AbstractJmsListeningContainer.destroy(AbstractJmsListeningContainer.java:177)
	at org.springframework.jms.config.JmsListenerEndpointRegistry.destroy(JmsListenerEndpointRegistry.java:252)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:272)
	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$2.run(AbstractApplicationContext.java:929)
27 09:19:29.755  INFO [Thread-11]      o.s.s.concurrent.ThreadPoolTaskScheduler:203 : Shutting down ExecutorService 'defaultScheduler'
27 09:19:29.795  INFO [Thread-11] .s.o.j.LocalContainerEntityManagerFactoryBean:548 : Closing JPA EntityManagerFactory for persistence unit 'default'

Process finished with exit code 0

Affects: 4.3.9

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

@spring-issuemaster spring-issuemaster commented Dec 27, 2017

yael commented

need to make sure shutdown is orderly
we sometimes see errors on reconnect tries, which should not happen on shutdown ever
we need to always chk the shutdown flag before doing anything
also, these exceptions are not caught, but thrown to the running thread. this means they cannot be removed from the log file with suppress

27 10:54:16.401 ERROR [DefaultMessageListenerContainer-2]      org.apache.activemq.broker.BrokerService:624 : Failed to start Apache ActiveMQ ([localhost, null], {})
javax.management.InstanceAlreadyExistsException: org.apache.activemq:type=Broker,brokerName=localhost
	at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
	at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
	at org.apache.activemq.broker.jmx.ManagementContext.registerMBean(ManagementContext.java:408)
	at org.apache.activemq.broker.jmx.AnnotatedMBean.registerMBean(AnnotatedMBean.java:72)
	at org.apache.activemq.broker.BrokerService.startManagementContext(BrokerService.java:2581)
	at org.apache.activemq.broker.BrokerService.start(BrokerService.java:606)
	at org.apache.activemq.transport.vm.VMTransportFactory.doCompositeConnect(VMTransportFactory.java:127)
	at org.apache.activemq.transport.vm.VMTransportFactory.doConnect(VMTransportFactory.java:56)
	at org.apache.activemq.transport.TransportFactory.connect(TransportFactory.java:69)
	at org.apache.activemq.ActiveMQConnectionFactory.createTransport(ActiveMQConnectionFactory.java:330)
	at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:345)
	at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:303)
	at org.apache.activemq.ActiveMQConnectionFactory.createConnection(ActiveMQConnectionFactory.java:243)
	at org.apache.activemq.jms.pool.PooledConnectionFactory.createConnection(PooledConnectionFactory.java:275)
	at org.apache.activemq.jms.pool.PooledConnectionFactory$1.makeObject(PooledConnectionFactory.java:95)
	at org.apache.activemq.jms.pool.PooledConnectionFactory$1.makeObject(PooledConnectionFactory.java:92)
	at org.apache.commons.pool2.impl.GenericKeyedObjectPool.create(GenericKeyedObjectPool.java:1041)
	at org.apache.commons.pool2.impl.GenericKeyedObjectPool.addObject(GenericKeyedObjectPool.java:1221)
	at org.apache.activemq.jms.pool.PooledConnectionFactory.createConnection(PooledConnectionFactory.java:221)
	at org.apache.activemq.jms.pool.PooledConnectionFactory.createConnection(PooledConnectionFactory.java:204)
	at org.springframework.jms.support.JmsAccessor.createConnection(JmsAccessor.java:180)
	at org.springframework.jms.listener.AbstractJmsListeningContainer.createSharedConnection(AbstractJmsListeningContainer.java:413)
	at org.springframework.jms.listener.AbstractJmsListeningContainer.refreshSharedConnection(AbstractJmsListeningContainer.java:398)
	at org.springframework.jms.listener.DefaultMessageListenerContainer.refreshConnectionUntilSuccessful(DefaultMessageListenerContainer.java:925)
	at org.springframework.jms.listener.DefaultMessageListenerContainer.recoverAfterListenerSetupFailure(DefaultMessageListenerContainer.java:899)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1077)
	at java.lang.Thread.run(Thread.java:748)
27 10:54:16.417  WARN [JMX connector]     o.a.activemq.broker.jmx.ManagementContext:158 : Failed to start JMX connector Cannot bind to URL [rmi://localhost:1099/jmxrmi]: javax.naming.NameAlreadyBoundException: jmxrmi [Root exception is java.rmi.AlreadyBoundException: jmxrmi]. Will restart management to re-create JMX connector, trying to remedy this issue.
27 10:54:16.559 ERROR [DefaultMessageListenerContainer-1]      org.apache.activemq.broker.BrokerService:624 : Failed to start Apache ActiveMQ ([localhost, null], {})
java.lang.IllegalStateException: Shutdown in progress
	at java.lang.ApplicationShutdownHooks.add(ApplicationShutdownHooks.java:66)
	at java.lang.Runtime.addShutdownHook(Runtime.java:211)
	at org.apache.activemq.broker.BrokerService.addShutdownHook(BrokerService.java:2498)
	at org.apache.activemq.broker.BrokerService.doStartBroker(BrokerService.java:725)
	at org.apache.activemq.broker.BrokerService.startBroker(BrokerService.java:718)
	at org.apache.activemq.broker.BrokerService.start(BrokerService.java:621)
	at org.apache.activemq.transport.vm.VMTransportFactory.doCompositeConnect(VMTransportFactory.java:127)
	at org.apache.activemq.transport.vm.VMTransportFactory.doConnect(VMTransportFactory.java:56)
	at org.apache.activemq.transport.TransportFactory.connect(TransportFactory.java:69)
	at org.apache.activemq.ActiveMQConnectionFactory.createTransport(ActiveMQConnectionFactory.java:330)
	at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:345)
	at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:303)
	at org.apache.activemq.ActiveMQConnectionFactory.createConnection(ActiveMQConnectionFactory.java:243)
	at org.apache.activemq.jms.pool.PooledConnectionFactory.createConnection(PooledConnectionFactory.java:275)
	at org.apache.activemq.jms.pool.PooledConnectionFactory$1.makeObject(PooledConnectionFactory.java:95)
	at org.apache.activemq.jms.pool.PooledConnectionFactory$1.makeObject(PooledConnectionFactory.java:92)
	at org.apache.commons.pool2.impl.GenericKeyedObjectPool.create(GenericKeyedObjectPool.java:1041)
	at org.apache.commons.pool2.impl.GenericKeyedObjectPool.addObject(GenericKeyedObjectPool.java:1221)
	at org.apache.activemq.jms.pool.PooledConnectionFactory.createConnection(PooledConnectionFactory.java:221)
	at org.apache.activemq.jms.pool.PooledConnectionFactory.createConnection(PooledConnectionFactory.java:204)
	at org.springframework.jms.support.JmsAccessor.createConnection(JmsAccessor.java:180)
	at org.springframework.jms.listener.AbstractJmsListeningContainer.createSharedConnection(AbstractJmsListeningContainer.java:413)
	at org.springframework.jms.listener.AbstractJmsListeningContainer.refreshSharedConnection(AbstractJmsListeningContainer.java:398)
	at org.springframework.jms.listener.DefaultMessageListenerContainer.refreshConnectionUntilSuccessful(DefaultMessageListenerContainer.java:925)
	at org.springframework.jms.listener.DefaultMessageListenerContainer.recoverAfterListenerSetupFailure(DefaultMessageListenerContainer.java:899)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1077)
	at java.lang.Thread.run(Thread.java:748)
@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

@spring-issuemaster spring-issuemaster commented Jan 7, 2018

Juergen Hoeller commented

Frankly, this looks more like internal ActiveMQ bugs (like trying to trigger a rollback on a close call and then stumbling upon its own inner close check there). I'm not sure what we can do about these in Spring since we seem to be handling everything ok from the JMS API side.

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

@spring-issuemaster spring-issuemaster commented Jan 8, 2018

yael commented

are you shutting down all DefaultMessageListenerContainer ?
cause it seems they try to reconnect...
i think the problem is AsyncMessageListenerInvoker at the bottom of the class that is not aware of the shutdown in progress

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
1 participant
You can’t perform that action at this time.