12:41:36,765 DEBUG [arjLogger] PeriodicRecovery: background thread Status <== SCANNING
12:41:36,765 DEBUG [arjLogger] PeriodicRecovery: background thread scanning
12:41:36,765 DEBUG [arjLogger] Periodic recovery - first pass <Mon, 18 Jan 2010 12:41:36>
12:41:36,765 DEBUG [arjLogger] InputObjectState::InputObjectState()
12:41:36,765 DEBUG [arjLogger] StatusModule: first pass 
12:41:36,765 DEBUG [arjLogger] HashedStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
12:41:36,781 DEBUG [arjLogger] OutputObjectState::OutputObjectState()
12:41:36,812 DEBUG [arjLogger] processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
12:41:36,812 DEBUG [arjLogger] found transaction -3f57994f:42f:4b5481c8:78e4
12:41:36,812 DEBUG [arjLogger]  
12:41:36,812 DEBUG [txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass
12:41:36,812 DEBUG [arjLogger] InputObjectState::InputObjectState()
12:41:36,812 DEBUG [arjLogger] FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: )
12:41:36,812 DEBUG [arjLogger] OutputObjectState::OutputObjectState()
12:41:36,812 DEBUG [arjLogger]  
12:41:36,812 DEBUG [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
12:41:36,812 DEBUG [arjLogger] InputObjectState::InputObjectState()
12:41:36,812 DEBUG [arjLogger] FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
12:41:36,812 DEBUG [arjLogger] OutputObjectState::OutputObjectState()
12:41:36,812 DEBUG [arjLogger]  
12:41:46,812 DEBUG [arjLogger] Periodic recovery - second pass <Mon, 18 Jan 2010 12:41:46>
12:41:46,812 DEBUG [arjLogger] AtomicActionRecoveryModule: Second pass 
12:41:46,812 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
12:41:46,812 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
12:41:46,812 DEBUG [arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
12:41:46,828 DEBUG [arjLogger] InputObjectState::InputObjectState()
12:41:46,828 DEBUG [arjLogger] HashedStore.allObjUids(/Recovery/TransactionStatusManager, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
12:41:46,828 DEBUG [arjLogger] OutputObjectState::OutputObjectState()
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.TransactionStatusConnectionManager_3] - found process uid -3f57994f:6fb:4b549612:0
12:41:46,843 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
12:41:46,843 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
12:41:46,843 DEBUG [arjLogger] transaction type is /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid is -3f57994f:42f:4b5481c8:78e4
 ActionStatus is ActionStatus.COMMITTED in flight is false
12:41:46,843 DEBUG [arjLogger] StateManager::StateManager( -3f57994f:42f:4b5481c8:78e4 )
12:41:46,843 DEBUG [arjLogger] BasicAction::BasicAction(-3f57994f:42f:4b5481c8:78e4)
12:41:46,843 DEBUG [arjLogger] BasicAction::activate() for action-id -3f57994f:42f:4b5481c8:78e4
12:41:46,843 DEBUG [arjLogger] ShadowingStore.ShadowingStore( 14 )
12:41:46,843 DEBUG [arjLogger] ShadowNoFileLockStore.ShadowNoFileLockStore( 14 )
12:41:46,843 DEBUG [arjLogger] HashedStore.HashedStore( 14 )
12:41:46,843 DEBUG [arjLogger] HashedStore.HashedActionStore()
12:41:46,843 DEBUG [arjLogger] FileSystemStore.setupStore()
12:41:46,843 DEBUG [arjLogger] FileSystemStore.createHierarchy(C:\jboss-as\server\default\data/tx-object-store\HashedActionStore\defaultStore\)
12:41:46,843 DEBUG [arjLogger] FileSystemStore.read_committed(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
12:41:46,843 DEBUG [arjLogger] ShadowingStore.read_state(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
12:41:46,843 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
12:41:46,843 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
12:41:46,843 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
12:41:46,843 DEBUG [arjLogger] FileSystemStore.openAndLock(C:\jboss-as\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#42#\-3f57994f_42f_4b5481c8_78e4, FileLock.F_RDLCK, false)
12:41:46,843 DEBUG [arjLogger] InputObjectState::InputObjectState(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
12:41:46,843 DEBUG [arjLogger] FileSystemStore.closeAndUnlock(C:\jboss-as\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#42#\-3f57994f_42f_4b5481c8_78e4, java.io.FileInputStream@a502bc, null)
12:41:46,843 DEBUG [arjLogger] BasicAction::restore_state ()
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_20] - Unpacked a 463 record
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_22] - HeuristicList - Unpacked heuristic list size of 1
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_23] - HeuristicList - Unpacked a 171 record
12:41:46,843 DEBUG [arjLogger] StateManager::StateManager( 0:0:0:0 )
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.AbstractRecord_1] - AbstractRecord::AbstractRecord () - crash recovery constructor
12:41:46,843 DEBUG [arjLogger] StateManager::StateManager( 0:0:0:0 )
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.AbstractRecord_1] - AbstractRecord::AbstractRecord () - crash recovery constructor
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57994f:42f:4b5481c8:7ab5
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_23] - HeuristicList - Unpacked a 463 record
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_25] - Restored action status of ActionStatus.COMMITTED 7
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_26] - Restored action type Top-level 0
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_27] - Restored heuristic decision of TwoPhaseOutcome.HEURISTIC_HAZARD 6
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_1] - RecoverAtomicAction.replayPhase2 recovering -3f57994f:42f:4b5481c8:78e4 ActionStatus is ActionStatus.COMMITTED
12:41:46,843 DEBUG [arjLogger] BasicAction::phase2Commit() for action-id -3f57994f:42f:4b5481c8:78e4
12:41:46,843 DEBUG [arjLogger] BasicAction::doForget (RecordList: -3f57994f:42f:4b5481c8:7ab5)
12:41:46,843 DEBUG [arjLogger] BasicAction::updateState() for action-id -3f57994f:42f:4b5481c8:78e4
12:41:46,843 DEBUG [arjLogger] OutputObjectState::OutputObjectState(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
12:41:46,843 DEBUG [arjLogger] BasicAction::save_state ()
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_17] - HeuristicList - packing a 171 record
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_18] - HeuristicList - packing a NONE_RECORD
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTING
12:41:46,843 DEBUG [arjLogger] FileSystemStore.write_committed(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
12:41:46,843 DEBUG [arjLogger] ShadowingStore.write_state(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
12:41:46,843 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
12:41:46,843 DEBUG [arjLogger] FileSystemStore.openAndLock(C:\jboss-as\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#42#\-3f57994f_42f_4b5481c8_78e4, FileLock.F_WRLCK, true)
12:41:46,843 DEBUG [arjLogger] FileSystemStore.closeAndUnlock(C:\jboss-as\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#42#\-3f57994f_42f_4b5481c8_78e4, null, java.io.FileOutputStream@156c38b)
12:41:46,843 DEBUG [arjLogger] BasicAction::updateState() for action-id -3f57994f:42f:4b5481c8:78e4
12:41:46,843 DEBUG [arjLogger] OutputObjectState::OutputObjectState(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
12:41:46,843 DEBUG [arjLogger] BasicAction::save_state ()
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_17] - HeuristicList - packing a 171 record
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_18] - HeuristicList - packing a NONE_RECORD
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTED
12:41:46,843 DEBUG [arjLogger] FileSystemStore.write_committed(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
12:41:46,843 DEBUG [arjLogger] ShadowingStore.write_state(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
12:41:46,843 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
12:41:46,843 DEBUG [arjLogger] FileSystemStore.openAndLock(C:\jboss-as\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#42#\-3f57994f_42f_4b5481c8_78e4, FileLock.F_WRLCK, true)
12:41:46,843 DEBUG [arjLogger] FileSystemStore.closeAndUnlock(C:\jboss-as\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#42#\-3f57994f_42f_4b5481c8_78e4, null, java.io.FileOutputStream@1400fad)
12:41:46,843 DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_3] - RecoverAtomicAction.replayPhase2( -3f57994f:42f:4b5481c8:78e4 )  finished
12:41:46,843 DEBUG [arjLogger]  
12:41:46,843 DEBUG [txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass
12:41:46,843 DEBUG [arjLogger]  
12:41:46,843 DEBUG [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
12:41:46,843 DEBUG [logger] Local XARecoveryModule.transactionInitiatedRecovery completed
12:41:46,859 DEBUG [AppServerJDBCXARecovery] Created new XAConnection
12:41:46,859 DEBUG [logger] xarecovery of com.ibm.db2.jcc.t4.bc@c560f1
12:41:46,875 DEBUG [logger] Found 0 xids in doubt
12:41:46,906 DEBUG [AppServerJDBCXARecovery] Created new XAConnection
12:41:46,906 DEBUG [logger] xarecovery of oracle.jdbc.driver.T4CXAResource@5f8113
12:41:46,906 DEBUG [logger] Found 1 xids in doubt
12:41:46,906 DEBUG [logger] Have 1 Xids to recover on this pass.
12:41:46,906 DEBUG [logger] Checking node name of oracle.jdbc.xa.OracleXid@80e4d6
12:41:46,906 DEBUG [logger] Node name is 1
12:41:46,906 DEBUG [logger] Will recover this Xid (b)
12:41:46,906 DEBUG [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.rollingback] Rolling back < 131075, 29, 27, 49454551102535557575210258525010258529853525649995658555610152455110253555757521025852501025852985352564999565855979852 >
12:41:46,906 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
12:41:46,906 DEBUG [arjLogger] HashedStore.genPathName(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
12:41:46,906 DEBUG [arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57994f:42f:4b5481c8:78e4, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
12:41:46,906 DEBUG [logger] Local XARecoveryModule.resourceInitiatedRecovery completed
12:41:46,906 DEBUG [arjLogger]  
12:41:46,906 DEBUG [arjLogger] PeriodicRecovery: background thread Status <== INACTIVE
12:41:46,906 DEBUG [arjLogger] PeriodicRecovery: background thread backing off