Periodic errors after JMS reconnect

Details

  • Type: Bug Bug
  • Status: Open 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:
    None

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

Ascending order - Click to sort in descending order
Hide
Permalink
Mike Schilling added a comment -

Please post the custom strategy code

Show
Mike Schilling added a comment - Please post the custom strategy code
Hide
Permalink
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
Permalink
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
Vote (0)
Watch (2)

Dates

  • Created:
    Updated: