[jhalliday]

> I have set DEBUG on the "com.arjuna" in the jboss-log4j.xml file do you need more than this? If so what do you want me to set?

If I had a dime for every user who does not read the manuals....

jbossts-properties.xml: com.arjuna.common.util.logging.DebugLevel 0xffffffff

> Then how do you want me to send this large server.log file?

1) Buy a support contract
2) Log on to the customer support portal
3) Upload the file.

Huh? What's that? You wanted a free option? Figure one out for yourself, it's not a significant concern to me.

[scarceller]

Jonathan,

I understand you are busy and that I have no support contract, I'm simply evaluating the ability of JBossASv5.1 to handle 2PC XA Transactions. So any help you can provide is most appreciated. I'm trying to get what you would need to quickly spot any issue, short of having a support contract I'll simply ask for your help in reviewing this section of the log file after I turned on more debugging as you instructed.

Here is the section that the TM repeats trying to recover the in-doubt, Is the TM really trying to rollback this transaction? if so why?

2009-07-22 12:12:55,062 INFO [org.jboss.bootstrap.microcontainer.ServerImpl] (main) JBoss (Microcontainer) [5.1.0.GA (build: SVNTag=JBoss_5_1_0_GA date=200905221053)] Started in 1m:3s:0ms

2009-07-22 12:12:57,718 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-9) ReaperThread.run ()
2009-07-22 12:12:57,718 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-9) TransactionReaper::check ()
2009-07-22 12:12:57,718 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-9) [com.arjuna.ats.internal.arjuna.coordinator.ReaperThread_1] - Thread Thread[Thread-9,5,jboss] sleeping for 9223372036854775807
2009-07-22 12:13:05,515 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) PeriodicRecovery: background thread Status <== SCANNING
2009-07-22 12:13:05,515 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) PeriodicRecovery: background thread scanning
2009-07-22 12:13:05,515 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) Periodic recovery - first pass <Wed, 22 Jul 2009 12:13:05>
2009-07-22 12:13:05,515 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] (Thread-12) [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2009-07-22 12:13:05,515 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) InputObjectState::InputObjectState()
2009-07-22 12:13:05,515 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid : 0:0:0:0
InputObjectState Type : null
InputObjectState Size : 0
InputObjectState Buffer: , 0)
2009-07-22 12:13:05,515 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) OutputObjectState::OutputObjectState()
2009-07-22 12:13:05,515 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12)
2009-07-22 12:13:15,515 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) Periodic recovery - second pass <Wed, 22 Jul 2009 12:13:15>
2009-07-22 12:13:15,515 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] (Thread-12) [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
2009-07-22 12:13:15,515 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Local XARecoveryModule.transactionInitiatedRecovery completed
2009-07-22 12:13:15,531 DEBUG [com.arjuna.ats.internal.jbossatx.jta.AppServerJDBCXARecovery] (Thread-12) XA datasource does not support isValid method - connection will always be recreated
2009-07-22 12:13:15,546 DEBUG [com.arjuna.ats.internal.jbossatx.jta.AppServerJDBCXARecovery] (Thread-12) Created new XAConnection
2009-07-22 12:13:15,546 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) xarecovery of oracle.jdbc.driver.T4CXAResource@1de22aa
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Found 1 xids in doubt
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Have 1 Xids to recover on this pass.
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Checking node name of oracle.jdbc.xa.OracleXid@a3d197
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Node name is 1
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Will recover this Xid (b)
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] (Thread-12) [com.arjuna.ats.internal.jta.recovery.info.rollingback] Rolling back < 131075, 28, 26, 49454551102535557575349585454995852975455495752100585451101455110253555757534958545499585297545549575210058555356 >
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) ShadowingStore.ShadowingStore( 14 )
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) ShadowNoFileLockStore.ShadowNoFileLockStore( 14 )
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) HashedStore.HashedStore( 14 )
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) HashedStore.HashedActionStore()
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) FileSystemStore.setupStore()
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) FileSystemStore.createHierarchy(C:\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\)
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) HashedStore.genPathName(-3f579951:66c:4a67194d:63e, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) HashedStore.genPathName(-3f579951:66c:4a67194d:63e, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-12) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f579951:66c:4a67194d:63e, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
2009-07-22 12:13:15,578 DEBUG [com.arjuna.ats.internal.jbossatx.jta.AppServerJDBCXARecovery] (Thread-12) XA datasource does not support isValid method - connection will always be recreated
2009-07-22 12:13:15,624 DEBUG [com.arjuna.ats.internal.jbossatx.jta.AppServerJDBCXARecovery] (Thread-12) Created new XAConnection
2009-07-22 12:13:15,624 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) xarecovery of com.ibm.db2.jcc.b.ic@371c41
2009-07-22 12:13:15,671 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Found 0 xids in doubt
2009-07-22 12:13:15,671 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Local XARecoveryModule.resourceInitiatedRecovery completed
2009-07-22 12:13:15,671 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12)
2009-07-22 12:13:15,671 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) PeriodicRecovery: background thread Status <== INACTIVE
2009-07-22 12:13:15,671 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-12) PeriodicRecovery: background thread backing off

[jhalliday]

2009-07-22 12:13:15,546 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) xarecovery of oracle.jdbc.driver.T4CXAResource@1de22aa
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Found 1 xids in doubt
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Have 1 Xids to recover on this pass.
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Checking node name of oracle.jdbc.xa.OracleXid@a3d197
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Node name is 1
2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-12) Will recover this Xid (b)

Well the good news is the AppServerJDBCXARecovery is working fine - it finds the in-doubt tx in the db and decides to do something about it.

2009-07-22 12:13:15,562 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] (Thread-12) [com.arjuna.ats.internal.jta.recovery.info.rollingback]

That bit is actually misleading due to incorrect placement of the log statements with relation to a conditional check. It's not necessarily going to roll back the tx branch. If it determines the branch belongs to a transaction for which it has a log in the object store, it will leave it alone and let the transaction recovery rather than the XA recovery deal with it. Unfortunately there is no log output for that decision - you'd have to stick a debugger on XARecoveryModule.xaRecovery The full logs should show the recovery module that is dealing with the transaction logs too. If that is processing the tx which owns the Xid it would explain why the XA module is leaving it alone.