[jboss-jira] [JBoss JIRA] (WFLY-5543) Can't recover transaction started by MDB on WSMQ when RAR is deployed as an archive
Ondřej Chaloupka (JIRA)
issues at jboss.org
Wed Oct 21 08:36:00 EDT 2015
[ https://issues.jboss.org/browse/WFLY-5543?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13120455#comment-13120455 ]
Ondřej Chaloupka commented on WFLY-5543:
----------------------------------------
Hi Amos,
I'm sorry for a bit later response. Yes, it would be expected result if the behavior of test would not be caused by issue in test :)
I put the steps wrong here. As test method {{commitHaltAtPhaseBeginning}} was arbitrarily added to {{eap-tests-transactions/jbossts/src/test/java/org/jboss/as/test/jbossts/crashrec/test/JMSMdbCrashRecoveryTestCase.java}} I left it empty. For the test would be really run it's needed to delete the test whole test method from the class. I'm sorry for this wrong. I've written the steps on top of my head and missed this fact.
Then the test result would be
{code}
-------------------------------------------------------
T E S T S
-------------------------------------------------------
Running org.jboss.as.test.jbossts.crashrec.test.JMSMdbCrashRecoveryRemoteTestCase
Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 166.712 sec <<< FAILURE! - in org.jboss.as.test.jbossts.crashrec.test.JMSMdbCrashRecoveryRemoteTestCase
commitHaltAtPhaseBeginning(org.jboss.as.test.jbossts.crashrec.test.JMSMdbCrashRecoveryRemoteTestCase) Time elapsed: 165.167 sec <<< FAILURE!
java.lang.AssertionError: - required maximum call count 0 but was 1
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.assertTrue(Assert.java:41)
at org.jboss.byteman.contrib.dtest.InstrumentedInstance.assertMethodCallCount(InstrumentedInstance.java:93)
...
Results :
Failed tests:
JMSMdbCrashRecoveryRemoteTestCase>TestBaseCrashRecovery.commitHaltAtPhaseBeginning:346->TestBaseCrashRecovery.commitHaltTest:432 - required maximum call count 0 but was 1
Tests run: 1, Failures: 1, Errors: 0, Skipped: 0
[INFO] ------------------------------------------------------------------------
{code}
You can check the test log under {{target/jbossas-jbossts/standalone/log/*.log}} and find word {{kill}}. This is the place where server jvm was killed and right after that time the server is restarted again. Then the recovery manager is started and you can see the exception of "class loading".
{code}
WARN [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016043: Exception on attempting to restore XAResource: java.lang.ClassNotFoundException: com.ibm.mq.connector.xa.XARWrapper
{code}
> Can't recover transaction started by MDB on WSMQ when RAR is deployed as an archive
> -----------------------------------------------------------------------------------
>
> Key: WFLY-5543
> URL: https://issues.jboss.org/browse/WFLY-5543
> Project: WildFly
> Issue Type: Bug
> Components: Transactions
> Affects Versions: 10.0.0.CR2
> Reporter: Ondřej Chaloupka
> Assignee: Amos Feng
> Priority: Blocker
> Fix For: 10.0.0.CR4
>
> Attachments: standalone-full.wmq.xml, tx-object-store.zip
>
>
> There is a problem with recovering transaction started by MDB pointing to a WSMQ JMS resource.
> If I do so then the recovery process fails with [1]
> {code}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)
> 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.
> InputObjectState Type : /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction
> InputObjectState Size : 7204
> InputObjectState Buffer: )
> WARN [com.arjuna.ats.arjuna] (Periodic Recovery) ARJUNA012379: ExpiredTransactionScanner - 0:ffff0a28048f:-470895ed:5624c495:34 is assumed complete and will be moved.
> {code}
> This means that instead of commiting 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.
> I'm attaching my configuration file.
> [1] trace level on transaction manager log category
> {code}
> 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 at 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 at 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
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
More information about the jboss-jira
mailing list