Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-7355

JTS bottom-up could roll-back prepared inflowed JCA transactions

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 7.1.0.DR9
    • 7.1.0.DR8
    • Transactions
    • None
    • Hide 
      mvn clean verify -am -pl jbossts -DfailIfNoTests=false -fn -Djbossts.noJTA -Dtest=JcaInflowTransactionTestCase#jvmCrashAfterPrepareJTS
      Show
      mvn clean verify -am -pl jbossts -DfailIfNoTests= false -fn -Djbossts.noJTA -Dtest=JcaInflowTransactionTestCase#jvmCrashAfterPrepareJTS

    Description

      I experience race condition in my testcase for JBTM-2748/JBEAP-5880. Even by "detailed" investigation on server.log I'm a bit lost in what can cause the problem. By my testing I can see that Narayana 5.3.3.Final fails my test anytime. Narayana 5.3.5.Final seems to pass in most of the cases but time to time fails. The result is the same as at 5.3.3.Final. Nevertheless I can see different behavior shown by server.log.

      For Narayana 5.3.3.Final during the JTS recovery second phase TM gets txn status and decides to rollback [1].
      For Narayana 5.3.5.Final during the JTS recovery second phase if TM gets txn status it goes for commit but if there is some trouble to get it it rollbacks. The problem that I refer to is represented by error WARN  [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022139: CORBA exception on trying to contact original process: org.omg.CORBA.BAD_OPERATION [2].

      I'm adding three server logs as attachment - fail for 5.3.3.Final and two for 5.3.5.Final - one failing, one passing.

      [1]

      2016-11-16 15:16:52,985 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning 2 Xids
2016-11-16 15:16:52,985 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning xid: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 15:16:52,985 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning xid: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 15:16:52,985 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@31a25bc7, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@3f537a39}, transactionOriginNodeIdentifier='1'} 1479305802928 1479305812985 false
2016-11-16 15:16:52,987 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0)) 1479305802969 1479305812985 false
2016-11-16 15:16:52,987 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@7a29e943 1479305802948 1479305812987 false
2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) JTS XARecoveryModule.resourceInitiatedRecovery completed
2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change SECOND_PASS->IDLE

2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE
2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: scan thread signals listener worker
2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off
2016-11-16 15:17:12,988 DEBUG [com.arjuna.ats.arjuna] (Listener:4712) Connected to 127.0.0.1 on port 50586 on listener port 4712 for service com.arjuna.ats.internal.arjuna.recovery.WorkerService
2016-11-16 15:17:12,989 DEBUG [com.arjuna.ats.arjuna] (Server.Connection:127.0.0.1:50586) PeriodicRecovery: listener worker interrupts background thread
2016-11-16 15:17:12,989 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING
2016-11-16 15:17:12,989 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning
2016-11-16 15:17:12,989 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Wed, 16 Nov 2016 15:17:12
2016-11-16 15:17:12,989 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) CommitMarkableResourceRecordRecoveryModule::periodicWorkFirstPass
2016-11-16 15:17:12,989 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,989 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
2016-11-16 15:17:12,989 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: )
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 28
OutputObjectState Buffer: , StateManager)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 60
OutputObjectState Buffer: , StateManager/BasicAction)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 112
OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 184
OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 276
OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 372
OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 396
OutputObjectState Buffer: , RecoveryCoordinator)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 416
OutputObjectState Buffer: , CosTransactions)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 456
OutputObjectState Buffer: , CosTransactions/XAResourceRecord)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 472
OutputObjectState Buffer: , Recovery)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000001:57fceedf:582c6a40:3c
OutputObjectState Type  : null
OutputObjectState Size  : 500
OutputObjectState Buffer: , Recovery/FactoryContact)
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager/BasicAction, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager/BasicAction/TwoPhaseCoordinator, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA, StateType.OS_SHADOW)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA, 10)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA, StateType.OS_ORIGINAL)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA, 11)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(RecoveryCoordinator, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff52e38d0c:c91:4140398c:0, RecoveryCoordinator, StateType.OS_SHADOW)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff52e38d0c:c91:4140398c:0, RecoveryCoordinator, 10)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff52e38d0c:c91:4140398c:0, RecoveryCoordinator, StateType.OS_ORIGINAL)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff52e38d0c:c91:4140398c:0, RecoveryCoordinator, 11)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff52e38d0c:c91:4140398c:0, RecoveryCoordinator) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(CosTransactions, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(CosTransactions/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, CosTransactions/XAResourceRecord, 10)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, CosTransactions/XAResourceRecord, 11)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2e, CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, CosTransactions/XAResourceRecord, 10)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, CosTransactions/XAResourceRecord, 11)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2b, CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(Recovery, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(Recovery/FactoryContact, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, Recovery/FactoryContact, StateType.OS_SHADOW)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, Recovery/FactoryContact, 10)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, Recovery/FactoryContact, StateType.OS_ORIGINAL)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, Recovery/FactoryContact, 11)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:10, Recovery/FactoryContact) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:57fceedf:582c6a40:1b, Recovery/FactoryContact, StateType.OS_SHADOW)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:57fceedf:582c6a40:1b, Recovery/FactoryContact, 10)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:57fceedf:582c6a40:1b, Recovery/FactoryContact, StateType.OS_ORIGINAL)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:57fceedf:582c6a40:1b, Recovery/FactoryContact, 11)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:57fceedf:582c6a40:1b, Recovery/FactoryContact) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:12,992 INFO  [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022199: TopLevelTransactionRecoveryModule First Pass
2016-11-16 15:17:12,992 INFO  [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022213: TransactionRecoveryModule.periodicWorkFirstPass()
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) TransactionRecoveryModule: scanning for /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,992 INFO  [com.arjuna.ats.arjuna] (Server.Connection:127.0.0.1:50586) ARJUNA012340: RecoveryManager scan scheduled to begin.
2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:12,992 INFO  [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022190: ServerTransactionRecoveryModule - First Pass
2016-11-16 15:17:12,992 INFO  [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022213: TransactionRecoveryModule.periodicWorkFirstPass()
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) TransactionRecoveryModule: scanning for /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change IDLE->FIRST_PASS

2016-11-16 15:17:12,993 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) JTS XARecoveryModule - first pass
2016-11-16 15:17:12,993 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:12,993 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/CosTransactions/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
2016-11-16 15:17:12,993 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:12,995 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) getXAResources() instance: TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0))
2016-11-16 15:17:12,997 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@31a25bc7, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@3f537a39}, transactionOriginNodeIdentifier='1'}
2016-11-16 15:17:12,997 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt
2016-11-16 15:17:12,997 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids updateIfEquivalentRM2 RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@31a25bc7, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@3f537a39}, transactionOriginNodeIdentifier='1'} 1479305832997
2016-11-16 15:17:12,997 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@7a29e943
2016-11-16 15:17:12,998 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt
2016-11-16 15:17:13,001 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0))
2016-11-16 15:17:13,005 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecovered] (Periodic Recovery) TestXAResourceRecovered.recover(i=16777216)[id=512]
2016-11-16 15:17:13,005 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) recover()
2016-11-16 15:17:13,005 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning 2 Xids
2016-11-16 15:17:13,005 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning xid: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 15:17:13,005 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning xid: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 15:17:13,005 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 2 xids in doubt
2016-11-16 15:17:13,005 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Recovered: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 15:17:13,005 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Recovered: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 15:17:13,010 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceCommon] (Periodic Recovery) TestXAResourceCommon.isSameRM(xaResource=RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@31a25bc7, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@3f537a39}, transactionOriginNodeIdentifier='1'})[return 'false'][id=512]
2016-11-16 15:17:13,013 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids updateIfEquivalentRM1 TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0)) 1479305833010
2016-11-16 15:17:13,016 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceCommon] (Periodic Recovery) TestXAResourceCommon.isSameRM(xaResource=org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@7a29e943)[return 'false'][id=512]
2016-11-16 15:17:13,017 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceCommon] (Periodic Recovery) getJndiName()[return java:/TestXAResource][id=512]
2016-11-16 15:17:13,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES

2016-11-16 15:17:13,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Wed, 16 Nov 2016 15:17:23
2016-11-16 15:17:23,017 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2016-11-16 15:17:23,017 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
2016-11-16 15:17:23,017 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:23,017 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 40
InputObjectState Buffer: , -1)
2016-11-16 15:17:23,017 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass
2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass
2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:23,018 INFO  [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022200: TopLevelTransactionRecoveryModule Second Pass
2016-11-16 15:17:23,018 INFO  [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022214: TransactionRecoveryModule.periodicWorkSecondPass()
2016-11-16 15:17:23,018 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:23,018 INFO  [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022191: ServerTransactionRecoveryModule - Second Pass
2016-11-16 15:17:23,018 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
2016-11-16 15:17:23,018 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS

2016-11-16 15:17:23,018 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) JTS XARecoveryModule - second pass
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 10)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 11)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 10)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 11)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 11)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2e, FileLock.F_RDLCK, false)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord)
2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2e, java.io.FileInputStream@655e320b, null)
2016-11-16 15:17:23,019 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XARecovery 0:ffff7f000001:5857c0a5:582c6a36:2e is non-recoverable
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, 10)
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, 11)
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord)
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, 10)
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, 11)
2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:23,020 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,020 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, 11)
2016-11-16 15:17:23,020 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2b, FileLock.F_RDLCK, false)
2016-11-16 15:17:23,020 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord)
2016-11-16 15:17:23,020 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2b, java.io.FileInputStream@4c2e5fd0, null)
2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XARecovery 0:ffff7f000001:5857c0a5:582c6a36:2b is non-recoverable
2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) JTS XARecoveryModule.transactionInitiatedRecovery completed
2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@31a25bc7, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@3f537a39}, transactionOriginNodeIdentifier='1'}
2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.
2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@7a29e943
2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.
2016-11-16 15:17:23,024 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0))
2016-11-16 15:17:23,028 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids _whenFirstSeen toRecover yes TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0)) 1479305802973 === 1479305843024
2016-11-16 15:17:23,030 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids _whenFirstSeen toRecover no TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0)) 1479305802973 === 1479305843024
2016-11-16 15:17:23,030 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 1 Xids to recover on this pass.
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord)
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 10)
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 11)
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 11)
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2e, FileLock.F_RDLCK, false)
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord)
2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2e, java.io.FileInputStream@75d2f77a, null)
2016-11-16 15:17:23,032 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.recover
2016-11-16 15:17:23,033 TRACE [com.arjuna.orbportability] (Periodic Recovery) RootOA::objectIsReady (Servant)
2016-11-16 15:17:23,034 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::send_request ( _is_a ) nodeId=1 requestId=7
2016-11-16 15:17:23,035 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( _is_a ) nodeId=1 requestId=7
2016-11-16 15:17:23,035 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request ( _is_a ) nodeId=1 requestId=7
2016-11-16 15:17:23,035 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( _is_a ) nodeId=1 requestId=7
2016-11-16 15:17:23,035 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( _is_a ) nodeId=1 requestId=7
2016-11-16 15:17:23,036 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( _is_a ) nodeId=1 requestId=7
2016-11-16 15:17:23,039 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::send_request ( replay_completion ) nodeId=1 requestId=8
2016-11-16 15:17:23,039 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ContextManager::current ()
2016-11-16 15:17:23,040 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( replay_completion ) nodeId=1 requestId=8
2016-11-16 15:17:23,041 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request ( replay_completion ) nodeId=1 requestId=8
2016-11-16 15:17:23,041 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) JavaIdlRCDefaultServant::replay_completion)
2016-11-16 15:17:23,042 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) RecoveryCoordinatorId(0:ffff7f000001:5857c0a5:582c6a36:2f*0:ffff7f000001:5857c0a5:582c6a36:25*0:ffff7f000001:5857c0a5:582c6a36:10*true)
2016-11-16 15:17:23,042 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) JavaIdlDefaultServant replay_completion for Id (0:ffff7f000001:5857c0a5:582c6a36:2f, 0:ffff7f000001:5857c0a5:582c6a36:25, 0:ffff7f000001:5857c0a5:582c6a36:10, interposed-tx)
2016-11-16 15:17:23,043 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) GenericRecoveryCoordinator(0:ffff7f000001:5857c0a5:582c6a36:2f).replay_completion(resource supplied)
2016-11-16 15:17:23,044 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.get_current_status(0:ffff7f000001:5857c0a5:582c6a36:25, 0:ffff7f000001:5857c0a5:582c6a36:10)
2016-11-16 15:17:23,044 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.checkOriginalStatus(0:ffff7f000001:5857c0a5:582c6a36:25, 0:ffff7f000001:5857c0a5:582c6a36:10, false)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, StateType.OS_SHADOW)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, 10)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, 11)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact) - returning StateStatus.OS_COMMITTED
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, 11)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/Recovery/FactoryContact/0_ffff7f000001_5857c0a5_582c6a36_10, FileLock.F_RDLCK, false)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact)
2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/Recovery/FactoryContact/0_ffff7f000001_5857c0a5_582c6a36_10, java.io.FileInputStream@4178e7fb, null)
2016-11-16 15:17:23,045 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:5857c0a5:582c6a36:25, com.arjuna.ats.internal.jts.recovery.contact.FactoryContactItem@d2278c3, false)
2016-11-16 15:17:23,046 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::send_request ( getCurrentStatus ) nodeId=1 requestId=9
2016-11-16 15:17:23,046 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ContextManager::current ()
2016-11-16 15:17:23,047 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( getCurrentStatus ) nodeId=1 requestId=9
2016-11-16 15:17:23,047 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request ( getCurrentStatus ) nodeId=1 requestId=9
2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_SHADOW)
2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 10)
2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 11)
2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_SHADOW)
2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 10)
2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,049 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 11)
2016-11-16 15:17:23,049 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,050 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_SHADOW)
2016-11-16 15:17:23,050 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 10)
2016-11-16 15:17:23,050 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,050 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 11)
2016-11-16 15:17:23,050 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,051 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_SHADOW)
2016-11-16 15:17:23,051 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 10)
2016-11-16 15:17:23,051 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,051 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 11)
2016-11-16 15:17:23,051 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,052 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( getCurrentStatus ) nodeId=1 requestId=9
2016-11-16 15:17:23,052 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( getCurrentStatus ) nodeId=1 requestId=9
2016-11-16 15:17:23,052 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( getCurrentStatus ) nodeId=1 requestId=9
2016-11-16 15:17:23,053 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:5857c0a5:582c6a36:25) - current status = CosTransactions::StatusNoTransaction
2016-11-16 15:17:23,053 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::send_request ( getStatus ) nodeId=1 requestId=10
2016-11-16 15:17:23,053 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ContextManager::current ()
2016-11-16 15:17:23,053 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( getStatus ) nodeId=1 requestId=10
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request ( getStatus ) nodeId=1 requestId=10
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_SHADOW)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 10)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 11)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_SHADOW)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 10)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 11)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_SHADOW)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 10)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 11)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_SHADOW)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 10)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 11)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_SHADOW)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 10)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 11)
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_SHADOW)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 10)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 11)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_SHADOW)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 10)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 11)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_SHADOW)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 10)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_ORIGINAL)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 11)
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( getStatus ) nodeId=1 requestId=10
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( getStatus ) nodeId=1 requestId=10
2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( getStatus ) nodeId=1 requestId=10
2016-11-16 15:17:23,055 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:5857c0a5:582c6a36:25) - stored status = CosTransactions::StatusNoTransaction
2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( replay_completion ) nodeId=1 requestId=8
2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( replay_completion ) nodeId=1 requestId=8
2016-11-16 15:17:23,057 DEBUG [com.arjuna.ats.jts] (Thread-109) ResourceCompletor.rollback()
2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( replay_completion ) nodeId=1 requestId=8
2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.recover got status: CosTransactions::StatusRolledBack
2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.doRecovery ( false )
2016-11-16 15:17:23,057 INFO  [com.arjuna.ats.jtax] (Periodic Recovery) ARJUNA024002: XA recovery rolling back < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.rollback for < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 15:17:23,068 TRACE [com.arjuna.ats.jts] (Thread-109) InterpositionClientRequestInterceptorImpl::send_request ( rollback ) nodeId=1 requestId=11
2016-11-16 15:17:23,068 TRACE [com.arjuna.ats.jts] (Thread-109) ContextManager::current ()
2016-11-16 15:17:23,069 TRACE [com.arjuna.ats.jts] (Thread-109) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( rollback ) nodeId=1 requestId=11
2016-11-16 15:17:23,069 TRACE [com.arjuna.ats.jts] (Thread-109) InterpositionServerRequestInterceptorImpl::receive_request ( rollback ) nodeId=1 requestId=11
2016-11-16 15:17:23,070 TRACE [com.arjuna.ats.jtax] (Thread-109) XAResourceRecord.rollback for < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 15:17:23,074 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecovered] (Periodic Recovery) TestXAResourceRecovered.rollback(Xid=< 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >)[id=512]
2016-11-16 15:17:23,074 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) removeLog(xid=< 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 15:17:23,074 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) Using file /home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/TestXAResourceStateStore/TestXAResource.ser for saving state of the org.jboss.as.test.jbossts.common.TestXAResource XA resource

      [2]

      2016-11-16 09:45:51,329 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:7c17affe:582c1c73:28, com.arjuna.ats.internal.jts.recovery.contact.FactoryContactItem@7b5023d7, false)
2016-11-16 09:45:51,330 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::send_request ( getCurrentStatus ) nodeId=1 requestId=10
2016-11-16 09:45:51,330 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ContextManager::current ()
2016-11-16 09:45:51,330 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( getCurrentStatus ) nodeId=1 requestId=10
2016-11-16 09:45:51,330 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request ( getCurrentStatus ) nodeId=1 requestId=10
2016-11-16 09:45:51,335 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_exception ( getCurrentStatus ) nodeId=1 requestId=10
2016-11-16 09:45:51,335 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( getCurrentStatus ) nodeId=1 requestId=10
2016-11-16 09:45:51,338 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_exception ( getCurrentStatus ) nodeId=1 requestId=10
2016-11-16 09:45:51,339 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:7c17affe:582c1c73:28) - COMM_FAILURE = dead
2016-11-16 09:45:51,339 WARN  [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022139: CORBA exception on trying to contact original process: org.omg.CORBA.BAD_OPERATION: ----------BEGIN server-side stack trace----------
org.omg.CORBA.BAD_OPERATION:   vmcid: 0x0  minor code: 0 completed: Maybe
	at com.arjuna.ArjunaOTS.ArjunaTransactionPOA._invoke(ArjunaTransactionPOA.java:50)
	at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:654)
	at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:205)
	at com.sun.corba.se.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1700)
	at com.sun.corba.se.impl.protocol.SharedCDRClientRequestDispatcherImpl.marshalingComplete(SharedCDRClientRequestDispatcherImpl.java:180)
	at com.sun.corba.se.impl.protocol.CorbaClientDelegateImpl.invoke(CorbaClientDelegateImpl.java:148)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:475)
	at com.arjuna.ArjunaOTS._ArjunaFactoryStub.getCurrentStatus(_ArjunaFactoryStub.java:76)
	at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.getStatus(StatusChecker.java:176)
	at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.checkOriginalStatus(StatusChecker.java:144)
	at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.get_current_status(StatusChecker.java:110)
	at com.arjuna.ats.internal.jts.orbspecific.recovery.recoverycoordinators.GenericRecoveryCoordinator.get_status(GenericRecoveryCoordinator.java:355)
	at com.arjuna.ats.internal.jts.orbspecific.recovery.recoverycoordinators.GenericRecoveryCoordinator.replay_completion(GenericRecoveryCoordinator.java:145)
	at com.arjuna.ats.internal.jts.orbspecific.javaidl.recoverycoordinators.JavaIdlRCDefaultServant.replay_completion(JavaIdlRCDefaultServant.java:101)
	at org.omg.CosTransactions.RecoveryCoordinatorPOA._invoke(RecoveryCoordinatorPOA.java:39)
	at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:654)
	at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:205)
	at com.sun.corba.se.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1700)
	at com.sun.corba.se.impl.protocol.SharedCDRClientRequestDispatcherImpl.marshalingComplete(SharedCDRClientRequestDispatcherImpl.java:180)
	at com.sun.corba.se.impl.protocol.CorbaClientDelegateImpl.invoke(CorbaClientDelegateImpl.java:148)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:475)
	at org.omg.CosTransactions._RecoveryCoordinatorStub.replay_completion(_RecoveryCoordinatorStub.java:20)
	at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.recover(XAResourceRecord.java:1226)
	at com.arjuna.ats.internal.jta.recovery.jts.XARecoveryResourceImple.recover(XARecoveryResourceImple.java:88)
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:736)
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:461)
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:218)
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811)
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377)

----------END server-side stack trace----------  vmcid: 0x0  minor code: 0 completed: Maybe
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at com.sun.corba.se.impl.protocol.giopmsgheaders.MessageBase.getSystemException(MessageBase.java:921)
	at com.sun.corba.se.impl.protocol.giopmsgheaders.ReplyMessage_1_2.getSystemException(ReplyMessage_1_2.java:116)
	at com.sun.corba.se.impl.protocol.CorbaMessageMediatorImpl.getSystemExceptionReply(CorbaMessageMediatorImpl.java:590)
	at com.sun.corba.se.impl.protocol.CorbaClientRequestDispatcherImpl.processResponse(CorbaClientRequestDispatcherImpl.java:489)
	at com.sun.corba.se.impl.protocol.SharedCDRClientRequestDispatcherImpl.marshalingComplete(SharedCDRClientRequestDispatcherImpl.java:222)
	at com.sun.corba.se.impl.protocol.CorbaClientDelegateImpl.invoke(CorbaClientDelegateImpl.java:148)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:475)
	at com.arjuna.ArjunaOTS._ArjunaFactoryStub.getCurrentStatus(_ArjunaFactoryStub.java:76)
	at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.getStatus(StatusChecker.java:176)
	at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.checkOriginalStatus(StatusChecker.java:144)
	at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.get_current_status(StatusChecker.java:110)
	at com.arjuna.ats.internal.jts.orbspecific.recovery.recoverycoordinators.GenericRecoveryCoordinator.get_status(GenericRecoveryCoordinator.java:355)
	at com.arjuna.ats.internal.jts.orbspecific.recovery.recoverycoordinators.GenericRecoveryCoordinator.replay_completion(GenericRecoveryCoordinator.java:145)
	at com.arjuna.ats.internal.jts.orbspecific.javaidl.recoverycoordinators.JavaIdlRCDefaultServant.replay_completion(JavaIdlRCDefaultServant.java:101)
	at org.omg.CosTransactions.RecoveryCoordinatorPOA._invoke(RecoveryCoordinatorPOA.java:39)
	at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:654)
	at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:205)
	at com.sun.corba.se.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1700)
	at com.sun.corba.se.impl.protocol.SharedCDRClientRequestDispatcherImpl.marshalingComplete(SharedCDRClientRequestDispatcherImpl.java:180)
	at com.sun.corba.se.impl.protocol.CorbaClientDelegateImpl.invoke(CorbaClientDelegateImpl.java:148)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:475)
	at org.omg.CosTransactions._RecoveryCoordinatorStub.replay_completion(_RecoveryCoordinatorStub.java:20)
	at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.recover(XAResourceRecord.java:1226)
	at com.arjuna.ats.internal.jta.recovery.jts.XARecoveryResourceImple.recover(XARecoveryResourceImple.java:88)
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:736)
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:461)
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:218)
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811)
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377)

2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.write_committed(0:ffff7f000001:7c17affe:582c1c73:14, /Recovery/FactoryContact)
2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.write_state(0:ffff7f000001:7c17affe:582c1c73:14, /Recovery/FactoryContact, StateType.OS_ORIGINAL)
2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:14, /Recovery/FactoryContact, StateType.OS_ORIGINAL)
2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:14, /Recovery/FactoryContact, 11)
2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/Recovery/FactoryContact/0_ffff7f000001_7c17affe_582c1c73_14, FileLock.F_WRLCK, true)
2016-11-16 09:45:51,345 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/Recovery/FactoryContact/0_ffff7f000001_7c17affe_582c1c73_14, null, java.io.FileOutputStream@33746342)
2016-11-16 09:45:51,346 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) CachedRecoveredTransaction created [0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction]
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 0:ffff7f000001:7c17affe:582c1c73:28 )
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::BasicAction(0:ffff7f000001:7c17affe:582c1c73:28)
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ArjunaTransactionImple::ArjunaTransactionImple ( 0:ffff7f000001:7c17affe:582c1c73:28 )
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ServerTransaction::ServerTransaction ( 0:ffff7f000001:7c17affe:582c1c73:28 )
2016-11-16 09:45:51,347 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) RecoveredServerTransaction 0:ffff7f000001:7c17affe:582c1c73:28 created
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_SHADOW)
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 10)
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_ORIGINAL)
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 11)
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 0:ffff7f000001:7c17affe:582c1c73:28 )
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::BasicAction(0:ffff7f000001:7c17affe:582c1c73:28)
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ArjunaTransactionImple::ArjunaTransactionImple ( 0:ffff7f000001:7c17affe:582c1c73:28 )
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ServerTransaction::ServerTransaction ( 0:ffff7f000001:7c17affe:582c1c73:28 )
2016-11-16 09:45:51,347 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) RecoveredServerTransaction 0:ffff7f000001:7c17affe:582c1c73:28 created
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteServerTransaction, StateType.OS_SHADOW)
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteServerTransaction, 10)
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteServerTransaction, StateType.OS_ORIGINAL)
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteServerTransaction, 11)
2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteServerTransaction) - returning StateStatus.OS_UNKNOWN
2016-11-16 09:45:51,347 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) AssumedCompleteServerTransaction 0:ffff7f000001:7c17affe:582c1c73:28 created
2016-11-16 09:45:51,347 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) CachedRecoveredTransaction.get_status [0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction] = CosTransactions::StatusRolledBack
2016-11-16 09:45:51,348 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( replay_completion ) nodeId=1 requestId=9
2016-11-16 09:45:51,348 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( replay_completion ) nodeId=1 requestId=9
2016-11-16 09:45:51,348 DEBUG [com.arjuna.ats.jts] (Thread-108) ResourceCompletor.rollback()
2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jts] (Thread-108) InterpositionClientRequestInterceptorImpl::send_request ( rollback ) nodeId=1 requestId=11
2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jts] (Thread-108) ContextManager::current ()
2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( replay_completion ) nodeId=1 requestId=9
2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.recover got status: CosTransactions::StatusRolledBack
2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.doRecovery ( false )
2016-11-16 09:45:51,349 INFO  [com.arjuna.ats.jtax] (Periodic Recovery) ARJUNA024002: XA recovery rolling back < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jts] (Thread-108) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( rollback ) nodeId=1 requestId=11
2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.rollback for < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jts] (Thread-108) InterpositionServerRequestInterceptorImpl::receive_request ( rollback ) nodeId=1 requestId=11
2016-11-16 09:45:51,350 TRACE [com.arjuna.ats.jtax] (Thread-108) XAResourceRecord.rollback for < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 09:45:51,354 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecovered] (Periodic Recovery) TestXAResourceRecovered.rollback(Xid=< 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >)[id=947]
2016-11-16 09:45:51,354 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) removeLog(xid=< 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
2016-11-16 09:45:51,354 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) Using file /home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/TestXAResourceStateStore/TestXAResource.ser for saving state of the org.jboss.as.test.jbossts.common.TestXAResource XA resource

      Attachments

        Issue Links

          is blocked by

          Bug - A problem that impairs or prevents the functions of the product. JBTM-2767 Allow JTS JCA imported transactions to have clearHeuristic called on their participants

          • Minor - To be worked after urgent, high, and medium priorities are resolved. This term is chosen when the severity of the issue is low, or the complexity or effort to correct it may be higher, relatively speaking. For low priority issues, known workarounds exist or are not needed due to the trivial effort needed to address the issue.
          • Closed
          is related to

          Bug - A problem that impairs or prevents the functions of the product. JBEAP-8022 JTA implementation does not remember participant heuristic type

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Verified

          Bug - A problem that impairs or prevents the functions of the product. JBEAP-11154 JCA inflow transaction committed by recovery is not removed from tx log when JTS is used

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Verified
          relates to

          Bug - A problem that impairs or prevents the functions of the product. JBEAP-5880 Prevent JTS bottom-up recovery from rolling back prepared inflowed JCA transactions

          • Blocker - To be worked above all other priorities. This term is chosen when the severity of the issue is very high, has no workaround, or the effort for the change is comparatively low. Issues that may be very publicly visible and could generate significant media attention may also drive a higher priority.
          • Verified

          Bug - A problem that impairs or prevents the functions of the product. JBEAP-7860 ResourceAdapter#endpointActivation called twice because of SuspendController activation

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Verified

          Activity

            People

              thjenkin@redhat.com Tom Jenkinson
              ochaloup@redhat.com Ondrej Chaloupka (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: