1 2 Previous Next 29 Replies Latest reply on May 29, 2008 12:15 PM by Brice Ruth

    XTS/bridge: two diff. TXs on same thread?

    Brice Ruth Novice

      I'm working with jhalliday's bridge for XTS/JTA and seeing something strange. The bridge appears to be running (web service invocation causes the in/out handlers to run, TRACE logging shows the bridge is "working") - but when execution reaches my user code and I enlist a "Dummy" AT participant, for some reason it appears to not be enlisting with the same Transaction that the bridge is using ...

      When I step through with the debugger, the TxM that's wired into my user code from JNDI appears to be this:

      JNDI->java:TransactionManager
      com.arjuna.ats.jbossatx.jta.TransactionManagerDelegate


      Whereas the TxM that's seen by the InboundBridge appears to be this:

      InboundBridge#start()
      com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionManagerImple
      


      My user code runs within an @Transactional annotation from Spring's transaction support. Spring is setup to use the java:TransactionManager JTA TxM, so in theory it should be joining up with the same thread-bound Tx, right?

      Any ideas?

      Thanks,
      Brice Ruth


        • 1. Re: XTS/bridge: two diff. TXs on same thread?
          Andrew Dinn Master

          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?
            Brice Ruth Novice

            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?
              Brice Ruth Novice

              Wow, I used "that said ..." way too much in that post. :-)

              • 4. Re: XTS/bridge: two diff. TXs on same thread?
                Jonathan Halliday Master

                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?
                  Brice Ruth Novice

                  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?
                    Andrew Dinn Master

                    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?
                      Brice Ruth Novice

                       

                      "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 to
                      0xffffffff
                      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?
                        Brice Ruth Novice

                        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?
                          Jonathan Halliday Master

                          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?
                            Brice Ruth Novice

                            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?
                              Brice Ruth Novice

                               

                              "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?
                                Jonathan Halliday Master

                                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?
                                  Brice Ruth Novice

                                  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?
                                    Brice Ruth Novice

                                     

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

                                    1 2 Previous Next