1 Reply Latest reply on Apr 7, 2014 10:32 AM by tomjenkinson

    jboss 7.1.1 with EJB client transaction: Transaction commits but record reverts to old value

    rvillen

      Hi,

       

       

      we have been trying to diagnose a strange issue related to the use of jboss client transactions. The client needs to perform a remote EJB operation, so we invoke a UserTransaction in a Business method, calling commit both for the remote Tx and then for the local Tx Manager if there were no errors.

       

      According to logs both EJB and Spring do their respective commits. At times, both DBs get updated. Other times, only Spring side gets updated. Seems related to server load, but we havent really identified a pattern.

       

      Here is the background info for the project:

       

       

      Client: Spring 2.5 App on Tomcat 6.0.32. Business methods on client are marked as transactional (propagation: required). Remote transactions are acquired invoking

      javax.transaction.UserTransaction EJBClient.getUserTransaction(nodename);

      Server: Jboss 7.1.1 with JBPM5.4 and EJB3 service to manage JBPM activity. EJB3 service is a SLSB with CMT. Bean methods are marked as @Transactional=Mandatory.

      DB: MySql 5.6.11, JBPM_DB is the schema accessed by JBPM and our EJB service, application_DB is the schema accessed by the Tomcat/Spring app.

       

       

      Execution flow (T: Tomcat, J: Jboss):

       

       

      1) BusinessMethod obtains UserTransaction (T)

      2) UserTransaction.begin() (T)

      3) BusinessMethod calls remote EJB method (T)

      4) Remote EJB method executes, updates a value on JBPM_DB, returns such value to client (J)

      5) BusinessMethod obtains result value from JBPM operation, persists on application_DB (T)

      6) invoke UserTransaction.commit(), invoke TransactionManager.commit() (T)

       

      After executing all these steps, the log output (Jboss side) is:

       

      11:27:51,382 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) BasicAction::Begin() for action-id 0:ffffc0a86e90:-1857ed06:53399cdd:15556

      11:27:51,383 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) BasicAction::actionInitialise() for action-id 0:ffffc0a86e90:-1857ed06:53399cdd:15556

      11:27:51,383 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) ActionHierarchy::ActionHierarchy(5)

      11:27:51,384 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) ActionHierarchy::add(0:ffffc0a86e90:-1857ed06:53399cdd:15556, 1)

      11:27:51,385 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) BasicAction::addChildThread () action 0:ffffc0a86e90:-1857ed06:53399cdd:15556 adding Thread[EJB default - 9,5,EJB default]

      11:27:51,386 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) BasicAction::addChildThread () action 0:ffffc0a86e90:-1857ed06:53399cdd:15556 adding Thread[EJB default - 9,5,EJB default] result = true

      11:27:51,387 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) TransactionReaper::insert ( BasicAction: 0:ffffc0a86e90:-1857ed06:53399cdd:15556 status: ActionStatus.RUNNING, 300 )

      11:27:51,388 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) ReaperElement::ReaperElement ( BasicAction: 0:ffffc0a86e90:-1857ed06:53399cdd:15556 status: ActionStatus.RUNNING, 300 )

      11:27:51,389 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,390 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,390 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,391 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,391 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,392 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,392 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,393 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,393 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,394 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,394 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,395 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,395 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,396 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,396 INFO  [stdout] (EJB default - 9) 6_NODE

       

       

      11:27:51,397 INFO  [com.test.JbpmEjb] (EJB default - 9) --------- JBPM:JBPM:INIT ---------

      11:27:51,397 INFO  [com.test.JbpmEjb] (EJB default - 9) method: signalEvent()->START

      11:27:51,398 INFO  [com.test.JbpmEjb] (EJB default - 9) - BPMN TYPE: TYPE1

      11:27:51,398 INFO  [com.test.JbpmEjb] (EJB default - 9) - InstanceID: 10778

      11:27:51,399 INFO  [com.test.JbpmEjb] (EJB default - 9) - JBPM NODE: 6_NODE

      11:27:51,400 INFO  [com.test.JbpmEjb] (EJB default - 9) - params: {}

      11:27:51,401 INFO  [com.test.JbpmEjb] (EJB default - 9) --------- JBPM:JBPM:END ---------

      11:27:51,402 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,403 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,403 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,404 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,404 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,405 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,405 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,406 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,407 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,407 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,408 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,408 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,409 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,409 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,410 INFO  [stdout] (EJB default - 9) 7_NODE

       

       

      11:27:51,410 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,411 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,412 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,412 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,413 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,413 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,414 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,414 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,415 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,415 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,416 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,417 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,417 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,418 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,418 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,419 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,419 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,420 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,420 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,421 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,421 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,422 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,422 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,423 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,423 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,424 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,424 TRACE [com.arjuna.ats.jta] (EJB default - 9) BaseTransaction.getStatus

      11:27:51,425 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImple.getStatus

      11:27:51,426 INFO  [com.test.JbpmEjb] (EJB default - 9) --------- JBPM:JBPM:INIT ---------

      11:27:51,426 INFO  [com.test.JbpmEjb] (EJB default - 9) method: signalEvent()->END

      11:27:51,427 INFO  [com.test.JbpmEjb] (EJB default - 9) - BPMN TYPE: TYPE1

      11:27:51,428 INFO  [com.test.JbpmEjb] (EJB default - 9) - InstanceID: 10778

      11:27:51,428 INFO  [com.test.JbpmEjb] (EJB default - 9) - JBPM NODE: 7_NODE

      11:27:51,429 INFO  [com.test.JbpmEjb] (EJB default - 9) - params: {}

      11:27:51,431 INFO  [com.test.JbpmEjb] (EJB default - 9) --------- JBPM:JBPM:END ---------

      11:27:51,431 TRACE [com.arjuna.ats.jta] (EJB default - 9) TransactionImpleManager.suspend

      11:27:51,432 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) BasicAction::removeChildThread () action 0:ffffc0a86e90:-1857ed06:53399cdd:15556 removing TSThread:c

      11:27:51,433 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) BasicAction::removeChildThread () action 0:ffffc0a86e90:-1857ed06:53399cdd:15556 removing TSThread:c result = true

      11:27:51,456 TRACE [com.arjuna.ats.jta] (EJB default - 6) TransactionImpleManager.resume

      11:27:51,457 TRACE [com.arjuna.ats.arjuna] (EJB default - 6) BasicAction::addChildThread () action 0:ffffc0a86e90:-1857ed06:53399cdd:15556 adding Thread[EJB default - 6,5,EJB default]

      11:27:51,459 TRACE [com.arjuna.ats.arjuna] (EJB default - 6) BasicAction::addChildThread () action 0:ffffc0a86e90:-1857ed06:53399cdd:15556 adding Thread[EJB default - 6,5,EJB default] result = true

      11:27:51,460 TRACE [com.arjuna.ats.jta] (EJB default - 6) BaseTransaction.commit

      11:27:51,460 TRACE [com.arjuna.ats.jta] (EJB default - 6) TransactionImple.commitAndDisassociate

      11:27:51,461 TRACE [com.arjuna.ats.arjuna] (EJB default - 6) BasicAction::End() for action-id 0:ffffc0a86e90:-1857ed06:53399cdd:15556

      11:27:51,462 TRACE [com.arjuna.ats.arjuna] (EJB default - 6) BasicAction::removeChildThread () action 0:ffffc0a86e90:-1857ed06:53399cdd:15556 removing TSThread:9

      11:27:51,463 TRACE [com.arjuna.ats.arjuna] (EJB default - 6) BasicAction::removeChildThread () action 0:ffffc0a86e90:-1857ed06:53399cdd:15556 removing TSThread:9 result = true

      11:27:51,464 TRACE [com.arjuna.ats.arjuna] (EJB default - 6) TransactionReaper::remove ( BasicAction: 0:ffffc0a86e90:-1857ed06:53399cdd:15556 status: ActionStatus.COMMITTED ) < Jboss Commit???

       

       

      We could use some help understanding the log output, we would like to know if that output is the expected output for the remote UserTransaction.commit() ??? is there a sure way to know if Jboss has finished committing before closing the transaction from the client side?

       

      Thanks in advance,

        • 1. Re: jboss 7.1.1 with EJB client transaction: Transaction commits but record reverts to old value
          tomjenkinson

          Hi Ramon,


          It sounds like you have two completely separate transactions in play here. I suspect you haven't configured the spring side of things to participate in the existing JTA transaction.

           

          The log appears to verify that only one resource is enlisted in the transaction.

           

          You wouldn't expect to need to call "commit" twice for a transaction (i.e. UserTransaction.commit(), invoke TransactionManager.commit()), that does appear to validate the theory you have two completely separate transactions.

           

          Try to get it working with just the one transaction, you will probably have to configure something in spring to lookup the UserTransaction.

           

          Is this all taking place in one JVM? It sounds like there are two JVMs and it sounds like the coordinator needs embedding in the client and use JTS to propagate the TX to the JBoss over CORBA (unless the spring app is also deployed in the same JBoss JVM).

           

          Tom