SQL Server and XA recovery

[jeremystone]

We have come across a number of quirks with using JBossTS with SQL Server as an XA resource:

* The MS DTC sub-coordinator for some reason returns Xids with a formatId of 0 (rather than 131075 as coded in the XATxConverter class) from its XAResource.recover() method. This prevented transaction initiated recovery for us because Xids did not match (though the global tx and branch qualifier fields matched). We had to patch the XATxConverter to use 0 to fix this. Not sure if there is a better way?

* Killing our application when database locks are held leaves orphaned processes in Sql Server. These are not automatically released on application restart nor are they released by recovery. Restarting SQL Server or killing off the orphaned processes (e.g. in an additional RecoveryModule) seems to be required.

* Occassionally the database will be marked as 'Suspect' in the SQL Server management studio if there are in-doubt transactions known to MS-DTC following application failure. In this case it does not seem to be possible to connect to the database in order to recover these transactions automatically and so they must be manually recovered. JBossTS will still hold references to these transactions in its log and will try to recover them. But because they are no longer returned by XAResource.recover() it will log the 'Could not find new XAResource to use for recovering non-serializable XAResource' warning. What's the best approach to dealing with this - presumably if a manual intervention is required we need to delete the object store record too? Or can we make these expire?

[marklittle]

"JeremyStone" wrote:
We have come across a number of quirks with using JBossTS with SQL Server as an XA resource:

* The MS DTC sub-coordinator for some reason returns Xids with a formatId of 0 (rather than 131075 as coded in the XATxConverter class) from its XAResource.recover() method. This prevented transaction initiated recovery for us because Xids did not match (though the global tx and branch qualifier fields matched). We had to patch the XATxConverter to use 0 to fix this. Not sure if there is a better way?

I'm not sure what you mean by this. You shouldn't have to modify XATxConverter: that is the util that creates JBossTS Xids. Each formatId can be defined by the creator. Are you saying that MS DTC does not allow anything other than 0?

* Killing our application when database locks are held leaves orphaned processes in Sql Server. These are not automatically released on application restart nor are they released by recovery. Restarting SQL Server or killing off the orphaned processes (e.g. in an additional RecoveryModule) seems to be required.

If you kill them app after prepare and before commit, then there should be a log at JBossTS that will cause it to run recovery. If you kill it before prepare then presumed abort semantics apply and Sql Server should rollback the transactions "eventually" (probably a configurable timeout option at the db, but I haven't checked).

* Occassionally the database will be marked as 'Suspect' in the SQL Server management studio if there are in-doubt transactions known to MS-DTC following application failure. In this case it does not seem to be possible to connect to the database in order to recover these transactions automatically and so they must be manually recovered. JBossTS will still hold references to these transactions in its log and will try to recover them. But because they are no longer returned by XAResource.recover() it will log the 'Could not find new XAResource to use for recovering non-serializable XAResource' warning. What's the best approach to dealing with this - presumably if a manual intervention is required we need to delete the object store record too? Or can we make these expire?

There have been some changes to the trunk that should deal with this. Basically if we can't recover after some period of time then the log is moved elsewhere and recovery stops. You then get told about that and can deal with the log. JBossTS assumes that a commit occurred and the committed response it should have received from the participant was lost. That's obviously not the case here, but it'll have the same affect.

[jeremystone]

I'm not sure what you mean by this. You shouldn't have to modify XATxConverter: that is the util that creates JBossTS Xids. Each formatId can be defined by the creator. Are you saying that MS DTC does not allow anything other than 0?

We were getting the 'Could not find new XAResource to use for recovering non-serializable XAResource' warning for one transaction. On debugging, the recovery thread we noticed that the reason for this was that during transaction-initiated recovery, the Xid from the object store matched that reported by the SqlServer XAResource recover() method except for the formatId which was zero in the Xid from Sql Server (MS DTC). MS DTC in this case was being used for nothing other than our application so I assume the original Xid must have been generated in JBossTS and the formatId ignored/replaced(?) by MS DTC.

Not sure if its a bug in MS DTC or something we have misconfigured.

We can easily double check this if you like.

[marklittle]

"JeremyStone" wrote:

I'm not sure what you mean by this. You shouldn't have to modify XATxConverter: that is the util that creates JBossTS Xids. Each formatId can be defined by the creator. Are you saying that MS DTC does not allow anything other than 0?

We were getting the 'Could not find new XAResource to use for recovering non-serializable XAResource' warning for one transaction. On debugging, the recovery thread we noticed that the reason for this was that during transaction-initiated recovery, the Xid from the object store matched that reported by the SqlServer XAResource recover() method except for the formatId which was zero in the Xid from Sql Server (MS DTC). MS DTC in this case was being used for nothing other than our application so I assume the original Xid must have been generated in JBossTS and the formatId ignored/replaced(?) by MS DTC.

Since we don't generate Xids with a format id of 0, it must be DTC that is changing it. That's not very nice of it ;-)

Not sure if its a bug in MS DTC or something we have misconfigured.

We can easily double check this if you like.

That would help. Thanks.

[jeremystone]

To aid debug logging we wrap the XAResources for SQLServer and JBoss messaging with our own implementation which simply delegates to the wrapped XAResource.

These are the debug logs for calls to recover() for a specific recovery attempt caused by killing our application where some threads had just performed a transaction prepare.

It shows the zero formatId comming from the SQLServerXAResource and the correct formatId from the JBoss Messaging XAResource:

2007-12-13 13:18:22,809 143684 DEBUG [RecoveryXAResourceWrapper] (Thread-6:) recover() called for Wrapped Unknown org.jboss.jms.server.recovery.MessagingXAResourceWrapper org.jboss.jms.server.recovery.MessagingXAResourceWrapper@f26dd8 with flag=16777216. Returning xids=
formatId: 131075 globalTxId: nP-a000007:11c7:47612f00:3061 branchQual: a000007:11c7:47612f00:31bc
formatId: 131075 globalTxId: nP-a000007:11c7:47612f00:3190 branchQual: a000007:11c7:47612f00:319b
formatId: 131075 globalTxId: nP-a000007:11c7:47612f00:3157 branchQual: a000007:11c7:47612f00:318a

2007-12-13 13:18:22,902 143777 DEBUG [RecoveryXAResourceWrapper] (Thread-6:) recover() called for Wrapped Unknown org.jboss.jms.server.recovery.MessagingXAResourceWrapper org.jboss.jms.server.recovery.MessagingXAResourceWrapper@f26dd8 with flag=8388608. Returning xids=

2007-12-13 13:18:22,980 143855 DEBUG [RecoveryXAResourceWrapper] (Thread-6:) recover() called for Wrapped Unknown com.microsoft.sqlserver.jdbc.SQLServerXAResource com.microsoft.sqlserver.jdbc.SQLServerXAResource@44ac1 with flag=16777216. Returning xids=
formatId: 0 globalTxId: nP-a000007:11c7:47612f00:3061 branchQual: a000007:11c7:47612f00:3065
formatId: 0 globalTxId: nP-a000007:11c7:47612f00:3157 branchQual: a000007:11c7:47612f00:315b
formatId: 0 globalTxId: nP-a000007:11c7:47612f00:3190 branchQual: a000007:11c7:47612f00:3194

2007-12-13 13:18:22,980 143855 DEBUG [RecoveryXAResourceWrapper] (Thread-6:) isSameRM() called for Wrapped Unknown com.microsoft.sqlserver.jdbc.SQLServerXAResource com.microsoft.sqlserver.jdbc.SQLServerXAResource@44ac1 with Wrapped Unknown org.jboss.jms.server.recovery.MessagingXAResourceWrapper org.jboss.jms.server.recovery.MessagingXAResourceWrapper@f26dd8 returning false
2007-12-13 13:18:22,980 143855 DEBUG [RecoveryXAResourceWrapper] (Thread-6:) recover() called for Wrapped Unknown com.microsoft.sqlserver.jdbc.SQLServerXAResource com.microsoft.sqlserver.jdbc.SQLServerXAResource@44ac1 with flag=8388608. Returning xids=

We have not applied any specific settings to MS DTC or SQL Server. We just ran the xa_install.sql script that comes with the Microsoft JDBC driver v1.2 to enable XA.

It would be interesting to know whether anyone else has experienced this...?

[marklittle]

It should be returning the exact same Xids. I haven't seen this before, unfortunately.

[ratrask]

I've been on a parallel development track to Jeremy, and I can confirm the behavior. It is easy to reproduce.

Here is my datasource definition:

<xa-datasource>
 <jndi-name>DefaultDS</jndi-name>
 <track-connection-by-tx/>
 <isSameRM-override-value>false</isSameRM-override-value>
 <xa-datasource-class>com.microsoft.sqlserver.jdbc.SQLServerXADataSource</xa-datasource-class>
 <xa-datasource-property name="ServerName">localhost</xa-datasource-property>
 <xa-datasource-property name="DatabaseName">jboss</xa-datasource-property>
 <xa-datasource-property name="SelectMethod">cursor</xa-datasource-property>
 <xa-datasource-property name="User">jboss</xa-datasource-property>
 <xa-datasource-property name="Password">jboss</xa-datasource-property>
 <xa-datasource-property name="URL">jdbc:sqlserver://localhost:1961</xa-datasource-property>
 <!-- sql to call when connection is created -->
 <new-connection-sql>select 1</new-connection-sql>
 <!-- sql to call on an existing pooled connection when it is obtained from pool -->
 <check-valid-connection-sql>select 1</check-valid-connection-sql>

 <!-- corresponding type-mapping in the standardjbosscmp-jdbc.xml -->
 <metadata>
 <type-mapping>MS SQLSERVER2000</type-mapping>
 </metadata>
 </xa-datasource>

Then simply follow the instructions from Mark's Wiki: http://wiki.jboss.org/wiki/Wiki.jsp?page=JBossTSRecovery

The output from running "java Test" is

0 [main] INFO com.arjuna.ats.arjuna.logging.arjLogger -
 --- Start RecoveryActivators
30 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.internal.arjuna.recovery.ExpiredEntryMonitor_3] - No Expiry scanners loaded - not scanning
30 [Thread-0] INFO com.arjuna.ats.arjuna.logging.arjLogger - Periodic recovery - first pass <Sun, 16 Dec 2007 22:28:59>
40 [main] INFO com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.internal.arjuna.recovery.ready] RecoveryManagerImple is ready on port 3,378
61 [main] DEBUG com.arjuna.ats.jta.logging.logger - BaseTransaction.begin
101 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - StateManager::StateManager( 2 )
101 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - BasicAction::BasicAction()
101 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - BasicAction::Begin() for action-id a00020d:d31:4766091b:0
101 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - BasicAction::actionInitialise() for action-id a00020d:d31:4766091b:0
101 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ActionHierarchy::ActionHierarchy(5)
101 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ActionHierarchy::add(a00020d:d31:4766091b:0, 1)
111 [main] WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.TxControl_1] - Name of XA node not defined. Using a00020d:d31:4766091b:1
121 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.ShadowingStore( 14 )
121 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowNoFileLockStore.ShadowNoFileLockStore( 14 )
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.HashedStore( 14 )
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.HashedActionStore()
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.setupStore()
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.createHierarchy(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\)
131 [main] INFO com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.recovery.TransactionStatusManager_1] - Starting service com.arjuna.ats.arjuna.recovery.ActionStatusService on port 3377
131 [main] INFO com.arjuna.ats.arjuna.logging.arjLogger - TransactionStatusManagerItem - host: 10.0.2.13 port: 3377
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - OutputObjectState::OutputObjectState()
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.ShadowingStore( 14 )
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowNoFileLockStore.ShadowNoFileLockStore( 14 )
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.HashedStore( 14 )
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.HashedActionStore()
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.setupStore()
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.createHierarchy(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\)
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.write_committed(a00020d:d31:4766091b:2, /Recovery/TransactionStatusManager)
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.write_state(a00020d:d31:4766091b:2, /Recovery/TransactionStatusManager, ObjectStore.OS_ORIGINAL)
131 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.genPathName(a00020d:d31:4766091b:2, /Recovery/TransactionStatusManager, ObjectStore.OS_ORIGINAL)
141 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.openAndLock(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\Recovery\TransactionStatusManager\#222#\a00020d_d31_4766091b_2, FileLock.F_WRLCK, true)
141 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.createHierarchy(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\Recovery\TransactionStatusManager\#222#\a00020d_d31_4766091b_2)
181 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.closeAndUnlock(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\Recovery\TransactionStatusManager\#222#\a00020d_d31_4766091b_2, null, java.io.FileOutputStream@1faba46)
181 [main] INFO com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.recovery.TransactionStatusManager_3] - TransactionStatusManager started on port 3377 with service com.arjuna.ats.arjuna.recovery.ActionStatusService
181 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action a00020d:d31:4766091b:0 adding Thread[main,5,main]
181 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action a00020d:d31:4766091b:0 adding Thread[main,5,main] result = true
181 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - TransactionReaper::create ( 120000 )
191 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - TransactionReaper::TransactionReaper ( 120000 )
191 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - TransactionReaper::insert ( BasicAction: a00020d:d31:4766091b:0 status: ActionStatus.RUNNING, 60 )
191 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ReaperElement::ReaperElement ( BasicAction: a00020d:d31:4766091b:0 status: ActionStatus.RUNNING, 60 )
191 [Thread-2] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ReaperThread.run ()
191 [Thread-2] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.internal.arjuna.coordinator.ReaperThread_1] - Thread Thread[Thread-2,5,main] sleeping for 60000
ExampleResource: ExampleXAResource (Constructor)
191 [main] DEBUG com.arjuna.ats.jta.logging.logger - TransactionImple.enlistResource ( ExampleXAResource@16fe0f4 )
191 [main] DEBUG com.arjuna.ats.jta.logging.logger - TransactionImple.getStatus
ExampleResource: setTransactionTimeout
ExampleResource: start
201 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - StateManager::StateManager( 1 )
201 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - AbstractRecord::AbstractRecord (a00020d:d31:4766091b:5, 1)
201 [main] DEBUG com.arjuna.ats.jta.logging.logger - XAResourceRecord.XAResourceRecord ( < 131075, 45, 22, a00020d:d31:4766091b:1-a00020d:d31:4766091b:0a00020d:d31:4766091b:4> )
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for a00020d:d31:4766091b:5
ExampleResource: ExampleXAResource (Constructor)
211 [main] DEBUG com.arjuna.ats.jta.logging.logger - TransactionImple.enlistResource ( ExampleXAResource@fd68b1 )
211 [main] DEBUG com.arjuna.ats.jta.logging.logger - TransactionImple.getStatus
ExampleResource: isSameRM
ExampleResource: setTransactionTimeout
ExampleResource: start
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - StateManager::StateManager( 1 )
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - AbstractRecord::AbstractRecord (a00020d:d31:4766091b:8, 1)
211 [main] DEBUG com.arjuna.ats.jta.logging.logger - XAResourceRecord.XAResourceRecord ( < 131075, 45, 22, a00020d:d31:4766091b:1-a00020d:d31:4766091b:0a00020d:d31:4766091b:7> )
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: a00020d:d31:4766091b:5) : appending /StateManager/AbstractRecord/XAResourceRecord for a00020d:d31:4766091b:8
211 [main] DEBUG com.arjuna.ats.jta.logging.logger - BaseTransaction.commit
211 [main] DEBUG com.arjuna.ats.jta.logging.logger - TransactionImple.commitAndDisassociate
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - BasicAction::End() for action-id a00020d:d31:4766091b:0
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - BasicAction::prepare () for action-id a00020d:d31:4766091b:0
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.ShadowingStore( 14 )
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowNoFileLockStore.ShadowNoFileLockStore( 14 )
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.HashedStore( 14 )
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.HashedActionStore()
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.setupStore()
211 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.createHierarchy(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\)
211 [main] DEBUG com.arjuna.ats.jta.logging.logger - XAResourceRecord.topLevelPrepare for < 131075, 45, 22, a00020d:d31:4766091b:1-a00020d:d31:4766091b:0a00020d:d31:4766091b:4>
ExampleResource: end
ExampleResource: prepare
221 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for a00020d:d31:4766091b:5
221 [main] DEBUG com.arjuna.ats.jta.logging.logger - XAResourceRecord.topLevelPrepare for < 131075, 45, 22, a00020d:d31:4766091b:1-a00020d:d31:4766091b:0a00020d:d31:4766091b:7>
ExampleResource: end
ExampleResource: prepare
221 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: a00020d:d31:4766091b:5) : appending /StateManager/AbstractRecord/XAResourceRecord for a00020d:d31:4766091b:8
221 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - OutputObjectState::OutputObjectState(a00020d:d31:4766091b:0, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
221 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - BasicAction::save_state ()
221 [main] 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
221 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
ExampleResource: writeObject (Serialized)
241 [main] 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
241 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
ExampleResource: writeObject (Serialized)
241 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD
241 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTING
241 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.write_committed(a00020d:d31:4766091b:0, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
241 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.write_state(a00020d:d31:4766091b:0, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
241 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.genPathName(a00020d:d31:4766091b:0, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
241 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.openAndLock(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#224#\a00020d_d31_4766091b_0, FileLock.F_WRLCK, true)
241 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.createHierarchy(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#224#\a00020d_d31_4766091b_0)
291 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.closeAndUnlock(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#224#\a00020d_d31_4766091b_0, null, java.io.FileOutputStream@13bd574)
291 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - BasicAction::phase2Commit() for action-id a00020d:d31:4766091b:0
291 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@13adc56)
291 [main] DEBUG com.arjuna.ats.jta.logging.logger - XAResourceRecord.topLevelCommit for < 131075, 45, 22, a00020d:d31:4766091b:1-a00020d:d31:4766091b:0a00020d:d31:4766091b:4>
ExampleResource: commit,xid=< 131075, 45, 22, a00020d:d31:4766091b:1-a00020d:d31:4766091b:0a00020d:d31:4766091b:4>,onePhase=false
ExampleResource: Sleeping 20000 milliseconds
10035 [Thread-0] INFO com.arjuna.ats.arjuna.logging.arjLogger - Periodic recovery - second pass <Sun, 16 Dec 2007 22:29:09>
ExampleResource: Sleep complete
20300 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@157aa53)
20300 [main] DEBUG com.arjuna.ats.jta.logging.logger - XAResourceRecord.topLevelCommit for < 131075, 45, 22, a00020d:d31:4766091b:1-a00020d:d31:4766091b:0a00020d:d31:4766091b:7>
ExampleResource: commit,xid=< 131075, 45, 22, a00020d:d31:4766091b:1-a00020d:d31:4766091b:0a00020d:d31:4766091b:7>,onePhase=false
ExampleResource: Sleeping 20000 milliseconds
34069 [Thread-1] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - FileSystemStore.remove_committed(a00020d:d31:4766091b:2, /Recovery/TransactionStatusManager)
34069 [Thread-1] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.remove_state(a00020d:d31:4766091b:2, /Recovery/TransactionStatusManager, ObjectStore.OS_ORIGINAL)
34069 [Thread-1] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.genPathName(a00020d:d31:4766091b:2, /Recovery/TransactionStatusManager, ObjectStore.OS_SHADOW)
34069 [Thread-1] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.genPathName(a00020d:d31:4766091b:2, /Recovery/TransactionStatusManager, ObjectStore.OS_ORIGINAL)
34069 [Thread-1] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(a00020d:d31:4766091b:2, /Recovery/TransactionStatusManager) - returning ObjectStore.OS_COMMITTED
34069 [Thread-1] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - HashedStore.genPathName(a00020d:d31:4766091b:2, /Recovery/TransactionStatusManager, ObjectStore.OS_ORIGINAL)
34069 [Thread-1] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.openAndLock(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\Recovery\TransactionStatusManager\#222#\a00020d_d31_4766091b_2, FileLock.F_WRLCK, false)
34079 [Thread-1] DEBUG com.arjuna.ats.arjuna.logging.arjLogger - ShadowingStore.closeAndUnlock(C:\cygwin\home\rtrask\jta\localrecovery\ObjectStore\HashedActionStore\defaultStore\Recovery\TransactionStatusManager\#222#\a00020d_d31_4766091b_2, null, null)

Checking the ObjectStore yeilds:

$ find /c/jboss/jboss-4.2.1.GA/server/mssql-fast/data -type f -ls
562949953943074 1 -rwxrwxr-x 1 rtrask Domain Users 45 Nov 23 17:03 /c/jboss/jboss-4.2.1.GA/server/mssql-fast/data/jboss.identity
1179098677440942147 1 -rwxrwxr-x 1 rtrask Domain Users 36 Dec 16 22:27 /c/jboss/jboss-4.2.1.GA/server/mssql-fast/data/tx-object-store/HashedActionStore/defaultStore/Recovery/TransactionStatusManager/#100#/a00020d_d03_476608a7_0

The output from running "java Test -recover" is:

0 [main] INFO com.arjuna.ats.arjuna.logging.arjLogger -
 --- Start RecoveryActivators
30 [main] DEBUG com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.internal.arjuna.recovery.ExpiredEntryMonitor_3] - No Expiry scanners loaded - not scanning
40 [main] INFO com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.internal.arjuna.recovery.ready] RecoveryManagerImple is ready on port 3,380
DONE
90 [Thread-0] INFO com.arjuna.ats.arjuna.logging.arjLogger - Periodic recovery - first pass <Sun, 16 Dec 2007 22:30:39>
10084 [Thread-0] INFO com.arjuna.ats.arjuna.logging.arjLogger - Periodic recovery - second pass <Sun, 16 Dec 2007 22:30:49>

Checking the ObjectStore shows that the log entry is still present.

If you now try to repeat the process, you will find that you can not until you bounce SQL Server.

I ran into a similar issue in my application in an MDB that had a UserTransaction which got hung up. I have not researched the issue fully, but I found that switching to CMT allowed me to get past the issue to continue with some sunny day testing. This does not really solve my issue, because I need to set a long transaction timeout on the MDB.

I hope this helps.

I am wondering about the work around that Jeremy developed. How much of the problem does it resolve? As he asked in his original post, is this an appropriate work around? Finally, Jeremy depending on the answers to the above, would you be willing to share your work around?

www.xaware.org

[jeremystone]

Yes. We can share our transaction-related code if it is of any use.

[ratrask]

Thanks Jeremy, could you fill me in on what problems remain after your patch to the transaction code?

[ratrask]

I would like to see your patch, please post it, or if you would prefer, just email it to me directly at [e-mail]

[marklittle]

Have you spoken with Microsoft? Just ignoring the fact that the formatID has been overwritten would certainly not be my preferred option in addressing this.

[jeremystone]

No, I haven't contacted Microsoft. But I agree it's not an ideal solution.

Am sending you the relevant source code by email.

[marklittle]

Thanks.

[ratrask]

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.

Getting back on topic,

Jeremy, Thanks for sharing your code. There was a lot more there than I expected.

I must be doing something wrong, because the log still shows a 131075 formatId rather than a 0 formatId I have verified via verbose:class, that the version of com.arjuna.ats.internal.arjuna.utils.XATxConverter that is getting loaded is the patched version, and I have seen additional messages in the log which I believe are from your code, but I still see 131075 rather than 0. Any Ideas of what I am doing wrong?

I have also modified and copied a version of jbossjta-netPrefect-properties.xml which matches my DefaultDS. I have the jboss database, and my application databases seperate. I assume that this means I will need to modify the code to instantiate a second MSSqlOrphanedProcessDao, what are your thoughts o this?

[jeremystone]

I must be doing something wrong, because the log still shows a 131075 formatId rather than a 0 formatId I have verified via verbose:class, that the version of com.arjuna.ats.internal.arjuna.utils.XATxConverter that is getting loaded is the patched version, and I have seen additional messages in the log which I believe are from your code, but I still see 131075 rather than 0. Any Ideas of what I am doing wrong?

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

I have also modified and copied a version of jbossjta-netPrefect-properties.xml which matches my DefaultDS. I have the jboss database, and my application databases seperate. I assume that this means I will need to modify the code to instantiate a second MSSqlOrphanedProcessDao, what are your thoughts o this?

Yes. The code at present is limited to one data source and one MSSqlOrphanedProcessDao. You would need to modify it if you need to have multiple instances of the Dao within the orphan recovery module. I don't see why this would cause any problems. The recovery module would need to keep track of scans for each database separately and of course the config xml would have to be a bit more complex.

Good luck with it.