Mule
  1. Mule
  2. MULE-5564

Periodic errors after JMS reconnect

    Details

    • Type: Bug Bug
    • Status: Open
    • Priority: Major Major
    • Resolution: Unresolved
    • Affects Version/s: 3.1.1
    • Fix Version/s: None
    • Component/s: Core: (other)
    • Labels:
      None
    • Environment:

      WinXP
      Eclipse Helios Service Release 2
      Mule IDE 2.1.2.201103101711
      JBoss 4.2.3 JMS server

    • User impact:
      Medium
    • Configuration:
      Hide

      <jms:connector persistentDelivery="true" name="jmsConnector" jndiInitialFactory="org.jnp.interfaces.NamingContextFactory"
      jndiProviderUrl="jnp://$

      {JNDIProviderURL}

      :$

      {JNDIProviderPort}

      " connectionFactoryJndiName="java:/$

      {ConnectionFactoryJNDIName}

      "
      jndiDestinations="true" forceJndiDestinations="true" createMultipleTransactedReceivers="true" disableTemporaryReplyToDestinations="true">
      <spring:property name="retryPolicyTemplate">
      <spring:bean class="myPackage.core.JMSRetryPolicyTpl">
      <spring:property name="delay" value="$

      {JMSRetryDelay}

      "/>
      <spring:property name="count" value="$

      {JMSRetryCount}

      "/>
      </spring:bean>
      </spring:property>
      </jms:connector>

      Show
      <jms:connector persistentDelivery="true" name="jmsConnector" jndiInitialFactory="org.jnp.interfaces.NamingContextFactory" jndiProviderUrl="jnp://$ {JNDIProviderURL} :$ {JNDIProviderPort} " connectionFactoryJndiName="java:/$ {ConnectionFactoryJNDIName} " jndiDestinations="true" forceJndiDestinations="true" createMultipleTransactedReceivers="true" disableTemporaryReplyToDestinations="true"> <spring:property name="retryPolicyTemplate"> <spring:bean class="myPackage.core.JMSRetryPolicyTpl"> <spring:property name="delay" value="$ {JMSRetryDelay} "/> <spring:property name="count" value="$ {JMSRetryCount} "/> </spring:bean> </spring:property> </jms:connector>
    • Log Output:
      Hide
      INFO 2011-05-10 15:00:03,562 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.exception.DefaultSystemExceptionStrategy: Exception caught is a ConnectException, attempting to reconnect...
      INFO 2011-05-10 15:00:03,562 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.lifecycle.AbstractLifecycleManager: Stopping connector: jmsConnector
      INFO 2011-05-10 15:00:03,562 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Disconnected: JmsConnector
      {
      name=jmsConnector
      lifecycle=start
      this=1cf243b
      numberOfConcurrentTransactedReceivers=4
      createMultipleTransactedReceivers=true
      connected=true
      supportedProtocols=jms
      serviceOverrides=<none>
      }

      INFO 2011-05-10 15:00:03,562 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Disconnected: JmsConnector
      {
      name=jmsConnector
      lifecycle=stop
      this=1cf243b
      numberOfConcurrentTransactedReceivers=4
      createMultipleTransactedReceivers=true
      connected=false
      supportedProtocols=jms
      serviceOverrides=<none>
      }

      ERROR 2011-05-10 15:00:03,562 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.exception.DefaultSystemExceptionStrategy:
      ********************************************************************************
      Message : Cannot ping the JMS server; - nested throwable: (java.io.IOException: Client is not connected) (org.jboss.mq.SpyJMSException)
      Code : MULE_ERROR--2
      Exception stack is:
      1. Client is not connected (java.io.IOException)
      org.jboss.mq.il.uil2.SocketManager:288 (null)
      2. Cannot ping the JMS server; - nested throwable: (java.io.IOException: Client is not connected)(JMS Code: null) (org.jboss.mq.SpyJMSException)
      org.jboss.mq.SpyJMSException:72 (null)
      3. Cannot ping the JMS server; - nested throwable: (java.io.IOException: Client is not connected) (org.jboss.mq.SpyJMSException) (org.mule.transport.ConnectException)
      org.mule.transport.jms.JmsConnector:510 (http://www.mulesoft.org/docs/site/current3/apidocs/org/mule/transport/ConnectException.html)
      Root Exception stack trace:
      java.io.IOException: Client is not connected
      at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:288)
      at org.jboss.mq.il.uil2.SocketManager.sendReply(SocketManager.java:262)
      at org.jboss.mq.il.uil2.UILServerIL.ping(UILServerIL.java:345)
      + 3 more (set debug level logging or '-Dmule.verbose.exceptions=true' for everything)
      ********************************************************************************

      INFO 2011-05-10 15:00:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Connected: JmsConnector
      {
      name=jmsConnector
      lifecycle=stop
      this=1cf243b
      numberOfConcurrentTransactedReceivers=4
      createMultipleTransactedReceivers=true
      connected=true
      supportedProtocols=jms
      serviceOverrides=<none>
      }

      INFO 2011-05-10 15:00:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Starting: JmsConnector
      {
      name=jmsConnector
      lifecycle=stop
      this=1cf243b
      numberOfConcurrentTransactedReceivers=4
      createMultipleTransactedReceivers=true
      connected=true
      supportedProtocols=jms
      serviceOverrides=<none>
      }

      INFO 2011-05-10 15:00:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.lifecycle.AbstractLifecycleManager: Starting connector: jmsConnector
      INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.exception.DefaultSystemExceptionStrategy: Exception caught is a ConnectException, attempting to reconnect...
      INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.lifecycle.AbstractLifecycleManager: Stopping connector: jmsConnector
      INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Disconnected: JmsConnector
      {
      name=jmsConnector
      lifecycle=start
      this=1cf243b
      numberOfConcurrentTransactedReceivers=4
      createMultipleTransactedReceivers=true
      connected=true
      supportedProtocols=jms
      serviceOverrides=<none>
      }

      INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Disconnected: JmsConnector
      {
      name=jmsConnector
      lifecycle=stop
      this=1cf243b
      numberOfConcurrentTransactedReceivers=4
      createMultipleTransactedReceivers=true
      connected=false
      supportedProtocols=jms
      serviceOverrides=<none>
      }

      ERROR 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.exception.DefaultSystemExceptionStrategy:
      ********************************************************************************
      Message : No pong received; - nested throwable: (java.io.IOException: ping timeout.) (org.jboss.mq.SpyJMSException)
      Code : MULE_ERROR--2
      Exception stack is:
      1. ping timeout. (java.io.IOException)
      org.jboss.mq.Connection$PingTask:1313 (null)
      2. No pong received; - nested throwable: (java.io.IOException: ping timeout.)(JMS Code: null) (org.jboss.mq.SpyJMSException)
      org.jboss.mq.Connection$PingTask:1313 (null)
      3. No pong received; - nested throwable: (java.io.IOException: ping timeout.) (org.jboss.mq.SpyJMSException) (org.mule.transport.ConnectException)
      org.mule.transport.jms.JmsConnector:510 (http://www.mulesoft.org/docs/site/current3/apidocs/org/mule/transport/ConnectException.html)
      Root Exception stack trace:
      java.io.IOException: ping timeout.
      at org.jboss.mq.Connection$PingTask.run(Connection.java:1313)
      at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
      at java.lang.Thread.run(Thread.java:619)
      + 3 more (set debug level logging or '-Dmule.verbose.exceptions=true' for everything)
      ********************************************************************************

      INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Connected: JmsConnector
      {
      name=jmsConnector
      lifecycle=stop
      this=1cf243b
      numberOfConcurrentTransactedReceivers=4
      createMultipleTransactedReceivers=true
      connected=true
      supportedProtocols=jms
      serviceOverrides=<none>
      }

      INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Starting: JmsConnector
      {
      name=jmsConnector
      lifecycle=stop
      this=1cf243b
      numberOfConcurrentTransactedReceivers=4
      createMultipleTransactedReceivers=true
      connected=true
      supportedProtocols=jms
      serviceOverrides=<none>
      }

      INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token=ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.lifecycle.AbstractLifecycleManager: Starting connector: jmsConnector
      Show
      INFO 2011-05-10 15:00:03,562 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.exception.DefaultSystemExceptionStrategy: Exception caught is a ConnectException, attempting to reconnect... INFO 2011-05-10 15:00:03,562 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.lifecycle.AbstractLifecycleManager: Stopping connector: jmsConnector INFO 2011-05-10 15:00:03,562 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Disconnected: JmsConnector { name=jmsConnector lifecycle=start this=1cf243b numberOfConcurrentTransactedReceivers=4 createMultipleTransactedReceivers=true connected=true supportedProtocols=jms serviceOverrides=<none> } INFO 2011-05-10 15:00:03,562 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Disconnected: JmsConnector { name=jmsConnector lifecycle=stop this=1cf243b numberOfConcurrentTransactedReceivers=4 createMultipleTransactedReceivers=true connected=false supportedProtocols=jms serviceOverrides=<none> } ERROR 2011-05-10 15:00:03,562 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.exception.DefaultSystemExceptionStrategy: ******************************************************************************** Message : Cannot ping the JMS server; - nested throwable: (java.io.IOException: Client is not connected) (org.jboss.mq.SpyJMSException) Code : MULE_ERROR--2 Exception stack is: 1. Client is not connected (java.io.IOException) org.jboss.mq.il.uil2.SocketManager:288 (null) 2. Cannot ping the JMS server; - nested throwable: (java.io.IOException: Client is not connected)(JMS Code: null) (org.jboss.mq.SpyJMSException) org.jboss.mq.SpyJMSException:72 (null) 3. Cannot ping the JMS server; - nested throwable: (java.io.IOException: Client is not connected) (org.jboss.mq.SpyJMSException) (org.mule.transport.ConnectException) org.mule.transport.jms.JmsConnector:510 ( http://www.mulesoft.org/docs/site/current3/apidocs/org/mule/transport/ConnectException.html ) Root Exception stack trace: java.io.IOException: Client is not connected at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:288) at org.jboss.mq.il.uil2.SocketManager.sendReply(SocketManager.java:262) at org.jboss.mq.il.uil2.UILServerIL.ping(UILServerIL.java:345) + 3 more (set debug level logging or '-Dmule.verbose.exceptions=true' for everything) ******************************************************************************** INFO 2011-05-10 15:00:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Connected: JmsConnector { name=jmsConnector lifecycle=stop this=1cf243b numberOfConcurrentTransactedReceivers=4 createMultipleTransactedReceivers=true connected=true supportedProtocols=jms serviceOverrides=<none> } INFO 2011-05-10 15:00:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Starting: JmsConnector { name=jmsConnector lifecycle=stop this=1cf243b numberOfConcurrentTransactedReceivers=4 createMultipleTransactedReceivers=true connected=true supportedProtocols=jms serviceOverrides=<none> } INFO 2011-05-10 15:00:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.lifecycle.AbstractLifecycleManager: Starting connector: jmsConnector INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.exception.DefaultSystemExceptionStrategy: Exception caught is a ConnectException, attempting to reconnect... INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.lifecycle.AbstractLifecycleManager: Stopping connector: jmsConnector INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Disconnected: JmsConnector { name=jmsConnector lifecycle=start this=1cf243b numberOfConcurrentTransactedReceivers=4 createMultipleTransactedReceivers=true connected=true supportedProtocols=jms serviceOverrides=<none> } INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Disconnected: JmsConnector { name=jmsConnector lifecycle=stop this=1cf243b numberOfConcurrentTransactedReceivers=4 createMultipleTransactedReceivers=true connected=false supportedProtocols=jms serviceOverrides=<none> } ERROR 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.exception.DefaultSystemExceptionStrategy: ******************************************************************************** Message : No pong received; - nested throwable: (java.io.IOException: ping timeout.) (org.jboss.mq.SpyJMSException) Code : MULE_ERROR--2 Exception stack is: 1. ping timeout. (java.io.IOException) org.jboss.mq.Connection$PingTask:1313 (null) 2. No pong received; - nested throwable: (java.io.IOException: ping timeout.)(JMS Code: null) (org.jboss.mq.SpyJMSException) org.jboss.mq.Connection$PingTask:1313 (null) 3. No pong received; - nested throwable: (java.io.IOException: ping timeout.) (org.jboss.mq.SpyJMSException) (org.mule.transport.ConnectException) org.mule.transport.jms.JmsConnector:510 ( http://www.mulesoft.org/docs/site/current3/apidocs/org/mule/transport/ConnectException.html ) Root Exception stack trace: java.io.IOException: ping timeout. at org.jboss.mq.Connection$PingTask.run(Connection.java:1313) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364) at java.lang.Thread.run(Thread.java:619) + 3 more (set debug level logging or '-Dmule.verbose.exceptions=true' for everything) ******************************************************************************** INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Connected: JmsConnector { name=jmsConnector lifecycle=stop this=1cf243b numberOfConcurrentTransactedReceivers=4 createMultipleTransactedReceivers=true connected=true supportedProtocols=jms serviceOverrides=<none> } INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.transport.jms.JmsConnector: Starting: JmsConnector { name=jmsConnector lifecycle=stop this=1cf243b numberOfConcurrentTransactedReceivers=4 createMultipleTransactedReceivers=true connected=true supportedProtocols=jms serviceOverrides=<none> } INFO 2011-05-10 15:01:03,578 [ExceptionListener Connection@22763395token =ConnectionToken:ID:3/65e864f13b06a66e7c38cbd5048ffd09 rcvstate=STOPPED] org.mule.lifecycle.AbstractLifecycleManager: Starting connector: jmsConnector
    • Similar Issues:
      MULE-5653Weblogic JMS transport, error in the reconnection to JMS
      MULE-3446StackOverflowError reconnecting JMS through SimplyRetryConnectionStrategy
      MULE-718inbound queues are not polled after successful reconnect
      MULE-2616MuleWorkManager is stopped after JMS reconnection
      MULE-7329Number of JMS consumers decreases to 1 after reconnection
      MULE-5124ActiveMQ connectors fail to reconnect after JMS server restart
      MULE-952Why doesn't my JMS queue consumer reconnect?
      MULE-7331JMS inbound do not reconnect to queue after broker restart
      MULE-7278[JMS][XA] Reconnection strategy after startup doesn't work
      MULE-6599Default reconnection strategy with reconnect-forever and blocking=false

      Description

      I use a simple custom reconnection strategy to try to reconnect every X seconds. It worked like a charm with Mule 2 but now with Mule 3.1.1 the following happen:
      After the reconnection (sucessful as I can send messages in the queue), after 60s, the connector is disconnected, I have a "Client not connected error", and the connector connects again (by itself, not going through the retry policy). Then, every 60s, the connector is disconnected, I have a "ping timeout error", and the connector connects again.

      Despite the error, new messages are sent to the queue without any problem. I don't have this connector disconnect/reconnect behaviour in normal use, only if I first loose the connection with the JMS server and get it back.
      I tried the org.mule.modules.common.retry.policies.ForeverRetryPolicyTemplate but it gives me the same problem.

      My custom reconnection strategy works perfectly on a FTP connector.

      Maybe somehow linked to MULE-5124 ?

        Activity

        Hide
        Mike Schilling added a comment -

        Please post the custom strategy code

        Show
        Mike Schilling added a comment - Please post the custom strategy code
        Hide
        Samuel Danhardt added a comment -

        Sorry for the delay, here is the code :

        public class JMSRetryPolicyTpl  extends AbstractPolicyTemplate {    
            int delay;
            int count;
            
            public int getDelay() {
        		return delay;
        	}
        
        	public void setDelay(int delay) {
        		this.delay = delay;
        	}
        
        	public int getCount() {
        		return count;
        	}
        
        	public void setCount(int count) {
        		this.count = count;
        	}
        
        	public RetryPolicy createRetryInstance() {
                return new JMSRetryPolicy(delay, count);
            }
            
            protected static class JMSRetryPolicy implements RetryPolicy {
            	int delay;
                int count;
                int currentCount = 1;
                Logger logger = Logger.getLogger(JMSRetryPolicy.class);
                
                public JMSRetryPolicy(int delay, int count) {
                	this.delay = delay;
                	this.count = count;
                }
                
                public PolicyStatus applyPolicy(Throwable cause) {
                	logger.debug("Enter the JMS retry policy for the " + currentCount + " time.");
                    if (currentCount > count){
                    	logger.error("Retry policy exhausted - JMS is now disconnected.");
                        return PolicyStatus.policyExhausted(cause);
                    } else {
                    	currentCount++;
                        try {
        					Thread.sleep(delay);
        				} catch (InterruptedException e) {
        					e.printStackTrace();
        				}
                        return PolicyStatus.policyOk();
                    }
                }
            }
            
        }
        
        Show
        Samuel Danhardt added a comment - Sorry for the delay, here is the code : public class JMSRetryPolicyTpl extends AbstractPolicyTemplate { int delay; int count; public int getDelay() { return delay; } public void setDelay( int delay) { this .delay = delay; } public int getCount() { return count; } public void setCount( int count) { this .count = count; } public RetryPolicy createRetryInstance() { return new JMSRetryPolicy(delay, count); } protected static class JMSRetryPolicy implements RetryPolicy { int delay; int count; int currentCount = 1; Logger logger = Logger.getLogger(JMSRetryPolicy.class); public JMSRetryPolicy( int delay, int count) { this .delay = delay; this .count = count; } public PolicyStatus applyPolicy(Throwable cause) { logger.debug( "Enter the JMS retry policy for the " + currentCount + " time." ); if (currentCount > count){ logger.error( "Retry policy exhausted - JMS is now disconnected." ); return PolicyStatus.policyExhausted(cause); } else { currentCount++; try { Thread .sleep(delay); } catch (InterruptedException e) { e.printStackTrace(); } return PolicyStatus.policyOk(); } } } }
        Hide
        Daniel Feist added a comment -

        Did you get a chance to look at this one Mike?

        Show
        Daniel Feist added a comment - Did you get a chance to look at this one Mike?

          People

          • Assignee:
            Unassigned
            Reporter:
            Samuel Danhardt
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:

              Development