[JBoss JIRA] (JBTM-2792) Participant is not rolled-back when RMERR thrown during prepare phase
by Ondra Chaloupka (JIRA)
[ https://issues.jboss.org/browse/JBTM-2792?page=com.atlassian.jira.plugin.... ]
Ondra Chaloupka reassigned JBTM-2792:
-------------------------------------
Assignee: Tom Jenkinson
> 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}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
7 years, 5 months
- 1
- 0
[JBoss JIRA] (JBTM-2792) Participant is not rolled-back when RMERR thrown during prepare phase
by Ondra Chaloupka (JIRA)
[ https://issues.jboss.org/browse/JBTM-2792?page=com.atlassian.jira.plugin.... ]
Ondra Chaloupka updated JBTM-2792:
----------------------------------
Attachment: JPAProxyCrashRecoveryTestCase_prepareHalt_jta_server-5.3.3.Final.log
JPAProxyCrashRecoveryTestCase_prepareHalt_jta_server-5.3.5.Final.log
> 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}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
7 years, 5 months
- 1
- 0
[JBoss JIRA] (JBTM-2792) Participant is not rolled-back when RMERR thrown during prepare phase
by Ondra Chaloupka (JIRA)
Ondra Chaloupka created JBTM-2792:
-------------------------------------
Summary: 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
Priority: Critical
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}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
7 years, 5 months
- 1
- 0
[JBoss JIRA] (JBTM-2791) JTS bottom-up could roll-back prepared inflowed JCA transactions
by Ondra Chaloupka (JIRA)
[ https://issues.jboss.org/browse/JBTM-2791?page=com.atlassian.jira.plugin.... ]
Ondra Chaloupka moved JBEAP-7356 to JBTM-2791:
----------------------------------------------
Project: JBoss Transaction Manager (was: JBoss Enterprise Application Platform)
Key: JBTM-2791 (was: JBEAP-7356)
Workflow: GIT Pull Request workflow (was: CDW with loose statuses v1)
Component/s: JTS
(was: Transactions)
Affects Version/s: 5.3.5.Final
(was: 7.1.0.DR8)
> JTS bottom-up could roll-back prepared inflowed JCA transactions
> ----------------------------------------------------------------
>
> Key: JBTM-2791
> URL: https://issues.jboss.org/browse/JBTM-2791
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: JTS
> Affects Versions: 5.3.5.Final
> Reporter: Ondra Chaloupka
> Assignee: Tom Jenkinson
> Attachments: 5.3.3.Final-fail-jvmCrashAfterPrepareJTS_jts_server.log, 5.3.5.Final-fail-jvmCrashAfterPrepareJTS_jts_server.log, 5.3.5.Final-pass-jvmCrashAfterPrepareJTS_jts_server.log
>
>
> I experience race condition in my testcase for JBTM-2748/JBEAP-5880. Even by "detailed" investigation on {{server.log}} I'm a bit lost in what can cause the problem. By my testing I can see that Narayana 5.3.3.Final fails my test anytime. Narayana 5.3.5.Final seems to pass in most of the cases but time to time fails. The result is the same as at 5.3.3.Final. Nevertheless I can see different behavior shown by {{server.log}}.
> For Narayana 5.3.3.Final during the JTS recovery second phase TM gets txn status and decides to rollback [1].
> For Narayana 5.3.5.Final during the JTS recovery second phase if TM gets txn status it goes for commit but if there is some trouble to get it it rollbacks. The problem that I refer to is represented by error {{WARN [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022139: CORBA exception on trying to contact original process: org.omg.CORBA.BAD_OPERATION}} [2].
> I'm adding three server logs as attachment - fail for 5.3.3.Final and two for 5.3.5.Final - one failing, one passing.
> [1]
> {code}
> 2016-11-16 15:16:52,985 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning 2 Xids
> 2016-11-16 15:16:52,985 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning xid: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 15:16:52,985 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning xid: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 15:16:52,985 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@31a25bc7, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@3f537a39}, transactionOriginNodeIdentifier='1'} 1479305802928 1479305812985 false
> 2016-11-16 15:16:52,987 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0)) 1479305802969 1479305812985 false
> 2016-11-16 15:16:52,987 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@7a29e943 1479305802948 1479305812987 false
> 2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) JTS XARecoveryModule.resourceInitiatedRecovery completed
> 2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change SECOND_PASS->IDLE
> 2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE
> 2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: scan thread signals listener worker
> 2016-11-16 15:16:52,987 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off
> 2016-11-16 15:17:12,988 DEBUG [com.arjuna.ats.arjuna] (Listener:4712) Connected to 127.0.0.1 on port 50586 on listener port 4712 for service com.arjuna.ats.internal.arjuna.recovery.WorkerService
> 2016-11-16 15:17:12,989 DEBUG [com.arjuna.ats.arjuna] (Server.Connection:127.0.0.1:50586) PeriodicRecovery: listener worker interrupts background thread
> 2016-11-16 15:17:12,989 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING
> 2016-11-16 15:17:12,989 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning
> 2016-11-16 15:17:12,989 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Wed, 16 Nov 2016 15:17:12
> 2016-11-16 15:17:12,989 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) CommitMarkableResourceRecordRecoveryModule::periodicWorkFirstPass
> 2016-11-16 15:17:12,989 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,989 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , -1)
> 2016-11-16 15:17:12,989 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , -1)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , -1)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
> 2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:12,990 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: )
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 28
> OutputObjectState Buffer: , StateManager)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 60
> OutputObjectState Buffer: , StateManager/BasicAction)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 112
> OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 184
> OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 276
> OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 372
> OutputObjectState Buffer: , StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 396
> OutputObjectState Buffer: , RecoveryCoordinator)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 416
> OutputObjectState Buffer: , CosTransactions)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 456
> OutputObjectState Buffer: , CosTransactions/XAResourceRecord)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 472
> OutputObjectState Buffer: , Recovery)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid : 0:ffff7f000001:57fceedf:582c6a40:3c
> OutputObjectState Type : null
> OutputObjectState Size : 500
> OutputObjectState Buffer: , Recovery/FactoryContact)
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,990 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager/BasicAction, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager/BasicAction/TwoPhaseCoordinator, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA, StateType.OS_SHADOW)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA, 10)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA, 11)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction/JCA) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(RecoveryCoordinator, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff52e38d0c:c91:4140398c:0, RecoveryCoordinator, StateType.OS_SHADOW)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff52e38d0c:c91:4140398c:0, RecoveryCoordinator, 10)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff52e38d0c:c91:4140398c:0, RecoveryCoordinator, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff52e38d0c:c91:4140398c:0, RecoveryCoordinator, 11)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff52e38d0c:c91:4140398c:0, RecoveryCoordinator) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(CosTransactions, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(CosTransactions/XAResourceRecord, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
> 2016-11-16 15:17:12,991 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, CosTransactions/XAResourceRecord, 10)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, CosTransactions/XAResourceRecord, 11)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2e, CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, CosTransactions/XAResourceRecord, 10)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, CosTransactions/XAResourceRecord, 11)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2b, CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(Recovery, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(Recovery/FactoryContact, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , 2)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, Recovery/FactoryContact, StateType.OS_SHADOW)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, Recovery/FactoryContact, 10)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, Recovery/FactoryContact, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, Recovery/FactoryContact, 11)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:10, Recovery/FactoryContact) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:57fceedf:582c6a40:1b, Recovery/FactoryContact, StateType.OS_SHADOW)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:57fceedf:582c6a40:1b, Recovery/FactoryContact, 10)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:57fceedf:582c6a40:1b, Recovery/FactoryContact, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:57fceedf:582c6a40:1b, Recovery/FactoryContact, 11)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:57fceedf:582c6a40:1b, Recovery/FactoryContact) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:12,992 INFO [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022199: TopLevelTransactionRecoveryModule First Pass
> 2016-11-16 15:17:12,992 INFO [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022213: TransactionRecoveryModule.periodicWorkFirstPass()
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) TransactionRecoveryModule: scanning for /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , -1)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,992 INFO [com.arjuna.ats.arjuna] (Server.Connection:127.0.0.1:50586) ARJUNA012340: RecoveryManager scan scheduled to begin.
> 2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:12,992 INFO [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022190: ServerTransactionRecoveryModule - First Pass
> 2016-11-16 15:17:12,992 INFO [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022213: TransactionRecoveryModule.periodicWorkFirstPass()
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) TransactionRecoveryModule: scanning for /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , -1)
> 2016-11-16 15:17:12,992 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:12,992 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change IDLE->FIRST_PASS
> 2016-11-16 15:17:12,993 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) JTS XARecoveryModule - first pass
> 2016-11-16 15:17:12,993 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:12,993 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/CosTransactions/XAResourceRecord, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , -1)
> 2016-11-16 15:17:12,993 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:12,995 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) getXAResources() instance: TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0))
> 2016-11-16 15:17:12,997 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@31a25bc7, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@3f537a39}, transactionOriginNodeIdentifier='1'}
> 2016-11-16 15:17:12,997 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt
> 2016-11-16 15:17:12,997 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids updateIfEquivalentRM2 RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@31a25bc7, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@3f537a39}, transactionOriginNodeIdentifier='1'} 1479305832997
> 2016-11-16 15:17:12,997 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@7a29e943
> 2016-11-16 15:17:12,998 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt
> 2016-11-16 15:17:13,001 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0))
> 2016-11-16 15:17:13,005 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecovered] (Periodic Recovery) TestXAResourceRecovered.recover(i=16777216)[id=512]
> 2016-11-16 15:17:13,005 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) recover()
> 2016-11-16 15:17:13,005 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning 2 Xids
> 2016-11-16 15:17:13,005 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning xid: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 15:17:13,005 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) returning xid: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 15:17:13,005 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 2 xids in doubt
> 2016-11-16 15:17:13,005 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Recovered: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 15:17:13,005 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Recovered: < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 15:17:13,010 INFO [org.jboss.as.test.jbossts.common.TestXAResourceCommon] (Periodic Recovery) TestXAResourceCommon.isSameRM(xaResource=RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@31a25bc7, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@3f537a39}, transactionOriginNodeIdentifier='1'})[return 'false'][id=512]
> 2016-11-16 15:17:13,013 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids updateIfEquivalentRM1 TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0)) 1479305833010
> 2016-11-16 15:17:13,016 INFO [org.jboss.as.test.jbossts.common.TestXAResourceCommon] (Periodic Recovery) TestXAResourceCommon.isSameRM(xaResource=org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@7a29e943)[return 'false'][id=512]
> 2016-11-16 15:17:13,017 INFO [org.jboss.as.test.jbossts.common.TestXAResourceCommon] (Periodic Recovery) getJndiName()[return java:/TestXAResource][id=512]
> 2016-11-16 15:17:13,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES
> 2016-11-16 15:17:13,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Wed, 16 Nov 2016 15:17:23
> 2016-11-16 15:17:23,017 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
> 2016-11-16 15:17:23,017 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 0
> InputObjectState Buffer: , -1)
> 2016-11-16 15:17:23,017 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:23,017 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicActionConnectable, InputObjectState Uid : 0:0:0:0:0
> InputObjectState Type : null
> InputObjectState Size : 40
> InputObjectState Buffer: , -1)
> 2016-11-16 15:17:23,017 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass
> 2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass
> 2016-11-16 15:17:23,017 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:23,018 INFO [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022200: TopLevelTransactionRecoveryModule Second Pass
> 2016-11-16 15:17:23,018 INFO [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022214: TransactionRecoveryModule.periodicWorkSecondPass()
> 2016-11-16 15:17:23,018 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:23,018 INFO [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022191: ServerTransactionRecoveryModule - Second Pass
> 2016-11-16 15:17:23,018 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
> 2016-11-16 15:17:23,018 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 2016-11-16 15:17:23,018 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) JTS XARecoveryModule - second pass
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 10)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 11)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 10)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 11)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 11)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2e, FileLock.F_RDLCK, false)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord)
> 2016-11-16 15:17:23,018 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2e, java.io.FileInputStream@655e320b, null)
> 2016-11-16 15:17:23,019 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XARecovery 0:ffff7f000001:5857c0a5:582c6a36:2e is non-recoverable
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, 10)
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, 11)
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord)
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, 10)
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, 11)
> 2016-11-16 15:17:23,019 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:23,020 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,020 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord, 11)
> 2016-11-16 15:17:23,020 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2b, FileLock.F_RDLCK, false)
> 2016-11-16 15:17:23,020 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffff7f000001:5857c0a5:582c6a36:2b, /CosTransactions/XAResourceRecord)
> 2016-11-16 15:17:23,020 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2b, java.io.FileInputStream@4c2e5fd0, null)
> 2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) XARecovery 0:ffff7f000001:5857c0a5:582c6a36:2b is non-recoverable
> 2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) JTS XARecoveryModule.transactionInitiatedRecovery completed
> 2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@31a25bc7, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@3f537a39}, transactionOriginNodeIdentifier='1'}
> 2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.
> 2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@7a29e943
> 2016-11-16 15:17:23,021 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.
> 2016-11-16 15:17:23,024 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0))
> 2016-11-16 15:17:23,028 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids _whenFirstSeen toRecover yes TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0)) 1479305802973 === 1479305843024
> 2016-11-16 15:17:23,030 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids _whenFirstSeen toRecover no TestXAResourceRecovered(TestXAResourceCommon(id:512, xid:null, timeout:0, prepareReturn:0)) 1479305802973 === 1479305843024
> 2016-11-16 15:17:23,030 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 1 Xids to recover on this pass.
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord)
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 10)
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 11)
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord, 11)
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2e, FileLock.F_RDLCK, false)
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffff7f000001:5857c0a5:582c6a36:2e, /CosTransactions/XAResourceRecord)
> 2016-11-16 15:17:23,031 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/CosTransactions/XAResourceRecord/0_ffff7f000001_5857c0a5_582c6a36_2e, java.io.FileInputStream@75d2f77a, null)
> 2016-11-16 15:17:23,032 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.recover
> 2016-11-16 15:17:23,033 TRACE [com.arjuna.orbportability] (Periodic Recovery) RootOA::objectIsReady (Servant)
> 2016-11-16 15:17:23,034 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::send_request ( _is_a ) nodeId=1 requestId=7
> 2016-11-16 15:17:23,035 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( _is_a ) nodeId=1 requestId=7
> 2016-11-16 15:17:23,035 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request ( _is_a ) nodeId=1 requestId=7
> 2016-11-16 15:17:23,035 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( _is_a ) nodeId=1 requestId=7
> 2016-11-16 15:17:23,035 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( _is_a ) nodeId=1 requestId=7
> 2016-11-16 15:17:23,036 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( _is_a ) nodeId=1 requestId=7
> 2016-11-16 15:17:23,039 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::send_request ( replay_completion ) nodeId=1 requestId=8
> 2016-11-16 15:17:23,039 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ContextManager::current ()
> 2016-11-16 15:17:23,040 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( replay_completion ) nodeId=1 requestId=8
> 2016-11-16 15:17:23,041 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request ( replay_completion ) nodeId=1 requestId=8
> 2016-11-16 15:17:23,041 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) JavaIdlRCDefaultServant::replay_completion)
> 2016-11-16 15:17:23,042 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) RecoveryCoordinatorId(0:ffff7f000001:5857c0a5:582c6a36:2f*0:ffff7f000001:5857c0a5:582c6a36:25*0:ffff7f000001:5857c0a5:582c6a36:10*true)
> 2016-11-16 15:17:23,042 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) JavaIdlDefaultServant replay_completion for Id (0:ffff7f000001:5857c0a5:582c6a36:2f, 0:ffff7f000001:5857c0a5:582c6a36:25, 0:ffff7f000001:5857c0a5:582c6a36:10, interposed-tx)
> 2016-11-16 15:17:23,043 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) GenericRecoveryCoordinator(0:ffff7f000001:5857c0a5:582c6a36:2f).replay_completion(resource supplied)
> 2016-11-16 15:17:23,044 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.get_current_status(0:ffff7f000001:5857c0a5:582c6a36:25, 0:ffff7f000001:5857c0a5:582c6a36:10)
> 2016-11-16 15:17:23,044 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.checkOriginalStatus(0:ffff7f000001:5857c0a5:582c6a36:25, 0:ffff7f000001:5857c0a5:582c6a36:10, false)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, 10)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, 11)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact) - returning StateStatus.OS_COMMITTED
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact, 11)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/Recovery/FactoryContact/0_ffff7f000001_5857c0a5_582c6a36_10, FileLock.F_RDLCK, false)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffff7f000001:5857c0a5:582c6a36:10, /Recovery/FactoryContact)
> 2016-11-16 15:17:23,044 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/Recovery/FactoryContact/0_ffff7f000001_5857c0a5_582c6a36_10, java.io.FileInputStream@4178e7fb, null)
> 2016-11-16 15:17:23,045 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:5857c0a5:582c6a36:25, com.arjuna.ats.internal.jts.recovery.contact.FactoryContactItem@d2278c3, false)
> 2016-11-16 15:17:23,046 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::send_request ( getCurrentStatus ) nodeId=1 requestId=9
> 2016-11-16 15:17:23,046 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ContextManager::current ()
> 2016-11-16 15:17:23,047 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( getCurrentStatus ) nodeId=1 requestId=9
> 2016-11-16 15:17:23,047 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request ( getCurrentStatus ) nodeId=1 requestId=9
> 2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 10)
> 2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 11)
> 2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 10)
> 2016-11-16 15:17:23,048 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,049 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 11)
> 2016-11-16 15:17:23,049 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,050 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,050 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 10)
> 2016-11-16 15:17:23,050 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,050 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 11)
> 2016-11-16 15:17:23,050 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,051 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,051 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 10)
> 2016-11-16 15:17:23,051 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,051 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 11)
> 2016-11-16 15:17:23,051 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,052 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( getCurrentStatus ) nodeId=1 requestId=9
> 2016-11-16 15:17:23,052 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( getCurrentStatus ) nodeId=1 requestId=9
> 2016-11-16 15:17:23,052 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( getCurrentStatus ) nodeId=1 requestId=9
> 2016-11-16 15:17:23,053 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:5857c0a5:582c6a36:25) - current status = CosTransactions::StatusNoTransaction
> 2016-11-16 15:17:23,053 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::send_request ( getStatus ) nodeId=1 requestId=10
> 2016-11-16 15:17:23,053 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ContextManager::current ()
> 2016-11-16 15:17:23,053 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( getStatus ) nodeId=1 requestId=10
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request ( getStatus ) nodeId=1 requestId=10
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 10)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 11)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 10)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 11)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 10)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 11)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 10)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 11)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 10)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple, 11)
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,054 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 10)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction, 11)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 10)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 11)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_SHADOW)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 10)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction, 11)
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:5857c0a5:582c6a36:25, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteHeuristicServerTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( getStatus ) nodeId=1 requestId=10
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( getStatus ) nodeId=1 requestId=10
> 2016-11-16 15:17:23,055 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( getStatus ) nodeId=1 requestId=10
> 2016-11-16 15:17:23,055 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:5857c0a5:582c6a36:25) - stored status = CosTransactions::StatusNoTransaction
> 2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( replay_completion ) nodeId=1 requestId=8
> 2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( replay_completion ) nodeId=1 requestId=8
> 2016-11-16 15:17:23,057 DEBUG [com.arjuna.ats.jts] (Thread-109) ResourceCompletor.rollback()
> 2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( replay_completion ) nodeId=1 requestId=8
> 2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.recover got status: CosTransactions::StatusRolledBack
> 2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.doRecovery ( false )
> 2016-11-16 15:17:23,057 INFO [com.arjuna.ats.jtax] (Periodic Recovery) ARJUNA024002: XA recovery rolling back < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 15:17:23,057 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.rollback for < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 15:17:23,068 TRACE [com.arjuna.ats.jts] (Thread-109) InterpositionClientRequestInterceptorImpl::send_request ( rollback ) nodeId=1 requestId=11
> 2016-11-16 15:17:23,068 TRACE [com.arjuna.ats.jts] (Thread-109) ContextManager::current ()
> 2016-11-16 15:17:23,069 TRACE [com.arjuna.ats.jts] (Thread-109) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( rollback ) nodeId=1 requestId=11
> 2016-11-16 15:17:23,069 TRACE [com.arjuna.ats.jts] (Thread-109) InterpositionServerRequestInterceptorImpl::receive_request ( rollback ) nodeId=1 requestId=11
> 2016-11-16 15:17:23,070 TRACE [com.arjuna.ats.jtax] (Thread-109) XAResourceRecord.rollback for < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 15:17:23,074 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecovered] (Periodic Recovery) TestXAResourceRecovered.rollback(Xid=< 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >)[id=512]
> 2016-11-16 15:17:23,074 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) removeLog(xid=< 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 15:17:23,074 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) Using file /home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/TestXAResourceStateStore/TestXAResource.ser for saving state of the org.jboss.as.test.jbossts.common.TestXAResource XA resource
> {code}
> [2]
> {code}
> 2016-11-16 09:45:51,329 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:7c17affe:582c1c73:28, com.arjuna.ats.internal.jts.recovery.contact.FactoryContactItem@7b5023d7, false)
> 2016-11-16 09:45:51,330 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::send_request ( getCurrentStatus ) nodeId=1 requestId=10
> 2016-11-16 09:45:51,330 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ContextManager::current ()
> 2016-11-16 09:45:51,330 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( getCurrentStatus ) nodeId=1 requestId=10
> 2016-11-16 09:45:51,330 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::receive_request ( getCurrentStatus ) nodeId=1 requestId=10
> 2016-11-16 09:45:51,335 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_exception ( getCurrentStatus ) nodeId=1 requestId=10
> 2016-11-16 09:45:51,335 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( getCurrentStatus ) nodeId=1 requestId=10
> 2016-11-16 09:45:51,338 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_exception ( getCurrentStatus ) nodeId=1 requestId=10
> 2016-11-16 09:45:51,339 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:7c17affe:582c1c73:28) - COMM_FAILURE = dead
> 2016-11-16 09:45:51,339 WARN [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022139: CORBA exception on trying to contact original process: org.omg.CORBA.BAD_OPERATION: ----------BEGIN server-side stack trace----------
> org.omg.CORBA.BAD_OPERATION: vmcid: 0x0 minor code: 0 completed: Maybe
> at com.arjuna.ArjunaOTS.ArjunaTransactionPOA._invoke(ArjunaTransactionPOA.java:50)
> at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:654)
> at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:205)
> at com.sun.corba.se.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1700)
> at com.sun.corba.se.impl.protocol.SharedCDRClientRequestDispatcherImpl.marshalingComplete(SharedCDRClientRequestDispatcherImpl.java:180)
> at com.sun.corba.se.impl.protocol.CorbaClientDelegateImpl.invoke(CorbaClientDelegateImpl.java:148)
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:475)
> at com.arjuna.ArjunaOTS._ArjunaFactoryStub.getCurrentStatus(_ArjunaFactoryStub.java:76)
> at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.getStatus(StatusChecker.java:176)
> at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.checkOriginalStatus(StatusChecker.java:144)
> at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.get_current_status(StatusChecker.java:110)
> at com.arjuna.ats.internal.jts.orbspecific.recovery.recoverycoordinators.GenericRecoveryCoordinator.get_status(GenericRecoveryCoordinator.java:355)
> at com.arjuna.ats.internal.jts.orbspecific.recovery.recoverycoordinators.GenericRecoveryCoordinator.replay_completion(GenericRecoveryCoordinator.java:145)
> at com.arjuna.ats.internal.jts.orbspecific.javaidl.recoverycoordinators.JavaIdlRCDefaultServant.replay_completion(JavaIdlRCDefaultServant.java:101)
> at org.omg.CosTransactions.RecoveryCoordinatorPOA._invoke(RecoveryCoordinatorPOA.java:39)
> at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:654)
> at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:205)
> at com.sun.corba.se.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1700)
> at com.sun.corba.se.impl.protocol.SharedCDRClientRequestDispatcherImpl.marshalingComplete(SharedCDRClientRequestDispatcherImpl.java:180)
> at com.sun.corba.se.impl.protocol.CorbaClientDelegateImpl.invoke(CorbaClientDelegateImpl.java:148)
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:475)
> at org.omg.CosTransactions._RecoveryCoordinatorStub.replay_completion(_RecoveryCoordinatorStub.java:20)
> at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.recover(XAResourceRecord.java:1226)
> at com.arjuna.ats.internal.jta.recovery.jts.XARecoveryResourceImple.recover(XARecoveryResourceImple.java:88)
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:736)
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:461)
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:218)
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811)
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377)
> ----------END server-side stack trace---------- vmcid: 0x0 minor code: 0 completed: Maybe
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> at com.sun.corba.se.impl.protocol.giopmsgheaders.MessageBase.getSystemException(MessageBase.java:921)
> at com.sun.corba.se.impl.protocol.giopmsgheaders.ReplyMessage_1_2.getSystemException(ReplyMessage_1_2.java:116)
> at com.sun.corba.se.impl.protocol.CorbaMessageMediatorImpl.getSystemExceptionReply(CorbaMessageMediatorImpl.java:590)
> at com.sun.corba.se.impl.protocol.CorbaClientRequestDispatcherImpl.processResponse(CorbaClientRequestDispatcherImpl.java:489)
> at com.sun.corba.se.impl.protocol.SharedCDRClientRequestDispatcherImpl.marshalingComplete(SharedCDRClientRequestDispatcherImpl.java:222)
> at com.sun.corba.se.impl.protocol.CorbaClientDelegateImpl.invoke(CorbaClientDelegateImpl.java:148)
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:475)
> at com.arjuna.ArjunaOTS._ArjunaFactoryStub.getCurrentStatus(_ArjunaFactoryStub.java:76)
> at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.getStatus(StatusChecker.java:176)
> at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.checkOriginalStatus(StatusChecker.java:144)
> at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.get_current_status(StatusChecker.java:110)
> at com.arjuna.ats.internal.jts.orbspecific.recovery.recoverycoordinators.GenericRecoveryCoordinator.get_status(GenericRecoveryCoordinator.java:355)
> at com.arjuna.ats.internal.jts.orbspecific.recovery.recoverycoordinators.GenericRecoveryCoordinator.replay_completion(GenericRecoveryCoordinator.java:145)
> at com.arjuna.ats.internal.jts.orbspecific.javaidl.recoverycoordinators.JavaIdlRCDefaultServant.replay_completion(JavaIdlRCDefaultServant.java:101)
> at org.omg.CosTransactions.RecoveryCoordinatorPOA._invoke(RecoveryCoordinatorPOA.java:39)
> at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:654)
> at com.sun.corba.se.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:205)
> at com.sun.corba.se.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1700)
> at com.sun.corba.se.impl.protocol.SharedCDRClientRequestDispatcherImpl.marshalingComplete(SharedCDRClientRequestDispatcherImpl.java:180)
> at com.sun.corba.se.impl.protocol.CorbaClientDelegateImpl.invoke(CorbaClientDelegateImpl.java:148)
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:475)
> at org.omg.CosTransactions._RecoveryCoordinatorStub.replay_completion(_RecoveryCoordinatorStub.java:20)
> at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.recover(XAResourceRecord.java:1226)
> at com.arjuna.ats.internal.jta.recovery.jts.XARecoveryResourceImple.recover(XARecoveryResourceImple.java:88)
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:736)
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:461)
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:218)
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811)
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377)
> 2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
> 2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.write_committed(0:ffff7f000001:7c17affe:582c1c73:14, /Recovery/FactoryContact)
> 2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.write_state(0:ffff7f000001:7c17affe:582c1c73:14, /Recovery/FactoryContact, StateType.OS_ORIGINAL)
> 2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:14, /Recovery/FactoryContact, StateType.OS_ORIGINAL)
> 2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:14, /Recovery/FactoryContact, 11)
> 2016-11-16 09:45:51,339 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/Recovery/FactoryContact/0_ffff7f000001_7c17affe_582c1c73_14, FileLock.F_WRLCK, true)
> 2016-11-16 09:45:51,345 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/Recovery/FactoryContact/0_ffff7f000001_7c17affe_582c1c73_14, null, java.io.FileOutputStream@33746342)
> 2016-11-16 09:45:51,346 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) CachedRecoveredTransaction created [0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction]
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 0:ffff7f000001:7c17affe:582c1c73:28 )
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::BasicAction(0:ffff7f000001:7c17affe:582c1c73:28)
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ArjunaTransactionImple::ArjunaTransactionImple ( 0:ffff7f000001:7c17affe:582c1c73:28 )
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ServerTransaction::ServerTransaction ( 0:ffff7f000001:7c17affe:582c1c73:28 )
> 2016-11-16 09:45:51,347 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) RecoveredServerTransaction 0:ffff7f000001:7c17affe:582c1c73:28 created
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_SHADOW)
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 10)
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction, 11)
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 0:ffff7f000001:7c17affe:582c1c73:28 )
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::BasicAction(0:ffff7f000001:7c17affe:582c1c73:28)
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ArjunaTransactionImple::ArjunaTransactionImple ( 0:ffff7f000001:7c17affe:582c1c73:28 )
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.jts] (Periodic Recovery) ServerTransaction::ServerTransaction ( 0:ffff7f000001:7c17affe:582c1c73:28 )
> 2016-11-16 09:45:51,347 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) RecoveredServerTransaction 0:ffff7f000001:7c17affe:582c1c73:28 created
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteServerTransaction, StateType.OS_SHADOW)
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteServerTransaction, 10)
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteServerTransaction, StateType.OS_ORIGINAL)
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteServerTransaction, 11)
> 2016-11-16 09:45:51,347 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/AssumedCompleteServerTransaction) - returning StateStatus.OS_UNKNOWN
> 2016-11-16 09:45:51,347 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) AssumedCompleteServerTransaction 0:ffff7f000001:7c17affe:582c1c73:28 created
> 2016-11-16 09:45:51,347 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) CachedRecoveredTransaction.get_status [0:ffff7f000001:7c17affe:582c1c73:28, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction] = CosTransactions::StatusRolledBack
> 2016-11-16 09:45:51,348 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( replay_completion ) nodeId=1 requestId=9
> 2016-11-16 09:45:51,348 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( replay_completion ) nodeId=1 requestId=9
> 2016-11-16 09:45:51,348 DEBUG [com.arjuna.ats.jts] (Thread-108) ResourceCompletor.rollback()
> 2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jts] (Thread-108) InterpositionClientRequestInterceptorImpl::send_request ( rollback ) nodeId=1 requestId=11
> 2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jts] (Thread-108) ContextManager::current ()
> 2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( replay_completion ) nodeId=1 requestId=9
> 2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.recover got status: CosTransactions::StatusRolledBack
> 2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.doRecovery ( false )
> 2016-11-16 09:45:51,349 INFO [com.arjuna.ats.jtax] (Periodic Recovery) ARJUNA024002: XA recovery rolling back < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jts] (Thread-108) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( rollback ) nodeId=1 requestId=11
> 2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.rollback for < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 09:45:51,349 TRACE [com.arjuna.ats.jts] (Thread-108) InterpositionServerRequestInterceptorImpl::receive_request ( rollback ) nodeId=1 requestId=11
> 2016-11-16 09:45:51,350 TRACE [com.arjuna.ats.jtax] (Thread-108) XAResourceRecord.rollback for < 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 09:45:51,354 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecovered] (Periodic Recovery) TestXAResourceRecovered.rollback(Xid=< 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >)[id=947]
> 2016-11-16 09:45:51,354 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) removeLog(xid=< 4660, 64, 64, 12700100004200042000000000000000000000000000000000000000000000000000, 12700100004200042000000000000000000000000000000000000000000000000000 >
> 2016-11-16 09:45:51,354 INFO [org.jboss.as.test.jbossts.common.TestXAResourceRecoveryHelper] (Periodic Recovery) Using file /home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/standalone/data/tx-object-store/TestXAResourceStateStore/TestXAResource.ser for saving state of the org.jboss.as.test.jbossts.common.TestXAResource XA resource
> {code}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
7 years, 5 months
- 1
- 0
[JBoss JIRA] (JBTM-2763) problem running with hibernate
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-2763?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson updated JBTM-2763:
--------------------------------
Status: Resolved (was: Pull Request Sent)
Resolution: Done
> problem running with hibernate
> ------------------------------
>
> Key: JBTM-2763
> URL: https://issues.jboss.org/browse/JBTM-2763
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: JTA
> Affects Versions: 5.3.5.Final
> Environment: Spring 4.3.3.RELEASE
> Hibernate 5.1.2.Final
> Narayana 5.3.5
> Not in an application server - running standalone spring app
> Reporter: davidkarlsen
> Assignee: Tom Jenkinson
>
> With the same libraries as above, except narayana 5.3.5 the following config worked just fine:
> {noformat}
> <bean id="abstractEntityManagerFactory" abstract="true" class="org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean" depends-on="cacheManagerFactoryBean">
> <property name="jpaVendorAdapter">
> <bean class="org.springframework.orm.jpa.vendor.HibernateJpaVendorAdapter">
> <property name="generateDdl" value="false" />
> <property name="showSql" value="${hibernate.showSql}" />
> <property name="database">
> <util:constant static-field="org.springframework.orm.jpa.vendor.Database.ORACLE" />
> </property>
> <property name="databasePlatform" value="${hibernate.dialect}" />
> </bean>
> </property>
> <property name="jpaProperties">
> <props>
> <!-- <prop key="hibernate.cache.region.factory_class">net.sf.ehcache.hibernate.EhCacheRegionFactory</prop> -->
> <prop key="hibernate.cache.region.factory_class">org.hibernate.cache.ehcache.SingletonEhCacheRegionFactory</prop>
> <prop key="hibernate.cache.use_query_cache">${hibernate.cache.use_query_cache}</prop>
> <prop key="hibernate.cache.use_second_level_cache">${hibernate.cache.use_second_level_cache}</prop>
> <prop key="hibernate.generate_statistics">${hibernate.generate_statistics}</prop>
> <prop key="hibernate.cache.use_structured_entries">${hibernate.cache.use_structured_entries}</prop>
> <prop key="hibernate.transaction.jta.platform">${hibernate.transaction.jta.platform:org.hibernate.engine.transaction.jta.platform.internal.JBossStandAloneJtaPlatform}</prop>
> <!-- release mode, see:
> https://developer.jboss.org/thread/221140
> http://docs.jboss.org/hibernate/stable/core.old/reference/en/html/transac...
> -->
> <prop key="hibernate.connection.release_mode">${hibernate.connection.release_mode:AFTER_STATEMENT}</prop>
> <prop key="hibernate.jdbc.use_get_generated_keys">${hibernate.jdbc.use_get_generated_keys}</prop>
> <prop key="hibernate.jdbc.fetch_size">${hibernate.jdbc.fetch_size}</prop>
> <prop key="hibernate.jdbc.batch_size">${hibernate.jdbc.batch_size}</prop>
> <prop key="hibernate.show_sql">${hibernate.showSql}</prop>
> <prop key="hibernate.format_sql">${hibernate.format_sql}</prop>
> <prop key="hibernate.use_sql_comments">${hibernate.use_sql_comments}</prop>
> </props>
> </property>
> </bean>
> {noformat}
> If I upgrade Narayana to 5.3.5 I consistently get:
> {noformat}
> java.sql.SQLSyntaxErrorException: ORA-02049: timeout: distributed transaction waiting for lock
> at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:450)
> at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:399)
> at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1059)
> at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:522)
> at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:257)
> at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:587)
> at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:210)
> at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:30)
> at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:931)
> at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1150)
> at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1792)
> at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1745)
> at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:334)
> at sun.reflect.GeneratedMethodAccessor84.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at net.bull.javamelody.JdbcWrapper.doExecute(JdbcWrapper.java:404)
> at net.bull.javamelody.JdbcWrapper$StatementInvocationHandler.invoke(JdbcWrapper.java:129)
> at net.bull.javamelody.JdbcWrapper$DelegatingInvocationHandler.invoke(JdbcWrapper.java:286)
> at com.sun.proxy.$Proxy143.execute(Unknown Source)
> at org.dbunit.database.statement.SimpleStatement.executeBatch(SimpleStatement.java:69)
> at org.dbunit.operation.DeleteAllOperation.execute(DeleteAllOperation.java:126)
> at org.dbunit.operation.CompositeOperation.execute(CompositeOperation.java:79)
> at com.github.springtestdbunit.DbUnitRunner.setupOrTeardown(DbUnitRunner.java:183)
> at com.github.springtestdbunit.DbUnitRunner.beforeTestMethod(DbUnitRunner.java:75)
> at com.github.springtestdbunit.DbUnitTestExecutionListener.beforeTestMethod(DbUnitTestExecutionListener.java:185)
> at org.springframework.test.context.TestContextManager.beforeTestMethod(TestContextManager.java:269)
> at org.springframework.test.context.junit4.statements.RunBeforeTestMethodCallbacks.evaluate(RunBeforeTestMethodCallbacks.java:74)
> at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.springframework.test.context.junit4.statements.RunAfterTestMethodCallbacks.evaluate(RunAfterTestMethodCallbacks.java:86)
> at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> at org.springframework.test.context.junit4.statements.SpringRepeat.evaluate(SpringRepeat.java:84)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:252)
> at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:94)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
> at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191)
> at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:367)
> at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:274)
> at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
> at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:161)
> at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
> at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
> at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.
> {noformat}
> If I leave hibernate.connection.release_mode to default (e.g. not specifying it) or after_transaction I get:
> {noformat}
> WARN com.arjuna.ats.jta - ARJUNA016029: SynchronizationImple.afterCompletion - failed for org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization@6811fa19 with exception
> 22:59:01 java.lang.NullPointerException: null
> 22:59:01 at com.arjuna.ats.internal.jdbc.ConnectionImple.getConnection(ConnectionImple.java:864)
> 22:59:01 at com.arjuna.ats.internal.jdbc.ConnectionImple.getWarnings(ConnectionImple.java:476)
> 22:59:01 at sun.reflect.GeneratedMethodAccessor113.invoke(Unknown Source)
> 22:59:01 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 22:59:01 at java.lang.reflect.Method.invoke(Method.java:498)
> 22:59:01 at net.bull.javamelody.JdbcWrapper$ConnectionInvocationHandler.invoke(JdbcWrapper.java:189)
> 22:59:01 at net.bull.javamelody.JdbcWrapper$DelegatingInvocationHandler.invoke(JdbcWrapper.java:286)
> 22:59:01 at com.sun.proxy.$Proxy116.getWarnings(Unknown Source)
> 22:59:01 at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.handleAndClearWarnings(SqlExceptionHelper.java:277)
> 22:59:01 at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.logAndClearWarnings(SqlExceptionHelper.java:256)
> 22:59:01 at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.releaseConnection(LogicalConnectionManagedImpl.java:167)
> 22:59:01 at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.afterTransaction(LogicalConnectionManagedImpl.java:135)
> 22:59:01 at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterTransaction(JdbcCoordinatorImpl.java:296)
> 22:59:01 at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterTransactionCompletion(JdbcCoordinatorImpl.java:496)
> 22:59:01 at org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl.afterCompletion(JtaTransactionCoordinatorImpl.java:345)
> 22:59:01 at org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorNonTrackingImpl.doAfterCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:60)
> 22:59:01 at org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorTrackingImpl.afterCompletion(SynchronizationCallbackCoordinatorTrackingImpl.java:72)
> 22:59:01 at org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.afterCompletion(RegisteredSynchronization.java:44)
> 22:59:01 at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96)
> 22:59:01 at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:542)
> 22:59:01 at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:101)
> 22:59:01 at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
> 22:59:01 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1216)
> 22:59:01 at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
> 22:59:01 at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1023)
> 22:59:01 at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:761)
> 22:59:01 at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730)
> 22:59:01 at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:487)
> 22:59:01 at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:291)
> 22:59:01 at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
> 22:59:01 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
> 22:59:01 at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
> 22:59:01 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
> 22:59:01 at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
> 22:59:01 at com.sun.proxy.$Proxy292.create(Unknown Source)
> 22:59:01 at
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
7 years, 5 months
- 1
- 0
[JBoss JIRA] (JBTM-2673) ThreadUtil getThreadId(Thread) ignores argument
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-2673?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson updated JBTM-2673:
--------------------------------
Priority: Minor (was: Major)
> ThreadUtil getThreadId(Thread) ignores argument
> -----------------------------------------------
>
> Key: JBTM-2673
> URL: https://issues.jboss.org/browse/JBTM-2673
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Reporter: Tom Jenkinson
> Assignee: Tom Jenkinson
> Priority: Minor
>
> During investigation of https://developer.jboss.org/thread/269784?start=15&tstart=0 it was observed that the ThreadUtil implementation does not use the Thread argument and simply uses a ThreadLocal:
> https://github.com/jbosstm/narayana/blob/master/ArjunaCore/arjuna/classes...
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
7 years, 5 months
- 1
- 0
[JBoss JIRA] (JBTM-2673) ThreadUtil getThreadId(Thread) ignores argument
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-2673?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson updated JBTM-2673:
--------------------------------
Status: Resolved (was: Pull Request Sent)
Resolution: Done
> ThreadUtil getThreadId(Thread) ignores argument
> -----------------------------------------------
>
> Key: JBTM-2673
> URL: https://issues.jboss.org/browse/JBTM-2673
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Reporter: Tom Jenkinson
> Assignee: Tom Jenkinson
> Priority: Minor
>
> During investigation of https://developer.jboss.org/thread/269784?start=15&tstart=0 it was observed that the ThreadUtil implementation does not use the Thread argument and simply uses a ThreadLocal:
> https://github.com/jbosstm/narayana/blob/master/ArjunaCore/arjuna/classes...
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
7 years, 5 months
- 1
- 0
[JBoss JIRA] (JBTM-2790) Blacktie btadmin ResumeDomainTest failure
by Amos Feng (JIRA)
Amos Feng created JBTM-2790:
-------------------------------
Summary: Blacktie btadmin ResumeDomainTest failure
Key: JBTM-2790
URL: https://issues.jboss.org/browse/JBTM-2790
Project: JBoss Transaction Manager
Issue Type: Bug
Components: BlackTie, Testing
Reporter: Amos Feng
Assignee: Amos Feng
Priority: Minor
It looks like the ResumeDomainTest.setUp() sends the "pauseDomain' command but can not receive the response from the jboss-as server.
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
7 years, 5 months
- 1
- 0
[JBoss JIRA] (JBTM-2767) Allow JTS JCA imported transactions to have clearHeuristic called on their participants
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-2767?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson closed JBTM-2767.
-------------------------------
> Allow JTS JCA imported transactions to have clearHeuristic called on their participants
> ---------------------------------------------------------------------------------------
>
> Key: JBTM-2767
> URL: https://issues.jboss.org/browse/JBTM-2767
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: JCA, JTS
> Affects Versions: 5.3.5.Final
> Reporter: Ondra Chaloupka
> Assignee: Tom Jenkinson
> Priority: Minor
> Fix For: 5.4.0.Final
>
>
> If an XAResource throws a heuristic we can't forget it but we do clean up some transactional state meaning it will need reloading from disk (after the heuristic is cleared) before it can be meaningfully used again. In the state where it can't be meaningfully used we need to provide something to the caller.
> [1]
> {code}
> 2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1) java.lang.NullPointerException2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at com.arjuna.ats.internal.jta.transaction.jts.subordinate.jca.SubordinateAtomicTransaction.getXid(SubordinateAtomicTransaction.java:80)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at com.arjuna.ats.internal.jta.transaction.jts.subordinate.jca.TransactionImple.baseXid(TransactionImple.java:126)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1) at com.arjuna.ats.internal.jta.transaction.jts.jca.TransactionImporterImple.getImportedTransaction(TransactionImporterImple.java:135)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at com.arjuna.ats.internal.jta.transaction.jts.jca.XATerminatorImple.commit(XATerminatorImple.java:83)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at org.jboss.as.test.jbossts.crashrec.jca.rar.TestResourceTxnWorkUnit.run(Unknown Source)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at org.jboss.jca.core.workmanager.WorkWrapper.run(WorkWrapper.java:223)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at org.jboss.threads.SimpleDirectExecutor.execute(SimpleDirectExecutor.java:33)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at org.jboss.threads.QueueExecutor.runTask(QueueExecutor.java:808)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at org.jboss.threads.QueueExecutor.access$100(QueueExecutor.java:45)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at org.jboss.threads.QueueExecutor$Worker.run(QueueExecutor.java:828)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at java.lang.Thread.run(Thread.java:745)2016-10-05 16:19:23,537 ERROR [stderr] (default-threads - 1)
> at org.jboss.threads.JBossThread.run(JBossThread.java:320)
> 2016-10-05 16:19:23,538 ERROR [org.jboss.as.test.jbossts.crashrec.jca.rar.TestResourceTxnWorkUnit] (default-threads - 1) Unspecified sever exception: java.lang.NullPointerException at com.arjuna.ats.internal.jta.transaction.jts.subordinate.jca.TransactionImple.recover(TransactionImple.java:135)
> at com.arjuna.ats.internal.jta.transaction.jts.jca.TransactionImporterImple.getImportedTransaction(TransactionImporterImple.java:141)
> at com.arjuna.ats.internal.jta.transaction.jts.jca.XATerminatorImple.commit(XATerminatorImple.java:83) at org.jboss.as.test.jbossts.crashrec.jca.rar.TestResourceTxnWorkUnit.run(Unknown Source) at org.jboss.jca.core.workmanager.WorkWrapper.run(WorkWrapper.java:223)
> at org.jboss.threads.SimpleDirectExecutor.execute(SimpleDirectExecutor.java:33) at org.jboss.threads.QueueExecutor.runTask(QueueExecutor.java:808)
> at org.jboss.threads.QueueExecutor.access$100(QueueExecutor.java:45)
> at org.jboss.threads.QueueExecutor$Worker.run(QueueExecutor.java:828)
> at java.lang.Thread.run(Thread.java:745)
> at org.jboss.threads.JBossThread.run(JBossThread.java:320)
> {code}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
7 years, 5 months
- 1
- 0
[JBoss JIRA] (JBTM-2761) Add the nexus repository to the OSGi quickstart
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-2761?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson closed JBTM-2761.
-------------------------------
> Add the nexus repository to the OSGi quickstart
> -----------------------------------------------
>
> Key: JBTM-2761
> URL: https://issues.jboss.org/browse/JBTM-2761
> Project: JBoss Transaction Manager
> Issue Type: Enhancement
> Components: Documentation
> Reporter: Tom Jenkinson
> Assignee: Tom Jenkinson
> Fix For: 5.4.0.Final
>
>
> Can't be found by the CI system until it flushes to maven central
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
7 years, 5 months
- 1
- 0