[jboss-jira] [JBoss JIRA] (JBMESSAGING-1926) Root cause of XAException.XA_RBCOMMFAIL is never logged

[Duncan Doyle (JIRA)]

Duncan Doyle created JBMESSAGING-1926:
-----------------------------------------

             Summary: Root cause of XAException.XA_RBCOMMFAIL is never logged
                 Key: JBMESSAGING-1926
                 URL: https://issues.jboss.org/browse/JBMESSAGING-1926
             Project: JBoss Messaging
          Issue Type: Feature Request
          Components: Messaging Core
    Affects Versions: 1.4.7.GA
         Environment: RHEL5, JBoss SOA-P 5.1.0
            Reporter: Duncan Doyle


I'm analyzing a SOA-P 5.1 environment which throws a lot JBoss Messaging and transaction related errors, as shown here:
{code}
2012-06-20 06:22:38,711 WARN  [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] XAResourceRecord.prepare - prepare failed with exception XAException.XA_RBCOMMFAIL

2012-06-20 06:22:38,711 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_36] - BasicAction.End() - prepare phase of action-id -53ebcdb1:90b3:4fdef890:4817dd failed.

2012-06-20 06:22:38,711 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_38] - Action Aborting

2012-06-20 06:22:38,781 ERROR [org.jboss.resource.adapter.jms.inflow.JmsServerSession] Unexpected error delivering message delegator->JBossMessage[9210846958925290816]:PERSISTENT, deliveryId=95776

java.lang.reflect.UndeclaredThrowableException

                             at $Proxy1353.onMessage(Unknown Source)

                             at org.jboss.resource.adapter.jms.inflow.JmsServerSession.onMessage(JmsServerSession.java:179)

                             at org.jboss.jms.client.container.ClientConsumer.callOnMessageStatic(ClientConsumer.java:160)

                             at org.jboss.jms.client.container.SessionAspect.handleRun(SessionAspect.java:831)

                             at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect_z_handleRun_694184137.invoke(SessionAspect_z_handleRun_694184137.java)

                             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

                             at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:172)

                             at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:86)

                             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

                             at org.jboss.jms.client.delegate.ClientSessionDelegate.run(ClientSessionDelegate.java)

                             at org.jboss.jms.client.JBossSession.run(JBossSession.java:199)

                             at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:236)

                             at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)

                             at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)

                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

                             at java.lang.Thread.run(Thread.java:662)

Caused by: javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Could not commit transaction.

                             at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1443)

                             at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)

                             at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)

                             at org.jboss.soa.esb.listeners.jca.EndpointProxy.endTransaction(EndpointProxy.java:401)

                             at org.jboss.soa.esb.listeners.jca.EndpointProxy.delivery(EndpointProxy.java:281)

                             at org.jboss.soa.esb.listeners.jca.EndpointProxy.invoke(EndpointProxy.java:150)

                             ... 17 more
{code}

The problem I'm facing is that I can see that an XAException.XA_RBCOMMFAIL is thrown, but I can't see the root cause that caused this exception to be thrown.

I've tracked the probable cause back to the ResourceManager.sendTransactionXA(...) method, which, in case that the 'connection.sendTransaction(request, false)' throws a Throwable, creates a MessagingXAException, which wraps the root exception (i.e. the Throwable). This exception propagates back, through ResourceManager.prepare(...) and MessagingXAResource.prepare(...) to XAResourceRecord.topLevelPrepare(...). XAResourceRecord.topLevelPrepare(...) only logs the XA error code (i.e. XA_RBCOMMFAIL), but nowhere in that stack is the actual root-cause logged. This makes it extremely difficult to debug this problem.

In my opinion, the root cause (i.e. the Throwable) should be logged on DEBUG or WARN level by the ResourceManager in ResourceManager.sendTransactionXA(...). This is already done when it catches a JMSSecurityException, but not when it  catches a Throwable.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.jboss.org/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira