activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "thomas.r.parkinson" <thomas.r.parkin...@gmail.com>
Subject Re: Slow Failover
Date Thu, 02 May 2013 13:51:48 GMT
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.

Mime
View raw message