Arjuna aborting transaction internally
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