Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-12206

Sometimes shutdown of EAP takes long because of closing JMS connections

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Critical Critical
    • None
    • 7.1.0.ER2
    • ActiveMQ
    • None
    • User Experience
    • Hide

      I saw the issue in the following test.

      git clone git://git.app.eng.bos.redhat.com/jbossqe/eap-tests-hornetq.git
cd eap-tests-hornetq/scripts/
git checkout ea367e59e9daeac0f302a4ffc0813a6316b7a2d3
groovy -DEAP_VERSION=7.1.0.ER2.2 PrepareServers7.groovy
export WORKSPACE=$PWD
export JBOSS_HOME_1=$WORKSPACE/server1/jboss-eap
export JBOSS_HOME_2=$WORKSPACE/server2/jboss-eap
export JBOSS_HOME_3=$WORKSPACE/server3/jboss-eap
export JBOSS_HOME_4=$WORKSPACE/server4/jboss-eap

cd ../jboss-hornetq-testsuite/

mvn clean test -Dtest=RemoteJcaWithHighCpuLoadTestCase#loadOnJmsInClusterWithLodhLikeMdbLargeMessages -DfailIfNoTests=false -Deap=7x | tee log
      Show
      I saw the issue in the following test. git clone git: //git.app.eng.bos.redhat.com/jbossqe/eap-tests-hornetq.git cd eap-tests-hornetq/scripts/ git checkout ea367e59e9daeac0f302a4ffc0813a6316b7a2d3 groovy -DEAP_VERSION=7.1.0.ER2.2 PrepareServers7.groovy export WORKSPACE=$PWD export JBOSS_HOME_1=$WORKSPACE/server1/jboss-eap export JBOSS_HOME_2=$WORKSPACE/server2/jboss-eap export JBOSS_HOME_3=$WORKSPACE/server3/jboss-eap export JBOSS_HOME_4=$WORKSPACE/server4/jboss-eap cd ../jboss-hornetq-testsuite/ mvn clean test -Dtest=RemoteJcaWithHighCpuLoadTestCase#loadOnJmsInClusterWithLodhLikeMdbLargeMessages -DfailIfNoTests= false -Deap=7x | tee log

      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]

        1. server-trace.log.zip
          13.46 MB
        2. server.log.zip
          808 kB
        3. thread-dump.txt
          82 kB

              mtaylor1@redhat.com Martyn Taylor (Inactive)
              eduda_jira Erich Duda (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: