3 Replies Latest reply on Jun 19, 2006 8:11 AM by timfox

    Bizzare transaction commits..

    mskonda Jun 13, 2006 11:54 AM

      I am doing the xarecovery tests and found out a bizzare thing. Here's the scenario:

      I have created an in-doubt transaction (left the tx in PREPARED state, see log below)

      2006-06-13 16:29:28,299 TRACE [org.jboss.messaging.core.plugin.JDBCPersistenceManager] Inserting tx record for TX(0):ACTIVE
2006-06-13 16:29:28,302 TRACE [org.jboss.messaging.core.plugin.JDBCPersistenceManager] INSERT INTO JMSTransaction (TransactionId, BranchQual, FormatId, GlobalTxId) VALUES(0, <byte-array>, 131075, <byte-array>) inserted 1 row(s)
2006-06-13 16:29:28,303 TRACE [org.jboss.messaging.core.plugin.JDBCPersistenceManager] adding Reference[256]:RELIABLE to channel 21 on transaction: TX(0):ACTIVE
2006-06-13 16:29:28,304 TRACE [org.jboss.messaging.core.plugin.JDBCPersistenceManager] Inserted 1 rows
2006-06-13 16:29:28,315 TRACE [org.jboss.messaging.core.plugin.JDBCPersistenceManager] Inserted 1 rows
2006-06-13 16:29:28,336 TRACE [org.jboss.messaging.core.tx.Transaction] prepared TX(0):PREPARED
2006-06-13 16:29:28,336 TRACE [org.jboss.messaging.core.tx.Transaction] executing after prepare hooks TX(0):PREPARED
2006-06-13 16:29:28,336 TRACE [org.jboss.messaging.core.tx.Transaction] prepare process complete TX(0):PREPARED


      (I have chekced the database (in my case Sybase) for the transaction log and a record of prepared tx is present)

      I have re-booted the server back so the recovery manager starts its recovery process.

      It recovers the dummy resources as expected. However when it come to the recovery of messaging resource, the console output says that it has recovered a pending tx and committed. So it the server log. However, the tx is not erased from the database. The server trace indicates that it has COMMMITTED a tx (BUT with a different ID) which I think is bizzare.

      see the trace below: 
      2006-06-13 16:39:16,731 TRACE [org.jboss.jms.tx.ResourceManager] calling recover with flags: 8388608
2006-06-13 16:39:16,731 INFO [com.mizuho.cmi2.xa.recovery.MessagingRecoveryModule] Number of transactions: 1
2006-06-13 16:39:16,731 INFO [com.mizuho.cmi2.xa.recovery.MessagingRecoveryModule] committing transaction: 131075
2006-06-13 16:39:16,731 TRACE [org.jboss.jms.tx.MessagingXAResource] MessagingXAResource[-2147483645] committing org.jboss.messaging.core.tx.XidImpl@ff2add8 (two phase)
2006-06-13 16:39:16,731 TRACE [org.jboss.jms.tx.ResourceManager] commiting xid org.jboss.messaging.core.tx.XidImpl@ff2add8, onePhase=false
2006-06-13 16:39:16,734 TRACE [org.jboss.messaging.core.tx.Transaction] executing before commit hooks TX(4096):PREPARED
2006-06-13 16:39:16,734 TRACE [org.jboss.messaging.core.tx.Transaction] committed TX(4096):COMMITTED
2006-06-13 16:39:16,734 TRACE [org.jboss.messaging.core.tx.Transaction] executing after commit hooks TX(4096):COMMITTED
2006-06-13 16:39:16,734 TRACE [org.jboss.messaging.core.tx.Transaction] commit process complete TX(4096):COMMITTED
2006-06-13 16:39:16,734 INFO [com.mizuho.cmi2.xa.recovery.MessagingRecoveryModule] Finished the resource recovery
2006-06-13 16:39:16,731 TRACE [org.jboss.jms.tx.ResourceManager] calling recover with flags: 8388608
2006-06-13 16:39:16,731 INFO [com.mizuho.cmi2.xa.recovery.MessagingRecoveryModule] Number of transactions: 1
2006-06-13 16:39:16,731 INFO [com.mizuho.cmi2.xa.recovery.MessagingRecoveryModule] committing transaction: 131075
2006-06-13 16:39:16,731 TRACE [org.jboss.jms.tx.MessagingXAResource] MessagingXAResource[-2147483645] committing org.jboss.messaging.core.tx.XidImpl@ff2add8 (two phase)
2006-06-13 16:39:16,731 TRACE [org.jboss.jms.tx.ResourceManager] commiting xid org.jboss.messaging.core.tx.XidImpl@ff2add8, onePhase=false
2006-06-13 16:39:16,734 TRACE [org.jboss.messaging.core.tx.Transaction] executing before commit hooks TX(4096):PREPARED
2006-06-13 16:39:16,734 TRACE [org.jboss.messaging.core.tx.Transaction] committed TX(4096):COMMITTED
2006-06-13 16:39:16,734 TRACE [org.jboss.messaging.core.tx.Transaction] executing after commit hooks TX(4096):COMMITTED
2006-06-13 16:39:16,734 TRACE [org.jboss.messaging.core.tx.Transaction] commit process complete TX(4096):COMMITTED
2006-06-13 16:39:16,734 INFO [com.mizuho.cmi2.xa.recovery.MessagingRecoveryModule] Finished the resource recovery


      The bizzare (to me) things that I see are:

      A commit is executed on a Tx id 4096 where as the actual PREPARED tx was 0. How did the MessagingResource return this id 4096 (as everything was wiped off from the tables before starting the tests, there are no other tx in the databse other than the one with id 0). So how come a tx with id 4096 was created?

      The original tx with id 0 is still in the database as PREPARED!

      When I run the similar tests on a non-appserver platform, the transactions are recovered without any issues.

      Tell me I am doing something obviously wrong!

      Thanks
      Madhu

      • 3103 Views
      • Tags: