Transactional MDB on JBoss 5: look inside

10:36:49,975 (Connection consumer 120) BaseTransaction.begin
10:36:49,975 (Connection consumer 120) StateManager::StateManager( 2 )
10:36:49,971 (Connection consumer 115) [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action -3f57c7ff:eafe:542a6b9a:a2 adding Thread[Connection consumer 115,5,JBoss Pooled Threads] result = true
10:36:49,975 (Connection consumer 120) BasicAction::BasicAction()
10:36:49,976 (Connection consumer 120) BasicAction::Begin() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:49,976 (Connection consumer 120) BasicAction::actionInitialise() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:49,976 (Connection consumer 120) ActionHierarchy::ActionHierarchy(5)
10:36:49,976 (Connection consumer 120) ActionHierarchy::add(-3f57c7ff:eafe:542a6b9a:ab, 1)
10:36:49,976 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action -3f57c7ff:eafe:542a6b9a:ab adding Thread[Connection consumer 120,5,JBoss Pooled Threads]
10:36:49,976 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action -3f57c7ff:eafe:542a6b9a:ab adding Thread[Connection consumer 120,5,JBoss Pooled Threads] result = true
10:36:49,979 (Connection consumer 120) TransactionReaper::create ( 120000 )
10:36:49,979 (Connection consumer 120) TransactionReaper::insert ( BasicAction: -3f57c7ff:eafe:542a6b9a:ab status: ActionStatus.RUNNING, 300 )
10:36:49,979 (Connection consumer 120) ReaperElement::ReaperElement ( BasicAction: -3f57c7ff:eafe:542a6b9a:ab status: ActionStatus.RUNNING, 300 )
10:36:49,979 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue started transaction=TransactionImple < ac, BasicAction: -3f57c7ff:eafe:542a6b9a:ab status: ActionStatus.RUNNING >
10:36:49,979 (Connection consumer 120) TransactionImple.enlistResource ( com.tibco.tibjms.XResource@4f9ee648 )
10:36:49,979 (Connection consumer 120) TransactionImple.getStatus
10:36:49,980 (Connection consumer 115) TransactionReaper::create ( 120000 )
10:36:49,980 (Connection consumer 120) StateManager::StateManager( 1 )
10:36:49,980 (Connection consumer 120) AbstractRecord::AbstractRecord (-3f57c7ff:eafe:542a6b9a:ad, 1)
10:36:49,971 (Thread-15) ReaperThread.run ()
10:36:49,980 (Connection consumer 120) XAResourceRecord.XAResourceRecord ( < 131075, 28, 26, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797589799 > )
10:36:49,980 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:ad
10:36:49,980 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue enlisted=com.tibco.tibjms.XResource@4f9ee648
10:36:49,980 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue in use by public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message) Thread[Connection consumer 120,5,JBoss Pooled Threads]
10:36:49,980 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue delivering
10:36:51,262 [org.jboss.ejb3.pool.StrictMaxPool] (Connection consumer 120) Acquired(true) strictMaxSize semaphore, remaining=0

10:36:51,262 INFO  [STDOUT] (Connection consumer 120) Received text: 2014-09-30T10:35:10.304+02:00 on test.fw1, id=ID:EMS-SERVER-DC2.2354542947B3299:101

10:36:52,330 (Connection consumer 120) TransactionImple.registerSynchronization
10:36:52,331 (Connection consumer 120) TransactionImple.enlistResource ( org.jboss.resource.adapter.jdbc.xa.XAManagedConnection@5c675382 )
10:36:52,331 (Connection consumer 120) TransactionImple.getStatus
10:36:52,331 (Connection consumer 120) AbstractRecord::AbstractRecord (-3f57c7ff:eafe:542a6b9a:1d1, 1)
10:36:52,331 (Connection consumer 120) XAResourceRecord.XAResourceRecord ( < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910048 > )
10:36:52,333 (Connection consumer 120) TransactionImple.enlistResource ( org.jboss.resource.adapter.jms.JmsXAResource@21f7e1c6 )
10:36:52,333 (Connection consumer 120) TransactionImple.getStatus
10:36:52,333 (Connection consumer 120) StateManager::StateManager( 1 )
10:36:52,333 (Connection consumer 120) AbstractRecord::AbstractRecord (-3f57c7ff:eafe:542a6b9a:1d7, 1)
10:36:52,333 (Connection consumer 120) XAResourceRecord.XAResourceRecord ( < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910054 > )
10:36:52,360 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:eafe:542a6b9a:ad -3f57c7ff:eafe:542a6b9a:1d1) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:1d7
10:36:52,361 (Connection consumer 120) TransactionImple.getStatus
10:36:52,361 (Connection consumer 120) TransactionImple.getStatus
10:36:52,392 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) Invocation took 2412ms: public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message)
10:36:52,392 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue in use by public abstract void javax.resource.spi.endpoint.MessageEndpoint.afterDelivery() throws javax.resource.ResourceException Thread[Connection consumer 120,5,JBoss Pooled Threads]
10:36:52,392 (Connection consumer 120) TransactionImple.equals
10:36:52,392 (Connection consumer 120) TransactionImple.getStatus
10:36:52,392 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue commit
10:36:52,392 (Connection consumer 120) BaseTransaction.commit
10:36:52,392 (Connection consumer 120) TransactionImple.commitAndDisassociate
10:36:52,392 (Connection consumer 120) SynchronizationImple.beforeCompletion

10:36:52,392 (Connection consumer 120) BasicAction::End() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,392 (Connection consumer 120) BasicAction::prepare () for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,392 (Connection consumer 120) ShadowingStore.ShadowingStore( 14 )
10:36:52,392 (Connection consumer 120) ShadowNoFileLockStore.ShadowNoFileLockStore( 14 )
10:36:52,392 (Connection consumer 120) HashedStore.HashedStore( 14 )
10:36:52,392 (Connection consumer 120) HashedStore.HashedActionStore()
10:36:52,392 (Connection consumer 120) FileSystemStore.setupStore()
10:36:52,392 (Connection consumer 120) FileSystemStore.createHierarchy(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\)
10:36:52,393 (Connection consumer 120) XAResourceRecord.topLevelPrepare for < 131075, 28, 26, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797589799 >
10:36:52,430 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:ad
10:36:52,430 (Connection consumer 120) XAResourceRecord.topLevelPrepare for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910048 >
10:36:52,494 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:eafe:542a6b9a:ad) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:1d1
10:36:52,494 (Connection consumer 120) XAResourceRecord.topLevelPrepare for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910054 >
10:36:52,556 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:eafe:542a6b9a:ad -3f57c7ff:eafe:542a6b9a:1d1) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:1d7
10:36:52,557 (Connection consumer 120) OutputObjectState::OutputObjectState(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:36:52,557 (Connection consumer 120) BasicAction::save_state ()
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_14] - BasicAction::save_state - next record to pack is a 171 record (/StateManager/AbstractRecord/XAResourceRecord) should save it? = true
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_14] - BasicAction::save_state - next record to pack is a 171 record (/StateManager/AbstractRecord/XAResourceRecord) should save it? = true
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_14] - BasicAction::save_state - next record to pack is a 171 record (/StateManager/AbstractRecord/XAResourceRecord) should save it? = true
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTING
10:36:52,557 (Connection consumer 120) FileSystemStore.write_committed(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:36:52,557 (Connection consumer 120) ShadowingStore.write_state(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,557 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,557 (Connection consumer 120) FileSystemStore.openAndLock(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, FileLock.F_WRLCK, true)
10:36:52,557 (Connection consumer 120) FileSystemStore.createHierarchy(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab)
10:36:52,647 (Connection consumer 120) FileSystemStore.closeAndUnlock(C:\_dev\jboss-5.1.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, null, java.io.FileOutputStream@7e1b811b)
10:36:52,651 (Connection consumer 120) BasicAction::phase2Commit() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,651 (Connection consumer 120) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@4407393d)
10:36:52,651 (Connection consumer 120) XAResourceRecord.topLevelCommit for < 131075, 28, 26, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797589799 >
10:36:52,734 (Connection consumer 120) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@32955ada)
10:36:52,734 (Connection consumer 120) XAResourceRecord.topLevelCommit for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910048 >
10:36:52,911 (Connection consumer 120) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@1cc05dc2)
10:36:52,911 (Connection consumer 120) XAResourceRecord.topLevelCommit for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910054 >
10:36:52,947 (Connection consumer 120) BasicAction::updateState() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,947 (Connection consumer 120) FileSystemStore.remove_committed(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:36:52,947 (Connection consumer 120) ShadowingStore.remove_state(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,947 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
10:36:52,947 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,947 (Connection consumer 120) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
10:36:52,947 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,947 (Connection consumer 120) FileSystemStore.openAndLock(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, FileLock.F_WRLCK, false)
10:36:52,948 (Connection consumer 120) FileSystemStore.closeAndUnlock(C:\_dev\jboss-5.1.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, null, null)
10:36:52,948 (Connection consumer 120) SynchronizationImple.afterCompletion
10:36:52,948 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action -3f57c7ff:eafe:542a6b9a:ab removing TSThread:17
10:36:52,948 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_9] -  BasicAction::removeChildThread () action -3f57c7ff:eafe:542a6b9a:ab removing TSThread:17 result = true