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
Comment From: spring-projects-issues
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)
Comment From: spring-projects-issues
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.
Comment From: spring-projects-issues
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
Comment From: gregorycfrank
A similar issue happening for me during an integration test. I have a broker setup (named "broker") and a connection factory setup to connect to it via the VM transport (vm://broker). The listener container, of course, uses the factory to connect to the broker.
According to the logs, after the tests complete the broker shuts down correctly, but the DefaultListenerContainer detects a broken session and then tries to reconnect (recoverAfterListenerSetupFailure()). Since the VM transport automatically creates a new broker if one doesn't exist, it tries to create a new broker, which then immediately fails because Spring is shutting down. (Or, if the factory's brokerURL has create=false it complains the broker doesn't exist.) This happens two or three times until the shutdown is complete.
We're currently using the http://activemq.apache.org/schema/core and http://www.springframework.org/schema/jms XML namespaces to create the beans, so "dependsOn" can't be used without completely rewriting our configuration, and I'm not sure it would help the shutdown situation anyway.
Comment From: snicoll
Can any of you share a small sample that we can use to reproduce the problem?
@gregorycfrank, the dependsOn should happen transparently so sharing a test with us would help figuring out what is missing.
Comment From: spring-projects-issues
If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.
Comment From: spring-projects-issues
Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open the issue.