[
https://issues.jboss.org/browse/JBTM-3034?page=com.atlassian.jira.plugin....
]
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@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@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@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@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@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@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@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@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@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@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@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@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@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)