1 Reply Latest reply on Jun 18, 2014 9:32 AM by mmusgrov

    In last resource commit optimization, commit call to the last resource isn't invoked last which leads to inconsistent result

    lily.he

      We have a xa recovery test case as following:

      1. Deploy our jms RA to jboss which communicates to weblogic server.

      2. Start one transaction which includes msg sending via the RA to Weblogic server and some DB operations, so two RMs involved.

      3. From jboss log we found DB operations is wrapped by class com.arjuna.ats.internal.arjuna.abstractrecords.LastResourceRecord. LastResourceRecord is used to do the last resource commit optimization.

      4. In our case, weblogic server will shutdown during the prepare call and result in prepare call failed.

      5. From server log, we find jboss TM call DB prepare first and then call weblogic prepare. And DB prepare is optimized as commit call. Then weblogic prepare call failed and then TM try to rollback the transaction. But will got following exception when try to call DB rollback since the transaction in DB has been committed.

       

      Daemon Thread [http--0.0.0.0-8080-2] (Suspended (breakpoint at line 98 in org.jboss.jca.core.tx.jbossts.LocalXAResourceImpl))

        org.jboss.jca.core.tx.jbossts.LocalXAResourceImpl.start(javax.transaction.xa.Xid, int) line: 98

        com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(javax.transaction.xa.XAResource, java.lang.Object[]) line: 636

        com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(javax.transaction.xa.XAResource) line: 397

        org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.enlist() line: 587

        org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist() line: 264

        org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(org.jboss.jca.core.connectionmanager.listener.ConnectionListener) line: 467

        org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl(org.jboss.jca.core.connectionmanager.AbstractConnectionManager).reconnectManagedConnection(org.jboss.jca.core.connectionmanager.listener.ConnectionListener) line: 599

        org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl(org.jboss.jca.core.connectionmanager.AbstractConnectionManager).allocateConnection(javax.resource.spi.ManagedConnectionFactory, javax.resource.spi.ConnectionRequestInfo) line: 467

        org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection() line: 129

        wlstest.functional.jms.wlsra.common.utils.JMSRAServerUtil.getConnection(javax.naming.Context, java.lang.String) line: 952

        wlstest.functional.jms.wlsra.common.utils.JMSRAServerUtil.incrementCounter(javax.naming.Context, java.lang.String, java.lang.String, java.lang.String, java.lang.String) line: 1003

        wlstest.functional.jms.wlsra.JmsraCactusNonGFTest.doTxRecoveryWLSRestartITMInstrumentation(int, java.lang.String, java.lang.String) line: 968

        wlstest.functional.jms.wlsra.JmsraCactusNonGFTest.testTxRecoveryWLSRestartBeforePrepare() line: 739

        sun.reflect.NativeMethodAccessorImpl.invoke0(java.lang.reflect.Method, java.lang.Object, java.lang.Object[]) line: not available [native method]

        sun.reflect.NativeMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[]) line: 57

        sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[]) line: 43

        java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object...) line: 606

        wlstest.functional.jms.wlsra.JmsraCactusNonGFTest(junit.framework.TestCase).runTest() line: 154

        wlstest.functional.jms.wlsra.JmsraCactusNonGFTest(junit.framework.TestCase).runBare() line: 127

        org.apache.cactus.internal.server.ServletTestCaller(org.apache.cactus.internal.server.AbstractWebTestCaller).doTest() line: 124

        org.apache.cactus.internal.server.AbstractWebTestController.handleRequest_aroundBody0(org.apache.cactus.internal.server.AbstractWebTestController, org.apache.cactus.spi.server.ImplicitObjects, org.aspectj.lang.JoinPoint) line: 93

        org.apache.cactus.internal.server.AbstractWebTestController.handleRequest_aroundBody1$advice(org.apache.cactus.internal.server.AbstractWebTestController, org.apache.cactus.spi.server.ImplicitObjects, org.aspectj.lang.JoinPoint, org.apache.cactus.util.log.LogAspect, org.aspectj.runtime.internal.AroundClosure, org.aspectj.lang.JoinPoint) line: 224

        org.apache.cactus.internal.server.ServletTestController(org.apache.cactus.internal.server.AbstractWebTestController).handleRequest(org.apache.cactus.spi.server.ImplicitObjects) line: 1

        org.apache.cactus.server.ServletTestRedirector.doPost_aroundBody2(org.apache.cactus.server.ServletTestRedirector, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, org.aspectj.lang.JoinPoint) line: 101

        org.apache.cactus.server.ServletTestRedirector.doPost_aroundBody3$advice(org.apache.cactus.server.ServletTestRedirector, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, org.aspectj.lang.JoinPoint, org.apache.cactus.util.log.LogAspect, org.aspectj.runtime.internal.AroundClosure, org.aspectj.lang.JoinPoint) line: 224

        org.apache.cactus.server.ServletTestRedirector.doPost(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 1

        org.apache.cactus.server.ServletTestRedirector.doGet_aroundBody0(org.apache.cactus.server.ServletTestRedirector, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, org.aspectj.lang.JoinPoint) line: 72

        org.apache.cactus.server.ServletTestRedirector.doGet_aroundBody1$advice(org.apache.cactus.server.ServletTestRedirector, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, org.aspectj.lang.JoinPoint, org.apache.cactus.util.log.LogAspect, org.aspectj.runtime.internal.AroundClosure, org.aspectj.lang.JoinPoint) line: 224

        org.apache.cactus.server.ServletTestRedirector.doGet(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 1

        org.apache.cactus.server.ServletTestRedirector(javax.servlet.http.HttpServlet).service(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 734

        org.apache.cactus.server.ServletTestRedirector(javax.servlet.http.HttpServlet).service(javax.servlet.ServletRequest, javax.servlet.ServletResponse) line: 847

        org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) line: 329

        org.apache.catalina.core.ApplicationFilterChain.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) line: 248

        org.testlogic.testrunner.ant.cactus.CactusRemoteParamFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) line: 52

        org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) line: 280

        org.apache.catalina.core.ApplicationFilterChain.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) line: 248

        org.apache.catalina.core.StandardWrapperValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) line: 275

        org.apache.catalina.core.StandardContextValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) line: 161

        org.apache.catalina.authenticator.BasicAuthenticator(org.apache.catalina.authenticator.AuthenticatorBase).invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) line: 397

        org.jboss.as.web.security.SecurityContextAssociationValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) line: 153

        org.apache.catalina.core.StandardHostValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) line: 155

        org.apache.catalina.valves.ErrorReportValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) line: 102

        org.apache.catalina.core.StandardEngineValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) line: 109

        org.apache.catalina.connector.CoyoteAdapter.service(org.apache.coyote.Request, org.apache.coyote.Response) line: 368

        org.apache.coyote.http11.Http11Processor.process(java.net.Socket) line: 877

        org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(java.net.Socket) line: 671

        org.apache.tomcat.util.net.JIoEndpoint$Worker.run() line: 930

        java.lang.Thread.run() line: 744

       

      Pls check attached jboss log file.

      two XAResource enlist in one transaction: XAResourceWrapperImpl which represents weblogic opts and LocalXAResourceImpl which represents DB opts

      20:17:13,516 TRACE [com.arjuna.ats.jta] (http--0.0.0.0-8080-2) TransactionImple.enlistResource ( XAResourceWrapperImpl@39ce8088[xaResource=weblogic.jms.ra.XAResourceWrapper@24587e5e pad=false overrideRmValue=false productName=java:jboss/wljmsra/clusterXAQCF productVersion=java:jboss/wljmsra/clusterXAQCF jndiName=java:jboss/wljmsra/clusterXAQCF] )

      20:17:14,729 TRACE [com.arjuna.ats.jta] (http--0.0.0.0-8080-2) TransactionImple.enlistResource ( LocalXAResourceImpl@2f1b7528[connectionListener=634defe1 connectionManager=1c565475 warned=false currentXid=null] )

       

      XAResource prepare sequence: first LastResourceRecord which contains LocalXAResourceImpl and then XAResourceRecord which contains XAResourceWrapperImpl

      20:17:45,008 TRACE [com.arjuna.ats.arjuna] (http--0.0.0.0-8080-2) LastResourceRecord::topLevelPrepare() for 0:0:0:0:1

      20:17:45,013 TRACE [com.arjuna.ats.jta] (http--0.0.0.0-8080-2) XAResourceRecord.topLevelPrepare for XAResourceRecord < resource:XAResourceWrapperImpl@39ce8088[xaResource=weblogic.jms.ra.XAResourceWrapper@24587e5e pad=false overrideRmValue=false productName=java:jboss/wljmsra/clusterXAQCF productVersion=java:jboss/wljmsra/clusterXAQCF jndiName=java:jboss/wljmsra/clusterXAQCF], txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0af51e58:-79602179:539e611b:b, node_name=1, branch_uid=0:ffff0af51e58:-79602179:539e611b:10, subordinatenodename=null, eis_name=java:jboss/wljmsra/clusterXAQCF >, heuristic: TwoPhaseOutcome.FINISH_OK, product: java:jboss/wljmsra/clusterXAQCF/java:jboss/wljmsra/clusterXAQCF, jndiName: java:jboss/wljmsra/clusterXAQCF com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@1826b48 >