Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-5543

Can't recover transaction started by MDB on WSMQ when RAR is deployed as an archive

    Details

    • Steps to Reproduce:
      Hide
      1. start server with configuration pointing to WSMQ
      2. start receiving data from MDB and enlist one more resource to get XA doing 2PC
      3. crash jvm server at the start of commit phase of 2PC
      4. restart the server and see the warning

      The exception should be seen when attached transaction log with unfinished transaction and xml configuration and the rar is used.

      1. unzip the txn log to have directory structure like $JBOSS_HOME/standalone/data/tx-object-store/ShadowNoFileLockStore/...
      2. copy standalone-full.wsq.xml to $JBOSS_HOME/standalone/configuration
      3. copy rar archive to $JBOSS_HOME/standalone/deployments
      4. run server like ./bin/standalone.sh -c standalone-full.wmq.xml
      5. after start you can see the exception
      Show
      start server with configuration pointing to WSMQ start receiving data from MDB and enlist one more resource to get XA doing 2PC crash jvm server at the start of commit phase of 2PC restart the server and see the warning The exception should be seen when attached transaction log with unfinished transaction and xml configuration and the rar is used. unzip the txn log to have directory structure like $JBOSS_HOME/standalone/data/tx-object-store/ShadowNoFileLockStore/... copy standalone-full.wsq.xml to $JBOSS_HOME/standalone/configuration copy rar archive to $JBOSS_HOME/standalone/deployments run server like ./bin/standalone.sh -c standalone-full.wmq.xml after start you can see the exception

      Description

      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]

      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.
      

      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

      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
      

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  zhfeng Zheng Feng
                  Reporter:
                  ochaloup Ondrej Chaloupka
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  11 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: