Critical Description
In our tests we have 2 minutes timeout for shutting down the EAP. Sometimes it happens that the timeout is not enough and some tests fail because of it. Based on logs it seems that the bottleneck in this case is shutting down the pool with JMS connections. When a connection is closing, a close packet is sent to broker. Since broker is in the middle of shutdown, it doesn't respond and the thread waits 30 seconds until connection throws TimeoutException. This scenario repeats with each connection in the pool. Shutting down of the pool takes approximately "number of connections" x "30 seconds". However this happens only occasionally so it likely depends on ordering of events fired/handled in Artemis.
Customer impact: The shutdown sequence can hit the timeout set by EAP what can lead to an error. This can activate an alarm in customers automation and require admin's attention.
Below part of logs is shown which repeats for each JMS connection during the shutdown sequence.
09:22:52,973 DEBUG [org.apache.activemq.artemis.core.client.impl.ClientSessionImpl] (ServerService Thread Pool -- 84) Calling close on session ClientSessionImpl [name=978cd36b-6bb9-11e7-bd96-0015178e70d2, userna me=null, closed=false, factory = org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@6f966a44, metaData=(jms-session=,)]@6aa1c043 09:22:52,973 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl] (ServerService Thread Pool -- 84) Sending blocking PACKET(SessionCloseMessage)[type=69, channelID=10, packetObject=SessionClos eMessage] 09:22:52,973 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.RemotingConnectionImpl] (Thread-2 (ActiveMQ-client-netty-threads)) handling packet PACKET(NullResponseMessage)[type=21, channelID=10, packe tObject=NullResponseMessage] 09:22:52,973 DEBUG [org.apache.activemq.artemis.core.client.impl.ClientSessionImpl] (ServerService Thread Pool -- 84) calling cleanup on ClientSessionImpl [name=978cd36b-6bb9-11e7-bd96-0015178e70d2, username=nul l, closed=false, factory = org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@6f966a44, metaData=(jms-session=,)]@6aa1c043 09:22:52,973 DEBUG [org.apache.activemq.artemis.core.client.impl.ClientSessionImpl] (ServerService Thread Pool -- 84) Calling close on session ClientSessionImpl [name=978fb9a1-6bb9-11e7-bd96-0015178e70d2, userna me=null, closed=false, factory = org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@6f966a44, metaData=(jms-session=,)]@651c763f 09:22:52,973 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl] (ServerService Thread Pool -- 84) Sending blocking PACKET(SessionCloseMessage)[type=69, channelID=11, packetObject=SessionClos eMessage] 09:22:52,974 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.RemotingConnectionImpl] (Thread-2 (ActiveMQ-client-netty-threads)) handling packet PACKET(NullResponseMessage)[type=21, channelID=11, packe tObject=NullResponseMessage] 09:22:52,974 DEBUG [org.apache.activemq.artemis.core.client.impl.ClientSessionImpl] (ServerService Thread Pool -- 84) calling cleanup on ClientSessionImpl [name=978fb9a1-6bb9-11e7-bd96-0015178e70d2, username=nul l, closed=false, factory = org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@6f966a44, metaData=(jms-session=,)]@651c763f 09:22:52,974 DEBUG [org.apache.activemq.artemis.core.client.impl.ClientSessionImpl] (ServerService Thread Pool -- 84) Calling close on session ClientSessionImpl [name=979007c4-6bb9-11e7-bd96-0015178e70d2, userna me=null, closed=false, factory = org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@6f966a44, metaData=(jms-session=,)]@7d862bae 09:22:52,974 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl] (ServerService Thread Pool -- 84) Sending blocking PACKET(SessionCloseMessage)[type=69, channelID=12, packetObject=SessionClos eMessage] 09:22:52,974 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.RemotingConnectionImpl] (Thread-2 (ActiveMQ-client-netty-threads)) handling packet PACKET(NullResponseMessage)[type=21, channelID=12, packe tObject=NullResponseMessage] 09:22:52,974 DEBUG [org.apache.activemq.artemis.core.client.impl.ClientSessionImpl] (ServerService Thread Pool -- 84) calling cleanup on ClientSessionImpl [name=979007c4-6bb9-11e7-bd96-0015178e70d2, username=nul l, closed=false, factory = org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@6f966a44, metaData=(jms-session=,)]@7d862bae 09:22:52,975 DEBUG [org.apache.activemq.artemis.core.client.impl.ClientSessionImpl] (ServerService Thread Pool -- 84) Calling close on session ClientSessionImpl [name=979e86bd-6bb9-11e7-bd96-0015178e70d2, userna me=null, closed=false, factory = org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@27d418a3, metaData=(jms-session=,)]@5776b997 09:22:52,975 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl] (ServerService Thread Pool -- 84) Sending blocking PACKET(SessionCloseMessage)[type=69, channelID=10, packetObject=SessionClos eMessage] 09:22:52,975 TRACE [org.apache.activemq.artemis.core.client] (Thread-106 (ActiveMQ-client-global-threads)) AMQ214026: Failure captured on connectionID=-1,254,766,703, performing failover or reconnection now: Act iveMQNotConnectedException[errorType=NOT_CONNECTED message=AMQ119006: Channel disconnected] at org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl.connectionDestroyed(ClientSessionFactoryImpl.java:353) [artemis-core-client-1.5.5.004-redhat-1.jar:1.5.5.004-redhat-1] at org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector$Listener$1.run(NettyConnector.java:956) [artemis-core-client-1.5.5.004-redhat-1.jar:1.5.5.004-redhat-1] at org.apache.activemq.artemis.utils.OrderedExecutorFactory$OrderedExecutor$ExecutorTask.run(OrderedExecutorFactory.java:101) [artemis-commons-1.5.5.004-redhat-1.jar:1.5.5.004-redhat-1] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_131] at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_131] 09:23:22,977 TRACE [org.apache.activemq.artemis.core.client.impl.ClientSessionImpl] (ServerService Thread Pool -- 84) Failed to close session: ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=AMQ119014: Timed out after waiting 30,000 ms for response when sending packet 69] at org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:396) at org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:315) at org.apache.activemq.artemis.core.protocol.core.impl.ActiveMQSessionContext.sessionClose(ActiveMQSessionContext.java:482) at org.apache.activemq.artemis.core.client.impl.ClientSessionImpl.close(ClientSessionImpl.java:877) at org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl.closeCleanSessions(ClientSessionFactoryImpl.java:442) at org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl.interruptConnectAndCloseAllSessions(ClientSessionFactoryImpl.java:424) at org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl.close(ClientSessionFactoryImpl.java:457) at org.apache.activemq.artemis.core.client.impl.ServerLocatorImpl.doClose(ServerLocatorImpl.java:1364) at org.apache.activemq.artemis.core.client.impl.ServerLocatorImpl.close(ServerLocatorImpl.java:1307) at org.apache.activemq.artemis.jms.client.ActiveMQConnectionFactory.close(ActiveMQConnectionFactory.java:731) at org.apache.activemq.artemis.ra.ActiveMQResourceAdapter.closeConnectionFactory(ActiveMQResourceAdapter.java:2036) at org.apache.activemq.artemis.ra.ActiveMQRAManagedConnection.destroy(ActiveMQRAManagedConnection.java:299) at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.doDestroy(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:1369) at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.flush(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:882) at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.shutdown(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:1065) at org.jboss.jca.core.connectionmanager.pool.AbstractPool.shutdown(AbstractPool.java:930) at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.shutdown(AbstractConnectionManager.java:286) at org.jboss.as.connector.services.resourceadapters.deployment.AbstractResourceAdapterDeploymentService.unregisterAll(AbstractResourceAdapterDeploymentService.java:199) at org.jboss.as.connector.services.resourceadapters.deployment.AbstractResourceAdapterDeploymentService$3.run(AbstractResourceAdapterDeploymentService.java:353) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_131] at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_131] at org.jboss.threads.JBossThread.run(JBossThread.java:320) [jboss-threads-2.2.1.Final-redhat-1.jar:2.2.1.Final-redhat-1]
Attachments
Issue Links
- is related to
-
JBEAP-9235 (7.1.0) Cannot cleanly shutdown server disconnected inbound/outbound connections
-
- Verified
-
