4 Replies Latest reply on Jun 7, 2016 11:21 AM by Daniel Filippov

    Timed out waiting for response when sending packet 54

    Daniel Filippov Newbie

      Hello!

      I'm using HornetQ 2.4.7.Final bundled into Wildfly 9.0.2.Final as JMS broker (if it matters, messages are bridged from another Wildfly/HornetQ server). Recently, I got several exceptions during messages processing by MDB (3 times within half hour) with the following stack trace:

      10:32:58,638 WARN  [org.hornetq.core.client] (Thread-2495 (HornetQ-client-global-threads-1959776994)) HQ212015: failover occurred during prepare rolling back: HornetQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=HQ119014: Timed out waiting for response when sending packet 54]
        at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:390) [hornetq-core-client-2.4.7.Final.jar:]
        at org.hornetq.core.client.impl.ClientSessionImpl.prepare(ClientSessionImpl.java:1669) [hornetq-core-client-2.4.7.Final.jar:]
        at org.hornetq.core.client.impl.DelegatingSession.prepare(DelegatingSession.java:459) [hornetq-core-client-2.4.7.Final.jar:]
        at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:217) [narayana-jts-idlj-5.0.6.Final.jar:5.0.6.Final (revision: 4bf92)]
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2640) [narayana-jts-idlj-5.0.6.Final.jar:5.0.6.Final (revision: 4bf92)]
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2590) [narayana-jts-idlj-5.0.6.Final.jar:5.0.6.Final (revision: 4bf92)]
        at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2144) [narayana-jts-idlj-5.0.6.Final.jar:5.0.6.Final (revision: 4bf92)]
        at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1524) [narayana-jts-idlj-5.0.6.Final.jar:5.0.6.Final (revision: 4bf92)]
        at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [narayana-jts-idlj-5.0.6.Final.jar:5.0.6.Final (revision: 4bf92)]
        at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [narayana-jts-idlj-5.0.6.Final.jar:5.0.6.Final (revision: 4bf92)]
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1200) [narayana-jts-idlj-5.0.6.Final.jar:5.0.6.Final (revision: 4bf92)]
        at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [narayana-jts-idlj-5.0.6.Final.jar:5.0.6.Final (revision: 4bf92)]
        at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
        at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.afterDelivery(MessageEndpointInvocationHandler.java:71)
        at sun.reflect.GeneratedMethodAccessor145.invoke(Unknown Source) [:1.8.0_65]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) [rt.jar:1.8.0_65]
        at java.lang.reflect.Method.invoke(Unknown Source) [rt.jar:1.8.0_65]
        at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.handle(AbstractInvocationHandler.java:60)
        at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:135)
        at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73)
        at foo.bar.JmsDispatcher$$$endpoint1.afterDelivery(Unknown Source)
        at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:330) [hornetq-ra-2.4.7.Final.jar:]
        at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:1116) [hornetq-core-client-2.4.7.Final.jar:]
        at org.hornetq.core.client.impl.ClientConsumerImpl.access$500(ClientConsumerImpl.java:56) [hornetq-core-client-2.4.7.Final.jar:]
        at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:1251) [hornetq-core-client-2.4.7.Final.jar:]
        at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:104) [hornetq-core-client-2.4.7.Final.jar:]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [rt.jar:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [rt.jar:1.8.0_65]
        at java.lang.Thread.run(Unknown Source) [rt.jar:1.8.0_65]
      
      
      

      According to log, it looks like MDB's onMessage method completed without any visible errors, and error occurred on transaction commit (I found out that packet 54 is SESS_XA_PREPARE). But I have no idea on why these timeouts occurred and how I can prevent this in future.

      What could cause such a timeout?

      I'll appreciate any help!