Recovering Prepared transaction branch
traffic Aug 19, 2007 11:17 PMConducting a test, we came across an instance were the TM failed to recover an outstanding transaction branch.
Here's the situation: We have a single SLSB accessing one or more programs in an EIS environment using a resource adapter implementation. The SLSB uses 2 resource managers. After the SLSB completes its work and closes its connections, the following steps happen:
1) TM calls XAResource.end on RM-1, which completes successfully
2) TM calls XAResource.prepare on RM-1, which completes successfully
3) TM calls XAResource.end on RM-2, which completes successfully
4) TM calls XAResource.prepare on RM-2. At his point, JBoss is intentionally terminated to force a recovery situation. The termination happens before the Prepare is propagated to the EIS environment, thus the termination of JBoss causes the transaction branch associated with RM-2 to be rolled back in the EIS environment.
5) JBoss is re-initiated.
6) Our XAResourceRecovery implementation returns the required XAResource
7) TM calls XAResource.recover, which returns 0 xids due to resources still initializing.
8) Step 6 is repeated by the JBoss recovery process
9) TM calls XAResource.recover, which returns a single xid
10) JBoss transactions continuously repeat steps 8 and 9.
Nothing happens after the xid has been recovered ? no call to XAResoure.rollback or XAResource.commit; steps 8 and 9 are repeated.
I was able to get this scenario to work in WebLogic 9.1, which rolled back the outstanding transaction branch as expected.
If JBoss is terminated after both branches have been Prepared, then the xids are recovered and committed.
Here's part of the server log after JBoss has been restarted.
2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - first pass <Sun, 19 Aug 2007 16:52:38> 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] InputObjectState::InputObjectState() 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule: first pass 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid : 0:0:0:0 InputObjectState Type : null InputObjectState Size : 0 InputObjectState Buffer: , 0) 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState() 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] found transaction -3fc40791:a32:46c8d687:40 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] InputObjectState::InputObjectState() 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.allTypes(InputObjectState Uid : 0:0:0:0 InputObjectState Type : null InputObjectState Size : 0 InputObjectState Buffer: ) 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState() 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] InputObjectState::InputObjectState() 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid : 0:0:0:0 InputObjectState Type : null InputObjectState Size : 0 InputObjectState Buffer: , 0) 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState() 2007-08-19 16:52:38,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - second pass <Sun, 19 Aug 2007 16:52:48> 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AtomicActionRecoveryModule: Second pass 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] InputObjectState::InputObjectState() 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.allObjUids(/Recovery/TransactionStatusManager, InputObjectState Uid : 0:0:0:0 InputObjectState Type : null InputObjectState Size : 0 InputObjectState Buffer: , 0) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState() 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.TransactionStatusConnectionManager_3] - found process uid -3fc40791:a73:46c8d72e:0 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] transaction type is /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid is -3fc40791:a32:46c8d687:40 ActionStatus is ActionStatus.COMMITTED in flight is false 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( -3fc40791:a32:46c8d687:40 ) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::BasicAction(-3fc40791:a32:46c8d687:40) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::activate() for action-id -3fc40791:a32:46c8d687:40 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.ShadowingStore( 14 ) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowNoFileLockStore.ShadowNoFileLockStore( 14 ) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.HashedStore( 14 ) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.HashedActionStore() 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.setupStore() 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.createHierarchy(C:\jboss-4.2.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.read_committed(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.read_state(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.openAndLock(C:\jboss-4.2.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, FileLock.F_RDLCK, false) 2007-08-19 16:52:48,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] InputObjectState::InputObjectState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.closeAndUnlock(C:\jboss-4.2.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, java.io.FileInputStream@1a5d6d6, null) 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::restore_state () 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_20] - Unpacked a 463 record 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_22] - HeuristicList - Unpacked heuristic list size of 1 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_23] - HeuristicList - Unpacked a 171 record 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 0:0:0:0 ) 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.AbstractRecord_1] - AbstractRecord::AbstractRecord () - crash recovery constructor 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 0:0:0:0 ) 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.AbstractRecord_1] - AbstractRecord::AbstractRecord () - crash recovery constructor 2007-08-19 16:52:48,172 WARN [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 30, 25, jrac--3fc40791:a32:46c8d687:40-3fc40791:a32:46c8d687:46 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3fc40791:a32:46c8d687:47 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_23] - HeuristicList - Unpacked a 463 record 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_25] - Restored action status of ActionStatus.COMMITTED 7 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_26] - Restored action type Top-level 0 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_27] - Restored heuristic decision of TwoPhaseOutcome.HEURISTIC_HAZARD 6 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_1] - RecoverAtomicAction.replayPhase2 recovering -3fc40791:a32:46c8d687:40 ActionStatus is ActionStatus.COMMITTED 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::phase2Commit() for action-id -3fc40791:a32:46c8d687:40 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::doForget (RecordList: -3fc40791:a32:46c8d687:47) 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::updateState() for action-id -3fc40791:a32:46c8d687:40 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::save_state () 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_17] - HeuristicList - packing a 171 record 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_18] - HeuristicList - packing a NONE_RECORD 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTING 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.write_committed(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.write_state(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:52:48,172 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.openAndLock(C:\jboss-4.2.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, FileLock.F_WRLCK, true) 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.closeAndUnlock(C:\jboss-4.2.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, null, java.io.FileOutputStream@bbb2d0) 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::updateState() for action-id -3fc40791:a32:46c8d687:40 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::save_state () 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_17] - HeuristicList - packing a 171 record 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_18] - HeuristicList - packing a NONE_RECORD 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTED 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.write_committed(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.write_state(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:52:48,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.openAndLock(C:\jboss-4.2.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, FileLock.F_WRLCK, true) 2007-08-19 16:52:48,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.closeAndUnlock(C:\jboss-4.2.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, null, java.io.FileOutputStream@d8a125) 2007-08-19 16:52:48,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_3] - RecoverAtomicAction.replayPhase2( -3fc40791:a32:46c8d687:40 ) finished 2007-08-19 16:52:48,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:52:48,203 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass 2007-08-19 16:52:48,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:52:48,203 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass 2007-08-19 16:52:48,203 DEBUG [com.arjuna.ats.jta.logging.logger] Local XARecoveryModule.transactionInitiatedRecovery completed 2007-08-19 16:52:48,203 DEBUG [com.arjuna.ats.jta.logging.logger] xarecovery of com.unisys.tip.TIPXAResource@3bbcfd 2007-08-19 16:52:48,500 DEBUG [com.arjuna.ats.jta.logging.logger] Found 1 xids in doubt 2007-08-19 16:52:48,500 DEBUG [com.arjuna.ats.jta.logging.logger] Local XARecoveryModule.resourceInitiatedRecovery completed 2007-08-19 16:52:48,500 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:54:22,158 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::check () 2007-08-19 16:54:22,158 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.coordinator.ReaperThread_1] - Thread Thread[Thread-9,5,jboss] sleeping for 120000 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - first pass <Sun, 19 Aug 2007 16:54:48> 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] InputObjectState::InputObjectState() 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule: first pass 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid : 0:0:0:0 InputObjectState Type : null InputObjectState Size : 0 InputObjectState Buffer: , 0) 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState() 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] found transaction -3fc40791:a32:46c8d687:40 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] InputObjectState::InputObjectState() 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.allTypes(InputObjectState Uid : 0:0:0:0 InputObjectState Type : null InputObjectState Size : 0 InputObjectState Buffer: ) 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState() 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] InputObjectState::InputObjectState() 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid : 0:0:0:0 InputObjectState Type : null InputObjectState Size : 0 InputObjectState Buffer: , 0) 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState() 2007-08-19 16:54:48,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:54:58,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - second pass <Sun, 19 Aug 2007 16:54:58> 2007-08-19 16:54:58,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AtomicActionRecoveryModule: Second pass 2007-08-19 16:54:58,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW) 2007-08-19 16:54:58,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:54:58,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED 2007-08-19 16:54:58,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] InputObjectState::InputObjectState() 2007-08-19 16:54:58,502 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.allObjUids(/Recovery/TransactionStatusManager, InputObjectState Uid : 0:0:0:0 InputObjectState Type : null InputObjectState Size : 0 InputObjectState Buffer: , 0) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState() 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.TransactionStatusConnectionManager_3] - found process uid -3fc40791:a73:46c8d72e:0 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] transaction type is /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid is -3fc40791:a32:46c8d687:40 ActionStatus is ActionStatus.COMMITTED in flight is false 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( -3fc40791:a32:46c8d687:40 ) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::BasicAction(-3fc40791:a32:46c8d687:40) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::activate() for action-id -3fc40791:a32:46c8d687:40 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.ShadowingStore( 14 ) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowNoFileLockStore.ShadowNoFileLockStore( 14 ) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.HashedStore( 14 ) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.HashedActionStore() 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.setupStore() 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.createHierarchy(C:\jboss-4.2.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.read_committed(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.read_state(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.openAndLock(C:\jboss-4.2.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, FileLock.F_RDLCK, false) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] InputObjectState::InputObjectState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.closeAndUnlock(C:\jboss-4.2.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, java.io.FileInputStream@10bbf6d, null) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::restore_state () 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_20] - Unpacked a 463 record 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_22] - HeuristicList - Unpacked heuristic list size of 1 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_23] - HeuristicList - Unpacked a 171 record 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 0:0:0:0 ) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.AbstractRecord_1] - AbstractRecord::AbstractRecord () - crash recovery constructor 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 0:0:0:0 ) 2007-08-19 16:54:58,517 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.AbstractRecord_1] - AbstractRecord::AbstractRecord () - crash recovery constructor 2007-08-19 16:54:58,533 WARN [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 30, 25, jrac--3fc40791:a32:46c8d687:40-3fc40791:a32:46c8d687:46 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3fc40791:a32:46c8d687:47 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_23] - HeuristicList - Unpacked a 463 record 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_25] - Restored action status of ActionStatus.COMMITTED 7 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_26] - Restored action type Top-level 0 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_27] - Restored heuristic decision of TwoPhaseOutcome.HEURISTIC_HAZARD 6 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_1] - RecoverAtomicAction.replayPhase2 recovering -3fc40791:a32:46c8d687:40 ActionStatus is ActionStatus.COMMITTED 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::phase2Commit() for action-id -3fc40791:a32:46c8d687:40 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::doForget (RecordList: -3fc40791:a32:46c8d687:47) 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::updateState() for action-id -3fc40791:a32:46c8d687:40 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::save_state () 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_17] - HeuristicList - packing a 171 record 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_18] - HeuristicList - packing a NONE_RECORD 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTING 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.write_committed(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.write_state(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.openAndLock(C:\jboss-4.2.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, FileLock.F_WRLCK, true) 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.closeAndUnlock(C:\jboss-4.2.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, null, java.io.FileOutputStream@938b4a) 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::updateState() for action-id -3fc40791:a32:46c8d687:40 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::save_state () 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_17] - HeuristicList - packing a 171 record 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_18] - HeuristicList - packing a NONE_RECORD 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTED 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.write_committed(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.write_state(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(-3fc40791:a32:46c8d687:40, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2007-08-19 16:54:58,564 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.openAndLock(C:\jboss-4.2.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, FileLock.F_WRLCK, true) 2007-08-19 16:54:58,580 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.closeAndUnlock(C:\jboss-4.2.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#199#\-3fc40791_a32_46c8d687_40, null, java.io.FileOutputStream@f72f09) 2007-08-19 16:54:58,580 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_3] - RecoverAtomicAction.replayPhase2( -3fc40791:a32:46c8d687:40 ) finished 2007-08-19 16:54:58,580 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:54:58,580 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass 2007-08-19 16:54:58,580 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:54:58,580 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass 2007-08-19 16:54:58,596 DEBUG [com.arjuna.ats.jta.logging.logger] Local XARecoveryModule.transactionInitiatedRecovery completed 2007-08-19 16:54:58,596 DEBUG [com.arjuna.ats.jta.logging.logger] xarecovery of com.unisys.tip.TIPXAResource@311410 2007-08-19 16:54:58,596 DEBUG [com.arjuna.ats.jta.logging.logger] Found 1 xids in doubt 2007-08-19 16:54:58,611 DEBUG [com.arjuna.ats.jta.logging.logger] Local XARecoveryModule.resourceInitiatedRecovery completed 2007-08-19 16:54:58,611 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] 2007-08-19 16:56:22,159 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::check () 2007-08-19 16:56:22,159 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.coordinator.ReaperThread_1] - Thread Thread[Thread-9,5,jboss] sleeping for 120000 2007-08-19 16:56:48,925 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action -3fc40791:a32:46c8d687:40 removing TSThread:1 2007-08-19 16:56:48,925 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action -3fc40791:a32:46c8d687:40 removing TSThread:1 result = false 2007-08-19 16:56:48,925 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::finalize() 2007-08-19 16:56:48,925 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action -3fc40791:a32:46c8d687:40 removing TSThread:1 2007-08-19 16:56:48,925 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action -3fc40791:a32:46c8d687:40 removing TSThread:1 result = false 2007-08-19 16:56:48,925 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::finalize() 2007-08-19 16:56:48,925 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action -3fc40791:a32:46c8d687:40 removing TSThread:1 2007-08-19 16:56:48,925 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action -3fc40791:a32:46c8d687:40 removing TSThread:1 result = false 2007-08-19 16:56:48,925 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::finalize()
Thank you for your help.