6 Replies Latest reply on Feb 7, 2012 11:26 AM by brind77

    multiple-failover example not working -Timeout issue

    brind77 Newbie

      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] #####################