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.