0 Replies Latest reply on Mar 11, 2016 3:03 AM by Syed Mahdi

    Arjuna aborting transaction internally

    Syed Mahdi Apprentice

      I have a Data migration tool that is deployed on Wildfly 9 and it connects through an EIS to a system (Progress) to get data and acknowledge received data back to the . it then passes on that data to JMS queues on Hornetq.

       

      a sample successful acknowledgment looks like below:

      2016-03-09 10:57:05,924 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) AckSender  : Sleeping for 10000 secs

      2016-03-09 10:57:05,926 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Starting to get ReplicationAcknowledgmentBlocks from backlogWorkQueues

      2016-03-09 10:57:05,927 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Starting to get ReplicationAcknowledgmentBlocks from currentWorkQueues

      2016-03-09 10:57:05,927 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender)  currentBlocksAvailable : processing current blocks to orderedAcknowledgments

      2016-03-09 10:57:05,931 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) orderedAcknowledgments has : 123 Acknowledgments: processing Order Acknowledgments

      2016-03-09 10:57:05,933 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) userTransaction.begin()  ..

      2016-03-09 10:57:06,885 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender)  JMS connection established

      2016-03-09 10:57:07,164 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 10:57:07,175 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 10:57:07,191 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 10:57:07,197 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 10:57:07,219 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 10:57:07,243 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 10:57:07,262 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 10:57:07,273 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) acknowledgeTransactionId ..

      2016-03-09 10:57:07,277 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) ProgressInteractionSpec created ...

      2016-03-09 10:57:07,278 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Interaction creating ...

      2016-03-09 10:57:07,279 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Interaction created ... Going to execute // takes almost one minute but not more

      2016-03-09 10:58:02,489 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) AckSender.acknowledgeTransactionId() : interaction executed for txnId.length: 23 txnId: [8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136, 8603136]

      2016-03-09 10:58:02,491 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) AckSender.acknowledgeTransactionId() : interaction closed

      2016-03-09 10:58:02,493 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) userTransaction.commit()  ..

      2016-03-09 10:58:02,674 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Starting to get ReplicationAcknowledgmentBlocks from backlogWorkQueues

      2016-03-09 10:58:02,676 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Starting to get ReplicationAcknowledgmentBlocks from currentWorkQueues

      2016-03-09 10:58:03,678 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) AckSender  : Sleeping for 1000 secs

       

       

       

       

       

       

      Instead of a successful run it fails like this. I enabled the Arjuna Debug logs so as to get a more clear picture.

       

       

      2016-03-09 21:18:54,893 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) AckSender  : Sleeping for 10000 secs

      2016-03-09 21:18:54,894 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Starting to get ReplicationAcknowledgmentBlocks from backlogWorkQueues

      2016-03-09 21:18:54,895 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Starting to get ReplicationAcknowledgmentBlocks from currentWorkQueues

      2016-03-09 21:18:54,895 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender)  currentBlocksAvailable : processing current blocks to orderedAcknowledgments

      2016-03-09 21:18:54,896 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) orderedAcknowledgments has : 24 Acknowledgments: processing Order Acknowledgments

      2016-03-09 21:18:54,896 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) userTransaction.begin()  ..

      2016-03-09 21:18:54,899 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender)  JMS connection established

      2016-03-09 21:18:54,900 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 21:18:54,900 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 21:18:54,901 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 21:18:54,901 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 21:18:54,902 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 21:18:54,902 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 21:18:54,903 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Ending Endpoint

      2016-03-09 21:18:54,903 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) acknowledgeTransactionId ..

      2016-03-09 21:18:54,903 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) ProgressInteractionSpec created ...

      2016-03-09 21:18:54,904 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Interaction creating ...

      2016-03-09 21:18:54,904 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Interaction created ... Going to execute

      2016-03-09 21:20:13,887 WARN  [org.hornetq.core.server] (Thread-21 (HornetQ-server-HornetQServerImpl::serverUUID=7b38a0ed-a2bf-11e5-bf03-f34f9f2b1bae-277709671)) HQ222149: Message Reference[2171946632]:RELIABLE:ServerMessage[messageID=2171946632,durable=true,userID=2fed063e-d46b-11e5-88b6-f3d2ac951b29,priority=4, bodySize=2048,expiration=0, durable=true, address=jms.queue.datamigrationtool.ubs_test_odc_capfo,properties=TypedProperties[__HQ_CID=ac3c0dbf-d435-11e5-88b6-f3d2ac951b29]]@1856158707 has reached maximum delivery attempts, sending it to Dead Letter Address jms.queue.DLQ from jms.queue.datamigrationtool.ubs_test_odc_capfo

      2016-03-09 21:20:40,969 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

      2016-03-09 21:20:40,970 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

      2016-03-09 21:20:40,970 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Wed, 9 Mar 2016 21:20:40

      2016-03-09 21:20:40,970 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

      2016-03-09 21:20:40,971 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:20:40,971 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

      2016-03-09 21:20:40,971 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

      2016-03-09 21:20:40,971 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:20:40,972 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

      2016-03-09 21:20:40,973 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:20:40,973 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change IDLE->FIRST_PASS

       

      2016-03-09 21:20:40,974 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

      2016-03-09 21:20:40,975 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of HornetQXAResourceWrapper [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], csf=ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], delegate=DelegatingSession [session=ClientSessionImpl [name=e6ce6d11-e58f-11e5-b320-799df7f39f91, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=()]@3b0e9cf7], xaRecoveryConfigs=[XARecoveryConfig [transportConfiguration = [TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryConfiguration = null, username=null, password=****]], instance=568011057]

      2016-03-09 21:20:40,978 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

      2016-03-09 21:20:40,978 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES

       

      2016-03-09 21:20:40,978 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:20:50,980 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Wed, 9 Mar 2016 21:20:50

      2016-03-09 21:20:50,981 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:20:50,981 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

      2016-03-09 21:20:50,981 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:20:50,981 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

      2016-03-09 21:20:50,981 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:20:50,981 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS

       

      2016-03-09 21:20:50,982 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

      2016-03-09 21:20:50,982 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

      2016-03-09 21:20:50,983 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

      2016-03-09 21:20:50,984 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

      2016-03-09 21:20:50,984 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change SECOND_PASS->IDLE

       

      2016-03-09 21:20:50,984 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:20:50,984 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

      2016-03-09 21:20:50,984 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

      2016-03-09 21:21:37,268 WARN  [org.hornetq.core.server] (Thread-4 (HornetQ-server-HornetQServerImpl::serverUUID=7b38a0ed-a2bf-11e5-bf03-f34f9f2b1bae-277709671)) HQ222149: Message Reference[2171946676]:RELIABLE:ServerMessage[messageID=2171946676,durable=true,userID=3007ba4a-d46b-11e5-88b6-f3d2ac951b29,priority=4, bodySize=2048,expiration=0, durable=true, address=jms.queue.datamigrationtool.ubs_test_odc_capfo,properties=TypedProperties[__HQ_CID=ac3c0dbf-d435-11e5-88b6-f3d2ac951b29]]@1742127786 has reached maximum delivery attempts, sending it to Dead Letter Address jms.queue.DLQ from jms.queue.datamigrationtool.ubs_test_odc_capfo

      2016-03-09 21:22:50,995 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

      2016-03-09 21:22:50,996 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

      2016-03-09 21:22:50,996 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Wed, 9 Mar 2016 21:22:50

      2016-03-09 21:22:50,997 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

      2016-03-09 21:22:50,997 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:22:50,997 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

      2016-03-09 21:22:50,997 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

      2016-03-09 21:22:50,997 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:22:50,998 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

      2016-03-09 21:22:50,999 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:22:50,999 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change IDLE->FIRST_PASS

       

      2016-03-09 21:22:51,000 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

      2016-03-09 21:22:51,001 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of HornetQXAResourceWrapper [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], csf=ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], delegate=DelegatingSession [session=ClientSessionImpl [name=e6ce6d11-e58f-11e5-b320-799df7f39f91, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=()]@3b0e9cf7], xaRecoveryConfigs=[XARecoveryConfig [transportConfiguration = [TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryConfiguration = null, username=null, password=****]], instance=568011057]

      2016-03-09 21:22:51,004 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

      2016-03-09 21:22:51,005 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES

       

      2016-03-09 21:22:51,005 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:23:00,160 WARN  [org.hornetq.core.server] (Thread-4 (HornetQ-server-HornetQServerImpl::serverUUID=7b38a0ed-a2bf-11e5-bf03-f34f9f2b1bae-277709671)) HQ222149: Message Reference[2171971298]:RELIABLE:ServerMessage[messageID=2171971298,durable=true,userID=791a3fcf-d47a-11e5-88b6-f3d2ac951b29,priority=4, bodySize=2048,expiration=0, durable=true, address=jms.queue.datamigrationtool.ubs_test_odc_capfo,properties=TypedProperties[__HQ_CID=ac3c0dbf-d435-11e5-88b6-f3d2ac951b29]]@694869368 has reached maximum delivery attempts, sending it to Dead Letter Address jms.queue.DLQ from jms.queue.datamigrationtool.ubs_test_odc_capfo

      2016-03-09 21:23:01,016 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Wed, 9 Mar 2016 21:23:01

      2016-03-09 21:23:01,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:23:01,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

      2016-03-09 21:23:01,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:23:01,017 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

      2016-03-09 21:23:01,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:23:01,018 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS

       

      2016-03-09 21:23:01,018 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

      2016-03-09 21:23:01,018 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

      2016-03-09 21:23:01,019 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of HornetQXAResourceWrapper [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], csf=ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], delegate=DelegatingSession [session=ClientSessionImpl [name=e6ce6d11-e58f-11e5-b320-799df7f39f91, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=()]@3b0e9cf7], xaRecoveryConfigs=[XARecoveryConfig [transportConfiguration = [TransportConfiguration(name=d257521d-e58f-11e5-b320-799df7f39f91, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryConfiguration = null, username=null, password=****]], instance=568011057]

      2016-03-09 21:23:01,019 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

      2016-03-09 21:23:01,020 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

      2016-03-09 21:23:01,020 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change SECOND_PASS->IDLE

       

      2016-03-09 21:23:01,020 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

      2016-03-09 21:23:01,020 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

      2016-03-09 21:23:01,020 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

      2016-03-09 21:23:54,918 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffc0a84e1e:-6cc9c9b5:56df709a:222e in state  RUN   // This is where it times out!!

      2016-03-09 21:23:54,946 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffc0a84e1e:-6cc9c9b5:56df709a:222e invoked while multiple threads active within it. // then it tries to Abort it .

      2016-03-09 21:23:54,947 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffffc0a84e1e:-6cc9c9b5:56df709a:222e aborting with 1 threads active! 

      2016-03-09 21:23:54,972 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffffc0a84e1e:-6cc9c9b5:56df709a:222e

      2016-03-09 21:24:20,707 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Exception on executing transaction ...   javax.resource.ResourceException: Already running the datamigrationtool acknowledgement process. // this error is not an issue it only means that the progress is slow in responding perhaps.  the transactionreaper timesout even if there is no error of this sort...

      2016-03-09 21:24:20,708 ERROR [stderr] (Instrumented Acknowledgment Sender) javax.resource.ResourceException: Already running the datamigrationtool acknowledgement process.

      2016-03-09 21:24:20,709 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.demo.progress.ProgressInteraction.execute(ProgressInteraction.java:116)

      2016-03-09 21:24:20,709 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread.acknowledgeTransactionId(AckSender.java:447)

      2016-03-09 21:24:20,710 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread.run(AckSender.java:363)

      2016-03-09 21:24:20,711 ERROR [stderr] (Instrumented Acknowledgment Sender) Caused by: com.progress.open4gl.RunTime4GLErrorException: ERROR condition: The Server application has returned an error. (7243) (7211)

      2016-03-09 21:24:20,712 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.progress.open4gl.RunTime4GLException.createException(RunTime4GLException.java:46)

      2016-03-09 21:24:20,712 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.progress.open4gl.dynamicapi.ErrorMessageReader.get4GLError(ErrorMessageReader.java:60)

      2016-03-09 21:24:20,713 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.progress.open4gl.dynamicapi.Session.handleOutputErrors(Session.java:1448)

      2016-03-09 21:24:20,713 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.progress.open4gl.dynamicapi.Session.runProcedure0(Session.java:1154)

      2016-03-09 21:24:20,714 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.progress.open4gl.dynamicapi.Session.runProcedure(Session.java:737)

      2016-03-09 21:24:20,715 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.progress.open4gl.dynamicapi.Session.runPersistentProcedure(Session.java:451)

      2016-03-09 21:24:20,715 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.demo.progress.ProgressSession.createPersistentProcedure(ProgressSession.java:174)

      2016-03-09 21:24:20,716 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.demo.progress.ProgressSession.getStatefulProcedure(ProgressSession.java:136)

      2016-03-09 21:24:20,716 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.demo.progress.ProgressSession.runStatefulMethod(ProgressSession.java:125)

      2016-03-09 21:24:20,717 ERROR [stderr] (Instrumented Acknowledgment Sender)      at com.demo.progress.ProgressInteraction.execute(ProgressInteraction.java:108)

      2016-03-09 21:24:20,717 ERROR [stderr] (Instrumented Acknowledgment Sender)      ... 2 more

      2016-03-09 21:24:20,718 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) AckSender.acknowledgeTransactionId() : interaction closed

      2016-03-09 21:24:20,718 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) userTransaction.commit()  ..

      2016-03-09 21:24:20,719 WARN  [com.arjuna.ats.arjuna] (Instrumented Acknowledgment Sender) ARJUNA012077: Abort called on already aborted atomic action 0:ffffc0a84e1e:-6cc9c9b5:56df709a:222e  // This error IS the issue where it just shutsdown

      2016-03-09 21:24:20,722 ERROR [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) Unexpected shutdown: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffffc0a84e1e:-6cc9c9b5:56df709a:222e

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

              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.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:173)

              at com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread.run(AckSender.java:367)

       

      2016-03-09 21:24:20,724 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) AckSender : isRunning : false

       

       

      some Questions that I have so far:

      1) What is this; This comes a lot. and some times in the same place it does not (when i restart that is) So i want to understand the circumstances when it does these passes.

      2016-03-09 21:22:50,999 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change IDLE->FIRST_PASS

      then

      2016-03-09 21:23:01,018 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS

      then

      2016-03-09 21:23:01,020 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change SECOND_PASS->IDLE

      2) Why is it timing out: What could be the possible reason.

      2016-03-09 21:23:54,918 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffc0a84e1e:-6cc9c9b5:56df709a:222e in state  RUN   // This is where it times out!!

      2016-03-09 21:23:54,946 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffc0a84e1e:-6cc9c9b5:56df709a:222e invoked while multiple threads active within it. // then it tries to Abort it .

      2016-03-09 21:23:54,947 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffffc0a84e1e:-6cc9c9b5:56df709a:222e aborting with 1 threads active! 

      3) Even if it is Timing out why does it say its just a WARN when it should be an exception thrown so that we don't do this which make it fail.

      2016-03-09 21:24:20,718 INFO  [com.demo.datamigrationtool.AckSender$InstrumentedAckSenderThread] (Instrumented Acknowledgment Sender) userTransaction.commit()  ..

      Any Insight will be good. i can increase the time out but i would rather like the transaction to be done within the present time out.

       

      Thanks