multiple-failover example not working -Timeout issue

[brind77]

Tried the jms/multiple-failover example in HornetQ2.2.5-Final on a Windows box  and this is what I get. Tried increasing the disocvery group initial-wait-timoeut value to 20000 and that didnt help.

Is this a loopback issue or something else

runExample:

     [java] serverProps = -XX:+UseParallelGC -Xms256M -Xmx256M -XX:+AggressiveOpts -XX:+UseFastAccessorMethods -Dcom.sun.management.jmxremote -Djava.util.logging.config.file=C:\hornetq-2.2.5.Final-src\hornetq-2.2.5.Final-src\examples\common/config/logging.properties -Djava.naming.factory.initial=org.jnp.interfaces.NamingContextFactory -Djava.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces

     [java] Feb 3, 2012 1:01:56 PM org.hornetq.common.example.HornetQExample run

     [java] INFO: hornetq.example.runServer is true

     [java] Feb 3, 2012 1:01:56 PM org.hornetq.common.example.HornetQExample startServer

     [java] INFO: starting server with config 'server0' logServerOutput true

     [java] HornetQServer_0 err:[main] 13:01:57,226 WARNING [org.hornetq.core.deployers.impl.FileConfigurationParser]  AIO wasn't located on this platform, it will fall back to using pure Java NIO. If your platform is Linux, install LibAIO to enable the AIO journal

     [java] HornetQServer_0 err:[main] 13:01:57,441 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  live server is starting with configuration HornetQ Configuration (clustered=true,backup=false,sharedStore=true,journalDirectory=data/journal,bindingsDirectory=data/bindings,largeMessagesDirectory=data/largemessages,pagingDirectory=data/paging)

     [java] HornetQServer_0 err:[main] 13:01:57,442 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  Waiting to obtain live lock

     [java] HornetQServer_0 err:[main] 13:01:57,467 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Using NIO Journal

     [java] HornetQServer_0 err:[main] 13:01:57,480 WARNING [org.hornetq.core.server.impl.HornetQServerImpl]  Security risk! It has been detected that the cluster admin user and password have not been changed from the installation default. Please see the HornetQ user guide, cluster chapter, for instructions on how to do this.

     [java] HornetQServer_0 err:[main] 13:01:57,651 INFO [org.hornetq.core.server.impl.FileLockNodeManager]  Waiting to obtain live lock

     [java] HornetQServer_0 err:[main] 13:01:57,651 INFO [org.hornetq.core.server.impl.FileLockNodeManager]  Live Server Obtained live lock

     [java] HornetQServer_0 err:[main] 13:01:58,597 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  trying to deploy queue jms.queue.exampleQueue

     [java] HornetQServer_0 err:[main] 13:01:58,800 INFO [org.hornetq.core.remoting.impl.netty.NettyAcceptor]  Started Netty Acceptor version 3.2.3.Final-r${buildNumber} localhost:5445 for CORE protocol

     [java] HornetQServer_0 err:[main] 13:01:58,800 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  Server is now live

     [java] HornetQServer_0 err:[main] 13:01:58,800 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  HornetQ Server version 2.2.5.Final (HQ_2_2_5_FINAL_AS7, 121) [29a97048-4e91-11e1-8cfe-b8ac6f0eb250] started

     [java] HornetQServer_0 out:STARTED::

     [java] Feb 3, 2012 1:01:58 PM org.hornetq.common.example.HornetQExample startServer

     [java] INFO: starting server with config 'server1' logServerOutput true

     [java] HornetQServer_1 err:[main] 13:01:59,648 WARNING [org.hornetq.core.deployers.impl.FileConfigurationParser]  AIO wasn't located on this platform, it will fall back to using pure Java NIO. If your platform is Linux, install LibAIO to enable the AIO journal

     [java] HornetQServer_1 err:[main] 13:01:59,705 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  backup server is starting with configuration HornetQ Configuration (clustered=true,backup=true,sharedStore=true,journalDirectory=../server0/data/journal,bindingsDirectory=../server0/data/bindings,largeMessagesDirectory=../server0/data/large-messages,pagingDirectory=../server0/data/paging)

     [java] HornetQServer_1 err:[Thread-2] 13:01:59,706 INFO [org.hornetq.core.server.impl.FileLockNodeManager]  Waiting to become backup node

     [java] HornetQServer_1 out:STARTED::

     [java] HornetQServer_1 err:[Thread-2] 13:01:59,707 INFO [org.hornetq.core.server.impl.FileLockNodeManager]  ** got backup lock

     [java] Feb 3, 2012 1:01:59 PM org.hornetq.common.example.HornetQExample startServer

     [java] INFO: starting server with config 'server2' logServerOutput true

     [java] HornetQServer_1 err:[Thread-2] 13:01:59,731 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Using NIO Journal

     [java] HornetQServer_1 err:[Thread-2] 13:01:59,743 WARNING [org.hornetq.core.server.impl.HornetQServerImpl]  Security risk! It has been detected that the cluster admin user and password have not been changed from the installation default. Please see the HornetQ user guide, cluster chapter, for instructions on how to do this.

     [java] HornetQServer_1 err:[Thread-2] 13:01:59,923 INFO [org.hornetq.core.server.cluster.impl.ClusterManagerImpl]  announcing backup

     [java] HornetQServer_1 err:[Thread-2] 13:01:59,925 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  HornetQ Backup Server version 2.2.5.Final (HQ_2_2_5_FINAL_AS7, 121) [29a97048-4e91-11e1-8cfe-b8ac6f0eb250] started, waiting live to fail before it gets active

     [java] HornetQServer_2 err:[main] 13:02:00,585 WARNING [org.hornetq.core.deployers.impl.FileConfigurationParser]  AIO wasn't located on this platform, it will fall back to using pure Java NIO. If your platform is Linux, install LibAIO to enable the AIO journal

     [java] HornetQServer_2 err:[main] 13:02:00,639 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  backup server is starting with configuration HornetQ Configuration (clustered=true,backup=true,sharedStore=true,journalDirectory=../server0/data/journal,bindingsDirectory=../server0/data/bindings,largeMessagesDirectory=../server0/data/large-messages,pagingDirectory=../server0/data/paging)

     [java] HornetQServer_2 err:[Thread-2] 13:02:00,641 INFO [org.hornetq.core.server.impl.FileLockNodeManager]  Waiting to become backup node

     [java] HornetQServer_2 out:STARTED::

     [java] Feb 3, 2012 1:02:00 PM org.hornetq.common.example.HornetQExample getContext

     [java] INFO: using server0\client-jndi.properties for jndi

     [java] HornetQServer_1 err:[Thread-0 (group:HornetQ-server-threads211201404-1226621799)] 13:02:00,877 INFO [org.hornetq.core.server.cluster.impl.ClusterManagerImpl]  backup announced

     [java] Sent message: This is text message 0

     [java] Sent message: This is text message 1

     [java] Sent message: This is text message 2

     [java] Sent message: This is text message 3

     [java] Sent message: This is text message 4

     [java] Sent message: This is text message 5

     [java] Sent message: This is text message 6

     [java] Sent message: This is text message 7

     [java] Sent message: This is text message 8

     [java] Sent message: This is text message 9

     [java] Sent message: This is text message 10

     [java] Sent message: This is text message 11

     [java] Sent message: This is text message 12

     [java] Sent message: This is text message 13

     [java] Sent message: This is text message 14

     [java] Sent message: This is text message 15

     [java] Sent message: This is text message 16

     [java] Sent message: This is text message 17

     [java] Sent message: This is text message 18

     [java] Sent message: This is text message 19

     [java] Sent message: This is text message 20

     [java] Sent message: This is text message 21

     [java] Sent message: This is text message 22

     [java] Sent message: This is text message 23

     [java] Sent message: This is text message 24

     [java] Sent message: This is text message 25

     [java] Sent message: This is text message 26

     [java] Sent message: This is text message 27

     [java] Sent message: This is text message 28

     [java] Sent message: This is text message 29

     [java] Got message: This is text message 0

     [java] Got message: This is text message 1

     [java] Got message: This is text message 2

     [java] Got message: This is text message 3

     [java] Got message: This is text message 4

     [java] Got message: This is text message 5

     [java] Got message: This is text message 6

     [java] Got message: This is text message 7

     [java] Got message: This is text message 8

     [java] Got message: This is text message 9

     [java] Got message: This is text message 10

     [java] Got message: This is text message 11

     [java] Got message: This is text message 12

     [java] Got message: This is text message 13

     [java] Got message: This is text message 14

     [java] Got message: This is text message 15

     [java] Got message: This is text message 16

     [java] Got message: This is text message 17

     [java] Got message: This is text message 18

     [java] Got message: This is text message 19

     [java] Got message: This is text message 20

     [java] Got message: This is text message 21

     [java] Got message: This is text message 22

     [java] Got message: This is text message 23

     [java] Got message: This is text message 24

     [java] Got message: This is text message 25

     [java] Got message: This is text message 26

     [java] Got message: This is text message 27

     [java] Got message: This is text message 28

     [java] Got message: This is text message 29

     [java] Killing server 0

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,701 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=5 from the journal

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,702 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=6 from the journal

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,702 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=7 from the journal

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,702 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=8 from the journal

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,702 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=9 from the journal

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,702 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=10 from the journal

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,703 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=11 from the journal

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,703 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=12 from the journal

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,703 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=13 from the journal

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,703 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=14 from the journal

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,860 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  trying to deploy queue jms.queue.exampleQueue

     [java] HornetQServer_1 err:[Thread-2] 13:02:04,911 INFO [org.hornetq.core.remoting.impl.netty.NettyAcceptor]  Started Netty Acceptor version 3.2.3.Final-r${buildNumber} localhost:5446 for CORE protocol

     [java] HornetQServer_1 err:[Thread-1 (group:HornetQ-client-global-threads-69518356)] 13:02:05,419 WARNING [org.hornetq.core.client.impl.ClientSessionFactoryImpl]  Failed to connect to server.

     [java] HornetQServer_1 err:[Thread-2] 13:02:05,454 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  Backup Server is now live

     [java] HornetQServer_2 err:[Thread-2] 13:02:05,661 INFO [org.hornetq.core.server.impl.FileLockNodeManager]  ** got backup lock

     [java] HornetQServer_2 err:[Thread-2] 13:02:05,709 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Using NIO Journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:05,720 WARNING [org.hornetq.core.server.impl.HornetQServerImpl]  Security risk! It has been detected that the cluster admin user and password have not been changed from the installation default. Please see the HornetQ user guide, cluster chapter, for instructions on how to do this.

     [java] HornetQServer_2 err:[Thread-2] 13:02:05,890 INFO [org.hornetq.core.server.cluster.impl.ClusterManagerImpl]  announcing backup

     [java] HornetQServer_2 err:[Thread-2] 13:02:05,891 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  HornetQ Backup Server version 2.2.5.Final (HQ_2_2_5_FINAL_AS7, 121) [29a97048-4e91-11e1-8cfe-b8ac6f0eb250] started, waiting live to fail before it gets active

     [java] HornetQServer_2 err:[Thread-0 (group:HornetQ-server-threads1628606298-1844438133)] 13:02:05,998 INFO [org.hornetq.core.server.cluster.impl.ClusterManagerImpl]  backup announced

     [java] Got exception while acknowledging message: The transaction was rolled back on failover to a backup server

     [java] Got message: This is text message 10 (redelivered?: false)

     [java] Got message: This is text message 11 (redelivered?: false)

     [java] Got message: This is text message 12 (redelivered?: false)

     [java] Got message: This is text message 13 (redelivered?: false)

     [java] Got message: This is text message 14 (redelivered?: false)

     [java] Got message: This is text message 15 (redelivered?: false)

     [java] Got message: This is text message 16 (redelivered?: false)

     [java] Got message: This is text message 17 (redelivered?: false)

     [java] Got message: This is text message 18 (redelivered?: false)

     [java] Got message: This is text message 19 (redelivered?: false)

     [java] Killing server 1

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,243 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=15 from the journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,244 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=17 from the journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,245 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=16 from the journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,245 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=19 from the journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,245 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=18 from the journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,246 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=21 from the journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,246 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=20 from the journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,246 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=23 from the journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,247 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=22 from the journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,247 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Deleting unreferenced message id=24 from the journal

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,414 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  trying to deploy queue jms.queue.exampleQueue

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,480 INFO [org.hornetq.core.remoting.impl.netty.NettyAcceptor]  Started Netty Acceptor version 3.2.3.Final-r${buildNumber} localhost:5447 for CORE protocol

     [java] HornetQServer_2 err:[Thread-1 (group:HornetQ-client-global-threads-1320687469)] 13:02:10,636 WARNING [org.hornetq.core.client.impl.ClientSessionFactoryImpl]  Failed to connect to server.

     [java] HornetQServer_2 err:[Thread-2] 13:02:10,683 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  Backup Server is now live

     [java] Feb 3, 2012 1:02:39 PM org.hornetq.core.logging.impl.JULLogDelegate error

     [java] SEVERE: Failed to handle failover

     [java] HornetQException[errorCode=3 message=Timed out waiting for response when sending packet 32]

     [java]           at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:276)

     [java]           at org.hornetq.core.client.impl.ClientSessionImpl.handleFailover(ClientSessionImpl.java:921)

     [java]           at org.hornetq.core.client.impl.ClientSessionFactoryImpl.reconnectSessions(ClientSessionFactoryImpl.java:873)

     [java]           at org.hornetq.core.client.impl.ClientSessionFactoryImpl.failoverOrReconnect(ClientSessionFactoryImpl.java:588)

     [java]           at org.hornetq.core.client.impl.ClientSessionFactoryImpl.handleConnectionFailure(ClientSessionFactoryImpl.java:482)

     [java]           at org.hornetq.core.client.impl.ClientSessionFactoryImpl.connectionException(ClientSessionFactoryImpl.java:369)

     [java]           at org.hornetq.core.remoting.impl.netty.NettyConnector$Listener$2.run(NettyConnector.java:700)

     [java]           at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100)

     [java]           at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

     [java]           at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

     [java]           at java.lang.Thread.run(Thread.java:619)

     [java] Got exception while acknowledging message: Timed out waiting for response when sending packet 43

     [java] Got message: This is text message 20 (redelivered?: false)

     [java] Got message: This is text message 21 (redelivered?: false)

     [java] Got message: This is text message 22 (redelivered?: false)

     [java] Got message: This is text message 23 (redelivered?: false)

     [java] Got message: This is text message 24 (redelivered?: false)

     [java] Got message: This is text message 25 (redelivered?: false)

     [java] Got message: This is text message 26 (redelivered?: false)

     [java] Got message: This is text message 27 (redelivered?: false)

     [java] Got message: This is text message 28 (redelivered?: false)

     [java] Got message: This is text message 29 (redelivered?: false)

     [java] Feb 3, 2012 1:03:09 PM org.hornetq.core.logging.impl.JULLogDelegate warn

     [java] WARNING: Connection failure has been detected: Did not receive data from server for org.hornetq.core.remoting.impl.netty.NettyConnection@1629ce8c[local= /127.0.0.1:56648, remote=localhost/127.0.0.1:5446] [code=3]

     [java] Feb 3, 2012 1:03:09 PM org.hornetq.core.logging.impl.JULLogDelegate error

     [java] SEVERE: Failed to handle failover

     [java] HornetQException[errorCode=3 message=Timed out waiting for response when sending packet 32]

     [java]           at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:276)

     [java]           at org.hornetq.core.client.impl.ClientSessionImpl.handleFailover(ClientSessionImpl.java:921)

     [java]           at org.hornetq.core.client.impl.ClientSessionFactoryImpl.reconnectSessions(ClientSessionFactoryImpl.java:873)

     [java]           at org.hornetq.core.client.impl.ClientSessionFactoryImpl.failoverOrReconnect(ClientSessionFactoryImpl.java:588)

     [java]           at org.hornetq.core.client.impl.ClientSessionFactoryImpl.handleConnectionFailure(ClientSessionFactoryImpl.java:482)

     [java]           at org.hornetq.core.client.impl.ClientSessionFactoryImpl.connectionException(ClientSessionFactoryImpl.java:369)

     [java]           at org.hornetq.core.remoting.impl.netty.NettyConnector$Listener$2.run(NettyConnector.java:700)

     [java]           at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100)

     [java]           at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

     [java]           at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

     [java]           at java.lang.Thread.run(Thread.java:619)

     [java] javax.jms.TransactionRolledBackException: The transaction was rolled back on failover to a backup server

     [java]           at org.hornetq.core.client.impl.ClientSessionImpl.rollbackOnFailover(ClientSessionImpl.java:511)

     [java]           at org.hornetq.core.client.impl.ClientSessionImpl.commit(ClientSessionImpl.java:537)

     [java]           at org.hornetq.core.client.impl.DelegatingSession.commit(DelegatingSession.java:157)

     [java]           at org.hornetq.jms.client.HornetQMessage.acknowledge(HornetQMessage.java:857)

     [java]           at org.hornetq.jms.example.MultipleFailoverExample.runExample(MultipleFailoverExample.java:143)

     [java]           at org.hornetq.common.example.HornetQExample.run(HornetQExample.java:76)

     [java]           at org.hornetq.jms.example.MultipleFailoverExample.main(MultipleFailoverExample.java:41)

     [java] Caused by: HornetQException[errorCode=111 message=The transaction was rolled back on failover to a backup server]

     [java]           ... 7 more

     [java]

     [java] #####################

     [java] ###    FAILURE!   ###

     [java] #####################

[brind77]

Hi

Is the above so basic and everybody had it working that I couldn't get a response or do I need to provide more details?

I did look around for enough issues around this in the user forum and tried some of those including setting the initial-wait-timoeut value to 20000. Would appreciate some help on this.

Thanks

[ataylor]

its late friday for a lot of people, Im sure by monday you will get an answer.

Andy UK - very late

[gaohoward]

It works for me. my env is:

Windows Vista 32 bit

java 1.6.0_17

Did you change anything ?

Howard

[brind77]

My environment is Windows 7-64  bit.

Tried on CentOS and I get the same exception stack posted above

[ataylor]

its probably a loopback issue, with out a loopback the cluster won't form. On linux this added by running the command 'route add -net 224.0.0.0 netmask 240.0.0.0 dev lo' on windows i have no idea.

[brind77]

Thanks. The loopback was fixed and I could get the multiple-failover, bridge and cluster discovery examples working.

We are considering a setup where a bridge configured via discovery sends messages to a queue hosted on a remote live/backup pair.

Modified the existing multiple_failover example where messages are sent to server0 which is configured to route messages via a bridge to live/backup server. Also modifed the example code message to reflect some of these changes.

Attached is the zip of the code/configuration. Running the build.sh always leads to issues related to bridge connectivity(HornetQException[errorCode=3 message=Timed out waiting to receive initial broadcast from cluster].

Deployed this on the same CentOS VM where I tested the dicovery and other examples that worked after fixing loopback.

The build.sh etc in the archive is the same as the multiple-failover example that was shipped with HornetQ2.2.5-Final.

Would appreciate if somebody could see if the basic setup itself (in the zip) is flawed that led to this timeout issue