9 Replies Latest reply on Aug 22, 2007 3:42 AM by traffic

    Recovering Prepared transaction branch

    traffic

      Conducting 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.

        • 1. Re: Recovering Prepared transaction branch
          jhalliday

          Be patient and allow the recovery process to iterate over steps 8 and 9 a few times. It's very conservative and takes a while to convince itself the resource really needs recovery, but it should eventually do so.

          • 2. Re: Recovering Prepared transaction branch
            marklittle

             

            2007-08-19 16:54:58,533 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.c
            oordinator.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.c
            oordinator.BasicAction_27] - Restored heuristic decision of TwoPhaseOutcome.HEURISTIC_HAZARD 6
            


            For some reason it appears that you have a heuristic outcome. In that case there can be no automatic recovery. It's not possible to see if this has happened during recovery or in the original failure situation. If you have a stand-alone test case that you can send me then I can take a closer look.

            • 3. Re: Recovering Prepared transaction branch
              traffic

              I backed off from terminating JBoss during the XAResource.prepare call, and terminated JBoss during the call of XAResource.end for the second resource (RM-2). This was done to try to eliminate any possibility of a heuristic outcome. Besides, if the TM recognizes a xid returned during recovery, it should make some kind of recovery decision (rollback or commit) on the xid, but let?s move on for now...

              The test now executes as follows:

              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. At this point, JBoss is intentionally terminated to force a recovery situation. The termination happens before the XAResource.end call returns to the TM. The transaction branch associated with RM-2 is rolled back in the EIS environment due to the JBoss termination.

              4) JBoss is re-initiated.

              5) Our XAResourceRecovery implementation returns the required XAResource

              6) TM calls XAResource.recover, which returns all outstanding xids

              7) JBoss transactions continuously repeat steps 5 and 6

              I let the recovery process continue for a couple of hours - the outstanding transaction was never recovered.

              I used the Test.java transaction program from the JBossTS Recovery wiki to verify this behavior. I turned the program into an EJB application since I wasn't able to get the recovery manager and the program to sync up (user error). The EJB has the following business method:

               public String method() throws EJBException {
               try {
               UserTransaction ut = com.arjuna.ats.jta.UserTransaction.userTransaction();
              
               ut.begin();
              
               Transaction txImple = TransactionManager.transactionManager().getTransaction();
              
               txImple.enlistResource(new ExampleXAResource());
               txImple.enlistResource(new ExampleXAResource());
              
               ut.commit();
               } catch (Exception e) {
               throw new EJBException(e);
               }
              
               return "Done!";
               }
              




              The end and prepare methods of ExampleXAResource.java were updated as follows:

               public void end(Xid xid, int flags) throws XAException
               {
               System.out.println("Waiting end...");
               mySleep(_sleepTime * 3);
               System.out.println("End Continuing...");
              
               myLog("end");
               _currentXid = null;
               }
              
               public int prepare(Xid xid) throws XAException
               {
               System.out.println("Waiting prepare...");
               mySleep(_sleepTime * 3);
               System.out.println("Prepare continuing...");
              
               myLog("prepare");
               int i = 2;
               if (i == 1)
               {
               throw(new XAException(XAException.XA_RBROLLBACK));
               }
              
               return XA_OK;
               }
              


              When running this application, I observed that a log entry isn't written to the object store (tx-store-object?TwoPhaseCoordinator/AtomicAction) until all resources have been prepared. If JBoss dies before the second resource (or presumably the last resource ? I never tried more than 2 resources) has been prepared, then it appears that the remaining outstanding transaction branches aren't recovered - the last resource wouldn't have a Prepared log record. This is merely an observation on my part, I'm not sure if a corresponding log entry exists under the TransactionStatusManager directory.

              Additionally, I'm not sure if this behavior manifests itself when the application is executed as design or if I'm simply doing something wrong, which is a huge possibility. I can send you my application if you like, or perhaps it may be easier to update ExampleXAResource.java and try running Test.java as a standalone application.

              I'm running JBoss 4.2.0 and JBoss 4.0.3.

              Thanks for your help


              • 4. Re: Recovering Prepared transaction branch
                jhalliday

                It's correct that the log is not written until a commit decision is reached. In all other cases the transaction is presumed abort. In the case above the transaction recovers bottom up (i.e. resource driven), not top down (coordinator driven). It looks like there is a problem with the recovery module for the resource in question. If you send me the test app you are using for 4.2 I'll take a look when I have time. Please include your jbossjta-properties.xml file too.

                • 5. Re: Recovering Prepared transaction branch
                  marklittle

                   

                  "traffic" wrote:
                  When running this application, I observed that a log entry isn't written to the object store (tx-store-object?TwoPhaseCoordinator/AtomicAction) until all resources have been prepared.


                  Yes, that's because we implement presumed abort. You only log when you know the outcome of the transaction, i.e., after all prepares have returned successfully. If you want to log after each prepare, then you are not doing presumed abort.


                  If JBoss dies before the second resource (or presumably the last resource ? I never tried more than 2 resources) has been prepared, then it appears that the remaining outstanding transaction branches aren't recovered - the last resource wouldn't have a Prepared log record. This is merely an observation on my part, I'm not sure if a corresponding log entry exists under the TransactionStatusManager directory.


                  Again, it's presumed abort. Completely valid. The prepared participants (or recovery acting on their behalf) should attempt to contact the coordinator after some timeout and find out what happened. The lack of a log means that the transaction rolled back. In that case, the participants should roll back as well.


                  Additionally, I'm not sure if this behavior manifests itself when the application is executed as design or if I'm simply doing something wrong, which is a huge possibility. I can send you my application if you like, or perhaps it may be easier to update ExampleXAResource.java and try running Test.java as a standalone application.


                  No need, unless you are saying that participant driven recovery isn't working?

                  • 6. Re: Recovering Prepared transaction branch
                    marklittle

                    BTW, do you generate your own Xids? If not, do you tell the recovery manager which types of Xids it can attempt to recover? If you are at all unsure about either of these questions, please check out the Failure Recovery guide and pay particular attention to the Node Name aspect of Xids and recovery. You may be running into the fact that JBossTS will only attempt recovery on Xids that it knows about, in case it inadvertently rolls back Xids from some other JBossTS or transaction service instance.

                    • 7. Re: Recovering Prepared transaction branch
                      traffic

                       


                      It's correct that the log is not written until a commit decision is reached. In all other cases the transaction is presumed abort. In the case above the transaction recovers bottom up (i.e. resource driven), not top down (coordinator driven). It looks like there is a problem with the recovery module for the resource in question. If you send me the test app you are using for 4.2 I'll take a look when I have time. Please include your jbossjta-properties.xml file too.


                      I see; I became a little shortsighted during my testing. I've become so accustomed to testing transaction managers that could recover from this scenario that it just didn't occur to me that JBossTS wouldn't, which is document.

                      Thanks for the clarification.


                      BTW, do you generate your own Xids? If not, do you tell the recovery manager which types of Xids it can attempt to recover? If you are at all unsure about either of these questions, please check out the Failure Recovery guide and pay particular attention to the Node Name aspect of Xids and recovery. You may be running into the fact that JBossTS will only attempt recovery on Xids that it knows about, in case it inadvertently rolls back Xids from some other JBossTS or transaction service instance.


                      No, we don't generate our own Xids, and we have set up the JBossTS properties file to inform the recovery manager about which types of Xids to recover (which in my test case there weren't any). Like I said in my original post, all outstanding transaction branches were recovered if all RMs involved in the transaction successfully completed the prepare phase. I got off track (and wasted a lot of your time) in thinking a Prepare record should have been logged immediately after the XAResource.prepare call for an individual RM (which is not the presumed-abort pattern) - this is not the case with JBossTS.

                      Again, thanks for the clarification and your time.


                      • 8. Re: Recovering Prepared transaction branch
                        marklittle

                         

                        "traffic" wrote:

                        It's correct that the log is not written until a commit decision is reached. In all other cases the transaction is presumed abort. In the case above the transaction recovers bottom up (i.e. resource driven), not top down (coordinator driven). It looks like there is a problem with the recovery module for the resource in question. If you send me the test app you are using for 4.2 I'll take a look when I have time. Please include your jbossjta-properties.xml file too.


                        I see; I became a little shortsighted during my testing. I've become so accustomed to testing transaction managers that could recover from this scenario that it just didn't occur to me that JBossTS wouldn't, which is document.


                        It's not that it can't, it's just that by default it doesn't. If you want presumed commit or presumed nothing capabilities then they can be supported. However, if you are saying that you're using a TM that does presumed abort and it logs after each prepare, then I'd complain about *that* implementation, because it's not giving you the benefits of presumed abort at all. It's not actually implementing presumed abort!


                        Thanks for the clarification.


                        BTW, do you generate your own Xids? If not, do you tell the recovery manager which types of Xids it can attempt to recover? If you are at all unsure about either of these questions, please check out the Failure Recovery guide and pay particular attention to the Node Name aspect of Xids and recovery. You may be running into the fact that JBossTS will only attempt recovery on Xids that it knows about, in case it inadvertently rolls back Xids from some other JBossTS or transaction service instance.


                        No, we don't generate our own Xids, and we have set up the JBossTS properties file to inform the recovery manager about which types of Xids to recover (which in my test case there weren't any). Like I said in my original post, all outstanding transaction branches were recovered if all RMs involved in the transaction successfully completed the prepare phase. I got off track (and wasted a lot of your time) in thinking a Prepare record should have been logged immediately after the XAResource.prepare call for an individual RM (which is not the presumed-abort pattern) - this is not the case with JBossTS.

                        Again, thanks for the clarification and your time.


                        No problem. But in which case your original issue still remains. If you have a test case that you can send me then I'll take a look.

                        • 9. Re: Recovering Prepared transaction branch
                          traffic

                           


                          It's not that it can't, it's just that by default it doesn't. If you want presumed commit or presumed nothing capabilities then they can be supported. However, if you are saying that you're using a TM that does presumed abort and it logs after each prepare, then I'd complain about *that* implementation, because it's not giving you the benefits of presumed abort at all. It's not actually implementing presumed abort!


                          I'm not making any assumptions (well, trying not to) about any vendor's implementation (why and how it works - that's not my place); I'm only testing and making observations - hopefully accurately.


                          No problem. But in which case your original issue still remains. If you have a test case that you can send me then I'll take a look.


                          It looks like I'm done with this issue - at least for now...

                          Thanks.