[jbossts-issues] [JBoss JIRA] (JBTM-2792) Participant is not rolled-back when RMERR thrown during prepare phase

Participant is not rolled-back when RMERR thrown during prepare phase --------------------------------------------------------------------- Key: JBTM-2792 URL: https://issues.jboss.org/browse/JBTM-2792 Project: JBoss Transaction Manager Issue Type: Bug Reporter: Ondra Chaloupka Assignee: Tom Jenkinson Priority: Critical Attachments: JPAProxyCrashRecoveryTestCase_prepareHalt_jta_server-5.3.3.Final.log, JPAProxyCrashRecoveryTestCase_prepareHalt_jta_server-5.3.5.Final.log I do experience trouble - or maybe different behavior against older version of Narayana - with forgetting transaction log when failure is caused by jdbc driver throws XAException.XAER_RMERR during prepare phase of 2PC. The test scenario is following {quote} * prepare db/jms XA * stop connection to db/jms * prepare test XA * commit db/jms XA (connection is down - jdbc driver throws XAException.XAER_RMERR) * client gets javax.transaction.TransactionRolledbackException from server side * trying to abort transaction * rollback of db resource but connection is down * rolback test XA     * connection is started again * expected behaviour: periodic recovery -> rollback db XA {quote} For current Narayana version (tested with 5.3.5 and 5.4.1.snapshot) the periodic recovery does not rolled back the participant during recovery cycle. For Narayana 5.3.3.Final periodic recovery votes for rollback (ROLLBACK)[1]. Narayan 5.3.5.Final ends with voting for doing nothing (JTATransactionLogXAResourceOrphanFilter.LEAVE_ALONE)[2]. It seems to me that's caused by fact that directly after transaction commit fails (because of not existing connection) for previous version of Narayana transaction record about participant was removed from txn log [3]. But in current version the transaction record is left in log[4] and orphan filters do not vote for roll-backing in bottom-up phase later on. [1] {code} 2016-11-21 09:01:25,576 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:-70f14116:5832a97b:26, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_UNKNOWN2016-11-21 09:01:25,576 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) No record found for < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-70f14116:5832a97b:26, node_name=1, branch_uid=0:ffff7f000001:-70f14116:5832a97b:29, subordinatenodename=null, eis_name=java:jboss/xa-datasources/CrashRecoveryDS >2016-11-21 09:01:25,576 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.JTATransactionLogXAResourceOrphanFilter voted ABSTAIN2016-11-21 09:01:25,576 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) node name of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-70f14116:5832a97b:26, node_name=1, branch_uid=0:ffff7f000001:-70f14116:5832a97b:29, subordinatenodename=null, eis_name=java:jboss/xa-datasources/CrashRecoveryDS > is 12016-11-21 09:01:25,576 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.JTANodeNameXAResourceOrphanFilter voted ROLLBACK2016-11-21 09:01:25,576 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) subordinate node name of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-70f14116:5832a97b:26, node_name=1, branch_uid=0:ffff7f000001:-70f14116:5832a97b:29, subordinatenodename=null, eis_name=java:jboss/xa-datasources/CrashRecoveryDS > is null2016-11-21 09:01:25,576 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.SubordinateJTAXAResourceOrphanFilter voted ABSTAIN2016-11-21 09:01:25,577 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) node name of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-70f14116:5832a97b:26, node_name=1, branch_uid=0:ffff7f000001:-70f14116:5832a97b:29, subordinatenodename=null, eis_name=java:jboss/xa-datasources/CrashRecoveryDS > is 1 {code} [2] {code} 2016-11-21 09:18:03,008 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found record for < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-359c90f5:5832ad62:27, node_name=1, branch_uid=0:ffff7f000001:-359c90f5:5832ad62:2a, subordinatenodename=null, eis_name=java:jboss/xa-datasources/CrashRecoveryDS >2016-11-21 09:18:03,008 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XAResourceOrphanFilter com.arjuna.ats.internal.jta.recovery.arjunacore.JTATransactionLogXAResourceOrphanFilter voted LEAVE_ALONE {code} [3] {code} 2016-11-21 09:00:33,981 TRACE [com.arjuna.ats.arjuna] (default task-8) BasicAction::updateState() for action-id 0:ffff7f000001:-70f14116:5832a97b:262016-11-21 09:00:33,981 TRACE [com.arjuna.ats.arjuna] (default task-8) FileSystemStore.remove_committed(0:ffff7f000001:-70f14116:5832a97b:26, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)2016-11-21 09:00:33,981 TRACE [com.arjuna.ats.arjuna] (default task-8) ShadowingStore.remove_state(0:ffff7f000001:-70f14116:5832a97b:26, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL) {code} [4] {code} 2016-11-21 09:17:11,785 TRACE [com.arjuna.ats.arjuna] (default task-8) Packing action status of ActionStatus.ABORTING2016-11-21 09:17:11,785 TRACE [com.arjuna.ats.arjuna] (default task-8) FileSystemStore.write_committed(0:ffff7f000001:-359c90f5:5832ad62:27, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)2016-11-21 09:17:11,785 TRACE [com.arjuna.ats.arjuna] (default task-8) ShadowingStore.write_state(0:ffff7f000001:-359c90f5:5832ad62:27, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)2016-11-21 09:17:11,785 TRACE [com.arjuna.ats.arjuna] (default task-8) ShadowingStore.genPathName(0:ffff7f000001:-359c90f5:5832ad62:27, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL) {code}