-
1. Re: XTS/bridge: two diff. TXs on same thread?
You are not looking at the right information here. Firstly, the two classes you have pointed to are transaction manager implementations, not transactions. So, this is not really the place to look to reason about questions of transaction identity.
The first class is the one the app server uses to create and manage transactions. That is why it is in the com.arjuna.ats package hierarchy. The second one is one of several transaction manager implementations in the JBossTS code base, each of which supports its own flavour of transaction implemented by an underlying xxx.YyyTransactionImple class.
The second TM class is actually used by the ats class under the hood i.e. the ats class is a wrapper which makes the implementation available to the app server (the clue is in the name -- it delegates to another TM provided during bootstrap). The TxBridge code cuts out the middle man and goes direct to the implementation class since it does not need to be generic nor does it have to be shielded from implementation details.
However, there is a deeper misunderstanding here which needs explaining. Even if you were to look at the transaction instances either side of the bridge you would not necessarily find that they had the same class and they definitely will not be the same instance. The bridge code creates a new TXImple instance which it uses to implement a distributed transaction (distributed in the sense that it is made up of several TX instances, even if they are on the same host). The bridge makes the new TXImple instance part of the original TX by propagating prepare and commit calls and participant registration calls through the bridge i.e. it ties the two transaction instances together into a single transaction. -
2. Re: XTS/bridge: two diff. TXs on same thread?
Thanks for the quick response!
"adinn" wrote:
You are not looking at the right information here. Firstly, the two classes you have pointed to are transaction manager implementations, not transactions. So, this is not really the place to look to reason about questions of transaction identity.
Right, I realized after I posted that that was confusing. I realized I was pointing out what appeared to be the existence of, ostensibly, two TxM's, but my subject was talking about two different transactions. That said, you explained it more clearly than I could have!"adinn" wrote:
The first class is the one the app server uses to create and manage transactions. That is why it is in the com.arjuna.ats package hierarchy. The second one is one of several transaction manager implementations in the JBossTS code base, each of which supports its own flavour of transaction implemented by an underlying xxx.YyyTransactionImple class.
The second TM class is actually used by the ats class under the hood i.e. the ats class is a wrapper which makes the implementation available to the app server (the clue is in the name -- it delegates to another TM provided during bootstrap). The TxBridge code cuts out the middle man and goes direct to the implementation class since it does not need to be generic nor does it have to be shielded from implementation details.
Got it, OK. So, in all likelihood, they're both talking to the same TxM. That said, from what I'm seeing, it doesn't appear that the TxM is managing both transaction instances together. The bridge is receiving the CoordinationContext in the SOAP header and appears to be using the id provided to start a bridged transaction. That appears to be managed correctly by the originating Coordinator (so the basic XTS pieces appear to be communicating) - I can see this via TRACE logging on org.jboss.txbridge.
That said, in our user code, when the web service method being invoked completes (and passes back through the Spring transaction advice), it looks like *that* transaction is committed right then and there."adinn" wrote:
However, there is a deeper misunderstanding here which needs explaining. Even if you were to look at the transaction instances either side of the bridge you would not necessarily find that they had the same class and they definitely will not be the same instance. The bridge code creates a new TXImple instance which it uses to implement a distributed transaction (distributed in the sense that it is made up of several TX instances, even if they are on the same host). The bridge makes the new TXImple instance part of the original TX by propagating prepare and commit calls and participant registration calls through the bridge i.e. it ties the two transaction instances together into a single transaction.
My understanding was that the bridge would setup a TXImple (is this the BridgeParticipantAT?) and that this would be the transaction "on the thread" that further requests to the JTA TxM on that thread would enlist in. It seems like the BridgeParticipantAT is being setup, but requests to the JTA TxM on the same thread (in the same request) are going to a new TXImple, they aren't enlisting in the Tx that is managed by the bridge and driven by the Coordinator.
It has been a few months (Oct. '07) since Paul R. walked us through the details and helped us get the bridge code running, so I'm trying to dust off the cob webs and get this code integrated with our "real" project code, ported over from our POC project(s). I truly appreciate your quick response and help! -
3. Re: XTS/bridge: two diff. TXs on same thread?
Wow, I used "that said ..." way too much in that post. :-)
-
4. Re: XTS/bridge: two diff. TXs on same thread?
Turn on debug logging for the transaction manager, it will show if the transactions used by the bridge is being suspended in favour of something else. That may happen if @Transactional is using e.g. REQUIRES_NEW rather than REQUIRED.
-
5. Re: XTS/bridge: two diff. TXs on same thread?
Any hint as to which package I should enable logging on and at what level? I hesitate to just set org.jboss or com.arjuna to TRACE, as that'll be like looking for a needle in a haystack!
-
6. Re: XTS/bridge: two diff. TXs on same thread?
Just set the relevant entries in the jbossjta.properties file to enable TX debug trace. In theory trace can be generated selectively but in practice it is not easy to configure.
-
7. Re: XTS/bridge: two diff. TXs on same thread?
"adinn" wrote:
Just set the relevant entries in the jbossjta.properties file to enable TX debug trace. In theory trace can be generated selectively but in practice it is not easy to configure.
That would be setting the DebugLevel in conf/jbossjta-properties.xml to0xffffffff
right?
The http://www.jboss.org/jbosstm/docs/4.2.3/manuals/html/core/AdministrationGuide.html section that talks about the DebugLevels doesn't actually seem to provide the hex values specified in the DebugLevel class (but looking at the source will probably work!). Thanks, Andrew -
8. Re: XTS/bridge: two diff. TXs on same thread?
I don't think I'm getting any additional log output, here's the relevant entries from conf/jbossjta-properties.xml:
<properties name="common"> <!-- CLF 2.0 properties --> <property name="com.arjuna.common.util.logging.DebugLevel" type="System" value="0xffffffff"/> <property name="com.arjuna.common.util.logging.FacilityLevel" type="System" value="0xffffffff"/> <property name="com.arjuna.common.util.logging.VisibilityLevel" type="System" value="0xffffffff"/> <property name="com.arjuna.common.util.logger" type="System" value="log4j"/> </properties>
Maybe I need to go into JBoss' log4j.xml and see if its throttling certain levels back ... -
9. Re: XTS/bridge: two diff. TXs on same thread?
The hex values are in the docs, just not in the expected place. But using anything other than 0xffffffff requires not only knowing the hex values, but also knowing what information you want to see vs. what you do not. That's the really tricky bit :-) You'll need com.arjuna at DEBUG in log4j too. A log statement has to pass both hurdles before seeing the light of day...
-
10. Re: XTS/bridge: two diff. TXs on same thread?
My bad, not going to the console because of jboss-log4j.xml settings, going out to server.log (file) instead.
-
11. Re: XTS/bridge: two diff. TXs on same thread?
"jhalliday" wrote:
The hex values are in the docs, just not in the expected place. But using anything other than 0xffffffff requires not only knowing the hex values, but also knowing what information you want to see vs. what you do not. That's the really tricky bit :-) You'll need com.arjuna at DEBUG in log4j too. A log statement has to pass both hurdles before seeing the light of day...
OK, I *think* the logging information below is what you're looking for. Thanks, Jonathan.2008-05-28 10:56:25,121 INFO [STDOUT] 10:56:25,121 DEBUG [ewsng/HandlerPipeline] Invoking handler org.jboss.txbridge.contrib.xfire.service.InBridgeHandler in phase user 2008-05-28 10:56:26,793 INFO [STDOUT] 10:56:26,793 TRACE [ewsng/JaxWSTransactionBridgeHandler] handleInbound() 2008-05-28 10:56:26,871 INFO [STDOUT] 10:56:26,871 TRACE [ewsng/TxBridgeManager] getInboundBridge() 2008-05-28 10:56:26,871 INFO [STDOUT] 10:56:26,871 TRACE [ewsng/TxBridgeManager] createMappings(externalIxId=AtomicTransactionIdentifier: urn:a413888:d13:483c5ce9:17c) 2008-05-28 10:56:27,231 INFO [STDOUT] 10:56:27,231 TRACE [ewsng/InboundBridge] InboundBridge(Xid=< 131075, 45, 64, a413888:d00:483d80aa:1-a413888:d00:483d80aa:0>) 2008-05-28 10:56:27,465 INFO [STDOUT] 10:56:27,465 TRACE [ewsng/BridgeParticipantAT] BridgeParticipantAT(XATerminatorImple=com.arjuna.ats.internal.jta.transaction.arjunacore.jca.XATerminatorImple@145dbcd, Xid=< 131075, 45, 64, a413888:d00:483d80aa:1-a413888:d00:483d80aa:0>) 2008-05-28 10:56:27,684 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus 2008-05-28 10:56:27,684 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.suspend 2008-05-28 10:56:29,918 INFO [STDOUT] 10:56:29,918 TRACE [ewsng/InboundBridge] start(Xid=< 131075, 45, 64, a413888:d00:483d80aa:1-a413888:d00:483d80aa:0>) 2008-05-28 10:56:29,949 INFO [STDOUT] 10:56:29,949 DEBUG [ewsng/HandlerPipeline] Invoking phase pre-invoke 2008-05-28 10:56:29,949 INFO [STDOUT] 10:56:29,949 DEBUG [ewsng/HandlerPipeline] Invoking handler org.codehaus.xfire.soap.handler.ValidateHeadersHandler in phase pre-invoke 2008-05-28 10:56:29,965 INFO [STDOUT] 10:56:29,965 DEBUG [ewsng/HandlerPipeline] Invoking phase service 2008-05-28 10:56:29,965 INFO [STDOUT] 10:56:29,965 DEBUG [ewsng/HandlerPipeline] Invoking handler org.codehaus.xfire.service.binding.ServiceInvocationHandler in phase service 2008-05-28 10:56:30,027 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus 2008-05-28 10:56:30,027 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.begin 2008-05-28 10:56:30,027 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 2 ) 2008-05-28 10:56:30,027 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::BasicAction() 2008-05-28 10:56:30,027 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::Begin() for action-id a413888:c0b:483d7e2b:1b 2008-05-28 10:56:30,027 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::actionInitialise() for action-id a413888:c0b:483d7e2b:1b 2008-05-28 10:56:30,043 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ActionHierarchy::ActionHierarchy(5) 2008-05-28 10:56:30,043 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ActionHierarchy::add(a413888:c0b:483d7e2b:1b, 1) 2008-05-28 10:56:30,043 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action a413888:c0b:483d7e2b:1b adding Thread[http-127.0.0.3-8080-1,5,jboss] 2008-05-28 10:56:30,043 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action a413888:c0b:483d7e2b:1b adding Thread[http-127.0.0.3-8080-1,5,jboss] result = true 2008-05-28 10:56:30,043 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::create ( 120000 ) 2008-05-28 10:56:30,043 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::insert ( BasicAction: a413888:c0b:483d7e2b:1b status: ActionStatus.RUNNING, 300 ) 2008-05-28 10:56:30,043 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement::ReaperElement ( BasicAction: a413888:c0b:483d7e2b:1b status: ActionStatus.RUNNING, 300 ) 2008-05-28 10:56:32,371 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( com.arjuna.xaResources.XAResourceLogger@4425a7 ) 2008-05-28 10:56:32,371 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,402 INFO [STDOUT] XA http-127.0.0.3-8080-1 [dummy1] [setTransactionTimeout] timeoutSet=true 2008-05-28 10:56:32,402 INFO [STDOUT] XA http-127.0.0.3-8080-1 [dummy1] [start] 2008-05-28 10:56:32,402 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 1 ) 2008-05-28 10:56:32,402 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (a413888:c0b:483d7e2b:1d, 1) 2008-05-28 10:56:32,402 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.XAResourceRecord ( < 131075, 25, 23, 1-a413888:c0b:483d7e2b:1ba413888:c0b:483d7e2b:1c> ) 2008-05-28 10:56:32,418 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for a413888:c0b:483d7e2b:1d 2008-05-28 10:56:32,684 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,684 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,684 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] internalRegisterPool: registering pool with interval 900000 old interval: 450000 2008-05-28 10:56:32,684 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,699 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization 2008-05-28 10:56:32,699 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,840 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,840 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,840 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus 2008-05-28 10:56:32,840 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,840 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,840 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,840 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization 2008-05-28 10:56:32,840 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,840 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@1a58470 ) 2008-05-28 10:56:32,840 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:32,840 INFO [STDOUT] XA http-127.0.0.3-8080-1 [dummy1] [isSameRM] returning false 2008-05-28 10:56:32,856 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 1 ) 2008-05-28 10:56:32,856 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (a413888:c0b:483d7e2b:22, 1) 2008-05-28 10:56:32,856 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.XAResourceRecord ( < 131075, 25, 23, 1-a413888:c0b:483d7e2b:1ba413888:c0b:483d7e2b:21> ) 2008-05-28 10:56:32,856 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: a413888:c0b:483d7e2b:1d) : appending /StateManager/AbstractRecord/XAResourceRecord for a413888:c0b:483d7e2b:22 2008-05-28 10:56:32,887 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus 2008-05-28 10:56:32,887 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.commit 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.commitAndDisassociate 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::End() for action-id a413888:c0b:483d7e2b:1b 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::prepare () for action-id a413888:c0b:483d7e2b:1b 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.ShadowingStore( 14 ) 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowNoFileLockStore.ShadowNoFileLockStore( 14 ) 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.HashedStore( 14 ) 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.HashedActionStore() 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.setupStore() 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.createHierarchy(XTSObjectStore\HashedActionStore\defaultStore\) 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelPrepare for < 131075, 25, 23, 1-a413888:c0b:483d7e2b:1ba413888:c0b:483d7e2b:1c> 2008-05-28 10:56:33,324 INFO [STDOUT] XA http-127.0.0.3-8080-1 [dummy1] [end] 2008-05-28 10:56:33,324 INFO [STDOUT] XA http-127.0.0.3-8080-1 [dummy1] [prepare] 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for a413888:c0b:483d7e2b:1d 2008-05-28 10:56:33,324 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelPrepare for < 131075, 25, 23, 1-a413888:c0b:483d7e2b:1ba413888:c0b:483d7e2b:21> 2008-05-28 10:56:33,543 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for a413888:c0b:483d7e2b:22 2008-05-28 10:56:33,543 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] OutputObjectState::OutputObjectState(a413888:c0b:483d7e2b:1b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2008-05-28 10:56:33,543 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::save_state () 2008-05-28 10:56:33,543 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [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 2008-05-28 10:56:33,543 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record 2008-05-28 10:56:33,559 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD 2008-05-28 10:56:33,559 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTING 2008-05-28 10:56:33,559 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.write_committed(a413888:c0b:483d7e2b:1b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2008-05-28 10:56:33,559 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.write_state(a413888:c0b:483d7e2b:1b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2008-05-28 10:56:33,559 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(a413888:c0b:483d7e2b:1b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2008-05-28 10:56:33,559 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.openAndLock(XTSObjectStore\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#188#\a413888_c0b_483d7e2b_1b, FileLock.F_WRLCK, true) 2008-05-28 10:56:33,559 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.createHierarchy(XTSObjectStore\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#188#\a413888_c0b_483d7e2b_1b) 2008-05-28 10:56:33,574 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.closeAndUnlock(XTSObjectStore\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#188#\a413888_c0b_483d7e2b_1b, null, java.io.FileOutputStream@1959415) 2008-05-28 10:56:33,574 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::phase2Commit() for action-id a413888:c0b:483d7e2b:1b 2008-05-28 10:56:33,574 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@12d0e49) 2008-05-28 10:56:33,574 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelCommit for < 131075, 25, 23, 1-a413888:c0b:483d7e2b:1ba413888:c0b:483d7e2b:1c> 2008-05-28 10:56:33,574 INFO [STDOUT] XA http-127.0.0.3-8080-1 [dummy1] [commit] onePhase=false 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::updateState() for action-id a413888:c0b:483d7e2b:1b 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.remove_committed(a413888:c0b:483d7e2b:1b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.remove_state(a413888:c0b:483d7e2b:1b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(a413888:c0b:483d7e2b:1b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW) 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(a413888:c0b:483d7e2b:1b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(a413888:c0b:483d7e2b:1b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(a413888:c0b:483d7e2b:1b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL) 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.openAndLock(XTSObjectStore\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#188#\a413888_c0b_483d7e2b_1b, FileLock.F_WRLCK, false) 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.closeAndUnlock(XTSObjectStore\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#188#\a413888_c0b_483d7e2b_1b, null, null) 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action a413888:c0b:483d7e2b:1b removing TSThread:2 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action a413888:c0b:483d7e2b:1b removing TSThread:2 result = true 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::create ( 120000 ) 2008-05-28 10:56:33,590 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::remove ( BasicAction: a413888:c0b:483d7e2b:1b status: ActionStatus.COMMITTED ) 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 DEBUG [ewsng/HandlerPipeline] Invoking handler org.codehaus.xfire.service.binding.PostInvocationHandler in phase service 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 DEBUG [ewsng/HandlerPipeline] Invoking phase post-invoke 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 DEBUG [ewsng/HandlerPipeline] Invoking handler org.codehaus.xfire.soap.handler.SoapSerializerHandler in phase post-invoke 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 DEBUG [ewsng/HandlerPipeline] Invoking phase policy 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 DEBUG [ewsng/HandlerPipeline] Invoking phase user 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 DEBUG [ewsng/HandlerPipeline] Invoking handler org.jboss.txbridge.contrib.xfire.service.OutBridgeHandler in phase user 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 TRACE [ewsng/JaxWSTransactionBridgeHandler] handleOutbound() 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 TRACE [ewsng/JaxWSTransactionBridgeHandler] suspendTransaction() 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 TRACE [ewsng/TxBridgeManager] getInboundBridge() 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 TRACE [ewsng/InboundBridge] stop(< 131075, 45, 64, a413888:d00:483d80aa:1-a413888:d00:483d80aa:0>) 2008-05-28 10:56:33,590 INFO [STDOUT] 10:56:33,590 DEBUG [ewsng/HandlerPipeline] Invoking handler org.jboss.wst.contrib.xfire.service.XFireOutHeaderContextProcessor in phase user 2008-05-28 10:56:33,606 INFO [STDOUT] 10:56:33,606 DEBUG [ewsng/HandlerPipeline] Invoking phase transport 2008-05-28 10:56:33,606 INFO [STDOUT] 10:56:33,606 DEBUG [ewsng/HandlerPipeline] Invoking handler org.codehaus.xfire.soap.handler.SoapActionOutHandler in phase transport 2008-05-28 10:56:33,606 INFO [STDOUT] 10:56:33,606 DEBUG [ewsng/HandlerPipeline] Invoking phase send 2008-05-28 10:56:33,606 INFO [STDOUT] 10:56:33,606 DEBUG [ewsng/HandlerPipeline] Invoking handler org.codehaus.xfire.handler.OutMessageSender in phase send 2008-05-28 10:56:33,981 INFO [STDOUT] 10:56:33,981 DEBUG [ewsng/XMLBeanTypeInfo] Found mapping for property variables 2008-05-28 10:56:34,152 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus 2008-05-28 10:56:34,152 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.suspend 2008-05-28 10:56:40,606 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus 2008-05-28 10:56:40,606 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.suspend 2008-05-28 10:56:40,606 INFO [STDOUT] 10:56:40,606 TRACE [ewsng/BridgeParticipantAT] prepare(Xid=< 131075, 45, 64, a413888:d00:483d80aa:1-a413888:d00:483d80aa:0>) 2008-05-28 10:56:40,621 INFO [STDOUT] 10:56:40,621 DEBUG [ewsng/BridgeParticipantAT] prepare on Xid=< 131075, 45, 64, a413888:d00:483d80aa:1-a413888:d00:483d80aa:0> returning ReadOnly
-
12. Re: XTS/bridge: two diff. TXs on same thread?
Definitely something fishy going on there. Bundle up a test case and send it my way, I'll take a look when I get time.
-
13. Re: XTS/bridge: two diff. TXs on same thread?
OK, I'll see what I can put together. I'll first try to see if I can get the original POC code that Paul R. helped with, running in the same env. and if not, that'll be the easiest to bundle up. Thanks Jonathan.
-
14. Re: XTS/bridge: two diff. TXs on same thread?
"jhalliday" wrote:
Definitely something fishy going on there. Bundle up a test case and send it my way, I'll take a look when I get time.
Argh. The test case appears to work, but it is most definitely not working right in my project. Not sure where to go from here.
http://filebin.ca/dhyck/xts_bridge-4154027.zip [26MB]
Uploaded a ZIP with the client/service projects that are *working* ... now I need to dig through and figure out what the differences are between the way these test projects are setup and what's going on in my main project. I'm suspecting that Spring is involved somehow, and wondering if an older version of Spring may be to blame.