]
RH Bugzilla Integration commented on WFLY-6011:
-----------------------------------------------
baranowb <bbaranow(a)redhat.com> changed the Status of [bug
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@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@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
{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.