8 Replies Latest reply on Dec 13, 2013 8:43 AM by eldaryus

    JBAS014160: Wrong tx on thread when calling async EJB method from async servlet

    eldaryus

      Hi, I implemented a simple async servlet:

       

      @WebServlet(name = "hello", urlPatterns = "/", asyncSupported = true)
      public class HelloServlet extends HttpServlet {
          @Inject
          AsyncBean asyncBean;
      
          @Override
          protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
              AsyncContext ctx = req.startAsync(req, resp);
              asyncBean.count(ctx);
          }
      }
      
      And an async EJB bean:
      

       

      And a simple async EJB bean:

       

      @Stateless
      @Asynchronous
      public class AsyncBean {
          public void count(AsyncContext ctx) throws IOException {
              for (int i = 0; i < 1000; i++) {
                  ctx.getResponse().getWriter().println(i);
                  ctx.getResponse().getWriter().flush();
              }
              ctx.complete();
          }
      }
      
      

       

      When I try to run it with Wildfly, everything seems to work fine, but I get the following error after the method has finished:

       

      2013-12-13 00:42:01,913 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015874: WildFly 8.0.0.Beta1 "WildFly" started in 7696ms - Started 284 of 320 services (64 services are lazy, passive or on-demand)

      2013-12-13 00:42:03,489 ERROR [org.jboss.as.txn] (EJB default - 1) JBAS010152: APPLICATION ERROR: transaction still active in request with status 0

      2013-12-13 00:42:03,494 ERROR [org.jboss.as.ejb3.invocation] (EJB default - 1) JBAS014134: EJB Invocation failed on component AsyncBean for method public void com.okasamastarr.web.AsyncBean.count(javax.servlet.AsyncContext) throws java.io.IOException: java.lang.IllegalStateException: JBAS014160: Wrong tx on thread: expected TransactionImple < ac, BasicAction: 0:ffffac1e0f02:-40b55bbb:52aa1f96:8 status: ActionStatus.ABORTED >, actual null

          at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:85) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:277) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:340) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:95) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:64)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:325)

          at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:437)

          at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:61)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:325)

          at org.jboss.invocation.PrivilegedWithCombinerInterceptor.processInvocation(PrivilegedWithCombinerInterceptor.java:80)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)

          at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)

          at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.LogDiagnosticContextRecoveryInterceptor.processInvocation(LogDiagnosticContextRecoveryInterceptor.java:79) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.AsyncFutureInterceptorFactory$1$1.runInvocation(AsyncFutureInterceptorFactory.java:87) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.as.ejb3.component.interceptors.AsyncInvocationTask.run(AsyncInvocationTask.java:73) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_25]

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_25]

          at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_25]

          at org.jboss.threads.JBossThread.run(JBossThread.java:122)

       

      2013-12-13 00:42:07,313 ERROR [org.jboss.as.txn] (EJB default - 2) JBAS010152: APPLICATION ERROR: transaction still active in request with status 0

      2013-12-13 00:42:07,315 ERROR [org.jboss.as.ejb3.invocation] (EJB default - 2) JBAS014134: EJB Invocation failed on component AsyncBean for method public void com.okasamastarr.web.AsyncBean.count(javax.servlet.AsyncContext) throws java.io.IOException: java.lang.IllegalStateException: JBAS014160: Wrong tx on thread: expected TransactionImple < ac, BasicAction: 0:ffffac1e0f02:-40b55bbb:52aa1f96:a status: ActionStatus.ABORTED >, actual null

          at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:85) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:277) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:340) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:95) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:64)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:325)

          at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:437)

          at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:61)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:325)

          at org.jboss.invocation.PrivilegedWithCombinerInterceptor.processInvocation(PrivilegedWithCombinerInterceptor.java:80)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)

          at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)

          at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.LogDiagnosticContextRecoveryInterceptor.processInvocation(LogDiagnosticContextRecoveryInterceptor.java:79) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:309)

          at org.jboss.as.ejb3.component.interceptors.AsyncFutureInterceptorFactory$1$1.runInvocation(AsyncFutureInterceptorFactory.java:87) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at org.jboss.as.ejb3.component.interceptors.AsyncInvocationTask.run(AsyncInvocationTask.java:73) [wildfly-ejb3-8.0.0.Beta1.jar:8.0.0.Beta1]

          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_25]

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_25]

          at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_25]

          at org.jboss.threads.JBossThread.run(JBossThread.java:122)

       

      Can someone explain if I'm doing something wrong or it's a Wildfly issue?

        • 1. Re: JBAS014160: Wrong tx on thread when calling async EJB method from async servlet
          smarlow

          I have not heard of this issue yet but just in case its already fixed, could you try again with the nightly build via this link

           

          If the nightly build doesn't help, I would like to see TRACE output for "com.arjuna".  Some instructions for enabling TRACE logging are here (for JPA but should still help).  Please attach the server.log output (from wf8/standalone/log folder).  The trace logging should show start/end of each JTA transaction which we can correlate against the "Wrong tx on thread" error (please recreate that after enabling TRACE logging).

          • 2. Re: Re: JBAS014160: Wrong tx on thread when calling async EJB method from async servlet
            eldaryus

            Thanks for the suggestion!

            The issue reproduces with the latest (#180) nightly.

            I attached the server log with com.arjuna TRACE log level enabled.

            • 3. Re: Re: Re: JBAS014160: Wrong tx on thread when calling async EJB method from async servlet
              smarlow

              The following trace output shows the start of the "0:ffffac1e0f02:8227154:52aa4adf:8" transaction, which you can see is suspended so that another transaction (0:ffffac1e0f02:8227154:52aa4adf:9) can be started.  The nested transaction (0:ffffac1e0f02:8227154:52aa4adf:9) appears to be committed successfully, we then resume the "0:ffffac1e0f02:8227154:52aa4adf:8" transaction. 

               

              It seems odd to me that after we resume the "0:ffffac1e0f02:8227154:52aa4adf:8" transaction (see line 261 in attached server.log or below paste from it), the next trace log shows the active transaction status as "Status.STATUS_ACTIVE".  Then we reach the code in CMTTxInterceptor.endTransaction() that appears to get null back from TransactionManager.getTransaction().  That is what is happening, I'm just not sure why yet. 

               

              Does the problem still happen if the EJB bean isn't @Asynchronous?  How about if the WebServlet is not asynchronous?  Would be interesting to try both changes in isolation.  I suspect that we will have to debug to find out exactly why this is happening (unless someone else knows?)

               

              2013-12-13 03:46:48,953 TRACE [com.arjuna.ats.jta] (EJB default - 1) BaseTransaction.begin

              2013-12-13 03:46:48,955 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) StateManager::StateManager( 2, 0 )

              2013-12-13 03:46:48,955 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::BasicAction()

              2013-12-13 03:46:48,955 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::Begin() for action-id 0:ffffac1e0f02:8227154:52aa4adf:8

              2013-12-13 03:46:48,955 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::actionInitialise() for action-id 0:ffffac1e0f02:8227154:52aa4adf:8

              2013-12-13 03:46:48,957 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) ActionHierarchy::ActionHierarchy(1)

              2013-12-13 03:46:48,957 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) ActionHierarchy::add(0:ffffac1e0f02:8227154:52aa4adf:8, 1)

              2013-12-13 03:46:48,958 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::addChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:8 adding Thread[EJB default - 1,5,EJB default]

              2013-12-13 03:46:48,959 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::addChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:8 adding Thread[EJB default - 1,5,EJB default] result = true

              2013-12-13 03:46:48,960 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) TransactionReaper::insert ( BasicAction: 0:ffffac1e0f02:8227154:52aa4adf:8 status: ActionStatus.RUNNING, 300 )

              2013-12-13 03:46:48,961 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) ReaperElement::ReaperElement ( BasicAction: 0:ffffac1e0f02:8227154:52aa4adf:8 status: ActionStatus.RUNNING, 300 )

              2013-12-13 03:46:48,961 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) ReaperThread.run ()

              2013-12-13 03:46:48,962 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check ()

              2013-12-13 03:46:48,962 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1386892308961

              2013-12-13 03:46:48,963 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Thread Thread[Transaction Reaper,5,main] sleeping for 299998

              2013-12-13 03:46:48,963 TRACE [com.arjuna.ats.jta] (EJB default - 1) TransactionImpleManager.suspend

              2013-12-13 03:46:48,963 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::removeChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:8 removing TSThread:1

              2013-12-13 03:46:48,963 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::removeChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:8 removing TSThread:1 result = true

              2013-12-13 03:46:48,964 TRACE [com.arjuna.ats.jta] (EJB default - 1) BaseTransaction.begin

              2013-12-13 03:46:48,964 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) StateManager::StateManager( 2, 0 )

              2013-12-13 03:46:48,964 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::BasicAction()

              2013-12-13 03:46:48,964 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::Begin() for action-id 0:ffffac1e0f02:8227154:52aa4adf:9

              2013-12-13 03:46:48,964 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::actionInitialise() for action-id 0:ffffac1e0f02:8227154:52aa4adf:9

              2013-12-13 03:46:48,964 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) ActionHierarchy::ActionHierarchy(1)

              2013-12-13 03:46:48,965 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) ActionHierarchy::add(0:ffffac1e0f02:8227154:52aa4adf:9, 1)

              2013-12-13 03:46:48,965 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::addChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:9 adding Thread[EJB default - 1,5,EJB default]

              2013-12-13 03:46:48,965 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::addChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:9 adding Thread[EJB default - 1,5,EJB default] result = true

              2013-12-13 03:46:48,965 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) TransactionReaper::insert ( BasicAction: 0:ffffac1e0f02:8227154:52aa4adf:9 status: ActionStatus.RUNNING, 300 )

              2013-12-13 03:46:48,965 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) ReaperElement::ReaperElement ( BasicAction: 0:ffffac1e0f02:8227154:52aa4adf:9 status: ActionStatus.RUNNING, 300 )

              2013-12-13 03:46:48,976 TRACE [com.arjuna.ats.jta] (EJB default - 1) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              2013-12-13 03:46:48,977 TRACE [com.arjuna.ats.jta] (EJB default - 1) BaseTransaction.commit

              2013-12-13 03:46:48,977 TRACE [com.arjuna.ats.jta] (EJB default - 1) TransactionImple.commitAndDisassociate

              2013-12-13 03:46:48,977 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::End() for action-id 0:ffffac1e0f02:8227154:52aa4adf:9

              2013-12-13 03:46:48,978 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::End() result for action-id (0:ffffac1e0f02:8227154:52aa4adf:9) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

              2013-12-13 03:46:48,978 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::removeChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:9 removing TSThread:1

              2013-12-13 03:46:48,979 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::removeChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:9 removing TSThread:1 result = true

              2013-12-13 03:46:48,979 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) TransactionReaper::remove ( BasicAction: 0:ffffac1e0f02:8227154:52aa4adf:9 status: ActionStatus.COMMITTED )

              2013-12-13 03:46:48,979 TRACE [com.arjuna.ats.jta] (EJB default - 1) TransactionImpleManager.resume

              2013-12-13 03:46:48,979 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::addChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:8 adding Thread[EJB default - 1,5,EJB default]

              2013-12-13 03:46:48,980 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::addChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:8 adding Thread[EJB default - 1,5,EJB default] result = true

              2013-12-13 03:46:49,096 TRACE [com.arjuna.ats.jta] (EJB default - 1) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              2013-12-13 03:46:49,096 ERROR [org.jboss.as.txn] (EJB default - 1) JBAS010152: APPLICATION ERROR: transaction still active in request with status 0

              2013-12-13 03:46:49,097 TRACE [com.arjuna.ats.jta] (EJB default - 1) BaseTransaction.rollback

              2013-12-13 03:46:49,097 TRACE [com.arjuna.ats.jta] (EJB default - 1) TransactionImple.rollbackAndDisassociate

              2013-12-13 03:46:49,098 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::Abort() for action-id 0:ffffac1e0f02:8227154:52aa4adf:8

              2013-12-13 03:46:49,098 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::removeChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:8 removing TSThread:1

              2013-12-13 03:46:49,098 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) BasicAction::removeChildThread () action 0:ffffac1e0f02:8227154:52aa4adf:8 removing TSThread:1 result = true

              2013-12-13 03:46:49,098 TRACE [com.arjuna.ats.arjuna] (EJB default - 1) TransactionReaper::remove ( BasicAction: 0:ffffac1e0f02:8227154:52aa4adf:8 status: ActionStatus.ABORTED )

              2013-12-13 03:46:49,102 ERROR [org.jboss.as.ejb3.invocation] (EJB default - 1) JBAS014134: EJB Invocation failed on component AsyncBean for method public void com.okasamastarr.com.domain.AsyncBean.count(javax.servlet.AsyncContext) throws java.io.IOException: java.lang.IllegalStateException: JBAS014160: Wrong tx on thread: expected TransactionImple < ac, BasicAction: 0:ffffac1e0f02:8227154:52aa4adf:8 status: ActionStatus.ABORTED >, actual null

                      at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:85) [wildfly-ejb3-8.0.0.Beta2-SNAPSHOT.jar:8.0.0.Beta2-SNAPSHOT]

                      at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:277) [wildfly-ejb3-8.0.0.Beta2-SNAPSHOT.jar:8.0.0.Beta2-SNAPSHOT]

                      at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:340) [wildfly-ejb3-8.0.0.Beta2-SNAPSHOT.jar:8.0.0.Beta2-SNAPSHOT]

               

              • 4. Re: JBAS014160: Wrong tx on thread when calling async EJB method from async servlet
                eldaryus

                No issue if I remove @Asynchronous from EJB (leaving servlet async).  Is it really possible to test it the other way around? Can you let me know how I can change the code to test this?

                 

                Here's the log when calling synchronous EJB call from asynchronous servlet:

                2013-12-13 04:43:14,227 INFO  [org.jboss.weld.deployer] (MSC service thread 1-1) JBAS016005: Starting Services for CDI deployment: site-0.0.1-SNAPSHOT.war

                2013-12-13 04:43:14,244 INFO  [org.jboss.weld.deployer] (MSC service thread 1-1) JBAS016008: Starting weld service for deployment site-0.0.1-SNAPSHOT.war

                2013-12-13 04:43:14,804 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-8) JBAS017534: Register web context: /site-0.0.1-SNAPSHOT

                2013-12-13 04:43:14,921 INFO  [org.jboss.as.server] (DeploymentScanner-threads - 1) JBAS018565: Replaced deployment "site-0.0.1-SNAPSHOT.war" with deployment "site-0.0.1-SNAPSHOT.war"

                2013-12-13 04:43:19,051 TRACE [com.arjuna.ats.jta] (default task-7) BaseTransaction.begin

                2013-12-13 04:43:19,052 TRACE [com.arjuna.ats.arjuna] (default task-7) StateManager::StateManager( 2, 0 )

                2013-12-13 04:43:19,052 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::BasicAction()

                2013-12-13 04:43:19,053 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::Begin() for action-id 0:ffffac1e0f02:37deb643:52aa5442:23

                2013-12-13 04:43:19,053 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::actionInitialise() for action-id 0:ffffac1e0f02:37deb643:52aa5442:23

                2013-12-13 04:43:19,053 TRACE [com.arjuna.ats.arjuna] (default task-7) ActionHierarchy::ActionHierarchy(1)

                2013-12-13 04:43:19,054 TRACE [com.arjuna.ats.arjuna] (default task-7) ActionHierarchy::add(0:ffffac1e0f02:37deb643:52aa5442:23, 1)

                2013-12-13 04:43:19,054 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::addChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:23 adding Thread[default task-7,5,main]

                2013-12-13 04:43:19,054 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::addChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:23 adding Thread[default task-7,5,main] result = true

                2013-12-13 04:43:19,055 TRACE [com.arjuna.ats.arjuna] (default task-7) TransactionReaper::insert ( BasicAction: 0:ffffac1e0f02:37deb643:52aa5442:23 status: ActionStatus.RUNNING, 300 )

                2013-12-13 04:43:19,055 TRACE [com.arjuna.ats.arjuna] (default task-7) ReaperElement::ReaperElement ( BasicAction: 0:ffffac1e0f02:37deb643:52aa5442:23 status: ActionStatus.RUNNING, 300 )

                2013-12-13 04:43:19,056 TRACE [com.arjuna.ats.jta] (default task-7) TransactionImpleManager.suspend

                2013-12-13 04:43:19,056 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::removeChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:23 removing TSThread:5

                2013-12-13 04:43:19,056 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::removeChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:23 removing TSThread:5 result = true

                2013-12-13 04:43:19,057 TRACE [com.arjuna.ats.jta] (default task-7) BaseTransaction.begin

                2013-12-13 04:43:19,057 TRACE [com.arjuna.ats.arjuna] (default task-7) StateManager::StateManager( 2, 0 )

                2013-12-13 04:43:19,057 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::BasicAction()

                2013-12-13 04:43:19,058 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::Begin() for action-id 0:ffffac1e0f02:37deb643:52aa5442:24

                2013-12-13 04:43:19,058 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::actionInitialise() for action-id 0:ffffac1e0f02:37deb643:52aa5442:24

                2013-12-13 04:43:19,058 TRACE [com.arjuna.ats.arjuna] (default task-7) ActionHierarchy::ActionHierarchy(1)

                2013-12-13 04:43:19,059 TRACE [com.arjuna.ats.arjuna] (default task-7) ActionHierarchy::add(0:ffffac1e0f02:37deb643:52aa5442:24, 1)

                2013-12-13 04:43:19,059 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::addChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:24 adding Thread[default task-7,5,main]

                2013-12-13 04:43:19,059 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::addChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:24 adding Thread[default task-7,5,main] result = true

                2013-12-13 04:43:19,060 TRACE [com.arjuna.ats.arjuna] (default task-7) TransactionReaper::insert ( BasicAction: 0:ffffac1e0f02:37deb643:52aa5442:24 status: ActionStatus.RUNNING, 300 )

                2013-12-13 04:43:19,060 TRACE [com.arjuna.ats.arjuna] (default task-7) ReaperElement::ReaperElement ( BasicAction: 0:ffffac1e0f02:37deb643:52aa5442:24 status: ActionStatus.RUNNING, 300 )

                2013-12-13 04:43:19,063 TRACE [com.arjuna.ats.jta] (default task-7) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

                2013-12-13 04:43:19,064 TRACE [com.arjuna.ats.jta] (default task-7) BaseTransaction.commit

                2013-12-13 04:43:19,064 TRACE [com.arjuna.ats.jta] (default task-7) TransactionImple.commitAndDisassociate

                2013-12-13 04:43:19,064 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::End() for action-id 0:ffffac1e0f02:37deb643:52aa5442:24

                2013-12-13 04:43:19,064 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::End() result for action-id (0:ffffac1e0f02:37deb643:52aa5442:24) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

                2013-12-13 04:43:19,064 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::removeChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:24 removing TSThread:5

                2013-12-13 04:43:19,065 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::removeChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:24 removing TSThread:5 result = true

                2013-12-13 04:43:19,065 TRACE [com.arjuna.ats.arjuna] (default task-7) TransactionReaper::remove ( BasicAction: 0:ffffac1e0f02:37deb643:52aa5442:24 status: ActionStatus.COMMITTED )

                2013-12-13 04:43:19,065 TRACE [com.arjuna.ats.jta] (default task-7) TransactionImpleManager.resume

                2013-12-13 04:43:19,065 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::addChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:23 adding Thread[default task-7,5,main]

                2013-12-13 04:43:19,065 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::addChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:23 adding Thread[default task-7,5,main] result = true

                2013-12-13 04:43:19,189 TRACE [com.arjuna.ats.jta] (default task-7) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

                2013-12-13 04:43:19,189 TRACE [com.arjuna.ats.jta] (default task-7) BaseTransaction.commit

                2013-12-13 04:43:19,190 TRACE [com.arjuna.ats.jta] (default task-7) TransactionImple.commitAndDisassociate

                2013-12-13 04:43:19,190 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::End() for action-id 0:ffffac1e0f02:37deb643:52aa5442:23

                2013-12-13 04:43:19,190 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::End() result for action-id (0:ffffac1e0f02:37deb643:52aa5442:23) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

                2013-12-13 04:43:19,190 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::removeChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:23 removing TSThread:5

                2013-12-13 04:43:19,191 TRACE [com.arjuna.ats.arjuna] (default task-7) BasicAction::removeChildThread () action 0:ffffac1e0f02:37deb643:52aa5442:23 removing TSThread:5 result = true

                2013-12-13 04:43:19,191 TRACE [com.arjuna.ats.arjuna] (default task-7) TransactionReaper::remove ( BasicAction: 0:ffffac1e0f02:37deb643:52aa5442:23 status: ActionStatus.COMMITTED )

                2013-12-13 04:44:04,028 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                2013-12-13 04:44:04,028 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                2013-12-13 04:44:04,029 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Fri, 13 Dec 2013 04:44:04

                2013-12-13 04:44:04,029 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                2013-12-13 04:44:04,029 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                2013-12-13 04:44:04,030 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                InputObjectState Type  : null

                InputObjectState Size  : 0

                InputObjectState Buffer: , -1)

                2013-12-13 04:44:04,030 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                2013-12-13 04:44:04,030 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                2013-12-13 04:44:04,031 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

                2013-12-13 04:44:04,031 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                2013-12-13 04:44:04,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                2013-12-13 04:44:04,032 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                InputObjectState Type  : null

                InputObjectState Size  : 0

                InputObjectState Buffer: )

                2013-12-13 04:44:04,032 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                2013-12-13 04:44:04,032 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

                2013-12-13 04:44:04,032 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                2013-12-13 04:44:04,032 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                2013-12-13 04:44:04,033 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                InputObjectState Type  : null

                InputObjectState Size  : 0

                InputObjectState Buffer: , -1)

                2013-12-13 04:44:04,033 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                2013-12-13 04:44:04,033 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@18b6f025, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@58c3fbeb}, transactionOriginNodeIdentifier='1'}

                2013-12-13 04:44:04,033 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                2013-12-13 04:44:04,033 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

                2013-12-13 04:44:14,034 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Fri, 13 Dec 2013 04:44:14

                2013-12-13 04:44:14,034 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                2013-12-13 04:44:14,035 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

                2013-12-13 04:44:14,035 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                2013-12-13 04:44:14,035 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

                2013-12-13 04:44:14,036 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                2013-12-13 04:44:14,036 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                2013-12-13 04:44:14,036 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@18b6f025, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@58c3fbeb}, transactionOriginNodeIdentifier='1'}

                2013-12-13 04:44:14,037 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                2013-12-13 04:44:14,037 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                2013-12-13 04:44:14,037 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)

                2013-12-13 04:44:14,038 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                2013-12-13 04:44:14,038 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                • 5. Re: Re: JBAS014160: Wrong tx on thread when calling async EJB method from async servlet
                  smarlow

                  Eldar Yusupov wrote:

                   

                  No issue if I remove @Asynchronous from EJB (leaving servlet async).  Is it really possible to test it the other way around? Can you let me know how I can change the code to test this?

                  No need to change the code further, that is interesting that removing the @Asynchronous had an impact.  That gives me some ideas of what I should look at, to attempt helping with this.  I wonder what would happen if you add @Asynchronous back and make the bean remote.

                   

                  Unless we hear from someone else that knows more about the @Asynchronous implementation code in WildFly, I'll probably have to step through the code (well, anyone can step through it easily enough).

                   

                  One thing that I got from the EJB 3.2 core spec section 4.5.3 Transactions:

                  The client’s transaction context does not propagate with an asynchronous method invocation. From the Bean Provider’s point of view, there is never a transaction context flowing in from the client. This means, for example, that the semantics of the REQUIRED transaction attribute on an asynchronous method are exactly the same as REQUIRES_NEW.

                  The REQIRES_NEW behaviour is probably why we still the suspend (of the first) transaction but I'm not sure why two transactions are started for your code.  I suspect that making the bean remote will work around this problem but I want to understand why exactly its happening as well.

                  • 6. Re: Re: JBAS014160: Wrong tx on thread when calling async EJB method from async servlet
                    eldaryus

                    I tried adding @Asynchronous and @Remote annotations to the EJB - still have the same exception.

                    I uploaded the test case on github: https://github.com/eyusupov/async-testcase

                    • 7. Re: Re: JBAS014160: Wrong tx on thread when calling async EJB method from async servlet
                      smarlow

                      At this point, it looks like a bug in that we try to end the same transaction twice and get the error on the second time.

                       

                      Feel free to create a jira bug report (assign to me if you create one) for this.  I'm going to debug a few more times to try and understand better why this is happening.

                      • 8. Re: Re: JBAS014160: Wrong tx on thread when calling async EJB method from async servlet
                        eldaryus

                        Thanks, I created [WFLY-2651] JBAS014160: Wrong tx on thread when calling async EJB method from async servlet - JBoss Issue Tracker. Can't assign it on you though, can you please pick it up?