After digging in the source code and adding some additional logging statements, I found the client failure check period was working just fine. In fact, the client connection immediately switches over to the other active member of the cluster. I also added some logging to ChannelImpl to show where messages were getting sent. Here's a clip of the log. Here the client is sending to the node with acceptor on port 5446, then I kill that broker node and the client immediately starts sending to the node with acceptor on port 5445. After about 30 seconds, the client is finally able to send to the node without getting a timeout exception.
{noformat}
WARNING: Sending to remote address: localhost/127.0.0.1:5446
Mar 28, 2012 11:36:19 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5446
Mar 28, 2012 11:36:19 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5446
Mar 28, 2012 11:36:19 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5446
Mar 28, 2012 11:36:20 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Executing failoverOrReconnect
30331 WARN [Thread-1] org.springframework.jms.connection.CachingConnectionFactory - Encountered a JMSException - resetting the underlying JMS Connection
javax.jms.JMSException: HornetQException[errorCode=2 message=Channel disconnected]
at org.hornetq.jms.client.HornetQConnection$JMSFailureListener.connectionFailed(HornetQConnection.java:643)
at org.hornetq.core.client.impl.ClientSessionFactoryImpl.callFailureListeners(ClientSessionFactoryImpl.java:821)
at org.hornetq.core.client.impl.ClientSessionFactoryImpl.failoverOrReconnect(ClientSessionFactoryImpl.java:608)
at org.hornetq.core.client.impl.ClientSessionFactoryImpl.handleConnectionFailure(ClientSessionFactoryImpl.java:482)
at org.hornetq.core.client.impl.ClientSessionFactoryImpl.connectionDestroyed(ClientSessionFactoryImpl.java:363)
at org.hornetq.core.remoting.impl.netty.NettyConnector$Listener$1.run(NettyConnector.java:687)
at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: HornetQException[errorCode=2 message=Channel disconnected]
... 6 more
30334 WARN [listenerContainer-1] org.springframework.jms.listener.DefaultMessageListenerContainer - Setup of JMS message listener invoker failed for destination 'HornetQQueue[exampleQueue]' - trying to recover. Cause: Consumer is closed
30335 INFO [Thread-1] com.myco.jmstest.ConnectionDecorator - Stop connection
30335 INFO [Thread-1] com.myco.jmstest.ConnectionDecorator - Closing connection
Mar 28, 2012 11:36:20 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Creating ClientSessionFactoryImpl - attempt: 0
Mar 28, 2012 11:36:20 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Trying reconnection attempt: 0 reconnect attempts: 1
Mar 28, 2012 11:36:20 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Scheduling ping with frequency - ClientFailureCheckPeriod: 500
Mar 28, 2012 11:36:20 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
Mar 28, 2012 11:36:20 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
30345 INFO [listenerContainer-1] com.myco.jmstest.ConnectionDecorator - Creating connection
30345 INFO [listenerContainer-1] org.springframework.jms.connection.CachingConnectionFactory - Established shared JMS Connection: com.myco.jmstest.ConnectionDecorator@2db7ae22
30345 INFO [listenerContainer-1] com.myco.jmstest.ConnectionDecorator - Start connection
30345 INFO [listenerContainer-1] org.springframework.jms.listener.DefaultMessageListenerContainer - Successfully refreshed JMS Connection
30345 INFO [listenerContainer-2] com.myco.jmstest.ConnectionDecorator - Creating session
Mar 28, 2012 11:36:20 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
Mar 28, 2012 11:36:20 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
30347 INFO [listenerContainer-2] com.myco.jmstest.SessionDecorator - Session constructor
Mar 28, 2012 11:36:20 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
Mar 28, 2012 11:36:20 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
30532 INFO [listenerContainer-2] com.myco.jmstest.JmsListener - Messages received: 8889
org.springframework.jms.UncategorizedJmsException: Uncategorized exception occured during JMS processing; nested exception is javax.jms.JMSException: Timed out waiting for response when sending packet 71
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 org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:612)
at com.myco.jmstest.JmsSender.sendMessage(JmsSender.java:26)
at com.myco.jmstest.Main.main(Main.java:44)
Caused by: javax.jms.JMSException: Timed out waiting for response when sending packet 71
at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:277)
at org.hornetq.core.client.impl.ClientProducerImpl.doSend(ClientProducerImpl.java:287)
at org.hornetq.core.client.impl.ClientProducerImpl.send(ClientProducerImpl.java:142)
at org.hornetq.jms.client.HornetQMessageProducer.doSend(HornetQMessageProducer.java:451)
at org.hornetq.jms.client.HornetQMessageProducer.send(HornetQMessageProducer.java:210)
at org.springframework.jms.connection.CachedMessageProducer.send(CachedMessageProducer.java:117)
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)
... 4 more
Caused by: HornetQException[errorCode=3 message=Timed out waiting for response when sending packet 71]
... 14 more
35298 INFO [main] com.myco.jmstest.ConnectionDecorator - Creating session
Mar 28, 2012 11:36:24 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
Mar 28, 2012 11:36:25 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
35299 INFO [main] com.myco.jmstest.SessionDecorator - Session constructor
Mar 28, 2012 11:36:25 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
Mar 28, 2012 11:36:25 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
35303 INFO [main] com.myco.jmstest.JmsSender - Messages sent: 8273
Mar 28, 2012 11:36:25 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
org.springframework.jms.UncategorizedJmsException: Uncategorized exception occured during JMS processing; nested exception is javax.jms.JMSException: Timed out waiting for response when sending packet 71
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 org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:612)
at com.myco.jmstest.JmsSender.sendMessage(JmsSender.java:26)
at com.myco.jmstest.Main.main(Main.java:44)
Caused by: javax.jms.JMSException: Timed out waiting for response when sending packet 71
at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:277)
at org.hornetq.core.client.impl.ClientProducerImpl.doSend(ClientProducerImpl.java:287)
at org.hornetq.core.client.impl.ClientProducerImpl.send(ClientProducerImpl.java:142)
at org.hornetq.jms.client.HornetQMessageProducer.doSend(HornetQMessageProducer.java:451)
at org.hornetq.jms.client.HornetQMessageProducer.send(HornetQMessageProducer.java:210)
at org.springframework.jms.connection.CachedMessageProducer.send(CachedMessageProducer.java:117)
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)
... 4 more
Caused by: HornetQException[errorCode=3 message=Timed out waiting for response when sending packet 71]
... 14 more
Mar 28, 2012 11:36:30 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
org.springframework.jms.UncategorizedJmsException: Uncategorized exception occured during JMS processing; nested exception is javax.jms.JMSException: Timed out waiting for response when sending packet 71
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 org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:612)
at com.myco.jmstest.JmsSender.sendMessage(JmsSender.java:26)
at com.myco.jmstest.Main.main(Main.java:44)
Caused by: javax.jms.JMSException: Timed out waiting for response when sending packet 71
at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:277)
at org.hornetq.core.client.impl.ClientProducerImpl.doSend(ClientProducerImpl.java:287)
at org.hornetq.core.client.impl.ClientProducerImpl.send(ClientProducerImpl.java:142)
at org.hornetq.jms.client.HornetQMessageProducer.doSend(HornetQMessageProducer.java:451)
at org.hornetq.jms.client.HornetQMessageProducer.send(HornetQMessageProducer.java:210)
at org.springframework.jms.connection.CachedMessageProducer.send(CachedMessageProducer.java:117)
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)
... 4 more
Caused by: HornetQException[errorCode=3 message=Timed out waiting for response when sending packet 71]
... 14 more
Mar 28, 2012 11:36:35 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
org.springframework.jms.UncategorizedJmsException: Uncategorized exception occured during JMS processing; nested exception is javax.jms.JMSException: Timed out waiting for response when sending packet 71
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 org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:612)
at com.myco.jmstest.JmsSender.sendMessage(JmsSender.java:26)
at com.myco.jmstest.Main.main(Main.java:44)
Caused by: javax.jms.JMSException: Timed out waiting for response when sending packet 71
at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:277)
at org.hornetq.core.client.impl.ClientProducerImpl.doSend(ClientProducerImpl.java:287)
at org.hornetq.core.client.impl.ClientProducerImpl.send(ClientProducerImpl.java:142)
at org.hornetq.jms.client.HornetQMessageProducer.doSend(HornetQMessageProducer.java:451)
at org.hornetq.jms.client.HornetQMessageProducer.send(HornetQMessageProducer.java:210)
at org.springframework.jms.connection.CachedMessageProducer.send(CachedMessageProducer.java:117)
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)
... 4 more
Caused by: HornetQException[errorCode=3 message=Timed out waiting for response when sending packet 71]
... 14 more
Mar 28, 2012 11:36:40 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
org.springframework.jms.UncategorizedJmsException: Uncategorized exception occured during JMS processing; nested exception is javax.jms.JMSException: Timed out waiting for response when sending packet 71
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 org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:612)
at com.myco.jmstest.JmsSender.sendMessage(JmsSender.java:26)
at com.myco.jmstest.Main.main(Main.java:44)
Caused by: javax.jms.JMSException: Timed out waiting for response when sending packet 71
at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:277)
at org.hornetq.core.client.impl.ClientProducerImpl.doSend(ClientProducerImpl.java:287)
at org.hornetq.core.client.impl.ClientProducerImpl.send(ClientProducerImpl.java:142)
at org.hornetq.jms.client.HornetQMessageProducer.doSend(HornetQMessageProducer.java:451)
at org.hornetq.jms.client.HornetQMessageProducer.send(HornetQMessageProducer.java:210)
at org.springframework.jms.connection.CachedMessageProducer.send(CachedMessageProducer.java:117)
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)
... 4 more
Caused by: HornetQException[errorCode=3 message=Timed out waiting for response when sending packet 71]
... 14 more
Mar 28, 2012 11:36:45 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
org.springframework.jms.UncategorizedJmsException: Uncategorized exception occured during JMS processing; nested exception is javax.jms.JMSException: Timed out waiting for response when sending packet 71
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 org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:612)
at com.myco.jmstest.JmsSender.sendMessage(JmsSender.java:26)
at com.myco.jmstest.Main.main(Main.java:44)
Caused by: javax.jms.JMSException: Timed out waiting for response when sending packet 71
at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:277)
at org.hornetq.core.client.impl.ClientProducerImpl.doSend(ClientProducerImpl.java:287)
at org.hornetq.core.client.impl.ClientProducerImpl.send(ClientProducerImpl.java:142)
at org.hornetq.jms.client.HornetQMessageProducer.doSend(HornetQMessageProducer.java:451)
at org.hornetq.jms.client.HornetQMessageProducer.send(HornetQMessageProducer.java:210)
at org.springframework.jms.connection.CachedMessageProducer.send(CachedMessageProducer.java:117)
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)
... 4 more
Caused by: HornetQException[errorCode=3 message=Timed out waiting for response when sending packet 71]
... 14 more
Mar 28, 2012 11:36:50 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
65309 INFO [main] com.myco.jmstest.JmsSender - Messages sent: 8274
65309 INFO [listenerContainer-2] com.myco.jmstest.JmsListener - Messages received: 8998
Mar 28, 2012 11:36:55 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
Mar 28, 2012 11:36:55 AM org.hornetq.core.logging.impl.JULLogDelegate warn
WARNING: Sending to remote address: localhost/127.0.0.1:5445
{noformat}
I'm still not sure what causes the 30 second delay!