[jboss-jira] [JBoss JIRA] (WFLY-5543) Can't recover transaction started by MDB on WSMQ when RAR is deployed as an archive

[ https://issues.jboss.org/browse/WFLY-5543?page=com.atlassian.jira.plugin.... ] Ondřej Chaloupka edited comment on WFLY-5543 at 10/29/15 11:42 AM: ------------------------------------------------------------------- [~mmusgrov] ok, you're right. that was probably my wrong assumption where the exception was put out of. Nevertheless from my debugging it seems to me quite strange as I've got only {{EJBXAResourceDeserializer}} deserializer and no one else and that one seemed to me was tried to be used for deserialization of IBM xaresource. But I could be easily wrong here. [~zhfeng] what do you have experience here? Then I did some testing on my machine and I can say that I got exception {{method 'xa_recover' has failed with errorCode '-7'}} as well. Just I got this exception only when I'm shutting down my WFLY server (not during recovery). This is what I can get {code} 16:36:35,449 WARN [com.arjuna.ats.arjuna] (Periodic Recovery) ARJUNA012281: ShadowingStore::read_state() - no type name given for object state 0:ffff0a105b01:35345c2a:5617033b:26 16:36:35,451 WARN [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016027: Local XARecoveryModule.xaRecovery got XA exception XAException.XAER_RMFAIL: javax.transaction.xa.XAException: The method 'xa_recover' has failed with errorCode '-7' due to the resource being closed. at com.ibm.mq.jmqi.JmqiXAResource.recover(JmqiXAResource.java:806) at com.ibm.mq.connector.xa.XARWrapper.recover(XARWrapper.java:470) at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.recover(XAResourceWrapperImpl.java:185) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:744) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:435) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:219) at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:793) at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:375) There is interesting similarity with exception https://bugzilla.redhat.com/show_bug.cgi?id=1129891 (aka https://issues.jboss.org/browse/JBTM-1810). I'm not sure here if it's relevant or only a coincidence. Then I can say that it seems that setting security domain does not help and I can still get exception {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.DR13/modules,/home/ochaloup/jboss/jboss-eap-7.0.0.DR13/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.WARN  [com.arjuna.ats.arjuna] (Periodic Recovery) ARJUNA012379: ExpiredTransactionScanner - 0:ffff0a28048f:-470895ed:5624c495:34 is assumed complete and will be moved. {code} my resource adapter is configured as {code} <resource-adapters> <resource-adapter id="wmq.jmsra.rar"> <archive> wmq.jmsra.rar </archive> <transaction-support>XATransaction</transaction-support> <connection-definitions> <connection-definition class-name="com.ibm.mq.connector.outbound.ManagedConnectionFactoryImpl" jndi-name="java:/JmsXA" use-java-context="false" pool-name="JMS_XAQCF"> <config-property name="channel"> CH </config-property> <config-property name="hostName"> dev120.mw.lab.eng.bos.redhat.com </config-property> <config-property name="transportType"> CLIENT </config-property> <config-property name="queueManager"> QM </config-property> <config-property name="port"> 1414 </config-property> <security> <application/> </security> <!--<recovery> <recover-credential> <user-name>mqm</user-name> <password>mqm</password> </recover-credential> </recovery>--> <recovery> <recover-credential> <security-domain>mqm</security-domain> </recover-credential> </recovery> </connection-definition> </connection-definitions> <admin-objects> <admin-object class-name="com.ibm.mq.connector.outbound.MQQueueProxy" jndi-name="java:jboss/crashRecoveryQueue" enabled="true" pool-name="IBMMQ_RECOVERY_QUEUE"> <config-property name="baseQueueName"> QRECOVERY.TS </config-property> <config-property name="baseQueueManagerName"> QM </config-property> </admin-object> <admin-object class-name="com.ibm.mq.connector.outbound.MQQueueProxy" jndi-name="java:jboss/MDBTriggerQueue" enabled="true" pool-name="IBMMQ_MDB_QUEUE"> <config-property name="baseQueueName"> QRECOVERY.MDB.TS </config-property> <config-property name="baseQueueManagerName"> QM </config-property> </admin-object> </admin-objects> </resource-adapter> ... <security-domain name="mqm"> <authentication> <login-module code="ConfiguredIdentity" flag="required"> <module-option name="principal" value="mqm"/> <module-option name="userName" value="mqm"/> <module-option name="password" value="mqm"/> <module-option name="password-stacking" value="useFirstPass"/> </login-module> </authentication> </security-domain> {code} Then I have another intersting observation and it's that it seems that the problem is only for up-to-down recovery. Bottom-up seems to work as it returns the in-doubt transactions sitting on server {code} ./bin/standalone.sh -c standalone-full.wmq.xml -Dcom.arjuna.ats.arjuna.recovery.periodicRecoveryPeriod=20 {code} and log contains {code} 2015-10-29 16:40:24,196 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of XAResourceWrapperImpl@603cdb89[xaResource=com.ibm.mq.connector.xa.XARWrapper(a)7ea3f0bf pad=false overrideRmValue=null productName=WebSphere MQ productVersion=%I% %E% %U% jndiName=java:/JmsXA] 2015-10-29 16:40:24,344 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 1 xids in doubt 2015-10-29 16:40:24,344 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Recovered: < 131077, 32, 36, 0000000000-1-11016911535292428623359000388312087122, 0000000000-1-110169115352924286233590003900000000 > 2015-10-29 16:40:24,344 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids new recoveryXids XAResourceWrapperImpl@603cdb89[xaResource=com.ibm.mq.connector.xa.XARWrapper(a)7ea3f0bf pad=false overrideRmValue=null productName=WebSphere MQ productVersion=%I% %E% %U% jndiName=java:/JmsXA] 1446133224344 2015-10-29 16:40:24,345 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState() 2015-10-29 16:40:24,346 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid : 0:0:0:0:0 InputObjectState Type : null InputObjectState Size : 0 InputObjectState Buffer: , -1) 2015-10-29 16:40:24,346 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState() {code} was (Author: ochaloup): [~mmusgrov] ok, you're right. that was probably my wrong assumption where the exception was put out of. Nevertheless from my debugging it seems to me quite strange as I've got only {{EJBXAResourceDeserializer}} deserializer and no one else and that one seemed to me was tried to be used for deserialization of IBM xaresource. But I could be easily wrong here. [~zhfeng] what do you have experience here? Then I did some testing on my machine and I can say that I got exception {{method 'xa_recover' has failed with errorCode '-7'}} as well. Just I got this exception only when I'm shutting down my WFLY server (not during recovery). This is what I can get {code}  WARN  [com.arjuna.ats.arjuna] (Periodic Recovery) ARJUNA012281: ShadowingStore::read_state() - no type name given for object state 0:ffff0a105b01:35345c2a:5617033b:26 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016027: Local XARecoveryModule.xaRecovery got XA exception XAException.XAER_RMFAIL: javax.transaction.xa.XAException: The method 'xa_recover' has failed with errorCode '-7' due to the resource being closed. at com.ibm.mq.jmqi.JmqiXAResource.recover(JmqiXAResource.java:806) at com.ibm.mq.connector.xa.XARWrapper.recover(XARWrapper.java:470) at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.recover(XAResourceWrapperImpl.java:185) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:744) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:435) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:219) at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:793) at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:375) {code} There is interesting similarity with exception https://bugzilla.redhat.com/show_bug.cgi?id=1129891 (aka https://issues.jboss.org/browse/JBTM-1810). I'm not sure here if it's relevant or only a coincidence. Then I can say that it seems that setting security domain does not help and I can still get exception {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.DR13/modules,/home/ochaloup/jboss/jboss-eap-7.0.0.DR13/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.WARN  [com.arjuna.ats.arjuna] (Periodic Recovery) ARJUNA012379: ExpiredTransactionScanner - 0:ffff0a28048f:-470895ed:5624c495:34 is assumed complete and will be moved. {code} my resource adapter is configured as {code} <subsystem xmlns="urn:jboss:domain:resource-adapters:3.0"><resource-adapters><resource-adapter id="wmq.jmsra.rar"><archive>wmq.jmsra.rar</archive><transaction-support>XATransaction</transaction-support><connection-definitions><connection-definition class-name="com.ibm.mq.connector.outbound.ManagedConnectionFactoryImpl" jndi-name="java:/JmsXA" use-java-context="false" pool-name="JMS_XAQCF"><config-property name="channel">CH</config-property><config-property name="hostName">dev120.mw.lab.eng.bos.redhat.com</config-property><config-property name="transportType">CLIENT</config-property><config-property name="queueManager">QM</config-property><config-property name="port">1414</config-property><security><application/></security><recovery><recover-credential><security-domain>mqm</security-domain></recover-credential></recovery></connection-definition></connection-definitions><admin-objects><admin-object class-name="com.ibm.mq.connector.outbound.MQQueueProxy" jndi-name="java:jboss/crashRecoveryQueue" enabled="true" pool-name="IBMMQ_RECOVERY_QUEUE"><config-property name="baseQueueName">QRECOVERY.TS</config-property><config-property name="baseQueueManagerName">QM</config-property></admin-object><admin-object class-name="com.ibm.mq.connector.outbound.MQQueueProxy" jndi-name="java:jboss/MDBTriggerQueue" enabled="true" pool-name="IBMMQ_MDB_QUEUE"><config-property name="baseQueueName">QRECOVERY.MDB.TS</config-property><config-property name="baseQueueManagerName">QM</config-property></admin-object></admin-objects></resource-adapter></resource-adapters></subsystem><security-domain name="mqm"><authentication><login-module code="ConfiguredIdentity" flag="required"><module-option name="principal" value="mqm"/><module-option name="userName" value="mqm"/><module-option name="password" value="mqm"/><module-option name="password-stacking" value="useFirstPass"/></login-module></authentication></security-domain> {code} Then I have another intersting observation and it's that it seems that the problem is only for up-to-down recovery. Bottom-up seems to work as it returns the in-doubt transactions sitting on server {code} {code} and log contains {code} 2015-10-29 16:30:26,245 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of XAResourceWrapperImpl@6ca610e3[xaResource=com.ibm.mq.connector.xa.XARWrapper(a)52e17698 pad=false overrideRmValue=null productName=WebSphere MQ productVersion=%I% %E% %U% jndiName=java:/JmsXA]2015-10-29 16:30:26,393 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 1 xids in doubt2015-10-29 16:30:26,393 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Recovered: < 131077, 32, 36, 0000000000-1-11016911535292428623359000388312087122, 0000000000-1-110169115352924286233590003900000000 >2015-10-29 16:30:26,394 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids new recoveryXids XAResourceWrapperImpl@6ca610e3[xaResource=com.ibm.mq.connector.xa.XARWrapper(a)52e17698 pad=false overrideRmValue=null productName=WebSphere MQ productVersion=%I% %E% %U% jndiName=java:/JmsXA] 14461326263942015-10-29 16:30:26,395 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()2015-10-29 16:30:26,395 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0InputObjectState Type  : nullInputObjectState Size  : 0InputObjectState Buffer: , -1)2015-10-29 16:30:26,395 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()2015-10-29 16:30:26,395 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids _whenFirstSeen put nextScan XAResourceWrapperImpl@6ca610e3[xaResource=com.ibm.mq.connector.xa.XARWrapper(a)52e17698 pad=false overrideRmValue=null productName=WebSphere MQ productVersion=%I% %E% %U% jndiName=java:/JmsXA] 1446132626394 === < formatId=131077, gtrid_length=32, bqual_length=36, tx_uid=0:ffff0a105b01:35345c2a:5617033b:26, node_name=SxWz, branch_uid=0:ffff0a105b01:35345c2a:5617033b:27, subordinatenodename=null, eis_name=unknown eis name >2015-10-29 16:30:26,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES {code} -- This message was sent by Atlassian JIRA (v6.4.11#64026)