2 Replies Latest reply on Mar 11, 2009 11:48 AM by ajayazariah

    Recovery: Could not find new XAResource to use for recoverin

    ajayazariah

      After killing (-9) one node, the other node picks up and processes the messages.

      After that when I restart the fist node, I get the following on second pass of the recovery manager:

      WARN [com.arjuna.ats.jta.logging.loggerI18N] (Thread-6)
       [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa]
       Could not find new XAResource to use for recovering non-serializable XAResource
       < 131075, 28, 26, 7-aecd416:85c9:49ae79b7:1d7eaecd416:85c9:49ae79b7:1d9d >
      


      I have done the configuration according to http://www.jboss.org/community/docs/DOC-13171 , but that does not seem to fix it.

      Could someone point out the error in the configuration below:

      ( I get the same problem with and without the recovery entry for RemoteProvider2 )

      1) conf/jbossjta-properties.xml :
      
      
      Node 1:
      
       <!-- (Must be unique across all Arjuna instances.) -->
       <property name="com.arjuna.ats.arjuna.xa.nodeIdentifier" value="1"/>
      
       <!-- Configure which transactions must be recovered. Must match nodeIdentifier -->
       <property name="com.arjuna.ats.jta.xaRecoveryNode" value="1"/>
      
       <!-- configure XA recovery for JBoss Messaging -->
       <property name="com.arjuna.ats.jta.recovery.XAResourceRecovery.JBMESSAGING1"
       value="org.jboss.jms.server.recovery.MessagingXAResourceRecovery;java:/DefaultJMSProvider"/>
      
       <property name="com.arjuna.ats.jta.recovery.XAResourceRecovery.JBMESSAGING2"
       value="org.jboss.jms.server.recovery.MessagingXAResourceRecovery;java:/RemoteProvider2"/>
      
       <!-- specifying XA recovery for Oracle -->
       <property name="com.arjuna.ats.jta.recovery.XAResourceRecovery.Oracle"
       value="com.arjuna.ats.internal.jdbc.recovery.OracleXARecovery;oraclejta-properties.xml"/>
      
      
      Node 2:
      
       <!-- (Must be unique across all Arjuna instances.) -->
       <property name="com.arjuna.ats.arjuna.xa.nodeIdentifier" value="2"/>
      
       <!-- Configure which transactions must be recovered. Must match nodeIdentifier -->
       <property name="com.arjuna.ats.jta.xaRecoveryNode" value="2"/>
      
       <!-- configure XA recovery for JBoss Messaging -->
       <property name="com.arjuna.ats.jta.recovery.XAResourceRecovery.JBMESSAGING1"
       value="org.jboss.jms.server.recovery.MessagingXAResourceRecovery;java:/DefaultJMSProvider"/>
      
       <property name="com.arjuna.ats.jta.recovery.XAResourceRecovery.JBMESSAGING2"
       value="org.jboss.jms.server.recovery.MessagingXAResourceRecovery;java:/RemoteProvider2"/>
      
       <!-- specifying XA recovery for Oracle -->
       <property name="com.arjuna.ats.jta.recovery.XAResourceRecovery.Oracle"
       value="com.arjuna.ats.internal.jdbc.recovery.OracleXARecovery;oraclejta-properties.xml"/>
      
      
      
      2) deploy/hajndi-jms-ds.xml
      
      Node 1:
      
       <mbean code="org.jboss.jms.jndi.JMSProviderLoader"
       name="jboss.jms:service=JMSProviderLoader,name=RemoteProvider2">
       <attribute name="ProviderName">RemoteProvider2</attribute>
       <attribute name="ProviderAdapterClass">
       org.jboss.jms.jndi.JNDIProviderAdapter
       </attribute>
       <!-- The combined connection factory -->
       <attribute name="FactoryRef">XAConnectionFactory</attribute>
       <!-- The queue connection factory -->
       <attribute name="QueueFactoryRef">XAConnectionFactory</attribute>
       <!-- The topic factory -->
       <attribute name="TopicFactoryRef">XAConnectionFactory</attribute>
       <attribute name="Properties">
       java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory
       java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces
       java.naming.provider.url=node_2_hostname:1099
       </attribute>
       </mbean>
      
      
      Node 2:
      
       <mbean code="org.jboss.jms.jndi.JMSProviderLoader"
       name="jboss.jms:service=JMSProviderLoader,name=RemoteProvider2">
       <attribute name="ProviderName">RemoteProvider2</attribute>
       ...
       <attribute name="Properties">
       java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory
       java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces
       java.naming.provider.url=node_1_hostname:1099
       </attribute>
       </mbean>
      
      
      
      3) conf/oraclejta-properties.xml
      
      <transaction-service>
       <properties name="jdbc" type="system">
       <property name="DatabaseURL" value="jdbc:oracle:thin:@dbhost:25000:sid"/>
       <property name="UserName" value="jboss"/>
       <property name="Password" value="jboss"/>
       </properties>
      </transaction-service>
      
      
      
      4) Oracle user "jboss" has been granted following permissions:
       select on DBA_PENDING_TRANSACTIONS,
       execute on SYS.DBMS_SYSTEM
      
      


        • 1. Re: Recovery: Could not find new XAResource to use for recov
          mmusgrov

          I haven't tried clustered messaging myself but I have a couple of suggestions:

          - you could enable recovery debuging to get more detail on why the TM cannot recreate a suitable XAResource (the JBossTM adminstrators guide shows set the com.arjuna.common.util.logging.DebugLevel property to get targeted debug output);

          - is recoveryExtension5 enabled in jbossjts-properties.xml (property com.arjuna.ats.arjuna.recovery.recoveryExtension5 value com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule)

          • 2. Re: Recovery: Could not find new XAResource to use for recov
            ajayazariah

            I now find that this problem is NOT related to clustering or failover.

            Steps:

            - start jboss 4.2.2 (or 4.2.3)
            - start load test
            - kill jboss (stop load test also)
            - start jboss

            I have a feeling it may perhaps be related to the behaviour mentioned at:
            http://www.jboss.org/index.html?module=bb&op=viewtopic&t=96846

            Here are parts of the logs (following aecd416:e8c0:49b78190:264 and aecd416:e8c0:49b78190:1c8 ):

            10:23:17,043 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (JMS SessionPool Worker-0) BasicAction::prepare () for action-id aecd416:e8c0:49b78190:264
            10:23:17,044 DEBUG [com.arjuna.ats.jta.logging.logger] (JMS SessionPool Worker-0) XAResourceRecord.topLevelPrepare for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:264aecd416:e8c0:49b78190:266 >
            10:23:17,411 DEBUG [com.arjuna.ats.jta.logging.logger] (JMS SessionPool Worker-0) XAResourceRecord.topLevelPrepare for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:264aecd416:e8c0:49b78190:30f >
            
            10:23:18,410 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (JMS SessionPool Worker-4) BasicAction::prepare () for action-id aecd416:e8c0:49b78190:1c8
            10:23:18,410 DEBUG [com.arjuna.ats.jta.logging.logger] (JMS SessionPool Worker-4) XAResourceRecord.topLevelPrepare for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:1c8aecd416:e8c0:49b78190:1c9 >
            10:23:18,449 DEBUG [com.arjuna.ats.jta.logging.logger] (JMS SessionPool Worker-4) XAResourceRecord.topLevelPrepare for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:1c8aecd416:e8c0:49b78190:1f8 >
            
            
            10:23:18,509 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (JMS SessionPool Worker-0) BasicAction::phase2Commit() for action-id aecd416:e8c0:49b78190:264
            10:23:18,509 DEBUG [com.arjuna.ats.jta.logging.logger] (JMS SessionPool Worker-0) XAResourceRecord.topLevelCommit for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:264aecd416:e8c0:49b78190:266 >
            10:23:18,510 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (JMS SessionPool Worker-4) BasicAction::phase2Commit() for action-id aecd416:e8c0:49b78190:1c8
            10:23:18,511 DEBUG [com.arjuna.ats.jta.logging.logger] (JMS SessionPool Worker-4) XAResourceRecord.topLevelCommit for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:1c8aecd416:e8c0:49b78190:1c9 >
            10:23:18,524 DEBUG [com.arjuna.ats.jta.logging.logger] (JMS SessionPool Worker-0) XAResourceRecord.topLevelCommit for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:264aecd416:e8c0:49b78190:30f >
            


            10:23:53,642 { kill -9 }

            Note: Missing log entry for both aecd416:e8c0:49b78190:264 and aecd416:e8c0:49b78190:1c8
            (this entry below was seen for other transactions that did not have this recovery problem)

            DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (JMS SessionPool Worker-x) TransactionReaper::remove ( BasicAction: aecd416:e8c0:49b78190:XYZ status: ActionStatus.COMMITTED )

            10:25:56,414 { restarted }

            10:28:58,220 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-6) found transaction aecd416:e8c0:49b78190:264
            10:28:58,221 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-6) found transaction aecd416:e8c0:49b78190:1c8
            
            10:29:08,908 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-6) BasicAction::activate() for action-id aecd416:e8c0:49b78190:264
            
            10:29:08,911 WARN [com.arjuna.ats.jta.logging.loggerI18N] (Thread-6) [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 27, 25, 1-aecd416:e8c0:49b78190:264aecd416:e8c0:49b78190:266 >
            10:29:08,947 WARN [com.arjuna.ats.jta.logging.loggerI18N] (Thread-6) [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 27, 25, 1-aecd416:e8c0:49b78190:264aecd416:e8c0:49b78190:30f >
            10:29:08,949 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-6) [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_1] - RecoverAtomicAction.replayPhase2 recovering aecd416:e8c0:49b78190:264 ActionStatus is ActionStatus.COMMITTED
            10:29:08,949 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-6) BasicAction::phase2Commit() for action-id aecd416:e8c0:49b78190:264
            10:29:08,949 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-6) XAResourceRecord.topLevelCommit for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:264aecd416:e8c0:49b78190:266 >
            10:29:08,949 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-6) [com.arjuna.ats.arjuna.coordinator.BasicAction_51] - BasicAction.doCommit for aecd416:e8c0:49b78190:264 received TwoPhaseOutcome.FINISH_ERROR from <ClassName:RecordType.JTA_RECORD>
            10:29:08,949 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-6) XAResourceRecord.topLevelCommit for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:264aecd416:e8c0:49b78190:30f >
            10:29:08,949 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-6) [com.arjuna.ats.arjuna.coordinator.BasicAction_51] - BasicAction.doCommit for aecd416:e8c0:49b78190:264 received TwoPhaseOutcome.FINISH_ERROR from <ClassName:RecordType.JTA_RECORD>
            
            10:29:09,714 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-6) BasicAction::activate() for action-id aecd416:e8c0:49b78190:1c8
            
            10:29:09,715 WARN [com.arjuna.ats.jta.logging.loggerI18N] (Thread-6) [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 27, 25, 1-aecd416:e8c0:49b78190:1c8aecd416:e8c0:49b78190:1c9 >
            10:29:09,749 WARN [com.arjuna.ats.jta.logging.loggerI18N] (Thread-6) [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 27, 25, 1-aecd416:e8c0:49b78190:1c8aecd416:e8c0:49b78190:1f8 >
            10:29:09,750 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-6) [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_1] - RecoverAtomicAction.replayPhase2 recovering aecd416:e8c0:49b78190:1c8 ActionStatus is ActionStatus.COMMITTED
            10:29:09,750 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-6) BasicAction::phase2Commit() for action-id aecd416:e8c0:49b78190:1c8
            10:29:09,750 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-6) XAResourceRecord.topLevelCommit for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:1c8aecd416:e8c0:49b78190:1c9 >
            10:29:09,750 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-6) [com.arjuna.ats.arjuna.coordinator.BasicAction_51] - BasicAction.doCommit for aecd416:e8c0:49b78190:1c8 received TwoPhaseOutcome.FINISH_ERROR from <ClassName:RecordType.JTA_RECORD>
            10:29:09,750 DEBUG [com.arjuna.ats.jta.logging.logger] (Thread-6) XAResourceRecord.topLevelCommit for < 131075, 27, 25, 1-aecd416:e8c0:49b78190:1c8aecd416:e8c0:49b78190:1f8 >
            10:29:09,750 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-6) [com.arjuna.ats.arjuna.coordinator.BasicAction_51] - BasicAction.doCommit for aecd416:e8c0:49b78190:1c8 received TwoPhaseOutcome.FINISH_ERROR from <ClassName:RecordType.JTA_RECORD>