Customer is using spring with JTA transactions and doing remote EJB calls between different instances of JBoss (EAP 6.3.3). It seems that the global transactions do not work 100%. The remote branch of the transaction gets rollbacked but the global transaction gets committed as if nothing happened. The use case is as follow: Client makes a call to a bean on server-1 bean (server-1) inserts a row into table-1 bean (server-1) calls to a bean on server-2 bean (server-2) inserts a row into table-2 bean (server-2) goes to sleep for 3 minutes periodic recovery (server-1) flags the remote branchof the transaction (on server-2) as in doubt and rolls it back. (server-1 log) 11:53:37,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids _whenFirstSeen toRecover no RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@322f7790, receiver=Remoting connection EJB receiver [connection=Remoting connection <2c1ab3f6>,channel=jboss.ejb,nodename=server2]}, transactionOriginNodeIdentifier='server1'} 1452599607985 === 1452599617991 11:53:37,991 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 1 Xids to recover on this pass. 11:53:37,992 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) No record found for < formatId=131077, gtrid_length=35, bqual_length=43, tx_uid=0:ffffc0a80164:-fa2e9db:5694e833:2c, node_name=server1, branch_uid=0:ffffc0a80164:-fa2e9db:5694e833:39, subordinatenodename=server2, eis_name=unknown eis name > 11:53:37,992 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.JTATransactionLogXAResourceOrphanFilter voted ABSTAIN 11:53:37,993 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) node name of < formatId=131077, gtrid_length=35, bqual_length=43, tx_uid=0:ffffc0a80164:-fa2e9db:5694e833:2c, node_name=server1, branch_uid=0:ffffc0a80164:-fa2e9db:5694e833:39, subordinatenodename=server2, eis_name=unknown eis name > is server1 11:53:37,993 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.JTANodeNameXAResourceOrphanFilter voted ROLLBACK 11:53:37,993 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) subordinate node name of < formatId=131077, gtrid_length=35, bqual_length=43, tx_uid=0:ffffc0a80164:-fa2e9db:5694e833:2c, node_name=server1, branch_uid=0:ffffc0a80164:-fa2e9db:5694e833:39, subordinatenodename=server2, eis_name=unknown eis name > is server2 11:53:37,993 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Checking whether Xid < formatId=131077, gtrid_length=35, bqual_length=43, tx_uid=0:ffffc0a80164:-fa2e9db:5694e833:2c, node_name=server1, branch_uid=0:ffffc0a80164:-fa2e9db:5694e833:39, subordinatenodename=server2, eis_name=unknown eis name > exists in ObjectStore. 11:53:37,993 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Looking for 0:ffffc0a80164:-fa2e9db:5694e833:2c and /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/SubordinateAtomicAction/JCA 11:53:37,993 INFO [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016013: Rolling back < formatId=131077, gtrid_length=35, bqual_length=43, tx_uid=0:ffffc0a80164:-fa2e9db:5694e833:2c, node_name=server1, branch_uid=0:ffffc0a80164:-fa2e9db:5694e833:39, subordinatenodename=server2, eis_name=unknown eis name > (server-2 log) 11:53:37,997 TRACE [com.arjuna.ats.jta] (EJB default - 5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE 11:53:37,998 TRACE [com.arjuna.ats.arjuna] (EJB default - 5) BasicAction::phase2Abort() for action-id 0:ffffc0a80164:-41fcd6d0:5694e85a:34 11:53:37,998 TRACE [com.arjuna.ats.arjuna] (EJB default - 5) BasicAction::doAbort (XAResourceRecord < resource:XAResourceWrapperImpl@3de8e444[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@6440856e pad=false overrideRmValue=false productName=PostgreSQL productVersion=9.4.1 jndiName=java:jboss/datasources/testJBossDS], txid:< formatId=131077, gtrid_length=35, bqual_length=43, tx_uid=0:ffffc0a80164:-fa2e9db:5694e833:2c, node_name=server1, branch_uid=0:ffffc0a80164:-41fcd6d0:5694e85a:3e, subordinatenodename=server2, eis_name=java:jboss/datasources/testJBossDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: PostgreSQL/9.4.1, jndiName: java:jboss/datasources/testJBossDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@32ff4c6d >) 11:53:37,998 TRACE [com.arjuna.ats.jta] (EJB default - 5) XAResourceRecord.topLevelAbort for XAResourceRecord < resource:XAResourceWrapperImpl@3de8e444[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@6440856e pad=false overrideRmValue=false productName=PostgreSQL productVersion=9.4.1 jndiName=java:jboss/datasources/testJBossDS], txid:< formatId=131077, gtrid_length=35, bqual_length=43, tx_uid=0:ffffc0a80164:-fa2e9db:5694e833:2c, node_name=server1, branch_uid=0:ffffc0a80164:-41fcd6d0:5694e85a:3e, subordinatenodename=server2, eis_name=java:jboss/datasources/testJBossDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: PostgreSQL/9.4.1, jndiName: java:jboss/datasources/testJBossDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@32ff4c6d >, record id=0:ffffc0a80164:-41fcd6d0:5694e85a:3f 11:53:37,998 TRACE [org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$MyXaMCF] (EJB default - 5) Unlock: HeldByCurrentThread: Yes, Locked: Yes, HoldCount: 1, QueueLength: 0 11:53:37,998 TRACE [org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$MyXaMCF] (EJB default - 5) Owner: Thread[EJB default - 5,5,EJB default] 11:53:37,999 TRACE [com.arjuna.ats.arjuna] (EJB default - 5) BasicAction::doAbort() result for action-id (0:ffffc0a80164:-41fcd6d0:5694e85a:34) on record id: (0:ffffc0a80164:-41fcd6d0:5694e85a:3f) is (TwoPhaseOutcome.FINISH_OK) node id: (server2) 11:53:37,999 TRACE [com.arjuna.ats.arjuna] (EJB default - 5) BasicAction::updateState() for action-id 0:ffffc0a80164:-41fcd6d0:5694e85a:34 11:53:37,999 TRACE [com.arjuna.ats.jta] (EJB default - 5) SynchronizationImple.afterCompletion bean (server-2) wake up bean (server-1) updates the row in table-1 at this point the parent transaction gets committed without an error 11:55:31,104 TRACE [com.arjuna.ats.arjuna] (EJB default - 3) BasicAction::removeChildThread () action 0:ffffc0a80164:-fa2e9db:5694e833:2c removing TSThread:1 11:55:31,104 TRACE [com.arjuna.ats.arjuna] (EJB default - 3) BasicAction::removeChildThread () action 0:ffffc0a80164:-fa2e9db:5694e833:2c removing TSThread:1 result = true 11:55:31,104 TRACE [com.arjuna.ats.arjuna] (EJB default - 3) TransactionReaper::remove ( BasicAction: 0:ffffc0a80164:-fa2e9db:5694e833:2c status: ActionStatus.COMMITTED ) client call ends When I look at the table in the database I see a row in table-1 but no row in table-2. I would expect to see both tables empty. When I switch to JTS and run the same use case it all works as expected.
This is definitely a bug that we should fix
Would it be possible to test with the ejb-client code in one of the following branches (whichever one matches the minor version you are working with): https://github.com/jbossas/jboss-ejb-client/tree/2.1 https://github.com/jbossas/jboss-ejb-client/tree/2.0 https://github.com/jbossas/jboss-ejb-client/tree/1.0
Tom Jenkinson <tom.jenkinson> updated the status of jira JBEAP-2824 to Resolved
Reproducer based on BZ description shows the fix works. Verified for 6.4.8.CP.CR2.
Jiri Pallich <jpallich> updated the status of jira JBEAP-2824 to Closed
Retroactively bulk-closing issues from released EAP 6.4 cumulative patches.