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

Consumer MDB Transaction commit error

skionsnow Oct 22, 2015 5:00 PM

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]