[jboss-jira] [JBoss JIRA] (WFLY-6011) Remote branch of a transaction gets rolled back incorrectly.

[Tom Jenkinson (JIRA)]

    [ https://issues.jboss.org/browse/WFLY-6011?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13149627#comment-13149627 ] 

Tom Jenkinson commented on WFLY-6011:
-------------------------------------

The reason the unprepared branches are returned is caused by this:
https://github.com/wildfly/wildfly/blob/master/ejb3/src/main/java/org/jboss/as/ejb3/remote/EJBRemoteTransactionsRepository.java#L169

The reason that the unprepared branches are returned is to support the case where a remote server crashes and we then need some way to roll back transactions that have been propagated (which do not have a timeout value set). To be able to do that, does JBoss Remoting know when a remote server it has inflowed transactions for has crashed. If so EJB can hook into that and rollback the unprepared transactions at that point?

To recap, we should remove the inflight (unprepared) Xids from the getXidsToRecoverForParentNode() call but find a way to rollback those same inflight transactions once we detect the connection to the remote server is broken.

> Remote branch of a transaction gets rolled back incorrectly. 
> -------------------------------------------------------------
>
>                 Key: WFLY-6011
>                 URL: https://issues.jboss.org/browse/WFLY-6011
>             Project: WildFly
>          Issue Type: Bug
>          Components: EJB
>            Reporter: Jason Greene
>            Assignee: David Lloyd
>
> 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)
> {noformat}
> 11:53:37,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids _whenFirstSeen toRecover no RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext at 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 >
> {noformat}
> (server-2 log)
> {noformat}
> 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 at 3de8e444[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 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 at 32ff4c6d >)
> 11:53:37,998 TRACE [com.arjuna.ats.jta] (EJB default - 5) XAResourceRecord.topLevelAbort for XAResourceRecord < resource:XAResourceWrapperImpl at 3de8e444[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 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 at 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
> {noformat}
> 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
> {noformat}
> 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 )
> {noformat}
> 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 message was sent by Atlassian JIRA
(v6.4.11#64026)