JBossDeveloper

"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

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?

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)?

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

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

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.

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.

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.

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

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?

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)

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.

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.

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:

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

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?

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.