Bug 1298161 - [GSS](6.4.z) Remote branch of a transaction gets rolled back incorrectly.
Summary: [GSS](6.4.z) Remote branch of a transaction gets rolled back incorrectly.
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: EJB
Version: 6.3.3,6.3.0,6.3.1,6.4.0,6.3.2,6.3.4,6.4.1,6.4.2,6.4.3,6.4.4,6.4.5
Hardware: Unspecified
OS: Unspecified
urgent
urgent
Target Milestone: CR1
: EAP 6.4.8
Assignee: baranowb
QA Contact: Ondrej Chaloupka
URL:
Whiteboard:
Depends On:
Blocks: eap648-payload 1299983 1301676 1411287
TreeView+ depends on / blocked
 
Reported: 2016-01-13 11:37 UTC by Tom Ross
Modified: 2020-07-16 08:40 UTC (History)
10 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 1301676 (view as bug list)
Environment:
Last Closed: 2017-01-17 12:36:26 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker EJBCLIENT-151 0 Major Resolved Wrong handling of prepare in EJB recovery-only XAResource 2018-01-08 09:11:45 UTC
Red Hat Issue Tracker JBEAP-2824 0 Blocker Closed Remote branch of a transaction gets rolled back incorrectly 2018-01-08 09:11:45 UTC
Red Hat Issue Tracker WFLY-6011 0 Major Closed Remote branch of a transaction gets rolled back incorrectly. 2018-01-08 09:11:45 UTC

Description Tom Ross 2016-01-13 11:37:39 UTC
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.

Comment 7 Jason T. Greene 2016-01-15 19:54:47 UTC
This is definitely a bug that we should fix

Comment 8 David M. Lloyd 2016-01-18 14:56:18 UTC
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

Comment 16 JBoss JIRA Server 2016-02-08 10:55:03 UTC
Tom Jenkinson <tom.jenkinson> updated the status of jira JBEAP-2824 to Resolved

Comment 27 Ondrej Chaloupka 2016-05-17 11:55:40 UTC
Reproducer based on BZ description shows the fix works.
Verified for 6.4.8.CP.CR2.

Comment 28 JBoss JIRA Server 2016-06-14 11:36:40 UTC
Jiri Pallich <jpallich> updated the status of jira JBEAP-2824 to Closed

Comment 29 Petr Penicka 2017-01-17 12:36:26 UTC
Retroactively bulk-closing issues from released EAP 6.4 cumulative patches.


Note You need to log in before you can comment on or make changes to this bug.