Help needed on XAException.XA_RBROLLBACK while using jboss transaction management for spring boot

497 views
Skip to first unread message

Adarsh

unread,
Nov 4, 2020, 3:51:30 AM11/4/20
to narayana-users
Hello all,  I am facing problem in our application with Narayana transaction management using as XA . 

When system is under load we are seeing XA_RBROLLBACK and XA_NOTA exceptions. But could not find the root cause for this . 

Scenario:

1.  App is reading 100k+ messages from MQ (version 7.5.07)
2. Doing db operations read and write  -- In new transaction
3. Writing message to MQ .

Narayana transaction manager is not able to commit transaction. There are no exceptions related to db side.

versions:  
Spring boot -  2.1.16.RELEASE
Spring version - 5.1.17.RELEASE
Narayana TM version - 5.9.8.Final
Web sphere MQ  - 7.5.0.7
 
Any help to resolve this problem ?

2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT 2020-11-03 14:45:54.963 WARN  14 [c.a.a.jta] [DefaultMessageListenerContainer-665|1914.2|665485|XXXX|XXXXX|1] ARJUNA016129: Could not end XA resource com.ibm.mq.jmqi.JmqiXAResource@c5a876e
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT javax.transaction.xa.XAException: The method 'xa_end' has failed with errorCode '100'.
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.ibm.mq.jmqi.JmqiXAResource.end(JmqiXAResource.java:555) ~[com.ibm.mq.allclient-9.1.5.0.jar!/:9.1.5.0 - p915-L200316]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.doEnd(TransactionImple.java:1087) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.endAssociation(TransactionImple.java:1058) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.endAssociation(XAResourceRecord.java:1286) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:210) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2664) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2614) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2157) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1503) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1287) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1035) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:714) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:251) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1190) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1180) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1077) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at java.lang.Thread.run(Thread.java:748) [na:1.8.0_252]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT 2020-11-03 14:45:54.963 WARN  14 [c.a.a.jta] [DefaultMessageListenerContainer-665|1914.2|665485|EODSweepRequestController|GPL.EndOfDayDailyCalculation|1] ARJUNA016041: prepare on < formatId=131077, gtrid_length=58, bqual_length=36, tx_uid=0:ffff0aff3b73:97a1:5fa169e3:3c35c, node_name=b8ce4484-cd2f-494e-743d-23ee-4, branch_uid=0:ffff0aff3b73:97a1:5fa169e3:3c7f3, subordinatenodename=null, eis_name=0 > (com.ibm.mq.jmqi.JmqiXAResource@c5a876e) failed with exception XAException.XA_RBROLLBACK
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT javax.transaction.xa.XAException: The method 'xa_end' has failed with errorCode '100'.
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.ibm.mq.jmqi.JmqiXAResource.end(JmqiXAResource.java:555) ~[com.ibm.mq.allclient-9.1.5.0.jar!/:9.1.5.0 - p915-L200316]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.doEnd(TransactionImple.java:1087) [jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.endAssociation(TransactionImple.java:1058) [jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.endAssociation(XAResourceRecord.java:1286) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:210) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2664) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2614) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2157) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1503) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1287) [jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [jta-5.9.8.Final.jar!/:5.9.8.Final]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1035) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:714) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:251) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1190) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1180) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1077) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]
   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT at java.lang.Thread.run(Thread.java:748) [na:1.8.0_252]


Michael Musgrove

unread,
Nov 4, 2020, 4:00:55 AM11/4/20
to narayana-users
There is an IBM article which says it could be related to connections timing out. Could that be related to your issue?

Adarsh

unread,
Nov 4, 2020, 4:37:18 AM11/4/20
to narayana-users
More log: 

2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT 2020-11-03 14:45:54.963 WARN  14 [c.a.a.jta] [DefaultMessageListenerContainer-665|1914.2|665485|XXXX|XXXXXX |1] ARJUNA016129: Could not end XA resource com.ibm.mq.jmqi.JmqiXAResource@c5a876e

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT javax.transaction.xa.XAException: The method 'xa_end' has failed with errorCode '100'.

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.ibm.mq.jmqi.JmqiXAResource.end(JmqiXAResource.java:555) ~[com.ibm.mq.allclient-9.1.5.0.jar!/:9.1.5.0 - p915-L200316]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.doEnd(TransactionImple.java:1087) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]

  2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.endAssociation(TransactionImple.java:1058) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.endAssociation(XAResourceRecord.java:1286) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:210) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2664) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2614) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2157) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1503) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1287) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1035) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:714) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:251) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1190) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1180) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1077) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at java.lang.Thread.run(Thread.java:748) [na:1.8.0_252]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT 2020-11-03 14:45:54.963 WARN  14 [c.a.a.jta] [DefaultMessageListenerContainer-665|1914.2|665485|XXXXX |XXXXXXXX |1] ARJUNA016041: prepare on < formatId=131077, gtrid_length=58, bqual_length=36, tx_uid=0:ffff0aff3b73:97a1:5fa169e3:3c35c, node_name=b8ce4484-cd2f-494e-743d-23ee-4, branch_uid=0:ffff0aff3b73:97a1:5fa169e3:3c7f3, subordinatenodename=null, eis_name=0 > (com.ibm.mq.jmqi.JmqiXAResource@c5a876e) failed with exception XAException.XA_RBROLLBACK

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT javax.transaction.xa.XAException: The method 'xa_end' has failed with errorCode '100'.

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.ibm.mq.jmqi.JmqiXAResource.end(JmqiXAResource.java:555) ~[com.ibm.mq.allclient-9.1.5.0.jar!/:9.1.5.0 - p915-L200316]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.doEnd(TransactionImple.java:1087) [jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.endAssociation(TransactionImple.java:1058) [jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.endAssociation(XAResourceRecord.java:1286) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:210) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2664) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2614) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2157) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1503) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1287) [jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1035) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:714) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:251) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1190) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1180) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1077) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT            at java.lang.Thread.run(Thread.java:748) [na:1.8.0_252]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT 2020-11-03 14:45:54.963 WARN  14 [c.a.a.arjuna] [DefaultMessageListenerContainer-665|1914.2|665485|XXXX|XXXXX |1] ARJUNA012073: BasicAction.End() - prepare phase of action-id 0:ffff0aff3b73:97a1:5fa169e3:3c35c failed.

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/4] OUT 2020-11-03 14:45:54.963 WARN  14 [c.a.a.arjuna] [DefaultMessageListenerContainer-665|1914.2|665485|XXXXX |XXXX|1] ARJUNA012075: Action Aborting

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT 2020-11-03 14:45:54.963 WARN  13 [c.a.a.jta] [DefaultMessageListenerContainer-827|2591.2|665483|XXX|XXXX|1] ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=59, bqual_length=36, tx_uid=0:ffff0aff1b4b:8791:5fa169e4:4d2d6, node_name=4e807935-5e5f-4482-4e75-03bc-11, branch_uid=0:ffff0aff1b4b:8791:5fa169e4:4d928, subordinatenodename=null, eis_name=0 > (com.ibm.mq.jmqi.JmqiXAResource@6bf4ff38) failed with exception code XAException.XAER_NOTA

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT javax.transaction.xa.XAException: The method 'xa_rollback' has failed with errorCode '-4'.

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at com.ibm.mq.jmqi.JmqiXAResource.rollback(JmqiXAResource.java:880) ~[com.ibm.mq.allclient-9.1.5.0.jar!/:9.1.5.0 - p915-L200316]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:362) ~[jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3023) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3002) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:1981) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1519) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [arjuna-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1287) [jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [jta-5.9.8.Final.jar!/:5.9.8.Final]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1035) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:714) [spring-tx-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:251) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1190) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1180) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1077) [spring-jms-5.1.17.RELEASE.jar!/:5.1.17.RELEASE]

   2020-11-03T15:45:54.96+0100 [APP/PROC/WEB/11] OUT          at java.lang.Thread.run(Thread.java:748) [na:1.8.0_252]     


Adarsh

unread,
Nov 4, 2020, 4:37:22 AM11/4/20
to narayana-users

@Michael Musgrove -   Nope. It's not because of timeout. We have checked MQ logs there is not sign of saying transaction was rolledback because of timeout.  

Michael Musgrove

unread,
Nov 4, 2020, 5:16:38 AM11/4/20
to narayana-users
The log/stack trace shows the TM ending the association, ie it calls xa_end on the (jmqi) XA resource but that resource manager returns XAException.XA_RBROLLBACK [1].
This means that the resource has already rolled back when the TM tries to end the association.
The resource managers' XA logs should indicate why it rolled back before the end phase (I would still argue that timeout is the most likely culprit, perhaps you could try extending the timeout on the underlying XA resources to verify this).
 
[1] from the description of xa_end in the XA spec:
    [XA_RBROLLBACK] The resource manager rolled back the transaction branch for an unspecified reason.

Adarsh

unread,
Nov 4, 2020, 6:47:34 AM11/4/20
to narayana-users
@Micael Musgrove- Thank you. Do you know  where we need to increase timeout MQ side ?  What property would that be in qm.ini file ?

Michael Musgrove

unread,
Nov 4, 2020, 6:57:12 AM11/4/20
to narayana-users
The link I referenced in my initial response suggested:

> To resolve this issue, ensure that the JMS connection factory being used by the application has the connection pool property aged timeout set to zero. This will prevent JMS >Connections being closed when they are returned to the free pool, and so ensures that any outstanding transactional work can be completed.

There is some further information about the topic in the IBM Knowledge Center.

Adarsh

unread,
Nov 4, 2020, 7:23:13 AM11/4/20
to narayana-users
Unfortunately  MQ client api doesn't have that aged timeout to configure  "com.ibm.mq.jms.MQXAQueueConnectionFactory" . We are using com.ibm.all.client (9.1.5.0) .  Wondering where we need to set that property.  It would be helpful if you have any idea. 

Michael Musgrove

unread,
Nov 4, 2020, 7:41:35 AM11/4/20
to Adarsh, narayana-users
I've never used IBM MQ before, perhaps someone else on the lists has used com.ibm.all.client.
Do you have a link that shows how to configure the client, maybe you need to perform some config at the broker end of the MQ.

--
You received this message because you are subscribed to the Google Groups "narayana-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to narayana-user...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/narayana-users/a9e85cd7-d198-4f88-b236-72979d2cd93an%40googlegroups.com.

Michael Musgrove

unread,
Nov 4, 2020, 7:55:59 AM11/4/20
to Adarsh, narayana-users
The javadoc says

> MQConnectionFactory is the IBM MQ implementation of ConnectionFactory. A connection factory encapsulates a set of connection configuration parameters that has been defined by an administrator.

So you would need to work out how/where an administrator sets those parameters.

On Wed, Nov 4, 2020 at 12:23 PM Adarsh <adars...@gmail.com> wrote:

thje...@redhat.com

unread,
Nov 4, 2020, 7:59:25 AM11/4/20
to narayana-users
I think the reporter will need to contact an IBM MQ forum for the information. I think from reading the article that Mike shared that the problem could be that the connection is returned to the pool but then some configured period has expired on the connection not having been used before the transaction completes and so a second xa_end occurs - but that is just from reading not from any IBM MQ expertise. I found this: https://github.com/ibm-messaging/mq-jms-spring/ but I don't know if it is relevant, appropriate or helpful.

Ondra Chaloupka

unread,
Nov 4, 2020, 8:56:47 AM11/4/20
to narayana-users
I assume the configuration of the IBM MQ properties and/or the settings for the RA define only the default transaction timeout for the XAResource. If the RA works right then the timeout is defined by call of the setTransactionTimeout API method https://docs.oracle.com/javaee/7/api/javax/transaction/xa/XAResource.html#setTransactionTimeout-int-

The transaction timeout is set by Narayana TM when the instance of the XAResource is enlisted - https://github.com/jbosstm/narayana/blob/master/ArjunaJTS/jtax/classes/com/arjuna/ats/internal/jta/transaction/jts/TransactionImple.java#L725

As the first thing I would check what is the application transaction timeout - ie. the one defined for the particular transaction (e.g. at the call with annotation) or the default one configured for the whole runtime

Adarsh

unread,
Nov 4, 2020, 9:08:53 AM11/4/20
to narayana-users
Narayana Tm transaction timeout & dbcp properties are like below .   We have transaction timeout as 5 mins. But this rollback is happening in less than a minute.

narayana:
default-timeout: 300
dbcp:
maxTotal: 200
maxIdle: 200
minIdle: 30
initialSize: 30

thje...@redhat.com

unread,
Nov 4, 2020, 9:32:00 AM11/4/20
to narayana-users
One thing I starting realising is that at least xa_end would not likely be called by Narayana twice:

But maybe "aged timeout" could still somehow be related if IBM MQ somehow. Is there any connection.close() going on while this transaction is active?

Adarsh

unread,
Nov 4, 2020, 9:39:11 AM11/4/20
to narayana-users
No we are not calling any connection.close() explicitly.  Processing-   Reading message(create XA transaction) ->  do db(select & insert)(in new transaction(nested)) -> Write message to new MQ(parent transaction). Roll back is happening at parent transaction.

thje...@redhat.com

unread,
Nov 4, 2020, 12:42:55 PM11/4/20
to narayana-users
Perhaps if there is a connection.close() happening (not explicit in your code) it might perhaps be something from pooling or something else in DBCP or some element of Spring that could be doing it?

Michael Musgrove

unread,
Nov 4, 2020, 1:19:15 PM11/4/20
to narayana-users
Just to add to what Ondra said above: the relevant property is called "com.arjuna.ats.jta.xaTransactionTimeoutEnabled" [1]
But that property will only be used if you set it to true *and* if the transaction timeout is greater than zero. But isn't the default transaction timeout -1 (ie no timeout) in which case we would have no control over the resource timeout and you would need to configure it using the resource managers config mechanism. Are you able to verify what values you are using for both the transaction timeout and for the xaTransactionTimeoutEnabled property.

But I would still verify the issue with the IBM MQ forum and also consider Tom's suggestion.

Kamil Demecki

unread,
Nov 4, 2020, 3:06:11 PM11/4/20
to narayana-users
To give more context - project https://github.com/ibm-messaging/mq-jms-spring/ defines mq-jms-spring-boot-starter  which uses raw XA factory or non-XA factory with pooled-jms. Our code is similar to https://github.com/snowdrop/narayana-spring-boot which provides skeleton for non-pooled XA using Narayana. One difference is using pooled-jms like below

    @Bean(name = {"JmsQueueXA", "JmsXA"}, destroyMethod = "stop")
    @ConditionalOnProperty(prefix = "ibm.mq.pool", name = "enabled", havingValue = "true", matchIfMissing = true)
    @Autowired
    public QueueConnectionFactory pooledQueueConnectionFactory(MQConfigurationProperties mqProperties, TransactionManager transactionManager, IJmsPoolXAConnectionFactoryWrapper connectionFactoryWrapper) {
        MQConnectionFactoryFactory factory = new MQConnectionFactoryFactory(mqProperties, null);
        MQXAQueueConnectionFactory connectionFactory = factory.createConnectionFactory(MQXAQueueConnectionFactory.class);

        return connectionFactoryWrapper.wrapConnectionFactory(connectionFactory, transactionManager, mqProperties.getPool());
    }

Where  snowdrop 's code does

    @ConditionalOnProperty(prefix = "ibm.mq.pool", name = "enabled", havingValue = "false")
    @Autowired
    public QueueConnectionFactory queueConnectionFactory(MQConfigurationProperties mqProperties, XAConnectionFactoryWrapper wrapper) throws Exception {
        MQConnectionFactoryFactory factory = new MQConnectionFactoryFactory(mqProperties, null);
        MQXAQueueConnectionFactory connectionFactory = factory.createConnectionFactory(MQXAQueueConnectionFactory.class);
        return (QueueConnectionFactory) wrapper.wrapConnectionFactory(connectionFactory);
    }

But the issue happens only under high-load also when we disable pooled-jms - it is very easy to reproduce it within our application and 100k volume. 

IBM link says about "aged timeout set to zero" pooled-jms - but I am not sure if it means aged timeout on MQ level API or connection-pool (we have 10 minutes idleTimeout  in for pooled-jms but issue happens also without pooled-jms)

ibm:
  mq:
    queueManager:
    channel:
    connName:
    user:
    encryptedPassword:
    # Compatibility mode without MQCSP auth
    userAuthenticationMQCSP: false
    pool:
      enabled: true
      maxConnections: 1
      maxSessionsPerConnection: 200
      minIdleSessionsPerConnection: 30
      maxIdleSessionsPerConnection: 100
      blockIfFull: true
      blockIfFullTimeout: PT30S
      idleTimeout: PT10M
      timeBetweenExpirationCheck: PT30M
      useAnonymousProducers: true

thje...@redhat.com

unread,
Nov 5, 2020, 6:46:28 AM11/5/20
to narayana-users
Given this doesn't seem specific to Narayana I think you might get some broader feedback if you raised this on a Spring Boot or IBM MQ forum too.

Do you have a very small open source reproducer as that would possibly help people to understand better where the problem could be?
Reply all
Reply to author
Forward
0 new messages