Bug 1280275

Summary:	[QE] (6.4.z) Recover of transaction started by MDB on WSMQ when RAR is deployed as an archive does not work(JTA)
Product:	[JBoss] JBoss Enterprise Application Platform 6	Reporter:	Ondrej Chaloupka <ochaloup>
Component:	Transaction Manager	Assignee:	tom.jenkinson
Status:	CLOSED CURRENTRELEASE	QA Contact:	Ondrej Chaloupka <ochaloup>
Severity:	high	Docs Contact:
Priority:	unspecified
Version:	6.4.0	CC:	bbaranow, bmaxwell, dsimko, dtikhomi, istudens, jmartisk, jtruhlar, ochaloup, tom.jenkinson
Target Milestone:	CR1
Target Release:	EAP 6.4.8
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2017-01-17 12:34:11 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	1279553, 1289990, 1333245

Description Ondrej Chaloupka 2015-11-11 11:42:52 UTC

There is a problem with recovering transaction started by MDB pointing to a WSMQ JMS resource.

This happens if RAR is deployed as archive. If the rar is deployed as module and that module receives dependency to jts module then recovery works fine.

For recovery of RAR deployed as archive then the recovery process fails with [1]

WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016043: Exception on attempting to restore XAResource: java.lang.ClassNotFoundException: com.ibm.mq.connector.xa.XARWrapper from [Module "org.jboss.jts:main" from local module loader @707f7052 (finder: local module finder @11028347 (roots: /home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/modules,/home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/modules/system/layers/base))]
...
WARN  [com.arjuna.ats.arjuna] (Periodic Recovery) ARJUNA012154: RecoverAtomicAction: transaction 0:ffff0a28048f:-470895ed:5624c495:34 not activated, unable to replay phase 2 commit. Check state has not already been completed.
WARN  [com.arjuna.ats.arjuna] (Periodic Recovery) ARJUNA012379: ExpiredTransactionScanner - 0:ffff0a28048f:-470895ed:5624c495:34 is assumed complete and will be moved.


This means that instead of committing the unfinished transaction the txn log is put to expired part of txn object store and the transaction on wsmq broker side is left in-doubt.

This was discussed on WFLY issue: https://issues.jboss.org/browse/WFLY-5543 and the fix was provided by https://issues.jboss.org/browse/JBTM-2550


[1] trace level on  transaction manager log category
WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016043: Exception on attempting to restore XAResource: java.lang.ClassNotFoundException: com.ibm.mq.connector.xa.XARWrapper from [Module "org.jboss.jts:main" from local module loader @707f7052 (finder: local module finder @11028347 (roots: /home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/modules,/home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/modules/system/layers/base))]
 at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:205)
 at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:455)
 at org.jboss.modules.ConcurrentClassLoader.performLoadClassChecked(ConcurrentClassLoader.java:404)
 at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:385)
 at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:130)
 at java.lang.Class.forName0(Native Method)
 at java.lang.Class.forName(Class.java:348)
 at java.io.ObjectInputStream.resolveClass(ObjectInputStream.java:626)
 at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1613)
 at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1518)
 at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1774)
 at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1351)
 at java.io.ObjectInputStream.readObject(ObjectInputStream.java:371)
 at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.restore_state(XAResourceRecord.java:969)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.restore_state(BasicAction.java:1118)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.activate(BasicAction.java:488)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.activate(BasicAction.java:451)
 at com.arjuna.ats.arjuna.recovery.RecoverAtomicAction.<init>(RecoverAtomicAction.java:50)
 at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.doRecoverTransaction(AtomicActionRecoveryModule.java:149)
 at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactionsStatus(AtomicActionRecoveryModule.java:253)
 at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass(AtomicActionRecoveryModule.java:109)
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:793)
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:375)

DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) RecoverAtomicAction.replayPhase2 recovering 0:ffff0a28048f:-470895ed:5624c495:34 ActionStatus is ActionStatus.COMMITTED
WARN  [com.arjuna.ats.arjuna] (Periodic Recovery) ARJUNA012154: RecoverAtomicAction: transaction 0:ffff0a28048f:-470895ed:5624c495:34 not activated, unable to replay phase 2 commit. Check state has not already been completed.
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) StateManager::StateManager( 2, 0 )
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::BasicAction()
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.read_committed(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.read_state(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_COMMITTED
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffff0a28048f_-470895ed_5624c495_34, FileLock.F_RDLCK, false)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffff0a28048f_-470895ed_5624c495_34, java.io.FileInputStream@13c3edbd, null)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState(InputObjectState Uid   : 0:ffff0a28048f:-470895ed:5624c495:34
InputObjectState Type  : /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction
InputObjectState Size  : 7204
InputObjectState Buffer: )
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.write_committed(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/Expired)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.write_state(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/Expired, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/Expired, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/Expired, 11)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/Expired/0_ffff0a28048f_-470895ed_5624c495_34, FileLock.F_WRLCK, true)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.createHierarchy(/home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/Expired/0_ffff0a28048f_-470895ed_5624c495_34)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/Expired/0_ffff0a28048f_-470895ed_5624c495_34, null, java.io.FileOutputStream@322aab6a)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.remove_committed(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.remove_state(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_COMMITTED
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff0a28048f:-470895ed:5624c495:34, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.openAndLock(/home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffff0a28048f_-470895ed_5624c495_34, FileLock.F_WRLCK, false)
TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.closeAndUnlock(/home/ochaloup/jboss/jboss-eap-7.0.0.DR11-wsmq2/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffff0a28048f_-470895ed_5624c495_34, null, null)
WARN  [com.arjuna.ats.arjuna] (Periodic Recovery) ARJUNA012379: ExpiredTransactionScanner - 0:ffff0a28048f:-470895ed:5624c495:34 is assumed complete and will be moved.
DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass
DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS

DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass
DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed
DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed
DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change SECOND_PASS->IDLE

DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE
DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

Comment 3 JBoss JIRA Server 2015-12-07 12:06:57 UTC

Amos Feng <zfeng> updated the status of jira JBEAP-1523 to Resolved

Comment 4 JBoss JIRA Server 2015-12-21 10:39:18 UTC

Ondřej Chaloupka <ochaloup> updated the status of jira JBEAP-1523 to Reopened

Comment 5 JBoss JIRA Server 2016-01-04 10:02:30 UTC

Tom Jenkinson <tom.jenkinson> updated the status of jira JBEAP-1523 to Resolved

Comment 6 JBoss JIRA Server 2016-01-05 14:53:46 UTC

Tom Jenkinson <tom.jenkinson> updated the status of jira JBEAP-1523 to Reopened

Comment 7 JBoss JIRA Server 2016-01-05 14:54:25 UTC

Tom Jenkinson <tom.jenkinson> updated the status of jira JBEAP-1523 to Resolved

Comment 19 JBoss JIRA Server 2016-06-14 11:37:32 UTC

Jiri Pallich <jpallich> updated the status of jira JBEAP-1523 to Closed

Comment 20 Petr Penicka 2017-01-17 12:34:11 UTC

Retroactively bulk-closing issues from released EAP 6.4 cumulative patches.

Comment 21 Petr Penicka 2017-01-17 12:56:01 UTC

Retroactively bulk-closing issues from released EAP 6.4 cummulative patches.