[JBTM-2216] Extraneous warning message observed in XARecoveryModule.xaRecoverySecondPass if the first pass has already failed

Type: Bug
Resolution: Done
Priority: Major
Fix Version/s: 4.17.23, 5.0.4
Affects Version/s: 4.17.20, 4.17.21, 5.0.2
Component/s: JTA
Labels:
None

Steps to Reproduce:
Hide

Add AMQ RA and configure it so it contains ServerUrl property that uses failover protocol for example:

<config-property name="ServerUrl"> failover:(tcp://host1:61616?trace=true,tcp://host2:61616?trace=true)?initialReconnectDelay=100&jms.rmIdFromConnectionId=true&maxReconnectAttempts=0 </config-property>

Start JBoss EAP server and wait until the recovery runs second time. The errors will appear in the server log file.
Show
Add AMQ RA and configure it so it contains ServerUrl property that uses failover protocol for example: <config-property name="ServerUrl"> failover:(tcp://host1:61616?trace=true,tcp://host2:61616?trace=true)?initialReconnectDelay=100&jms.rmIdFromConnectionId=true&maxReconnectAttempts=0 </config-property> Start JBoss EAP server and wait until the recovery runs second time. The errors will appear in the server log file.
Workaround Description:

Hide

None

Show
None
Bugzilla References:
https://bugzilla.redhat.com/show_bug.cgi?id=1166754

When using AMQ failover protocol, the Narayana recovery process generates the following exception:

10:19:36,053 INFO  [org.apache.activemq.transport.failover.FailoverTransport] (ActiveMQ Task-1) Successfully connected to tcp://ragga:61616?trace=true
10:21:46,139 INFO  [org.apache.activemq.transport.failover.FailoverTransport] (ActiveMQ Task-1) Successfully connected to tcp://ragga:61616?trace=true
10:21:46,139 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016027: Local XARecoveryModule.xaRecovery got XA exception XAException.XAER_RMERR: javax.transaction.xa.XAException: Failover transport not connected: unconnected
	at org.apache.activemq.TransactionContext.recover(TransactionContext.java:656)
	at org.apache.activemq.ra.LocalAndXATransaction.recover(LocalAndXATransaction.java:135)
	at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.recover(XAResourceWrapperImpl.java:177)
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass(XARecoveryModule.java:548) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass(XARecoveryModule.java:187) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:743) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]

10:21:56,165 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016008: Local XARecoveryModule.xaRecovery - caught exception: java.lang.NullPointerException
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:619) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:431) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:212) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:789) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]

Although the first message may be expected if the resource manager throws an exception in XAResource::recover(), the second message does not add any further assistance in resolving the issue and should be removed as noise.

Tom Jenkinson added a comment - 2014/09/15 9:41 AM

Resolved in https://github.com/jbosstm/narayana/commit/18f1884ee15da0c2ec6a2a33e2bdacd1f8187cca

Tom Jenkinson added a comment - 2014/09/15 9:41 AM Resolved in https://github.com/jbosstm/narayana/commit/18f1884ee15da0c2ec6a2a33e2bdacd1f8187cca

Mark Little added a comment - 2014/07/04 10:36 AM

We should probably be more defensive, but the JTA spec "clearly" (well, as clearly as it ever does) doesn't allow null to be returned:

"The resource manager returns zero or more Xids for the transaction branches that are currently in a prepared or heuristically completed state. If an error occurs during the operation, the resource manager should throw the appropriate XAException."

So an array of 0 size is ok, but null isn't.

Mark Little added a comment - 2014/07/04 10:36 AM We should probably be more defensive, but the JTA spec "clearly" (well, as clearly as it ever does) doesn't allow null to be returned: "The resource manager returns zero or more Xids for the transaction branches that are currently in a prepared or heuristically completed state. If an error occurs during the operation, the resource manager should throw the appropriate XAException." So an array of 0 size is ok, but null isn't.

Tom Jenkinson added a comment - 2014/07/04 6:16 AM

Also, the first issue is not harmless, it means that recovery isn't going to work for the resource manager.

Tom Jenkinson added a comment - 2014/07/04 6:16 AM Also, the first issue is not harmless, it means that recovery isn't going to work for the resource manager.

Tom Jenkinson added a comment - 2014/07/04 6:10 AM

OK, I see your comment now. I will update the description to refer to the NPE rather than the error message coming from the resource manager.

Tom Jenkinson added a comment - 2014/07/04 6:10 AM OK, I see your comment now. I will update the description to refer to the NPE rather than the error message coming from the resource manager.

Tom Jenkinson added a comment - 2014/07/04 6:09 AM

Hi Tom,

Although I concede that the NPE is a little ugly, it won't have a material effect on the issue at hand.

The core problem is:
10:21:46,139 WARN [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016027: Local XARecoveryModule.xaRecovery got XA exception XAException.XAER_RMERR: javax.transaction.xa.XAException: Failover transport not connected: unconnected
at org.apache.activemq.TransactionContext.recover(TransactionContext.java:656)
at org.apache.activemq.ra.LocalAndXATransaction.recover(LocalAndXATransaction.java:135)
at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.recover(XAResourceWrapperImpl.java:177)
at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass(XARecoveryModule.java:548) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]
at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass(XARecoveryModule.java:187) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]
at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:743) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]
at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1]

This is an issue in the underlying resource manager and is not something that Narayana can handle any differently. We are calling XAResource::recover (http://docs.oracle.com/javaee/7/api/javax/transaction/xa/XAResource.html#recover(int)) and it is returning an error.

If you are happy with my explanation I will change this bug to be that we should check for the possibility of null in the second phase of recovery though, as I say above, it won't have a material effect on your case.

Tom

Tom Jenkinson added a comment - 2014/07/04 6:09 AM Hi Tom, Although I concede that the NPE is a little ugly, it won't have a material effect on the issue at hand. The core problem is: 10:21:46,139 WARN [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016027: Local XARecoveryModule.xaRecovery got XA exception XAException.XAER_RMERR: javax.transaction.xa.XAException: Failover transport not connected: unconnected at org.apache.activemq.TransactionContext.recover(TransactionContext.java:656) at org.apache.activemq.ra.LocalAndXATransaction.recover(LocalAndXATransaction.java:135) at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.recover(XAResourceWrapperImpl.java:177) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass(XARecoveryModule.java:548) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1] at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass(XARecoveryModule.java:187) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1] at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:743) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1] at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) [jbossjts-jacorb-4.17.21.Final-redhat-1.jar:4.17.21.Final-redhat-1] This is an issue in the underlying resource manager and is not something that Narayana can handle any differently. We are calling XAResource::recover ( http://docs.oracle.com/javaee/7/api/javax/transaction/xa/XAResource.html#recover(int )) and it is returning an error. If you are happy with my explanation I will change this bug to be that we should check for the possibility of null in the second phase of recovery though, as I say above, it won't have a material effect on your case. Tom

Tom Ross added a comment - 2014/07/04 5:58 AM

As far as I can tell the exceptions are completely harmless.

Tom Ross added a comment - 2014/07/04 5:58 AM As far as I can tell the exceptions are completely harmless.

Assignee:: Tom Jenkinson

Reporter:: Tom Ross

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Created:: 2014/07/04 5:44 AM

Updated:: 2015/03/13 3:11 PM

Resolved:: 2014/09/15 9:41 AM

Details

Description

Attachments

Easy Agile Planning Poker

Activity

Collapse comment: Tom Jenkinson added a comment - 2014/09/15 9:41 AM

Expand comment: Tom Jenkinson added a comment - 2014/09/15 9:41 AM

Collapse comment: Mark Little added a comment - 2014/07/04 10:36 AM

Expand comment: Mark Little added a comment - 2014/07/04 10:36 AM

Collapse comment: Tom Jenkinson added a comment - 2014/07/04 6:16 AM

Expand comment: Tom Jenkinson added a comment - 2014/07/04 6:16 AM

Collapse comment: Tom Jenkinson added a comment - 2014/07/04 6:10 AM

Expand comment: Tom Jenkinson added a comment - 2014/07/04 6:10 AM

Collapse comment: Tom Jenkinson added a comment - 2014/07/04 6:09 AM

Expand comment: Tom Jenkinson added a comment - 2014/07/04 6:09 AM

Collapse comment: Tom Ross added a comment - 2014/07/04 5:58 AM

Expand comment: Tom Ross added a comment - 2014/07/04 5:58 AM

People

Dates