activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Gary Tully <gary.tu...@gmail.com>
Subject Re: Slow Failover
Date Fri, 03 May 2013 11:54:44 GMT
To recognise the dead sockets that result from the cable pull more
promptly, reduce the default inactivity monitor timeouts: see:
http://activemq.apache.org/activemq-inactivitymonitor.html

If you want failover to retry immediately, reduce the failover
reconnectDelay to a few seconds.
http://activemq.apache.org/failover-transport-reference.html

On 2 May 2013 14:51, thomas.r.parkinson <thomas.r.parkinson@gmail.com> wrote:
> Creating two producers using Spring JMS template and two consumers using
> spring DefaultMessageListenerContainer. Using a ActiveMQConnectionFactory
> for both.
>
> When i pull the network cable on broker 4 i see an exception in the jms
> template about 30 seconds after then 30 seconds after that i see
> Failover.FailoverTransport: Waking up reconnect task then then 15 seconds
> later the re-connect happens.
>
> Any ideas?
>
> Logging output:
>
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Reconnect
> was triggered but transport is not started yet. Wait for start to connect
> the transport.
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Reconnect
> was triggered but transport is not started yet. Wait for start to connect
> the transport.
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Reconnect
> was triggered but transport is not started yet. Wait for start to connect
> the transport.
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Started
> unconnected
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Started
> unconnected
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Started
> unconnected
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waking up
> reconnect task
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waking up
> reconnect task
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waking up
> reconnect task
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: urlList
> connectionList:[tcp://amq-node-4:61616], from: [tcp://amq-node-4:61616]
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: urlList
> connectionList:[tcp://amq-node-4:61616], from: [tcp://amq-node-4:61616]
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: urlList
> connectionList:[tcp://amq-node-4:61616], from: [tcp://amq-node-4:61616]
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Attempting
> 0th  connect to: tcp://amq-node-4:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Attempting
> 0th  connect to: tcp://amq-node-4:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Attempting
> 0th  connect to: tcp://amq-node-4:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Connection
> established
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Connection
> established
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Connection
> established
> [02/05/13 02:40:48:048 BST]  INFO - failover.FailoverTransport: Successfully
> connected to tcp://amq-node-4:61616
> [02/05/13 02:40:48:048 BST]  INFO - failover.FailoverTransport: Successfully
> connected to tcp://amq-node-4:61616
> [02/05/13 02:40:48:048 BST]  INFO - failover.FailoverTransport: Successfully
> connected to tcp://amq-node-4:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waking up
> reconnect task
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waking up
> reconnect task
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Doing
> rebalance from: tcp://amq-node-4:61616 to [tcp://amq-node-5:61616,
> tcp://amq-node-4:61616]
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waking up
> reconnect task
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Doing
> rebalance from: tcp://amq-node-4:61616 to [tcp://amq-node-5:61616,
> tcp://amq-node-4:61616]
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waiting 10
> ms before attempting connection.
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waiting 10
> ms before attempting connection.
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Attempting
> 0th  connect to: tcp://amq-node-5:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Attempting
> 0th  connect to: tcp://amq-node-5:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Connection
> established
> [02/05/13 02:40:48:048 BST]  INFO - failover.FailoverTransport: Successfully
> reconnected to tcp://amq-node-5:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Connection
> established
> [02/05/13 02:40:48:048 BST]  INFO - failover.FailoverTransport: Successfully
> reconnected to tcp://amq-node-5:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Reconnect
> was triggered but transport is not started yet. Wait for start to connect
> the transport.
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Started
> unconnected
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waking up
> reconnect task
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: urlList
> connectionList:[tcp://amq-node-4:61616], from: [tcp://amq-node-4:61616]
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Attempting
> 0th  connect to: tcp://amq-node-4:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Connection
> established
> [02/05/13 02:40:48:048 BST]  INFO - failover.FailoverTransport: Successfully
> connected to tcp://amq-node-4:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waking up
> reconnect task
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Doing
> rebalance from: tcp://amq-node-4:61616 to [tcp://amq-node-5:61616,
> tcp://amq-node-4:61616]
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Waiting 10
> ms before attempting connection.
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Attempting
> 0th  connect to: tcp://amq-node-5:61616
> [02/05/13 02:40:48:048 BST] DEBUG - failover.FailoverTransport: Connection
> established
> [02/05/13 02:40:48:048 BST]  INFO - failover.FailoverTransport: Successfully
> reconnected to tcp://amq-node-5:61616
> Exception in thread "pool-1-thread-2"
> org.springframework.jms.UncategorizedJmsException: Uncategorized exception
> occured during JMS processing; nested exception is javax.jms.JMSException:
> org.apache.activemq.transport.RequestTimedOutIOException
>         at
> org.springframework.jms.support.JmsUtils.convertJmsAccessException(JmsUtils.java:316)
>         at
> org.springframework.jms.support.JmsAccessor.convertJmsAccessException(JmsAccessor.java:168)
>         at org.springframework.jms.core.JmsTemplate.execute(JmsTemplate.java:469)
>         at org.springframework.jms.core.JmsTemplate.send(JmsTemplate.java:534)
>         at
> com.brightpearl.mq.resource.dispatch.ActiveMqResourceEventDispatcher.dispatchToQueue(ActiveMqResourceEventDispatcher.java:160)
>         at
> com.brightpearl.mq.resource.dispatch.ActiveMqResourceEventDispatcher.dispatchCreation(ActiveMqResourceEventDispatcher.java:134)
>         at com.brightpearl.mq.it.Producer.produceMessages(Producer.java:59)
>         at com.brightpearl.mq.it.Producer.run(Producer.java:65)
>         at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>         at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:722)
> Caused by: javax.jms.JMSException:
> org.apache.activemq.transport.RequestTimedOutIOException
>         at
> org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:62)
>         at
> org.apache.activemq.ActiveMQConnection.doSyncSendPacket(ActiveMQConnection.java:1445)
>         at
> org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1425)
>         at org.apache.activemq.ActiveMQSession.send(ActiveMQSession.java:1796)
>         at
> org.apache.activemq.ActiveMQMessageProducer.send(ActiveMQMessageProducer.java:289)
>         at
> org.apache.activemq.ActiveMQMessageProducer.send(ActiveMQMessageProducer.java:224)
>         at
> org.apache.activemq.ActiveMQMessageProducerSupport.send(ActiveMQMessageProducerSupport.java:241)
>         at org.springframework.jms.core.JmsTemplate.doSend(JmsTemplate.java:592)
>         at org.springframework.jms.core.JmsTemplate.doSend(JmsTemplate.java:569)
>         at org.springframework.jms.core.JmsTemplate$3.doInJms(JmsTemplate.java:536)
>         at org.springframework.jms.core.JmsTemplate.execute(JmsTemplate.java:466)
>         ... 8 more
> Caused by: org.apache.activemq.transport.RequestTimedOutIOException
>         at
> org.apache.activemq.transport.FutureResponse.getResult(FutureResponse.java:54)
>         at
> org.apache.activemq.transport.ResponseCorrelator.request(ResponseCorrelator.java:92)
>         at
> org.apache.activemq.ActiveMQConnection.doSyncSendPacket(ActiveMQConnection.java:1432)
>         ... 17 more
> [02/05/13 02:42:15:015 BST] DEBUG - failover.FailoverTransport: Waking up
> reconnect task
> [02/05/13 02:42:28:028 BST] TRACE - failover.FailoverTransport:
> tcp://amq-node-5:61616 handleTransportFailure:
> org.apache.activemq.transport.InactivityIOException: Channel was inactive
> for too (>30000) long: tcp://172.27.1.126:61616
> [02/05/13 02:42:28:028 BST] TRACE - failover.FailoverTransport:
> tcp://amq-node-5:61616 handleTransportFailure:
> org.apache.activemq.transport.InactivityIOException: Channel was inactive
> for too (>30000) long: tcp://172.27.1.126:61616
> [02/05/13 02:42:28:028 BST]  WARN - failover.FailoverTransport: Transport
> (tcp://172.27.1.126:61616) failed, reason:
> org.apache.activemq.transport.InactivityIOException: Channel was inactive
> for too (>30000) long: tcp://172.27.1.126:61616, attempting to automatically
> reconnect
> [02/05/13 02:42:28:028 BST]  WARN - failover.FailoverTransport: Transport
> (tcp://172.27.1.126:61616) failed, reason:
> org.apache.activemq.transport.InactivityIOException: Channel was inactive
> for too (>30000) long: tcp://172.27.1.126:61616, attempting to automatically
> reconnect
> [02/05/13 02:42:28:028 BST] DEBUG - failover.FailoverTransport: Waiting 10
> ms before attempting connection.
> [02/05/13 02:42:28:028 BST] DEBUG - failover.FailoverTransport: Waiting 10
> ms before attempting connection.
> [02/05/13 02:42:28:028 BST] DEBUG - failover.FailoverTransport: Attempting
> 0th  connect to: tcp://amq-node-4:61616
> [02/05/13 02:42:28:028 BST] DEBUG - failover.FailoverTransport: Attempting
> 0th  connect to: tcp://amq-node-4:61616
> [02/05/13 02:42:28:028 BST] DEBUG - failover.FailoverTransport: Connection
> established
> [02/05/13 02:42:28:028 BST]  INFO - failover.FailoverTransport: Successfully
> reconnected to tcp://amq-node-4:61616
> [02/05/13 02:42:28:028 BST] TRACE - failover.FailoverTransport: restore
> requestMap, replay: ActiveMQTextMessage {commandId = 31302, responseRequired
> = true, messageId = ID:tom-OptiPlex-9010-38261-1367502048498-4:1:5217:1:1,
> originalDestination = null, originalTransactionId = null, producerId =
> ID:tom-OptiPlex-9010-38261-1367502048498-4:1:5217:1, destination =
> topic://VirtualTopic.resource.tom.created, transactionId = null, expiration
> = 0, timestamp = 1367502070257, arrival = 0, brokerInTime = 0, brokerOutTime
> = 0, correlationId = null, replyTo = null, persistent = true, type = null,
> priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null,
> compressed = false, userID = null, content =
> org.apache.activemq.util.ByteSequence@51a82311, marshalledProperties =
> org.apache.activemq.util.ByteSequence@75965af8, dataStructure = null,
> redeliveryCounter = 0, size = 0, properties = {account-id=ba,
> account-version=admindev}, readOnlyProperties = true, readOnlyBody = true,
> droppable = false, text =
> {"accountId":"ba","accountVersion":"admindev"...nalData":{}}}
> [02/05/13 02:42:28:028 BST] DEBUG - failover.FailoverTransport: Connection
> established
> [02/05/13 02:42:28:028 BST]  INFO - failover.FailoverTransport: Successfully
> reconnected to tcp://amq-node-4:61616
> [02/05/13 02:42:28:028 BST] TRACE - failover.FailoverTransport:
> tcp://amq-node-5:61616 handleTransportFailure:
> org.apache.activemq.transport.InactivityIOException: Channel was inactive
> for too (>30000) long: tcp://172.27.1.126:61616
> [02/05/13 02:42:28:028 BST]  WARN - failover.FailoverTransport: Transport
> (tcp://172.27.1.126:61616) failed, reason:
> org.apache.activemq.transport.InactivityIOException: Channel was inactive
> for too (>30000) long: tcp://172.27.1.126:61616, attempting to automatically
> reconnect
> [02/05/13 02:42:28:028 BST] DEBUG - failover.FailoverTransport: Waiting 10
> ms before attempting connection.
> [02/05/13 02:42:28:028 BST] DEBUG - failover.FailoverTransport: Attempting
> 0th  connect to: tcp://amq-node-4:61616
> [02/05/13 02:42:28:028 BST] DEBUG - failover.FailoverTransport: Connection
> established
> [02/05/13 02:42:28:028 BST]  INFO - failover.FailoverTransport: Successfully
> reconnected to tcp://amq-node-4:61616
>
>
>
> --
> View this message in context: http://activemq.2283324.n4.nabble.com/Slow-Failover-tp4666393p4666579.html
> Sent from the ActiveMQ - User mailing list archive at Nabble.com.



-- 
http://redhat.com
http://blog.garytully.com

Mime
View raw message