[jbossts-issues] [JBoss JIRA] (JBTM-3034) CMR recovery wrongly handles commit and rollback
Ondra Chaloupka (JIRA)
issues at jboss.org
Tue Jun 19 00:43:00 EDT 2018
[ https://issues.jboss.org/browse/JBTM-3034?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13592967#comment-13592967 ]
Ondra Chaloupka commented on JBTM-3034:
---------------------------------------
the wrong commit/rollback behaviour on the {{XAResource}} seems to be in the part of the recovery where {{AtomicActionRecoveryModule}} "commits" the CMR resource which is followed by {{XAResource}} commit and as next the {{XAResourceRecoveryModule}} forces to rollback during _bottomUp_ recovery by orphan detection.
The recovery scan part from the WFLY server:
{code}
2018-06-18 11:27:53,568 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Mon, 18 Jun 2018 11:27:53
2018-06-18 11:27:53,568 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) CommitMarkableResourceRecordRecoveryModule::periodicWorkFirstPass
2018-06-18 11:27:53,568 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) CommitMarkableResourceRecordRecoveryModule::connecting to: java:jboss/xa-datasources/CrashRecoveryDS
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) committedXidsToJndiNames.put< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:5c, subordinatenodename=null, eis_name=java:jboss/xa-datasources/CrashRecoveryDS > java:jboss/xa-datasources/CrashRecoveryDS
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,570 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)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_UNKNOWN
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state could not find committed or uncommitted state for 0:ffffc0a80066:d6f3988:5b277ade:54 instead found state StateStatus.OS_UNKNOWN
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_SHADOW)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 10)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 11)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable) - returning StateStatus.OS_COMMITTED
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,570 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 11)
2018-06-18 11:27:53,570 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable/0_ffffc0a80066_d6f3988_5b277ade_54, FileLock.F_RDLCK, false)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable)
2018-06-18 11:27:53,571 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable/0_ffffc0a80066_d6f3988_5b277ade_54, java.io.FileInputStream at 5e8b0ba, null)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 0:ffffc0a80066:d6f3988:5b277ade:54 )
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::BasicAction(0:ffffc0a80066:d6f3988:5b277ade:54)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager.unpackHeader for object-id 0:ffffc0a80066:d6f3988:5b277ade:54 birth-date 1529314033528
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) Moving 0:ffffc0a80066:d6f3988:5b277ade:54 back to being an AA
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_SHADOW)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 10)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 11)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable) - returning StateStatus.OS_COMMITTED
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 11)
2018-06-18 11:27:53,571 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable/0_ffffc0a80066_d6f3988_5b277ade_54, FileLock.F_RDLCK, false)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable)
2018-06-18 11:27:53,571 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable/0_ffffc0a80066_d6f3988_5b277ade_54, java.io.FileInputStream at 6907386a, null)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState(InputObjectState Uid : 0:ffffc0a80066:d6f3988:5b277ade:54
InputObjectState Type : /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable
InputObjectState Size : 672
InputObjectState Buffer: )
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.write_committed(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.write_state(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,571 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:27:53,571 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffffc0a80066_d6f3988_5b277ade_54, FileLock.F_WRLCK, true)
2018-06-18 11:27:53,582 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffffc0a80066_d6f3988_5b277ade_54, null, java.io.FileOutputStream at 3a23442a)
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.remove_committed(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable)
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.remove_state(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_SHADOW)
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 10)
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 11)
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable) - returning StateStatus.OS_COMMITTED
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 11)
2018-06-18 11:27:53,582 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable/0_ffffc0a80066_d6f3988_5b277ade_54, FileLock.F_WRLCK, false)
2018-06-18 11:27:53,582 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable/0_ffffc0a80066_d6f3988_5b277ade_54, null, null)
2018-06-18 11:27:53,582 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,582 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)
2018-06-18 11:27:53,582 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/Recovery/TransactionStatusManager, InputObjectState Uid : 0:0:0:0:0
InputObjectState Type : null
InputObjectState Size : 0
InputObjectState Buffer: , -1)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_COMMITTED
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_COMMITTED
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:27:53,583 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffffc0a80066_d6f3988_5b277ade_54, FileLock.F_RDLCK, false)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
2018-06-18 11:27:53,583 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffffc0a80066_d6f3988_5b277ade_54, java.io.FileInputStream at 195c1bc0, null)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 0:ffffc0a80066:d6f3988:5b277ade:54 )
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::BasicAction(0:ffffc0a80066:d6f3988:5b277ade:54)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager.unpackHeader for object-id 0:ffffc0a80066:d6f3988:5b277ade:54 birth-date 1529314033528
2018-06-18 11:27:53,583 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,583 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass
2018-06-18 11:27:53,583 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)
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,583 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
2018-06-18 11:27:53,583 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) found transaction 0:ffffc0a80066:d6f3988:5b277ade:54
2018-06-18 11:27:53,583 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
2018-06-18 11:27:53,583 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,583 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid : 0:0:0:0:0
InputObjectState Type : null
InputObjectState Size : 0
InputObjectState Buffer: )
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffffc0a80066:-74508445:5b277ae7:4f
OutputObjectState Type : null
OutputObjectState Size : 28
OutputObjectState Buffer: , StateManager)
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffffc0a80066:-74508445:5b277ae7:4f
OutputObjectState Type : null
OutputObjectState Size : 60
OutputObjectState Buffer: , StateManager/BasicAction)
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffffc0a80066:-74508445:5b277ae7:4f
OutputObjectState Type : null
OutputObjectState Size : 112
OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator)
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffffc0a80066:-74508445:5b277ae7:4f
OutputObjectState Type : null
OutputObjectState Size : 188
OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable)
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffffc0a80066:-74508445:5b277ae7:4f
OutputObjectState Type : null
OutputObjectState Size : 252
OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffffc0a80066:-74508445:5b277ae7:4f
OutputObjectState Type : null
OutputObjectState Size : 264
OutputObjectState Buffer: , EISNAME)
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,584 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)
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,584 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)
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,584 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)
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,584 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,584 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: , 2)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,585 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: , 2)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_COMMITTED
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid : 0:0:0:0:0
InputObjectState Type : null
InputObjectState Size : 0
InputObjectState Buffer: , 2)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:62, EISNAME, StateType.OS_SHADOW)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:62, EISNAME, 10)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:62, EISNAME, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:62, EISNAME, 11)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:62, EISNAME) - returning StateStatus.OS_COMMITTED
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:35, EISNAME, StateType.OS_SHADOW)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:35, EISNAME, 10)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:35, EISNAME, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:35, EISNAME, 11)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:35, EISNAME) - returning StateStatus.OS_COMMITTED
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:44, EISNAME, StateType.OS_SHADOW)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:44, EISNAME, 10)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:44, EISNAME, StateType.OS_ORIGINAL)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:44, EISNAME, 11)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:44, EISNAME) - returning StateStatus.OS_COMMITTED
2018-06-18 11:27:53,585 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/SubordinateAtomicAction/JCA, InputObjectState Uid : 0:0:0:0:0
InputObjectState Type : null
InputObjectState Size : 0
InputObjectState Buffer: , -1)
2018-06-18 11:27:53,585 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,586 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
2018-06-18 11:27:53,586 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change IDLE->FIRST_PASS
2018-06-18 11:27:53,586 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass
2018-06-18 11:27:53,586 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:27:53,586 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid : 0:0:0:0:0
InputObjectState Type : null
InputObjectState Size : 0
InputObjectState Buffer: , -1)
2018-06-18 11:27:53,586 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:27:53,586 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_toString_remotetrace_entry execute()
2018-06-18 11:27:53,590 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) getXAResources() instance: TestXAResourceRecovered(TestXAResourceCommon(id:805, xid:null, timeout:0, prepareReturn:0))
2018-06-18 11:27:53,590 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper at 770ad4b7
2018-06-18 11:27:53,592 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt
2018-06-18 11:27:53,592 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_toString_remotetrace_entry execute()
2018-06-18 11:27:53,597 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of TestXAResourceRecovered(TestXAResourceCommon(id:805, xid:null, timeout:0, prepareReturn:0))
2018-06-18 11:27:53,598 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_recover_remotetrace_entry execute()
2018-06-18 11:27:53,600 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecovered] (Periodic Recovery) TestXAResourceRecovered.recover(i=16777216)[id=805]
2018-06-18 11:27:53,600 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) recover()
2018-06-18 11:27:53,600 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning 1 Xids
2018-06-18 11:27:53,600 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning xid: < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource >
2018-06-18 11:27:53,600 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 1 xids in doubt
2018-06-18 11:27:53,600 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Recovered: < 131077, 29, 36, 0000000000-1-1-64-8801021311157-1209139122-340008449, 0000000000-1-1-64-8801021311157-1209139122-340009900030000 >
2018-06-18 11:27:53,600 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_toString_remotetrace_entry execute()
2018-06-18 11:27:53,602 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids updateIfEquivalentRM1 TestXAResourceRecovered(TestXAResourceCommon(id:805, xid:null, timeout:0, prepareReturn:0)) 1529314073600
2018-06-18 11:27:53,602 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_isSameRM_remotetrace_entry execute()
2018-06-18 11:27:53,604 INFO [org.jboss.as.test.jbossts.common.TestXAResourceCommon] (Periodic Recovery) TestXAResourceCommon.isSameRM(xaResource=org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper at 770ad4b7)[return 'false'][id=805]
2018-06-18 11:27:53,604 INFO [org.jboss.as.test.jbossts.common.TestXAResourceCommon] (Periodic Recovery) getJndiName()[return java:/TestXAResource][id=805]
2018-06-18 11:27:53,604 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES
2018-06-18 11:27:53,604 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
2018-06-18 11:28:03,604 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Mon, 18 Jun 2018 11:28:03
2018-06-18 11:28:03,605 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:28:03,605 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)
2018-06-18 11:28:03,605 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:28:03,605 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) found transaction 0:ffffc0a80066:d6f3988:5b277ade:54
2018-06-18 11:28:03,605 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 : 72
InputObjectState Buffer: , -1)
2018-06-18 11:28:03,605 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:28:03,605 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
2018-06-18 11:28:03,605 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass
2018-06-18 11:28:03,605 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
2018-06-18 11:28:03,605 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
2018-06-18 11:28:03,605 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,605 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:28:03,605 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_COMMITTED
2018-06-18 11:28:03,605 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2018-06-18 11:28:03,606 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/Recovery/TransactionStatusManager, InputObjectState Uid : 0:0:0:0:0
InputObjectState Type : null
InputObjectState Size : 0
InputObjectState Buffer: , -1)
2018-06-18 11:28:03,606 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2018-06-18 11:28:03,606 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
2018-06-18 11:28:03,606 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
2018-06-18 11:28:03,606 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,606 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:28:03,606 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_COMMITTED
2018-06-18 11:28:03,606 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) transaction type is /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid is 0:ffffc0a80066:d6f3988:5b277ade:54
ActionStatus is ActionStatus.COMMITTED in flight is false
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 0:ffffc0a80066:d6f3988:5b277ade:54 )
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::BasicAction(0:ffffc0a80066:d6f3988:5b277ade:54)
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::activate() for action-id 0:ffffc0a80066:d6f3988:5b277ade:54
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_COMMITTED
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:28:03,607 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffffc0a80066_d6f3988_5b277ade_54, FileLock.F_RDLCK, false)
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
2018-06-18 11:28:03,607 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffffc0a80066_d6f3988_5b277ade_54, java.io.FileInputStream at 7dc3220f, null)
2018-06-18 11:28:03,607 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::restore_state ()
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager.unpackHeader for object-id 0:ffffc0a80066:d6f3988:5b277ade:54 birth-date 1529314033528
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) Unpacked a 50 record
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 0:0:0:0:0 )
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) AbstractRecord::AbstractRecord () - crash recovery constructor
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) CommitMarkableResourceRecord.CommitMarkableResourceRecord (), record id=-8000000000000000:-8000000000000000:-80000000:-80000000:-80000000
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) unpack: java:jboss/xa-datasources/CrashRecoveryDS
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) unpack: < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:5c, subordinatenodename=null, eis_name=java:jboss/xa-datasources/CrashRecoveryDS >
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/CommitMarkableResourceRecord for -8000000000000000:-8000000000000000:-80000000:-80000000:-80000000
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) Unpacked a 171 record
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 0:0:0:0:0 )
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) AbstractRecord::AbstractRecord () - crash recovery constructor
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecordList::insert(RecordList: -8000000000000000:-8000000000000000:-80000000:-80000000:-80000000) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffc0a80066:d6f3988:5b277ade:64
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) Unpacked a 463 record
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) HeuristicList - Unpacked heuristic list size of 0
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) Restored action status of ActionStatus.COMMITTING 6
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) Restored action type Top-level 0
2018-06-18 11:28:03,608 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) Restored heuristic decision of TwoPhaseOutcome.PREPARE_OK 0
2018-06-18 11:28:03,609 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) RecoverAtomicAction.replayPhase2 recovering 0:ffffc0a80066:d6f3988:5b277ade:54 ActionStatus is ActionStatus.COMMITTED
2018-06-18 11:28:03,609 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::phase2Commit() for action-id 0:ffffc0a80066:d6f3988:5b277ade:54
2018-06-18 11:28:03,609 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.CommitMarkableResourceRecord at 5f9d8871)
2018-06-18 11:28:03,609 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) CommitMarkableResourceRecord.topLevelCommit for com.arjuna.ats.internal.jta.resources.arjunacore.CommitMarkableResourceRecord at 5f9d8871, record id=-8000000000000000:-8000000000000000:-80000000:-80000000:-80000000
2018-06-18 11:28:03,609 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::doCommit() result for action-id (0:ffffc0a80066:d6f3988:5b277ade:54) on record id: (-8000000000000000:-8000000000000000:-80000000:-80000000:-80000000) is (TwoPhaseOutcome.FINISH_OK) node id: (1)
2018-06-18 11:28:03,609 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_toString_remotetrace_entry execute()
2018-06-18 11:28:03,613 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::doCommit (XAResourceRecord < resource:TestXAResourceRecovered(TestXAResourceCommon(id:805, xid:null, timeout:0, prepareReturn:0)), txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource >, heuristic: TwoPhaseOutcome.FINISH_OK, product: Crash Recovery Test/EAP Test, jndiName: java:/TestXAResource com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord at 5ca8825d >)
2018-06-18 11:28:03,613 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_toString_remotetrace_entry execute()
2018-06-18 11:28:03,616 TRACE [com.arjuna.ats.jta] (Periodic Recovery) XAResourceRecord.topLevelCommit for XAResourceRecord < resource:TestXAResourceRecovered(TestXAResourceCommon(id:805, xid:null, timeout:0, prepareReturn:0)), txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource >, heuristic: TwoPhaseOutcome.FINISH_OK, product: Crash Recovery Test/EAP Test, jndiName: java:/TestXAResource com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord at 5ca8825d >, record id=0:ffffc0a80066:d6f3988:5b277ade:64
2018-06-18 11:28:03,618 INFO [stdout] (Periodic Recovery) Installed rule using default helper : org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_commit_remotetrace_entry
2018-06-18 11:28:03,619 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_commit_remotetrace_entry execute()
2018-06-18 11:28:03,622 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecovered] (Periodic Recovery) TestXAResourceRecovered.commit(Xid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource >, b=false)[id=805]
2018-06-18 11:28:03,622 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) removeLog(xid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource >
2018-06-18 11:28:03,622 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
2018-06-18 11:28:03,622 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) logging xids: [][number: 0] records to /home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/TestXAResourceStateStore/TestXAResource.ser
2018-06-18 11:28:03,623 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::doCommit() result for action-id (0:ffffc0a80066:d6f3988:5b277ade:54) on record id: (0:ffffc0a80066:d6f3988:5b277ade:64) is (TwoPhaseOutcome.FINISH_OK) node id: (1)
2018-06-18 11:28:03,623 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::updateState() for action-id 0:ffffc0a80066:d6f3988:5b277ade:54
2018-06-18 11:28:03,623 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.remove_committed(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
2018-06-18 11:28:03,624 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.remove_state(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,624 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
2018-06-18 11:28:03,624 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
2018-06-18 11:28:03,624 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,624 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:28:03,624 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_COMMITTED
2018-06-18 11:28:03,624 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,624 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:28:03,624 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffffc0a80066_d6f3988_5b277ade_54, FileLock.F_WRLCK, false)
2018-06-18 11:28:03,624 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/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffffc0a80066_d6f3988_5b277ade_54, null, null)
2018-06-18 11:28:03,624 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) RecoverAtomicAction.replayPhase2( 0:ffffc0a80066:d6f3988:5b277ade:54 ) finished
2018-06-18 11:28:03,624 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
2018-06-18 11:28:03,624 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass
2018-06-18 11:28:03,624 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
2018-06-18 11:28:03,624 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
2018-06-18 11:28:03,624 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
2018-06-18 11:28:03,624 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass
2018-06-18 11:28:03,624 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed
2018-06-18 11:28:03,624 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper at 770ad4b7
2018-06-18 11:28:03,624 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.
2018-06-18 11:28:03,625 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_toString_remotetrace_entry execute()
2018-06-18 11:28:03,628 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of TestXAResourceRecovered(TestXAResourceCommon(id:805, xid:null, timeout:0, prepareReturn:0))
2018-06-18 11:28:03,629 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_toString_remotetrace_entry execute()
2018-06-18 11:28:03,632 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids _whenFirstSeen toRecover yes TestXAResourceRecovered(TestXAResourceCommon(id:805, xid:null, timeout:0, prepareReturn:0)) 1529314033525 === 1529314083628
2018-06-18 11:28:03,632 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_toString_remotetrace_entry execute()
2018-06-18 11:28:03,635 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids _whenFirstSeen toRecover no TestXAResourceRecovered(TestXAResourceCommon(id:805, xid:null, timeout:0, prepareReturn:0)) 1529314033525 === 1529314083628
2018-06-18 11:28:03,635 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 1 Xids to recover on this pass.
2018-06-18 11:28:03,635 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 2, 0 )
2018-06-18 11:28:03,635 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::BasicAction()
2018-06-18 11:28:03,636 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Checking whether Xid < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource > exists in ObjectStore.
2018-06-18 11:28:03,636 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Looking for 0:ffffc0a80066:d6f3988:5b277ade:54 and /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable)
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_SHADOW)
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 10)
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, 11)
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable) - returning StateStatus.OS_UNKNOWN
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state could not find committed or uncommitted state for 0:ffffc0a80066:d6f3988:5b277ade:54 instead found state StateStatus.OS_UNKNOWN
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
2018-06-18 11:28:03,636 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffc0a80066:d6f3988:5b277ade:54, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_UNKNOWN
2018-06-18 11:28:03,636 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) No record found for < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource >
2018-06-18 11:28:03,636 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.JTATransactionLogXAResourceOrphanFilter voted ABSTAIN
2018-06-18 11:28:03,637 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) node name of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource > is 1
2018-06-18 11:28:03,637 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.JTANodeNameXAResourceOrphanFilter voted ROLLBACK
2018-06-18 11:28:03,637 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) subordinate node name of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource > is null
2018-06-18 11:28:03,637 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.SubordinateJTAXAResourceOrphanFilter voted ABSTAIN
2018-06-18 11:28:03,637 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) subordinate node name of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource > is null
2018-06-18 11:28:03,638 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.SubordinationManagerXAResourceOrphanFilter voted ABSTAIN
2018-06-18 11:28:03,638 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) node name of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource > is 1
2018-06-18 11:28:03,638 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.JTAActionStatusServiceXAResourceOrphanFilter voted ABSTAIN
2018-06-18 11:28:03,638 INFO [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016013: Rolling back < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource >
2018-06-18 11:28:03,640 INFO [stdout] (Periodic Recovery) Installed rule using default helper : org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_rollback_remotetrace_entry
2018-06-18 11:28:03,641 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_rollback_remotetrace_entry execute()
2018-06-18 11:28:03,644 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecovered] (Periodic Recovery) TestXAResourceRecovered.rollback(Xid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource >)[id=805]
2018-06-18 11:28:03,644 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) removeLog(xid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource >
2018-06-18 11:28:03,644 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) no log present for < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80066:d6f3988:5b277ade:54, node_name=1, branch_uid=0:ffffc0a80066:d6f3988:5b277ade:63, subordinatenodename=null, eis_name=java:/TestXAResource >
2018-06-18 11:28:03,644 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_recover_remotetrace_entry execute()
2018-06-18 11:28:03,646 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecovered] (Periodic Recovery) TestXAResourceRecovered.recover(i=8388608)[id=805]
2018-06-18 11:28:03,647 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) recover()
2018-06-18 11:28:03,647 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning 0 Xids
2018-06-18 11:28:03,647 INFO [stdout] (Periodic Recovery) org.jboss.byteman.contrib.dtest.Instrumentor_org.jboss.as.test.jbossts.common.TestXAResourceRecovered_toString_remotetrace_entry execute()
2018-06-18 11:28:03,649 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check TestXAResourceRecovered(TestXAResourceCommon(id:805, xid:null, timeout:0, prepareReturn:0)) 1529314073600 1529314083647 false
2018-06-18 11:28:03,649 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper at 770ad4b7 1529314033516 1529314083649 true
2018-06-18 11:28:03,649 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed
2018-06-18 11:28:03,649 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change SECOND_PASS->IDLE
2018-06-18 11:28:03,649 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
2018-06-18 11:28:03,649 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE
2018-06-18 11:28:03,649 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: scan thread signals listener worker
2018-06-18 11:28:03,649 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off
{code}
> CMR recovery wrongly handles commit and rollback
> -------------------------------------------------
>
> Key: JBTM-3034
> URL: https://issues.jboss.org/browse/JBTM-3034
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: JTA
> Affects Versions: 5.8.1.Final
> Reporter: Ondra Chaloupka
> Assignee: Ondra Chaloupka
>
> The recovery of CMR works wrongly.
> For scenario I currently investigate there is issue the second resource beging committed and rolled-back too.
> # cmr resource prepare (no real action on the local transction)
> # xa resource prepare (prepared in real as XA)
> # cmr resource commit (commiting the local transaction)
> # JVM crash
> # expecting the xa resource being committed, but it's committed and immediatelly rolled-back. fortunatelly it seems it does not causes data consistency issue.
> This is similar to what was seen in issue https://issues.jboss.org/browse/JBEAP-6326 but not the same. The seems could be connected with fix for https://issues.jboss.org/browse/JBTM-2734. More investigation is needed.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
More information about the jbossts-issues
mailing list