JBossTS recovery: look inside

10:40:44,801 (Thread-18) PeriodicRecovery: background thread Status <== SCANNING
10:40:44,801 (Thread-18) PeriodicRecovery: background thread scanning
10:40:44,802 (Thread-18) Periodic recovery - first pass <Wt, 30 wrz 2014 10:40:44>
10:40:44,802 (Thread-18) InputObjectState::InputObjectState()
10:40:44,802 (Thread-18) StatusModule: first pass
10:40:44,802 (Thread-18) HashedStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
10:40:44,802 (Thread-18) OutputObjectState::OutputObjectState()
10:40:44,890 (Thread-18) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
10:40:44,890 (Thread-18) found transaction -3f57c7ff:ecce:542a6c31:53b
10:40:44,890 (Thread-18) found transaction -3f57c7ff:ebbb:542a6bef:a98
10:40:44,890 (Thread-18) found transaction -3f57c7ff:ed72:542a6c5e:50c
...

10:40:44,891 (Thread-18) [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass
10:40:44,891 (Thread-18) InputObjectState::InputObjectState()
10:40:44,891 (Thread-18) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: )
10:40:44,892 (Thread-18) OutputObjectState::OutputObjectState()
10:40:44,892 (Thread-18)
10:40:44,896 (Thread-18) PERIODIC 1. PASS ON STORE  WITH TYPE /StateManager/AbstractRecord/XAResourceRecord
10:40:44,896 (Thread-18) [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
10:40:44,896 (Thread-18) InputObjectState::InputObjectState()
10:40:44,897 (Thread-18) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
10:40:44,897 (Thread-18) OutputObjectState::OutputObjectState()
10:45:42,120 (Thread-18) Periodic recovery - second pass <Wt, 30 wrz 2014 10:45:42>
10:45:42,120 (Thread-18) AtomicActionRecoveryModule: Second pass
10:45:42,136 (Thread-18) +---- RESOURCE INITIATED RECOVERY
10:45:42,136 (Thread-18) +--- RES RECOVERER: org.jboss.jms.server.recovery.MessagingXAResourceRecovery@7c9a899d
10:45:42,136 (Thread-18) org.jboss.jms.server.recovery.MessagingXAResourceRecovery@7c9a899d hasMoreResources
10:45:42,136 (Thread-18) org.jboss.jms.server.recovery.MessagingXAResourceRecovery@7c9a899d getXAResource
10:45:42,136 (Thread-18)  +-- CALLING XARECOVERY
10:45:42,136 (Thread-18) xarecovery of org.jboss.jms.server.recovery.MessagingXAResourceWrapper@53673666
10:45:42,136 (Thread-18) Recover java:DefaultEMSProvider
10:45:43,728 (Thread-18) [EMS] XA Recovery #15 sees 58 XIDs: [{formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:858-3f57c7ff:efbe:542a6d09:9aa}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:53b-3f57c7ff:ecce:542a6c31:693}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dad-3f57c7ff:f885:542a6d79:1efb}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:537-3f57c7ff:ecce:542a6c31:688}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:514-3f57c7ff:ed72:542a6c5e:66d}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dd0-3f57c7ff:f885:542a6d79:1f13}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:26a-3f57c7ff:ef42:542a6ce0:3e1}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4f5-3f57c7ff:ed72:542a6c5e:63c}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:16b-3f57c7ff:eb5c:542a6bc7:2c3}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dbe-3f57c7ff:f885:542a6d79:1f14}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:333-3f57c7ff:ee22:542a6c8c:48d}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:166-3f57c7ff:eb5c:542a6bc7:2b8}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ebbb:542a6bef:aaf-3f57c7ff:ebbb:542a6bef:bfc}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:160-3f57c7ff:eafe:542a6b9a:2c8}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:2a1-3f57c7ff:ef42:542a6ce0:3ec}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:863-3f57c7ff:efbe:542a6d09:9bd}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1d93-3f57c7ff:f885:542a6d79:1ee5}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:47e-3f57c7ff:eeb2:542a6cb6:5cc}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:52c-3f57c7ff:ed72:542a6c5e:67e}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:1ad-3f57c7ff:eb5c:542a6bc7:2ef}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:879-3f57c7ff:efbe:542a6d09:9cb}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:558-3f57c7ff:ecce:542a6c31:6a9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4ce-3f57c7ff:ed72:542a6c5e:626}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:304-3f57c7ff:ee22:542a6c8c:456}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:289-3f57c7ff:ef42:542a6ce0:3d6}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:183-3f57c7ff:eafe:542a6b9a:2d3}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:187-3f57c7ff:eb5c:542a6bc7:2d9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:18c-3f57c7ff:eafe:542a6b9a:2e9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:310-3f57c7ff:ee22:542a6c8c:461}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:31a-3f57c7ff:ee22:542a6c8c:471}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4df-3f57c7ff:ed72:542a6c5e:647}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ebbb:542a6bef:a98-3f57c7ff:ebbb:542a6bef:be6}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:16a-3f57c7ff:eb5c:542a6bc7:2ce}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:196-3f57c7ff:eb5c:542a6bc7:2e4}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:503-3f57c7ff:ed72:542a6c5e:652}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:54c-3f57c7ff:ecce:542a6c31:69e}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4e7-3f57c7ff:ed72:542a6c5e:631}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dd4-3f57c7ff:f885:542a6d79:1f27}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:176-3f57c7ff:eafe:542a6b9a:2bd}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1d9d-3f57c7ff:f885:542a6d79:1ef0}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:325-3f57c7ff:ee22:542a6c8c:477}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:46d-3f57c7ff:eeb2:542a6cb6:5c1}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4cd-3f57c7ff:ed72:542a6c5e:61b}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:464-3f57c7ff:eeb2:542a6cb6:5b6}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1db2-3f57c7ff:f885:542a6d79:1f1c}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:28a-3f57c7ff:ef42:542a6ce0:3cb}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:33c-3f57c7ff:ee22:542a6c8c:482}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:86e-3f57c7ff:efbe:542a6d09:9c0}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:182-3f57c7ff:eafe:542a6b9a:2de}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:521-3f57c7ff:ed72:542a6c5e:673}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:19e-3f57c7ff:eb5c:542a6bc7:305}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ebbb:542a6bef:aa0-3f57c7ff:ebbb:542a6bef:bf9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:2ac-3f57c7ff:ef42:542a6ce0:3f7}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:f7d0:542a6d3a:5af-3f57c7ff:f7d0:542a6d3a:700}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:192-3f57c7ff:eb5c:542a6bc7:2fa}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:842-3f57c7ff:efbe:542a6d09:99f}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:50c-3f57c7ff:ed72:542a6c5e:65d}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:48d-3f57c7ff:eeb2:542a6cb6:5d7}]
10:45:43,730 (Thread-18) Found 58 xids in doubt

10:45:47,213 (Thread-18) +---- RESOURCE INITIATED RECOVERY completed
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:ecce:542a6c31:540) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:ecce:542a6c31:691
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_20] - Unpacked a 171 record
10:45:47,213 (Thread-18) StateManager::StateManager( 0:0:0:0 )
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.AbstractRecord_1] - AbstractRecord::AbstractRecord () - crash recovery constructor
10:45:47,213 (Thread-18) | RECOVERY XIDS for org.jboss.jms.server.recovery.MessagingXAResourceWrapper@2c8b18f5 contains -1217944454 ? true
10:45:47,213 (Thread-18) +---- RESOURCE INITIATED RECOVERY completed
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:ecce:542a6c31:540 -3f57c7ff:ecce:542a6c31:691) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:ecce:542a6c31:694
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_20] - Unpacked a 463 record
10:45:47,214 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_22] - HeuristicList - Unpacked heuristic list size of 0
10:45:47,214 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_25] - Restored action status of ActionStatus.COMMITTING 6
10:45:47,214 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_26] - Restored action type Top-level 0
10:45:47,215 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_27] - Restored heuristic decision of TwoPhaseOutcome.PREPARE_OK 0
10:45:47,215 (Thread-18) [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_1] - RecoverAtomicAction.replayPhase2 recovering -3f57c7ff:ecce:542a6c31:53b ActionStatus is ActionStatus.COMMITTED
10:45:47,215 (Thread-18) BasicAction::phase2Commit() for action-id -3f57c7ff:ecce:542a6c31:53b
10:45:47,215 (Thread-18) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@6fd5af22)
10:45:47,215 (Thread-18) XAResourceRecord.topLevelCommit for < 131075, 29, 27, 494545511025355995510210258101999910158535250975499514958535198455110253559955102102581019999101585352509754995149585351102 >
10:45:47,215 (Thread-18) [EMS] Recovery session will be created
10:45:47,216 (Thread-18) [EMS] Establishing handler for connection #-17

10:45:48,222 (Thread-18) BasicAction::updateState() for action-id -3f57c7ff:ecce:542a6c31:53b
10:45:48,222 (Thread-18) FileSystemStore.remove_committed(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:45:48,222 (Thread-18) ShadowingStore.remove_state(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,222 (Thread-18) HashedStore.genPathName(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
10:45:48,222 (Thread-18) HashedStore.genPathName(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,222 (Thread-18) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
10:45:48,222 (Thread-18) HashedStore.genPathName(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,222 (Thread-18) FileSystemStore.openAndLock(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#102#\-3f57c7ff_ecce_542a6c31_53b, FileLock.F_WRLCK, false)
10:45:48,223 (Thread-18) FileSystemStore.closeAndUnlock(C:\_dev\jboss-5.1.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#102#\-3f57c7ff_ecce_542a6c31_53b, null, null)
10:45:48,223 (Thread-18) [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_3] - RecoverAtomicAction.replayPhase2( -3f57c7ff:ecce:542a6c31:53b )  finished
10:45:48,223 (Thread-18) HashedStore.genPathName(-3f57c7ff:ef42:542a6ce0:26a, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
10:45:48,223 (Thread-18) HashedStore.genPathName(-3f57c7ff:ef42:542a6ce0:26a, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,224 (Thread-18) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57c7ff:ef42:542a6ce0:26a, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
10:45:48,224 (Thread-18) InputObjectState::InputObjectState()
10:45:48,224 (Thread-18) HashedStore.allObjUids(/Recovery/TransactionStatusManager, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
10:45:48,224 (Thread-18) OutputObjectState::OutputObjectState()