2 Replies Latest reply on Oct 23, 2015 9:37 AM by James Murtaugh

    Consumer MDB Transaction commit error

    James Murtaugh Newbie

      Occasionally under heavy load I get an error shown below from the TransactionCoordinator. This always associated with trying to commit a transaction started by  a message Consumer MDB receiving a message in this case ConfWorker.   There are no other errors or exceptions prior to this error in the log.  There is nothing in this path that catches an exception without throwing a RuntimeException so I believe that if there was some exception it would be logged.  I noticed in my log that the same ( HornetQ-client-global-threads-xxxxx) is referenced by two different threads as shown:

      2015/10/22-19:59:37,689 DEBUG [com.tatacommunications.tp.jcm.synergy.SynergyToConfEvent] (Thread-9 (HornetQ-client-global-threads-1971002544)) Sending PARTICIPANT_DROP adbb5fa8-a50a-41b3-bf6f-8b437a91eac0

      2015/10/22-19:59:37,687 INFO [com.tatacommunications.tp.jcm.listener.ConfWorker] (Thread-14 (HornetQ-client-global-threads-1971002544)) ConfWorker finished processing

      In a normal sequence of events I see these two log entries in the opposite order and only see them in this order when the commit error occurs.  Also, there is typically a bigger separation in the time stamps.   The SynergyToConfEvent is invoked from another consumer MDB for a separate queue and produces a message for the queue that the ConfWorker listens to.  The Synergy queue has a higher priority(8) then the queue that the ConfWorker is listening to that priority is 7.  In this case there is a write to a datagrid cache and a message is queued to a third queue after which the transaction would commit.   I am trying to understand what is causing the transaction to be in an invalid state?  Any suggestions as to how to determine the cause of the transaction failure would be appreciated.  FYI:This particular experiment is being run on a single processor VM.

       

      2015/10/22-19:59:37,708 ERROR [org.infinispan.transaction.TransactionCoordinator] (Thread-14 (HornetQ-client-global-threads-1971002544)) ISPN000255: Error while processing prepare: com.arjuna.ats.jta.exceptions.InvalidTerminationStateException: ARJUNA016064: The transaction is in an invalid state!

              at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.setRollbackOnly(TransactionImple.java:313)

              at org.infinispan.interceptors.InvocationContextInterceptor.markTxForRollbackAndRethrow(InvocationContextInterceptor.java:163) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:73) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:103) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:122) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:104) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.transaction.xa.TransactionXaAdapter.prepare(TransactionXaAdapter.java:92) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:213)

              at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2522)

              at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2489)

              at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2066)

              at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1481)

              at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:98)

              at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)

              at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1189)

              at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)

              at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)

              at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.afterDelivery(MessageEndpointInvocationHandler.java:72) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

              at sun.reflect.GeneratedMethodAccessor40.invoke(Unknown Source) [:1.7.0_80]

              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80]

              at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80]

              at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.handle(AbstractInvocationHandler.java:60) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

              at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:136) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

              at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

              at com.sun.proxy.$Proxy172.afterDelivery(Unknown Source)

              at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:337)

              at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:1117)

              at org.hornetq.core.client.impl.ClientConsumerImpl.access$500(ClientConsumerImpl.java:57)

              at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:1252)

              at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:105)

              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_80]

              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_80]

              at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_80]

      015/10/22-19:59:37,715 WARN  [com.arjuna.ats.jta] (Thread-14 (HornetQ-client-global-threads-1971002544)) ARJUNA016041: prepare on < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a858f14:55edf947:56293fc1:bc1, node_name=1, branch_uid=0:ffff0a858f14:55edf947:56293fc1:bce, subordinatenodename=null, eis_name=unknown eis name > (TransactionXaAdapter{localTransaction=LocalXaTransaction{xid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a858f14:55edf947:56293fc1:bc1, node_name=1, branch_uid=0:ffff0a858f14:55edf947:56293fc1:bce, subordinatenodename=null, eis_name=unknown eis name >} LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, stateTransferFlag=null} org.infinispan.transaction.xa.LocalXaTransaction@1f2}) failed with exception XAException.XA_RBROLLBACK: javax.transaction.xa.XAException

              at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:142) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:104) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.transaction.xa.TransactionXaAdapter.prepare(TransactionXaAdapter.java:92) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:213)

              at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2522)

              at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2489)

              at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2066)

              at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1481)

              at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:98)

              at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)

              at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1189)

              at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)

              at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)

              at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.afterDelivery(MessageEndpointInvocationHandler.java:72) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

              at sun.reflect.GeneratedMethodAccessor40.invoke(Unknown Source) [:1.7.0_80]

              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_80]

              at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_80]

              at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.handle(AbstractInvocationHandler.java:60) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

              at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:136) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

              at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

              at com.sun.proxy.$Proxy172.afterDelivery(Unknown Source)

              at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:337)

              at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:1117)

              at org.hornetq.core.client.impl.ClientConsumerImpl.access$500(ClientConsumerImpl.java:57)

              at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:1252)

              at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:105)

              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_80]

              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_80]

              at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_80]

      Caused by: com.arjuna.ats.jta.exceptions.InvalidTerminationStateException: ARJUNA016064: The transaction is in an invalid state!

              at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.setRollbackOnly(TransactionImple.java:313)

              at org.infinispan.interceptors.InvocationContextInterceptor.markTxForRollbackAndRethrow(InvocationContextInterceptor.java:163) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:73) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:103) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:122) [infinispan-core-6.2.1.Final-redhat-2.jar:6.2.1.Final-redhat-2]

              ... 28 more

       

       

      2015/10/22-19:59:37,720 WARN  [com.arjuna.ats.arjuna] (Thread-14 (HornetQ-client-global-threads-1971002544)) ARJUNA012073: BasicAction.End() - prepare phase of action-id 0:ffff0a858f14:55edf947:56293fc1:bc1 failed.

      2015/10/22-19:59:37,720 WARN  [com.arjuna.ats.arjuna] (Thread-14 (HornetQ-client-global-threads-1971002544)) ARJUNA012075: Action Aborting

        • 1. Re: Consumer MDB Transaction commit error
          Justin Bertram Master

          Couple of things...

          1. This is the HornetQ Development forum which is specifically for discussions about the development of the HornetQ message broker.  It's not for usage questions.  That's what the more generic HornetQ forum is for.
          2. I don't see anything going wrong with HornetQ here.  The thread is managed by HornetQ, of course, since the container is delivering a message to an MDB, but aside from that I don't see anything related to HornetQ about your problem.  It seems to be some sort of issue between the transaction manager and Infinispan.  I recommend you post on the application server forum and ask how/why a transaction could get into an invalid state.
          • 2. Re: Consumer MDB Transaction commit error
            James Murtaugh Newbie

            Justin,

            Sorry, will be more careful where I post in the future.  Thanks for the reply.

             

            Jim