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 Apr 7, 2014 10:21 AM

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 Apr 7, 2014 10:32 AM (in response to rvillen)

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
Actions