1 2 3 Previous Next 38 Replies Latest reply on May 24, 2011 3:37 AM by Andrew Dinn Go to original post
      • 15. Re: SQL Server and XA recovery
        Mark Little Master

         

        "ratrask" wrote:
        First off, thanks for not jumping all over me for my first post. It must have been obvious that I was a bone head. The test that I ran clearly did not interact with the App server, and did not touch SQL Server, so it had nothing to do with this post. I apologize for not checking my facts. I took the first answer that matched my pre-supposition, and did not dig any deeper.

        If I can follow this rabit trail for a bit longer, I got the first test to run correctly by just copying the jbossjta-properties.xml file from my server conf directory to the directory into the directory I was runnig in. I was not able to run the jts test, because I could not find a jar file that had the ORB classes in it. I suspect it is not a part of 4.2.1
        Missing classes were
        com.arjuna.orbportability.*
        com.arjuna.ats.internal.jts.ORBManager
        com.arjuna.ats.jta.TransactionManager


        No. You need to download JBossTS (JTS) separately and install.


        For the xaresource test, I am getting a class not found exception for
        com.arjuna.ats.internal.jdbc.recovery.JNDIXARecovery is the "JNDI resource" still not working in 4.2.1? the notes say that it is not working in 4.0.3, and I suspect the same is true with 4.2.1 If I can get it working, this should be a good test to demonstrate the problems that I am seeing in my application, and which also match what Jeremy is reporting.


        Which notes?

        • 16. Re: SQL Server and XA recovery
          Ronald Trask Newbie


          Which notes?


          The README.txt file says the following:


          To use the JDBC Resource Recovery via DataSource in JNDI, add the following to the
          '<properties depends="arjuna" name="jta">' section of jbossjta-properties.xml (near end)
          (does not work in JBoss-4.0.3SP1):


          I'm not sure. 131075 must be coming from somewhere. Are both versions of XATxConverter being loaded with different class loaders? Or maybe are there old transactions in your object store (or in-doubt transactions in your database)?


          When I searched for XATxConverter, there was only one place that it was being loaded, which was the patched jar. and I know that the patched jar held the version with public static final int FORMAT_ID = 0; I'll experiment some more with it today, but I am also pretty sure that they were new transactions, not existing ones. There certainly was nothing in the object store, and it is unclear to me how it could be an in-doubt transaction in SQL Server, when the MDT always assigns a 0 formatID.


          • 17. Re: SQL Server and XA recovery
            Mark Little Master

            Can you cut-and-paste a link to the README.txt file you mean?

            • 18. Re: SQL Server and XA recovery
              Ronald Trask Newbie

              I can't post a link to the README, but I can here is a link to the zip file that contains the README.txt file.

              http://wiki.jboss.org/wiki/attach?page=JBossTSRecovery%2Fxarecovery.zip

              • 19. SQL Server and XA recovery
                yong deng Newbie

                Sorry to interrupt in. I have two questions:

                1. Is the format ID genreated by JBoss TM configurable? If so, I need not to touch JBoss TM code to make SQL server transaction recovery work along with JBoss
                2. If it is not configurable, to make the transaction recovery work with SQL server. I have to patch XATxConverter format id to 0. If I make this change, is there any side effect?

                 

                Thanks for sharing your insight.

                • 20. SQL Server and XA recovery
                  Jonathan Halliday Master

                  It's not, nor is using 0 an option - the spec reserves that value for OSI CCR naming.  This is a bug in the MS code. I've raised it with them before and been brushed off - they don't seem to regard it as a problem. Perhaps you'll have more luck convincing them to fix it.

                  • 21. SQL Server and XA recovery
                    Michael Burman Newbie

                    A slightly different issue, about one in every thousand transaction causes a HeuristicMixedException and lost message (the famous JMS+DB update combo).  I've tried to find out if it has something to do with the issue mentioned above, but I just can't trace it enough far. If I add com.arjuna to DEBUG level, I get no extra information to:

                     

                    2011-05-05 06:44:39,520 WARN  [com.arjuna.ats.jta.logging.loggerI18N] (ESBScheduler:Heracles.esb_Worker-3) [com.arjuna.ats.internal.jta.r\

                    esources.arjunacore.commitxaerror] [com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror] XAResourceRecord.commit - xa error XAException.XAER_NOTA

                     

                     

                     

                    Caused by:

                    javax.transaction.HeuristicMixedException

                            at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1439)

                            at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)

                            at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)

                            at org.jboss.soa.esb.common.JBossESBTransactionService$JTATransactionStrategy.terminate(JBossESBTransactionService.java:101)

                            ... 5 more

                     

                     

                    tag:JBOSSTS_4_6_1_GA_CP10 and JBoss Messaging 1.4.8 (etc, if it matters, but the newest stuff anyway).

                     

                    If I add more debug level to SQL Server's JDBC driver (version 3) I can find out the following:

                     

                    2011-05-06 16:38:41,821 FINE  [com.microsoft.sqlserver.jdbc.internals.SQLServerStatement] (WorkManager(2)-87) SQLServerCallableStatement:27\

                    85: calling sp_execute: PreparedHandle:4, SQL:EXEC master..xp_sqljdbc_xa_commit @P0 OUT, @P1 OUT, @P2, @P3, @P4                            \

                     

                    2011-05-06 16:38:42,280 WARN  [com.arjuna.ats.jta.logging.loggerI18N] (WorkManager(2)-87) [com.arjuna.ats.internal.jta.resources.arjunacore\

                    .commitxaerror] [com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror] XAResourceRecord.commit - xa error XAException.XAER_NOTA

                    2011-05-06 16:38:42,306 FINE  [com.microsoft.sqlserver.jdbc.internals.SQLServerStatement] (WorkManager(2)-87) SQLServerCallableStatement:30\

                    00: calling sp_execute: PreparedHandle:4, SQL:EXEC master..xp_sqljdbc_xa_commit @P0 OUT, @P1 OUT, @P2, @P3, @P4                            \

                     

                    2011-05-06 16:38:42,329 ERROR [org.jboss.resource.adapter.jms.inflow.JmsServerSession] (WorkManager(2)-87) Unexpected error delivering mess\

                    age delegator->JBossMessage[5344006629089850]:PERSISTENT, deliveryId=2168

                     

                    So the SQL Server is sent xa_commit request, but I don't know what happened to it, nor what the XiD is so I could even trace it from the SQL Server side what's causing these to happen. So what sort of logging should I add to find more out about what's happening? I can easily reproduce this issue. It's not always that the message is lost when HeuristicMixedException happens (they happen more often than commits fail).

                     

                    One weird thing is that both of the database XA-datasources are on the same SQL Server (just different databases) and commits succeed to one database but not the other one.

                    • 22. SQL Server and XA recovery
                      Michael Burman Newbie

                      With help of mmusgrov I now at least know what transaction XiD is failing.. now I just need to know why, but maybe that's issue for MSDTC..

                      • 23. SQL Server and XA recovery
                        Michael Burman Newbie

                        Quest continues, how can I trace back data between MSDTC and JBossTS? MSDTC gives out logs such as:

                         

                        pid=4056       ;tid=4152       ;time=05/09/2011-15:36:11.067   ;seq=81         ;eventid=RM_ISSUED_PREPARE                        ;tx_guid=f4d155a6-1bb5-4ea0-8d73-b2c3600eaf51     ;"TM Identifier='(null)                                            '" ;"prepare request issued to resource manager #1001 for transaction enlistment #1"

                         

                        While JBossTS talks about:

                         

                        2011-05-09 15:36:11,779 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkManager(2)-45) BasicAction::prepare () for action-id -53e4a5b3:ca2c:4dc7df5f:7fb

                        2011-05-09 15:36:11,779 DEBUG [com.arjuna.ats.jta.logging.logger] (WorkManager(2)-45) XAResourceRecord.topLevelPrepare for < 131075, 29, 27, 56454553511015297539851589997509958521009955100102531025855102984553511015297539851589997509958521009955100102531025855102102 >

                         

                        And JDBC driver gives no interesting information..

                         

                        2011-05-09 15:36:11,788 FINE  [com.microsoft.sqlserver.jdbc.internals.SQLServerStatement] (WorkManager(2)-45) SQLServerCallableStatement:981: calling sp_execute: PreparedHandle:4, SQL:EXEC master..xp_sqljdbc_xa_prepare @P0 OUT, @P1 OUT, @P2, @P3

                         

                        How on earth can I match these two IDs to find out from both sides what actually happened to the transaction and what later caused Heuristics?

                        • 24. SQL Server and XA recovery
                          Michael Musgrove Master
                          2011-05-09 15:36:11,779 DEBUG [com.arjuna.ats.jta.logging.logger] (WorkManager(2)-45) XAResourceRecord.topLevelPrepare for < 131075, 29, 27, 56454553511015297539851589997509958521009955100102531025855102984553511015297539851589997509958521009955100102531025855102102 >

                          I have zero experience with MTS but reading the manual I see it does have facilities for examing its in doubt transactions. For example the table oramts_2pc_pending contains columns called Formatid and branch_id. As a guess you could compare these with the format id and branch id reported by JBossTS ( 131075 and the first 29 digits of that long number in the above quote, the remaining 27 digits correspond to the branch qualifier)

                          • 25. SQL Server and XA recovery
                            Michael Burman Newbie

                            oramts_2pc_pending is Oracle's database table when used with MSDTC. So it's not available in the MS SQL. In any case, it is possible to view trace data on in-doubt transactions (from component services - Local DTC), however these heuristics do not leave any transactions in to in-doubt state, so tracing them that way is not possible.

                            • 26. SQL Server and XA recovery
                              Michael Burman Newbie

                              Keeps getting weirder.. unfortunately production system did not have enough debugging level to get more information out of it,but this is a lost message. In JBoss logs we have:

                               

                              2011-05-06 06:56:21,046 WARN  [com.arjuna.ats.jta.logging.loggerI18N] (WorkManager(2)-40) [com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror] [\

                              com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror] XAResourceRecord.commit - xa error XAException.XAER_NOTA

                               

                              And this time I can match it to a single transaction on MSDTC's tracelog files..

                               

                              pid=5772       ;tid=6096       ;time=05/06/2011-06:56:19.442   ;seq=242284     ;eventid=RM_ENLISTED_IN_TRANSACTION               ;tx_guid=a7878faf-9fab-4f3a-a7b7-255ebaf22a5b     ;"TM Identifier='(null)                                            '" ;"resource manager #1001 enlisted as transaction enlistment #1. RM guid = '9c70fa60-b2a6-473e-bbfc-4f819e38f7ae'"

                              pid=5772       ;tid=2404       ;time=05/06/2011-06:56:19.488   ;seq=242285     ;eventid=RM_ISSUED_PREPARE                        ;tx_guid=a7878faf-9fab-4f3a-a7b7-255ebaf22a5b     ;"TM Identifier='(null)                                            '" ;"prepare request issued to resource manager #1001 for transaction enlistment #1"

                              pid=5772       ;tid=2404       ;time=05/06/2011-06:56:19.504   ;seq=242286     ;eventid=RM_VOTED_COMMIT                          ;tx_guid=a7878faf-9fab-4f3a-a7b7-255ebaf22a5b     ;"TM Identifier='(null)                                            '" ;"resource manager #1001 voted commit for transaction enlistment #1"

                              pid=5772       ;tid=2404       ;time=05/06/2011-06:56:19.520   ;seq=242287     ;eventid=TRANSACTION_ABORTING                     ;tx_guid=a7878faf-9fab-4f3a-a7b7-255ebaf22a5b     ;"TM Identifier='(null)                                            '" ;"transaction is aborting"

                              pid=5772       ;tid=2404       ;time=05/06/2011-06:56:19.520   ;seq=242288     ;eventid=RM_ISSUED_ABORT                          ;tx_guid=a7878faf-9fab-4f3a-a7b7-255ebaf22a5b     ;"TM Identifier='(null)                                            '" ;"abort request issued to resource manager #1001 for transaction enlistment #1"

                              pid=5772       ;tid=2404       ;time=05/06/2011-06:56:19.520   ;seq=242289     ;eventid=RM_ACKNOWLEDGED_ABORT                    ;tx_guid=a7878faf-9fab-4f3a-a7b7-255ebaf22a5b     ;"TM Identifier='(null)                                            '" ;"received acknowledgement of abort request from the resource manager #1001 for transaction enlistment #1"

                              pid=5772       ;tid=2404       ;time=05/06/2011-06:56:19.535   ;seq=242290     ;eventid=TRANSACTION_ABORTED                      ;tx_guid=a7878faf-9fab-4f3a-a7b7-255ebaf22a5b     ;"TM Identifier='(null)                                            '" ;"transaction has been aborted"

                               

                              This is weird? I don't see anything about aborting transaction from TS, yet MSDTC thinks that's what has happened. Yet this only aborted one transaction from the multi-XA, rest were committed.. I'm not getting any smarter.

                              • 27. SQL Server and XA recovery
                                Michael Burman Newbie

                                Small update (although I haven't been able to trace back to MSDTC enough fast, we generate too many transactions to get the log out before it overwrites itself even with maximum settings.. darn).

                                 

                                The Heuristics are clearly coming from the problem between MSDTC & JDBC driver:

                                 

                                 

                                • 2011-05-13 09:44:52,359 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-43)  XAResourceID:25 Calling XA function for type:XA_COMMIT f\
                                  lags:TMNOFLAGS xid:formatId=131075 gtrid=0x35372D2D35336530643132633A666163313A34646363643163363A3535643461 bqual=0x2D35336530643132633A666163313A34646\
                                  363643163363A3535643531
                                  2011-05-13 09:44:52,380 WARN  [com.arjuna.ats.jta.logging.loggerI18N] (WorkManager(2)-43) [com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerr\
                                  or] [com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror] XAResourceRecord.commit - xa error XAException.XAER_NOTA
                                  2011-05-13 09:44:52,380 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (WorkManager(2)-43) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - Reco\
                                  rdList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -53e0d12c:fac1:4dccd1c6:55d52
                                  2011-05-13 09:44:52,381 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-43)  XAResourceID:132 Calling XA function for type:XA_COMMIT \
                                  flags:TMNOFLAGS xid:formatId=131075 gtrid=0x35372D2D35336530643132633A666163313A34646363643163363A3535643461 bqual=0x2D35336530643132633A666163313A3464\
                                  6363643163363A3535656230
                                  2011-05-13 09:44:52,429 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-43)  XAResourceID:132 Status:0

                                   

                                 

                                As you can see, JDBC-driver never replied Status:0 to the XAResourceID:25 (yet probably exited and that's why it generated Heuristic). In this case the transaction was committed though, but the lost messages are probably in this case of because of failed COMMIT. Why it fails after PREPARE is beyond my understanding..

                                • 28. SQL Server and XA recovery
                                  Michael Burman Newbie

                                  Maybe I did stumble upon to this formatId=0 after all:

                                   

                                  2011-05-16 16:24:12,631 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)          XAResourceID:2 Calling XA function for type:XA_ROLLBACK flags:TMNOFLAGS xid:formatId=0      gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                  2011-05-16 16:24:12,683 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-76)  XAResourceID:139 Calling XA function for type:XA_COMMIT flags:TMNOFLAGS xid:formatId=131075 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                   

                                  So the second one returns XAER_NOTA for obvious reason..? JDBC driver has already rollbacked it. At least gtrid and bqual match, only difference is in formatId. Different threads though, and why didn't TM remember what happened?

                                  • 29. Re: SQL Server and XA recovery
                                    Michael Burman Newbie

                                    Previous message was written in hurry, so here is more detailed stuff. Considering that bqual & gtrid have to be equal (and apparently according to Microsoft, that's all that needs to be equal), I can get logs from happening with this id:

                                     

                                     

                                    {noformat}

                                    2011-05-16 16:24:12,504 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-76)  XAResourceID:139 Calling XA function for type:XA_START flags:TMNOFLAGS xid:formatId=131075 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                    2011-05-16 16:24:12,574 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-76)  XAResourceID:139 Calling XA function for type:XA_END flags:TMSUCCESS xid:formatId=131075 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                    2011-05-16 16:24:12,576 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-76)  XAResourceID:139 Calling XA function for type:XA_PREPARE flags:TMNOFLAGS xid:formatId=131075 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                    2011-05-16 16:24:12,627 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:1 XID:formatId=0 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                    2011-05-16 16:24:12,630 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:2 XID:formatId=0 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                    2011-05-16 16:24:12,631 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:2 Calling XA function for type:XA_ROLLBACK flags:TMNOFLAGS xid:formatId=0 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                    2011-05-16 16:24:12,683 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-76)  XAResourceID:139 Calling XA function for type:XA_COMMIT flags:TMNOFLAGS xid:formatId=131075 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                    {noformat}

                                     

                                    The ones I've bolded are actually from RECOVER process:

                                     

                                     

                                    {noformat}

                                    2011-05-16 16:24:12,625 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] (Thread-23) [com.arjuna.ats.internal.jta.recovery.info.rollingbackignore] Ignoring Xid < 131\

                                    075, 33, 30, 535545455351101481004950995857102995458521009998541001001025851995454549945535110148100495099585710299545852100999854100100102585199545454100 > and l\

                                    eaving for transaction recovery to drive.

                                    2011-05-16 16:24:12,625 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:1 Calling XA function for type:XA_RECOVER flags:TMSTARTRSCAN x\

                                    id:(null)

                                    2011-05-16 16:24:12,627 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:1 Status:0

                                    2011-05-16 16:24:12,627 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:1 XID:formatId=0 gtrid=0x35372D2D35336530643132633A653265633A3\

                                    4646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                    2011-05-16 16:24:12,627 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:1 Calling XA function for type:XA_RECOVER flags:TMENDRSCAN xid\

                                    :(null)

                                    2011-05-16 16:24:12,628 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:1 Status:0

                                    2011-05-16 16:24:12,629 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:2 Calling XA function for type:XA_RECOVER flags:TMSTARTRSCAN x\

                                    id:(null)

                                    2011-05-16 16:24:12,630 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:2 Status:0

                                    2011-05-16 16:24:12,630 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:2 XID:formatId=0 gtrid=0x35372D2D35336530643132633A653265633A3\

                                    4646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                    2011-05-16 16:24:12,631 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-23) HashedStore.genPathName(-53e0d12c:e2ec:4dd10b19:23e1f8, /StateManager/BasicAct\

                                    ion/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)

                                    2011-05-16 16:24:12,631 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-23) HashedStore.genPathName(-53e0d12c:e2ec:4dd10b19:23e1f8, /StateManager/BasicAct\

                                    ion/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)

                                    2011-05-16 16:24:12,631 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-23) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - Shadowing\

                                    Store.currentState(-53e0d12c:e2ec:4dd10b19:23e1f8, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_UNKNOWN

                                    2011-05-16 16:24:12,631 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] (Thread-23) [com.arjuna.ats.internal.jta.recovery.info.rollingback] Rolling back < 0, 33, 30\

                                    , 53554545535110148100495099581015010199585210010049489849575850511014910256455351101481004950995810150101995852100100494898495758505110149102102 >

                                    2011-05-16 16:24:12,631 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Thread-23)  XAResourceID:2 Calling XA function for type:XA_ROLLBACK flags:TMNOFLAGS xid\

                                    :formatId=0 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365316666

                                    {noformat}

                                     

                                    What happens on the other thread is curious:

                                     

                                     

                                    {noformat}

                                    2011-05-16 16:24:12,624 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-76)  XAResourceID:55 Calling XA function for type:XA_PREPARE flags:TMNOF\

                                    LAGS xid:formatId=131075 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365\

                                    323034

                                    2011-05-16 16:24:12,653 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-76)  XAResourceID:55 Status:0

                                    2011-05-16 16:24:12,653 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (WorkManager(2)-76) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::ins\

                                    ert(RecordList: -53e0d12c:e2ec:4dd10b19:23e1fa -53e0d12c:e2ec:4dd10b19:23e200) : appending /StateManager/AbstractRecord/XAResourceRecord for -53e0d12c:e2ec:4dd10b\

                                    19:23e205

                                    2011-05-16 16:24:12,653 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkManager(2)-76) FileSystemStore.write_committed(-53e0d12c:e2ec:4dd10b19:23e1f8, /State\

                                    Manager/BasicAction/TwoPhaseCoordinator/AtomicAction)

                                    2011-05-16 16:24:12,653 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkManager(2)-76) ShadowingStore.write_state(-53e0d12c:e2ec:4dd10b19:23e1f8, /StateManag\

                                    er/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)

                                    2011-05-16 16:24:12,653 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkManager(2)-76) HashedStore.genPathName(-53e0d12c:e2ec:4dd10b19:23e1f8, /StateManager/\

                                    BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)

                                    2011-05-16 16:24:12,653 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkManager(2)-76) FileSystemStore.openAndLock(/esbdata1/heracles/jboss-5.1.1.Branch/serv\

                                    er/default/data/tx-object-store/HashedActionStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/#49#/-53e0d12c_e2ec_4dd10b19_23e1f8, File\

                                    Lock.F_WRLCK, true)

                                    2011-05-16 16:24:12,653 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkManager(2)-76) FileSystemStore.createHierarchy(/esbdata1/heracles/jboss-5.1.1.Branch/\

                                    server/default/data/tx-object-store/HashedActionStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/#49#/-53e0d12c_e2ec_4dd10b19_23e1f8)

                                    2011-05-16 16:24:12,657 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkManager(2)-76) FileSystemStore.closeAndUnlock(/esbdata1/heracles/jboss-5.1.1.Branch/s\

                                    erver/default/data/tx-object-store/HashedActionStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/#49#/-53e0d12c_e2ec_4dd10b19_23e1f8, n\

                                    ull, java.io.FileOutputStream@47874787)

                                    2011-05-16 16:24:12,683 FINER [com.microsoft.sqlserver.jdbc.internals.XA] (WorkManager(2)-76)  XAResourceID:139 Calling XA function for type:XA_COMMIT flags:TMNOF\

                                    LAGS xid:formatId=131075 gtrid=0x35372D2D35336530643132633A653265633A34646431306231393A323365316638 bqual=0x2D35336530643132633A653265633A34646431306231393A323365\

                                    316666

                                    2011-05-16 16:24:12,685 WARN  [com.arjuna.ats.jta.logging.loggerI18N] (WorkManager(2)-76) [com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror] [com.ar\

                                    juna.ats.internal.jta.resources.arjunacore.commitxaerror] XAResourceRecord.commit - xa error XAException.XAER_NOTA

                                    {noformat}

                                    To me it looks like before PREPARE was acknowledged by the JDBC driver, TM has decided to roll back for some reason from other thread (there's no Exception I could find from the application, so I don't know what causes TM to do that rollback) and then trying to commit something it has already rolled back.

                                     

                                    I made all logs available here: https://s3-eu-west-1.amazonaws.com/burmanm/jboss/16052011_1624_event.zip (includes 4 text files, one is all the events at 2011-05-16 16:24:*, rest are grepped files, one including WorkManager-2-(76) thread, one Thread-23 and one includes grep from that timeframe with the gtrid and bqual grepped.

                                     

                                    At the moment to me it looks like an error in the JBossTM, possibly caused by the Microsoft's JDBC drivers behaviour.. ärr.