Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1152507

Summary: Recovery for Mssql throws "The statement must be executed before any results can be obtained"
Product: [JBoss] JBoss Enterprise Application Platform 6 Reporter: Ondrej Chaloupka <ochaloup>
Component: Transaction ManagerAssignee: Gytis Trikleris <gtrikler>
Status: CLOSED NOTABUG QA Contact: Ondrej Chaloupka <ochaloup>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 6.4.0CC: hhovsepy
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-11-04 16:09:56 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
jts-server.log
none
jts-server.log without trace but with another subsequent exception none

Description Ondrej Chaloupka 2014-10-14 10:33:21 UTC 
Created attachment 946806 [details]
jts-server.log

It is happening that during recovery when transactions are run with JTS time to time is seen error "The statement must be executed before any results can be obtained" caused by exception [1] in server log.

It's a bit problematic to reproduce the problem. My hypothesis is that there could be some race condition.
When XAResourceRecord.rollback is called there are seen to be two threads - "RequestProcessor-9" and "Periodic Recover". It partly seems that those two threads touch the same statement. See:

(Periodic Recovery) com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$1PrepStmtExecOutParamHandler@1e8a56eb: Setting PreparedHandle:2
- and -
(RequestProcessor-9) SQLServerCallableStatement:11: calling sp_execute: PreparedHandle:2, SQL:EXEC master..xp_sqljdbc_xa_rollback @P0 OUT, @P1 OUT, @P2, @P3, @P4                                

I'm not sure whether this could be connected with recovery or it is just problem of MSSQL driver.

There is need to be said that this error does not causes any data inconsistency. Normally in next run of recovery the error is not shown again and recovery operation (rollback in this case) is proceeded fine.


[1]
TRACE [com.arjuna.ats.jtax] (RequestProcessor-9) XAResourceRecord.rollback for < 131072, 29, 36, 0000000000-1-110003-110-38-291058460-21-550005649, 29292929292929292929282839292932-81-90134113898-26292929857829292929292929 >
FINER [com.microsoft.sqlserver.jdbc.internals.XA] (RequestProcessor-9)  XAResourceID:2 Calling XA function for type:XA_ROLLBACK flags:TMNOFLAGS xid:formatId=131072 gtrid=0x00000000000000000000FFFF0A00000392DAE369543CEBC90000003831 bqual=0x00000000000000000000FFFF0A00000392DAE369543CEBC90000003F0000000000000000
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) ENTRY 1 4
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) RETURN
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) ENTRY 2 1
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) RETURN
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) ENTRY 3 [B@756940eb
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) RETURN
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) ENTRY 4 [B@51254085
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) RETURN
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) ENTRY 5 131,072
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) RETURN
FINER [com.microsoft.sqlserver.jdbc.Statement] (RequestProcessor-9) ENTRY
FINER [com.microsoft.sqlserver.jdbc.internals.SQLServerStatement] (Periodic Recovery) com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$1PrepStmtExecOutParamHandler@1e8a56eb: Setting PreparedHandle:2
FINER [com.microsoft.sqlserver.jdbc.Statement] (Periodic Recovery) RETURN false
FINER [com.microsoft.sqlserver.jdbc.Statement] (Periodic Recovery) ENTRY 1
FINE  [com.microsoft.sqlserver.jdbc.internals.SQLServerStatement] (RequestProcessor-9) SQLServerCallableStatement:11: calling sp_execute: PreparedHandle:2, SQL:EXEC master..xp_sqljdbc_xa_rollback @P0 OUT, @P1 OUT, @P2, @P3, @P4                                
FINE  [com.microsoft.sqlserver.jdbc.internals.SQLServerException] (Periodic Recovery) *** SQLException:SQLServerCallableStatement:11 com.microsoft.sqlserver.jdbc.SQLServerException: The statement must be executed before any results can be obtained. The statement must be executed before any results can be obtained.
FINER [com.microsoft.sqlserver.jdbc.internals.XA] (Periodic Recovery)  XAResourceID:2 exception:com.microsoft.sqlserver.jdbc.SQLServerException: The statement must be executed before any results can be obtained.
WARN  [com.arjuna.ats.jtax] (Periodic Recovery) ARJUNA024023: XAResourceRecord.rollback caused an XA error: XAException.XAER_RMERR from resource XAResourceWrapperImpl@7a3a0009[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@7b9f2d84 pad=false overrideRmValue=false productName=Microsoft SQL Server productVersion=11.00.5058 jndiName=java:jboss/xa-datasources/CrashRecoveryDS] in transaction < 131072, 29, 36, 0000000000-1-110003-110-38-291058460-21-550005649, 29292929292929292929282839292932-81-90134113898-26292929857829292929292929 >: javax.transaction.xa.XAException: com.microsoft.sqlserver.jdbc.SQLServerException: The statement must be executed before any results can be obtained.
 at com.microsoft.sqlserver.jdbc.SQLServerXAResource.DTC_XA_Interface(SQLServerXAResource.java:647)
 at com.microsoft.sqlserver.jdbc.SQLServerXAResource.rollback(SQLServerXAResource.java:718)
 at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.rollback(XAManagedConnection.java:346)
 at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.rollback(XAResourceWrapperImpl.java:196)
 at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.rollback(XAResourceRecord.java:377) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.doRecovery(XAResourceRecord.java:1406) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.recover(XAResourceRecord.java:1229) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.jts.XARecoveryResourceImple.recover(XARecoveryResourceImple.java:88) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:669) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:426) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:210) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:793) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:375) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
Comment 3 Ondrej Chaloupka 2014-10-14 12:51:25 UTC 
Created attachment 946868 [details]
jts-server.log without trace but with another subsequent exception

There is subsequent exceptions of "The statement must be executed before any results can be obtained" times to time. It seems that all of them could be connected.

The exceptions are:
javax.transaction.xa.XAException: com.microsoft.sqlserver.jdbc.SQLServerException: The TDS protocol stream is not valid.
-and-
javax.transaction.xa.XAException: com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.

More details at log or [1].


[1]
TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.rollback for < 131072, 29, 36, 0000000000-1-110168811256-96-9108457124-1010007149, 292929292929292929292828394511714185-67-622911386153-722929291007829292929292929 >
TRACE [com.arjuna.ats.jtax] (RequestProcessor-10) XAResourceRecord.rollback for < 131072, 29, 36, 0000000000-1-110168811256-96-9108457124-1010007149, 292929292929292929292828394511714185-67-622911386153-722929291007829292929292929 >
INFO  [com.microsoft.sqlserver.jdbc.internals.SQLServerStatement] (RequestProcessor-10) SQLServerCallableStatement:11 Unexpected outParamIndex: 3; adjustment: 1
WARN  [com.arjuna.ats.jtax] (Periodic Recovery) ARJUNA024023: XAResourceRecord.rollback caused an XA error: XAException.XAER_RMERR from resource XAResourceWrapperImpl@458abae5[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@4d75e357 pad=false overrideRmValue=false productName=Microsoft SQL Server productVersion=11.00.5058 jndiName=java:jboss/xa-datasources/CrashRecoveryDS] in transaction < 131072, 29, 36, 0000000000-1-110168811256-96-9108457124-1010007149, 292929292929292929292828394511714185-67-622911386153-722929291007829292929292929 >: javax.transaction.xa.XAException: com.microsoft.sqlserver.jdbc.SQLServerException: The statement must be executed before any results can be obtained.
 at com.microsoft.sqlserver.jdbc.SQLServerXAResource.DTC_XA_Interface(SQLServerXAResource.java:647)
 at com.microsoft.sqlserver.jdbc.SQLServerXAResource.rollback(SQLServerXAResource.java:718)
 at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.rollback(XAManagedConnection.java:346)
 at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.rollback(XAResourceWrapperImpl.java:196)
 at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.rollback(XAResourceRecord.java:377) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.doRecovery(XAResourceRecord.java:1406) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.recover(XAResourceRecord.java:1229) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.jts.XARecoveryResourceImple.recover(XARecoveryResourceImple.java:88) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:669) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:426) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:210) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:793) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:375) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]

TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.rollback exception XAException.XAER_RMERR resource_trace: txn uid=< 131072, 29, 36, 0000000000-1-110168811256-96-9108457124-1010007149, 292929292929292929292828394511714185-67-622911386153-722929291007829292929292929 > resource uid=0:ffff0a105870:38a0a500:54397c9b:4f

TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.write_committed(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.write_state(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, 11)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/mnt/hudson_workspace/workspace/eap-64-jbossts-crashrec-tests-mssql2012-jdk-matrix/23bde71e/eap-tests-transactions/integration/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff0a105870_38a0a500_54397c9b_4f, FileLock.F_WRLCK, true)
WARN  [com.arjuna.ats.jtax] (RequestProcessor-10) ARJUNA024023: XAResourceRecord.rollback caused an XA error: XAException.XAER_RMERR from resource XAResourceWrapperImpl@458abae5[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@4d75e357 pad=false overrideRmValue=false productName=Microsoft SQL Server productVersion=11.00.5058 jndiName=java:jboss/xa-datasources/CrashRecoveryDS] in transaction < 131072, 29, 36, 0000000000-1-110168811256-96-9108457124-1010007149, 292929292929292929292828394511714185-67-622911386153-722929291007829292929292929 >: javax.transaction.xa.XAException: com.microsoft.sqlserver.jdbc.SQLServerException: The TDS protocol stream is not valid.
 at com.microsoft.sqlserver.jdbc.SQLServerXAResource.DTC_XA_Interface(SQLServerXAResource.java:647)
 at com.microsoft.sqlserver.jdbc.SQLServerXAResource.rollback(SQLServerXAResource.java:718)
 at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.rollback(XAManagedConnection.java:346)
 at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.rollback(XAResourceWrapperImpl.java:196)
 at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.rollback(XAResourceRecord.java:377) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ArjunaOTS.OTSAbstractRecordPOA._invoke(OTSAbstractRecordPOA.java:213) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at org.jacorb.poa.RequestProcessor.invokeOperation(RequestProcessor.java:306) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
 at org.jacorb.poa.RequestProcessor.process(RequestProcessor.java:626) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
 at org.jacorb.poa.RequestProcessor.run(RequestProcessor.java:769) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]

TRACE [com.arjuna.ats.jtax] (RequestProcessor-10) XAResourceRecord.rollback exception XAException.XAER_RMERR resource_trace: txn uid=< 131072, 29, 36, 0000000000-1-110168811256-96-9108457124-1010007149, 292929292929292929292828394511714185-67-622911386153-722929291007829292929292929 > resource uid=0:ffff0a105870:38a0a500:54397c9b:4f

TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) OutputObjectState::OutputObjectState()
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) FileSystemStore.write_committed(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) ShadowingStore.write_state(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) ShadowingStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) FileSystemStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, 11)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) FileSystemStore.openAndLock(/mnt/hudson_workspace/workspace/eap-64-jbossts-crashrec-tests-mssql2012-jdk-matrix/23bde71e/eap-tests-transactions/integration/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff0a105870_38a0a500_54397c9b_4f, FileLock.F_WRLCK, true)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/mnt/hudson_workspace/workspace/eap-64-jbossts-crashrec-tests-mssql2012-jdk-matrix/23bde71e/eap-tests-transactions/integration/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff0a105870_38a0a500_54397c9b_4f, null, java.io.FileOutputStream@444bac06)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.remove_committed(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.remove_state(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, 10)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, 11)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, 11)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/mnt/hudson_workspace/workspace/eap-64-jbossts-crashrec-tests-mssql2012-jdk-matrix/23bde71e/eap-tests-transactions/integration/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff0a105870_38a0a500_54397c9b_4f, FileLock.F_WRLCK, false)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/mnt/hudson_workspace/workspace/eap-64-jbossts-crashrec-tests-mssql2012-jdk-matrix/23bde71e/eap-tests-transactions/integration/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff0a105870_38a0a500_54397c9b_4f, null, null)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) FileSystemStore.closeAndUnlock(/mnt/hudson_workspace/workspace/eap-64-jbossts-crashrec-tests-mssql2012-jdk-matrix/23bde71e/eap-tests-transactions/integration/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff0a105870_38a0a500_54397c9b_4f, null, java.io.FileOutputStream@7fdbf03e)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) FileSystemStore.remove_committed(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) ShadowingStore.remove_state(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) ShadowingStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) FileSystemStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, 10)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) ShadowingStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
WARN  [com.arjuna.ats.jtax] (Periodic Recovery) ARJUNA024016: Recovery of resource failed when trying to call rollback got exception: org.omg.CosTransactions.HeuristicHazard: IDL:omg.org/CosTransactions/HeuristicHazard:1.0
 at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.rollback(XAResourceRecord.java:407) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.doRecovery(XAResourceRecord.java:1406) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.recover(XAResourceRecord.java:1229) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.jts.XARecoveryResourceImple.recover(XARecoveryResourceImple.java:88) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:669) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:426) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:210) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:793) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:375) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]

TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) FileSystemStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, 11)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) ShadowingStore.currentState(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) ShadowingStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016005: JTS XARecoveryModule.xaRecovery - failed to recover XAResource. status is $2
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) FileSystemStore.genPathName(0:ffff0a105870:38a0a500:54397c9b:4f, /CosTransactions/XAResourceRecord, 11)
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) FileSystemStore.openAndLock(/mnt/hudson_workspace/workspace/eap-64-jbossts-crashrec-tests-mssql2012-jdk-matrix/23bde71e/eap-tests-transactions/integration/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff0a105870_38a0a500_54397c9b_4f, FileLock.F_WRLCK, false)
WARN  [com.arjuna.ats.arjuna] (RequestProcessor-10) ARJUNA012284: ShadowingStore::remove_state() - access problems on 0:ffff0a105870:38a0a500:54397c9b:4f and /CosTransactions/XAResourceRecord
DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.JTATransactionLogXAResourceOrphanFilter voted ABSTAIN
DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.JTANodeNameXAResourceOrphanFilter voted ABSTAIN
WARN  [com.arjuna.ats.arjuna] (RequestProcessor-10) ARJUNA012265: ShadowingStore::remove_state() - state 0:ffff0a105870:38a0a500:54397c9b:4f does not exist for type /CosTransactions/XAResourceRecord
TRACE [com.arjuna.ats.arjuna] (RequestProcessor-10) FileSystemStore.closeAndUnlock(/mnt/hudson_workspace/workspace/eap-64-jbossts-crashrec-tests-mssql2012-jdk-matrix/23bde71e/eap-tests-transactions/integration/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff0a105870_38a0a500_54397c9b_4f, null, null)
TRACE [com.arjuna.ats.jts] (RequestProcessor-10) InterpositionServerRequestInterceptorImpl::send_exception ( rollback ) nodeId=1 requestId=16 target=IOR:000000000000002F49444C3A61726A756E612E636F6D2F41726A756E614F54532F4F545341627374726163745265636F72643A312E3000000000000200000000000000CC000102000000000A3132372E302E302E31000DC800000016323435353537303132392F05182C002B3C2A2A0142350000000000060000000000000008000000004A4143000000000100000020000000000501000100000001000100010001010900000002050100010001010000000014000000080000001A00000DC900000021000000300000000000000001000000000000002200000000000000000000000000000000000000000000000000000000000000000000002000000004000000000000001F0000000400000003000000010000002000000000000000020000002000000004000000000000001F0000000400000003
TRACE [com.arjuna.ats.jts] (RequestProcessor-10) InterpositionServerRequestInterceptorImpl::suspendContext ( rollback ) nodeId=1 requestId=16 target=IOR:000000000000002F49444C3A61726A756E612E636F6D2F41726A756E614F54532F4F545341627374726163745265636F72643A312E3000000000000200000000000000CC000102000000000A3132372E302E302E31000DC800000016323435353537303132392F05182C002B3C2A2A0142350000000000060000000000000008000000004A4143000000000100000020000000000501000100000001000100010001010900000002050100010001010000000014000000080000001A00000DC900000021000000300000000000000001000000000000002200000000000000000000000000000000000000000000000000000000000000000000002000000004000000000000001F0000000400000003000000010000002000000000000000020000002000000004000000000000001F0000000400000003
DEBUG [com.arjuna.ats.jta] (Periodic Recovery) subordinate node name of < 131072, 29, 36, 0000000000-1-1101688-91-10775-122-4684512-78000-11549, 2929292929292929292928283945117-62-78104-93-171133441-49292929-867829292929292929 > is null
DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.SubordinateJTAXAResourceOrphanFilter voted ABSTAIN
WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016027: JTS XARecoveryModule.xaRecovery got XA exception XAException.XAER_RMERR: javax.transaction.xa.XAException: com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
 at com.microsoft.sqlserver.jdbc.SQLServerXAResource.DTC_XA_Interface(SQLServerXAResource.java:647)
 at com.microsoft.sqlserver.jdbc.SQLServerXAResource.recover(SQLServerXAResource.java:728)
 at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.recover(XAManagedConnection.java:362)
 at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.recover(XAResourceWrapperImpl.java:185)
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:703) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:426) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:210) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:793) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:375) [jbossjts-jacorb-4.17.23.Final.jar:4.17.23.Final]
Comment 4 Gytis Trikleris 2014-11-04 16:09:56 UTC 
Concurrent rollback is a consequence of the OTS spec. Both recovery coordinator and resource have to call rollback in such case and it can be concurrent. Also XAER_RMERR is a valid response, if something wrong happens during the rollback. Therefore, this is not a bug in transaction manager.

I recommend contacting Mssql driver team, because that's where the test failure comes from.