Recovery manager not calling recover

[timfox]

I notice that after our application (JBM) has been running for a while, the recovery manager only calls hasMoreResources() on the XAResourceRecovery instance.

16:39:58,812 INFO @Thread-4 [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
16:40:00,812 INFO @Thread-4 [arjLogger] Periodic recovery - second pass <Thu, 18 Jan 2007 16:40:00>
16:40:00,812 INFO @Thread-4 [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
16:40:00,812 TRACE @Thread-4 [BridgeXAResourceRecovery] org.jboss.jms.recovery.BridgeXAResourceRecovery@1e1dadb hasMoreResources
16:40:00,812 INFO @Thread-4 [BridgeXAResourceRecovery] Returning false
16:40:00,812 TRACE @Thread-4 [BridgeXAResourceRecovery] org.jboss.jms.recovery.BridgeXAResourceRecovery@e79839 hasMoreResources
16:40:00,812 INFO @Thread-4 [BridgeXAResourceRecovery] Returning false
16:40:10,812 INFO @Thread-4 [arjLogger] Periodic recovery - first pass <Thu, 18 Jan 2007 16:40:10>
16:40:10,812 INFO @Thread-4 [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
16:40:12,812 INFO @Thread-4 [arjLogger] Periodic recovery - second pass <Thu, 18 Jan 2007 16:40:12>
16:40:12,812 INFO @Thread-4 [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
16:40:12,812 TRACE @Thread-4 [BridgeXAResourceRecovery] org.jboss.jms.recovery.BridgeXAResourceRecovery@1e1dadb hasMoreResources
16:40:12,812 INFO @Thread-4 [BridgeXAResourceRecovery] Returning false
16:40:12,812 TRACE @Thread-4 [BridgeXAResourceRecovery] org.jboss.jms.recovery.BridgeXAResourceRecovery@e79839 hasMoreResources
16:40:12,812 INFO @Thread-4 [BridgeXAResourceRecovery] Returning false
16:40:16,968 WARN @Thread-5 [LeasePinger] Error sending lease ping to server for client invoker (session id 5c4o1b-flxk13-ex3esvbm-1-ex3eswde-b.
16:40:22,812 INFO @Thread-4 [arjLogger] Periodic recovery - first pass <Thu, 18 Jan 2007 16:40:22>
16:40:22,812 INFO @Thread-4 [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
16:40:24,812 INFO @Thread-4 [arjLogger] Periodic recovery - second pass <Thu, 18 Jan 2007 16:40:24>
16:40:24,812 INFO @Thread-4 [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
16:40:24,812 TRACE @Thread-4 [BridgeXAResourceRecovery] org.jboss.jms.recovery.BridgeXAResourceRecovery@1e1dadb hasMoreResources
16:40:24,812 INFO @Thread-4 [BridgeXAResourceRecovery] Returning false
16:40:24,812 TRACE @Thread-4 [BridgeXAResourceRecovery] org.jboss.jms.recovery.BridgeXAResourceRecovery@e79839 hasMoreResources
16:40:24,812 INFO @Thread-4 [BridgeXAResourceRecovery] Returning false
16:40:34,812 INFO @Thread-4 [arjLogger] Periodic recovery - first pass <Thu, 18 Jan 2007 16:40:34>
16:40:34,812 INFO @Thread-4 [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
16:40:36,828 INFO @Thread-4 [arjLogger] Periodic recovery - second pass <Thu, 18 Jan 2007 16:40:36>
16:40:36,828 INFO @Thread-4 [loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
16:40:36,828 TRACE @Thread-4 [BridgeXAResourceRecovery] org.jboss.jms.recovery.BridgeXAResourceRecovery@1e1dadb hasMoreResources
16:40:36,828 INFO @Thread-4 [BridgeXAResourceRecovery] Returning false
16:40:36,828 TRACE @Thread-4 [BridgeXAResourceRecovery] org.jboss.jms.recovery.BridgeXAResourceRecovery@e79839 hasMoreResources
16:40:36,828 INFO @Thread-4 [BridgeXAResourceRecovery] Returning false
16:40:36,984 WARN @Thread-5 [LeasePinger] Error sending lease ping to server for client invoker (session id 5c4o1b-flxk13-ex3esvbm-1-ex3eswde-b.

It doesn't call getXAResource() any more, neither does it call recover() on any previously got XAResources, or any other operations on them.

Is this correct operation? If so, then how can it know about any new transactions to recover?

[marklittle]

Did your resource return a list of Xids to recover during the first call to recover?

[timfox]

Yes, earlier calls to recover() return a list of Xids.

Then later I force a HeuristicMixedException by crashing the server of the second xa resource (there are 2 enlisted in the tx) at commit.

16:39:42,984 WARN @Thread-7 [loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror] [com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror] XAResourceRecord.commit - xa error XAException.XAER_RMERR
16:39:43,234 WARN @Thread-7 [Bridge] Failed to send + acknowledge batch, closing JMS objects
javax.transaction.HeuristicMixedException
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commit(TransactionImple.java:227)
 at org.jboss.jms.server.bridge.Bridge.sendBatch(Bridge.java:1169)
 at org.jboss.jms.server.bridge.Bridge.access$1500(Bridge.java:57)
 at org.jboss.jms.server.bridge.Bridge$BatchTimeChecker.run(Bridge.java:1270)
 at java.lang.Thread.run(Thread.java:534)
16:39:43,234 TRACE @Thread-7 [Bridge] org.jboss.jms.server.bridge.Bridge$BatchTimeChecker@1144ba2 sent batch

Some time after that I would expect the recovery manager to retry commiting that xaresource by calling recover() on a XAresource returned from our XAResourceRecovery instance, but the recovery manager never attempts this.

I can see the period first and second pass occurring, but as I say, they simply call hasMoreResources() which returns false, and the branch never gets committed.

[marklittle]

Is your XAResource serializable? It doesn't need to be, but it does affect the path through recovery. Hence the question.

[timfox]

No it's not serializable.

[marklittle]

If your resource throws a heuristic exception then it is supposed to have logged that fact. Did it? Also, is there a transaction log entry in the object store corresponding to the transaction within which your heuristic exception is caught?

[timfox]

The resource doesn't throw a heuristic exception, the resource throws a XAException.XAER_RMERR - arjuna catches this and throws a heuristic back up to the caller of commit(), this can be seen in the logs:

18:10:44,234 WARN @Thread-5 [loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror] [com.arjuna.ats.internal.jta.resources.arjunacore.commitxaerror] XAResourceRecord.commit - xa error XAException.XAER_RMERR
18:10:44,281 WARN @Thread-5 [Bridge] Failed to send + acknowledge batch, closing JMS objects
javax.transaction.HeuristicMixedException
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commit(TransactionImple.java:227)
 at org.jboss.jms.server.bridge.Bridge.sendBatch(Bridge.java:1169)
 at org.jboss.jms.server.bridge.Bridge.access$1500(Bridge.java:57)
 at org.jboss.jms.server.bridge.Bridge$BatchTimeChecker.run(Bridge.java:1270)
 at java.lang.Thread.run(Thread.java:534)

The uncommitted branch is logged - I can see this in the database (we use the db as out log) - this would have been inserted at the prepare stage.

I can see it sitting there waiting to be committed.

In the objectStore directory I can see ShadowNoFileLockStore (we are configured to use this) which has nothing in it.

(There is also HashedActionStore which has a couple of files in it's directories - but I don't think we're configured to use that)

[marklittle]

"timfox" wrote:

(There is also HashedActionStore which has a couple of files in it's directories - but I don't think we're configured to use that)

That's the transaction log. Is there any way you can clear this out and re-run only this one test? Just so we can check that everything in the log is solely on behalf of this case.

[timfox]

I have deleted the entire ObjectStore and cleared out the db and run the test.

At the end the prepared branch is in the database and in the objectstore I have:

a file in:

HashActionStore/defaultStore/Recovery/TransactionStatusManager/#223#

and another file in:

HashActionStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/#216#

[timfox]

Is there a tool that will allow me to read the contents of the transaction log in a human way?

I.e. see the xids and what state the tx is in?

[timfox]

The stuff in the files looks like some kind of Java serialization output, I think I can tell by the huge amount of useless padding Java serialization adds ;)

[marklittle]

"timfox" wrote:
The stuff in the files looks like some kind of Java serialization output, I think I can tell by the huge amount of useless padding Java serialization adds ;)

Nope. It's a format that predates Java and is intended to be language neutral. But we digress ;-)

[weston.price]

Speaking of 'useless', Tim, did you consider a career in something else other than computers?

;-)

[weston.price]

Oh, BTW, Tim you should read:

http://www.amazon.com/Java-Transaction-Processing-Implementation-Professional/dp/013035290X/sr=8-1/qid=1169148545/ref=pd_bbs_sr_1/105-5425912-8224448?ie=UTF8&s=books

It's a great read! And plus, you might actually feel less compelled to recommend it to others once you have actually read it yourself!

Cheers Mate!

[marklittle]

It's a great read! And plus, you might actually feel less compelled to recommend it to others once you have actually read it yourself!

So you won't be interested in the second edition then ;-)?