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

    Timed out waiting for response when sending packet 54

    dfilippov
    dfilippov Jun 7, 2016 4:07 AM

      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!