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

Mon Apr 25 06:13:02 EDT 2016

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

RH Bugzilla Integration commented on WFLY-6011:
-----------------------------------------------

Vladimir Dosoudil <dosoudil at redhat.com> changed the Status of [bug 1298161|https://bugzilla.redhat.com/show_bug.cgi?id=1298161] from MODIFIED to ON_QA

> 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)