[JBoss JIRA] (JBTM-3035) LRA context should propagate across non-LRA aware services
by Michael Musgrove (JIRA)
Michael Musgrove created JBTM-3035:
--------------------------------------
Summary: LRA context should propagate across non-LRA aware services
Key: JBTM-3035
URL: https://issues.jboss.org/browse/JBTM-3035
Project: JBoss Transaction Manager
Issue Type: Bug
Components: LRA
Affects Versions: 5.8.2.Final
Reporter: Michael Musgrove
Assignee: Michael Musgrove
Fix For: 5.next
If you have a microservice A that wants to participate in an LRA and calls microservice B (which does not have specific LRA behaviour) and this calls microservice C (which does have specific LRA behaviour), then B should not need to be annotated with @LRA.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 5 months
[JBoss JIRA] (JBTM-3034) CMR recovery wrongly handles commit and rollback
by Ondra Chaloupka (JIRA)
[ https://issues.jboss.org/browse/JBTM-3034?page=com.atlassian.jira.plugin.... ]
Ondra Chaloupka updated JBTM-3034:
----------------------------------
Description:
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 is *regression* against EAP 7.0.0. The same scenario works in 7.0.0 smoothly.
was:
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.
> 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 is *regression* against EAP 7.0.0. The same scenario works in 7.0.0 smoothly.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 5 months
[JBoss JIRA] (JBTM-3034) CMR recovery wrongly handles commit and rollback
by Ondra Chaloupka (JIRA)
[ 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)
6 years, 5 months
[JBoss JIRA] (JBTM-3034) CMR recovery wrongly handles commit and rollback
by Ondra Chaloupka (JIRA)
Ondra Chaloupka created JBTM-3034:
-------------------------------------
Summary: 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)
6 years, 5 months
[JBoss JIRA] (JBTM-3017) Provide a check to see if the last recovery scan "cleaned" the store.
by Michael Musgrove (JIRA)
[ https://issues.jboss.org/browse/JBTM-3017?page=com.atlassian.jira.plugin.... ]
Michael Musgrove updated JBTM-3017:
-----------------------------------
Status: Resolved (was: Pull Request Sent)
Resolution: Done
The fix detects and reports issues (via RecoveryMonitor) with XAResources (such as not being able to contact one of the configured resources). This is sufficient to ensure that all potential orphans were detected. If support for other transaction types such as subordinate transactions is required then a separate JIRA should be raised.
> Provide a check to see if the last recovery scan "cleaned" the store.
> ----------------------------------------------------------------------
>
> Key: JBTM-3017
> URL: https://issues.jboss.org/browse/JBTM-3017
> Project: JBoss Transaction Manager
> Issue Type: Feature Request
> Components: Recovery, Tooling
> Affects Versions: 5.8.1.Final
> Reporter: Michael Musgrove
> Assignee: Michael Musgrove
> Fix For: 5.next
>
>
> There are some recovery manager use cases where the user needs to know that the log store is empty and that all orphans have been detected (for example it is possible that some resource managers were not available during the last scan).
> This feature would be particularly useful when running on OpenShift in order to determine when it is safe scale down and reclaim the space used by a pod.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 5 months
[JBoss JIRA] (JBTM-3032) Check the connection pool with JMX when using Transactional DataSource
by Amos Feng (JIRA)
Amos Feng created JBTM-3032:
-------------------------------
Summary: Check the connection pool with JMX when using Transactional DataSource
Key: JBTM-3032
URL: https://issues.jboss.org/browse/JBTM-3032
Project: JBoss Transaction Manager
Issue Type: Enhancement
Components: Tomcat
Reporter: Amos Feng
Currently the common-dbcp2 only expose the org.apache.commons.dbcp2.PoolableConnectionMXBean for every database connection. And the customer want to check the connection pool with JMX just like org.apach.tomcat.jdbc.pool.jmx.ConnectionPoolMBean
* getIdle()
* getSize()
* getActive()
* getNumIdle()
* getNumActibe()
* getWaitCount()
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 5 months