Failed to connect to embedded hornetq

[tcataldobm]

Hi,

I have a pretty simple non-clustered setup.

When trying to establish a connection to my 5445 listening server I get on the client side :

2014-06-30 22:10:35,552 [main] o.h.c.client DEBUG - Trying reconnection attempt 0/1

2014-06-30 22:10:35,562 [main] o.h.c.client DEBUG - Trying to connect with connector = org.hornetq.core.remoting.impl.netty.NettyConnectorFactory@2ed705bd, parameters = {port=5445, host=127.0.0.1} connector = NettyConnector [host=127.0.0.1, port=5445, httpEnabled=false, httpUpgradeEnabled=false, useServlet=false, servletPath=/messaging/HornetQServlet, sslEnabled=false, useNio=true]

2014-06-30 22:10:35,591 [main] o.h.c.client DEBUG - Started Netty Connector version 4.0.20.Final

2014-06-30 22:10:35,591 [main] o.h.c.client DEBUG - Trying to connect at the main server using connector :TransportConfiguration(name=98b2b057-0092-11e4-9fc8-39834c881fe7, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=127-0-0-1

2014-06-30 22:10:35,591 [main] o.h.c.client DEBUG - Remote destination: /127.0.0.1:5445

2014-06-30 22:10:35,637 [main] o.h.c.client TRACE - Sending packet nonblocking PACKET(Ping)[type=10, channelID=0, packetObject=Ping, connectionTTL=60000] on channeID=0

2014-06-30 22:10:35,637 [main] o.h.c.client TRACE - Writing buffer for channelID=0

2014-06-30 22:10:35,637 [Thread-0 (HornetQ-client-global-scheduled-threads-2073486808)] o.h.c.client TRACE - Sending packet nonblocking PACKET(Ping)[type=10, channelID=0, packetObject=Ping, connectionTTL=60000] on channeID=0

2014-06-30 22:10:35,637 [Thread-0 (HornetQ-client-global-scheduled-threads-2073486808)] o.h.c.client TRACE - Writing buffer for channelID=0

2014-06-30 22:10:35,637 [main] o.h.c.client TRACE - ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=98b2b057-0092-11e4-9fc8-39834c881fe7, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=127-0-0-1], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=98b2b057-0092-11e4-9fc8-39834c881fe7, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=127-0-0-1, backupConfig=null]::Subscribing Topology

2014-06-30 22:10:35,639 [main] o.h.c.client TRACE - Sending packet nonblocking SubscribeClusterTopologyUpdatesMessage [clusterConnection=false, toString()=PACKET(SubscribeClusterTopologyUpdatesMessageV2)[type=113, channelID=0, packetObject=SubscribeClusterTopologyUpdatesMessageV2]] on channeID=0

2014-06-30 22:10:35,640 [main] o.h.c.client TRACE - Writing buffer for channelID=0

2014-06-30 22:10:35,641 [main] o.h.c.client TRACE - returning RemotingConnectionImpl [clientID=null, nodeID=null, transportConnection=org.hornetq.core.remoting.impl.netty.NettyConnection@1dbd5ff8[local= /127.0.0.1:60462, remote=/127.0.0.1:5445]]

2014-06-30 22:10:35,641 [main] o.h.c.client DEBUG - Reconnection successful

2014-06-30 22:11:05,638 [Thread-0 (HornetQ-client-global-scheduled-threads-2073486808)] o.h.c.client TRACE - Sending packet nonblocking PACKET(Ping)[type=10, channelID=0, packetObject=Ping, connectionTTL=60000] on channeID=0

2014-06-30 22:11:05,638 [Thread-0 (HornetQ-client-global-scheduled-threads-2073486808)] o.h.c.client TRACE - Writing buffer for channelID=0

HornetQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=HQ119013: Timed out waiting to receive cluster topology. Group:null]

  at org.hornetq.core.client.impl.ServerLocatorImpl.createSessionFactory(ServerLocatorImpl.java:946)

  at net.bluemind.hornetq.client.NonOsgiActivator.newCSF(NonOsgiActivator.java:73)

  at net.bluemind.hornetq.client.HQHelper.newSession(HQHelper.java:56)

  at net.bluemind.hornetq.client.tests.HprofOnMassNotifTest.testProduceMassImapNotifications(HprofOnMassNotifTest.java:22)

While the server remains silent :

2014-06-30 22:10:27,403 [main] n.b.h.MQServer INFO - Starting MQ Server...

2014-06-30 22:10:27,429 [main] o.j.logging DEBUG - Logging Provider: org.jboss.logging.Slf4jLoggerProvider

2014-06-30 22:10:27,429 [main] o.h.c.server DEBUG - Loading server configuration from bundleresource://18.fwk414538609/hornetq-configuration.xml

2014-06-30 22:10:27,606 [main] o.h.c.server DEBUG - Starting server HornetQServerImpl::

2014-06-30 22:10:27,609 [main] o.h.c.server INFO - HQ221000: live server is starting with configuration HornetQ Configuration (clustered=false,backup=false,sharedStore=true,journalDirectory=/var/lib/bm-mq-data/journal,bindingsDirectory=/var/lib/bm-mq-data/bindings,largeMessagesDirectory=/var/lib/bm-mq-data/large-messages,pagingDirectory=/var/lib/bm-mq-data/paging)

2014-06-30 22:10:27,609 [main] o.h.c.server INFO - HQ221006: Waiting to obtain live lock

2014-06-30 22:10:27,609 [main] o.h.c.server DEBUG - First part initialization on org.hornetq.core.server.impl.HornetQServerImpl$SharedStoreLiveActivation@6a535a0a

2014-06-30 22:10:27,633 [main] o.h.c.server INFO - HQ221013: Using NIO Journal

2014-06-30 22:10:27,688 [main] o.h.c.server INFO - HQ221043: Adding protocol support CORE

2014-06-30 22:10:27,735 [main] o.h.c.server DEBUG - the filename is hornetq-configuration.xml

2014-06-30 22:10:27,735 [main] o.h.c.server DEBUG - Got URI bundleresource://18.fwk414538609/hornetq-configuration.xml

2014-06-30 22:10:27,735 [main] o.h.c.server DEBUG - Deploying bundleresource://18.fwk414538609/hornetq-configuration.xml for AddressSettingsDeployer

2014-06-30 22:10:27,784 [main] o.h.c.server DEBUG - the filename is hornetq-queues.xml

2014-06-30 22:10:27,789 [main] o.h.c.server DEBUG - the filename is hornetq-users.xml

2014-06-30 22:10:27,789 [main] o.h.c.server DEBUG - Got URI bundleresource://18.fwk414538609/hornetq-users.xml

2014-06-30 22:10:27,789 [main] o.h.c.server DEBUG - Deploying bundleresource://18.fwk414538609/hornetq-users.xml for BasicUserCredentialsDeployer

2014-06-30 22:10:27,798 [main] o.h.c.server DEBUG - the filename is hornetq-configuration.xml

2014-06-30 22:10:27,798 [main] o.h.c.server DEBUG - Got URI bundleresource://18.fwk414538609/hornetq-configuration.xml

2014-06-30 22:10:27,798 [main] o.h.c.server DEBUG - Deploying bundleresource://18.fwk414538609/hornetq-configuration.xml for SecurityDeployer

2014-06-30 22:10:27,839 [main] o.h.c.server DEBUG - the filename is hornetq-queues.xml

2014-06-30 22:10:27,840 [main] o.h.c.server INFO - HQ221034: Waiting to obtain live lock

2014-06-30 22:10:27,840 [main] o.h.c.server INFO - HQ221035: Live Server Obtained live lock

2014-06-30 22:10:27,848 [main] o.h.journal TRACE - Loading file hornetq-bindings-1.bindings

2014-06-30 22:10:27,974 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-bindings-1.bindings id = 3, recordID = 3)

2014-06-30 22:10:27,975 [main] o.h.journal TRACE - Loading file hornetq-bindings-2.bindings

2014-06-30 22:10:27,979 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-bindings-2.bindings id = 4, recordID = 4)

2014-06-30 22:10:27,980 [main] o.h.journal TRACE - pushing openFile JournalFileImpl: (hornetq-bindings-2.bindings id = 6, recordID = 6)

2014-06-30 22:10:27,984 [main] o.h.journal TRACE - Loading file hornetq-data-1.hq

2014-06-30 22:10:28,023 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-data-1.hq id = 11, recordID = 11)

2014-06-30 22:10:28,023 [main] o.h.journal TRACE - Loading file hornetq-data-2.hq

2014-06-30 22:10:28,061 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-data-2.hq id = 12, recordID = 12)

2014-06-30 22:10:28,062 [main] o.h.journal TRACE - Loading file hornetq-data-3.hq

2014-06-30 22:10:28,095 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-data-3.hq id = 13, recordID = 13)

2014-06-30 22:10:28,096 [main] o.h.journal TRACE - Loading file hornetq-data-4.hq

2014-06-30 22:10:28,126 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-data-4.hq id = 14, recordID = 14)

2014-06-30 22:10:28,127 [main] o.h.journal TRACE - Loading file hornetq-data-5.hq

2014-06-30 22:10:28,157 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-data-5.hq id = 15, recordID = 15)

2014-06-30 22:10:28,158 [main] o.h.journal TRACE - Loading file hornetq-data-6.hq

2014-06-30 22:10:28,188 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-data-6.hq id = 16, recordID = 16)

2014-06-30 22:10:28,189 [main] o.h.journal TRACE - Loading file hornetq-data-7.hq

2014-06-30 22:10:28,223 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-data-7.hq id = 17, recordID = 17)

2014-06-30 22:10:28,223 [main] o.h.journal TRACE - Loading file hornetq-data-8.hq

2014-06-30 22:10:28,254 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-data-8.hq id = 18, recordID = 18)

2014-06-30 22:10:28,255 [main] o.h.journal TRACE - Loading file hornetq-data-9.hq

2014-06-30 22:10:28,286 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-data-9.hq id = 19, recordID = 19)

2014-06-30 22:10:28,286 [main] o.h.journal TRACE - Loading file hornetq-data-10.hq

2014-06-30 22:10:28,317 [main] o.h.journal TRACE - Adding free file JournalFileImpl: (hornetq-data-10.hq id = 20, recordID = 20)

2014-06-30 22:10:28,317 [main] o.h.journal TRACE - pushing openFile JournalFileImpl: (hornetq-data-2.hq id = 22, recordID = 22)

2014-06-30 22:10:28,318 [main] o.h.c.server DEBUG - the filename is hornetq-configuration.xml

2014-06-30 22:10:28,319 [main] o.h.c.server DEBUG - Got URI bundleresource://18.fwk414538609/hornetq-configuration.xml

2014-06-30 22:10:28,319 [main] o.h.c.server DEBUG - Deploying bundleresource://18.fwk414538609/hornetq-configuration.xml for QueueDeployer

2014-06-30 22:10:28,353 [main] o.h.c.server DEBUG - the filename is hornetq-queues.xml

2014-06-30 22:10:28,436 [main] o.h.c.server TRACE - Sending Notification = Notification[uid=null, type=ACCEPTOR_STARTED, properties=TypedProperties[{factory=org.hornetq.core.remoting.impl.netty.NettyAcceptorFactory, port=5445, host=0.0.0.0}]], notificationEnabled=true messagingServerControl=org.hornetq.core.management.impl.HornetQServerControlImpl@173b026e

2014-06-30 22:10:28,437 [main] o.h.c.server TRACE - Receiving notification : Notification[uid=null, type=ACCEPTOR_STARTED, properties=TypedProperties[{factory=org.hornetq.core.remoting.impl.netty.NettyAcceptorFactory, port=5445, host=0.0.0.0}]] on server HornetQServerImpl::serverUUID=c2db74e8-0085-11e4-ae3d-8dd45996e2ce

2014-06-30 22:10:28,437 [main] o.h.c.server DEBUG - ignoring message Notification[uid=null, type=ACCEPTOR_STARTED, properties=TypedProperties[{factory=org.hornetq.core.remoting.impl.netty.NettyAcceptorFactory, port=5445, host=0.0.0.0}]] as the server is not initialized

2014-06-30 22:10:28,437 [main] o.h.c.server INFO - HQ221020: Started Netty Acceptor version 4.0.20.Final 0.0.0.0:5445

2014-06-30 22:10:28,439 [main] o.h.c.server INFO - HQ221007: Server is now live

2014-06-30 22:10:28,439 [main] o.h.c.server INFO - HQ221001: HornetQ Server version 2.5.0.SNAPSHOT (Wild Hornet, 124) [c2db74e8-0085-11e4-ae3d-8dd45996e2ce]

When using wireshark, I see some client/server exchanges, but don't know what to look at.

Any idea ?

[jbertram]

Couple of questions...

1. Are you running the client and the server on the same machine?
2. Can you attach your config?
3. Can you attach the client code?

[tcataldobm]

For this test, they are running on the same machine. My configuration was 2.2.4 so the issue might be here.

And the client code :

  Map<String, Object> cp = new HashMap<String, Object>();

  cp.put(org.hornetq.core.remoting.impl.netty.TransportConstants.PORT_PROP_NAME,

  5445);

  cp.put(org.hornetq.core.remoting.impl.netty.TransportConstants.HOST_PROP_NAME,

  "127.0.0.1");

  TransportConfiguration tc = new TransportConfiguration(

  "org.hornetq.core.remoting.impl.netty.NettyConnectorFactory",

  cp);

  locator = HornetQClient.createServerLocatorWithoutHA(tc);

  locator.setBlockOnDurableSend(false);

  locator.setBlockOnNonDurableSend(false);

  locator.setReconnectAttempts(-1);

[jbertram]

The configuration looks OK for the most part.  However, it's worth noting that a connector pointing to 0.0.0.0 is not terribly useful since any remote client that might use that connector would then try to connect to 0.0.0.0 which would not be meaningful.

Also, it's worth noting that you're using a snapshot (i.e. 2.5.0.SNAPSHOT) and not an official release so there's no guarantee that it will work.  Why don't you try using 2.4.0.Final?

In any event, I'd need a reproducible test-case to investigate further.

[tcataldobm]

Ok, think I found it. My hornetq is running with osgi bundles. hornetq-core-client and hornetq-core-server are sitting in 2 different bundles. The same package being used in both client & server jar causes the following exception :

2014-07-01 10:35:36,567 [Thread-1 (hornetq-netty-threads-795235101)] o.h.c.client INFO - java.lang.IllegalAccessError: tried to access method org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.<init>(Lorg/hornetq/core/protocol/core/impl/PacketDecoder;Lorg/hornetq/spi/core/remoting/Connection;Ljava/util/List;Ljava/util/List;Ljava/util/concurrent/Executor;Lorg/hornetq/api/core/SimpleString;)V from class org.hornetq.core.protocol.core.impl.CoreProtocolManager

io.netty.handler.codec.DecoderException: java.lang.IllegalAccessError: tried to access method org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.<init>(Lorg/hornetq/core/protocol/core/impl/PacketDecoder;Lorg/hornetq/spi/core/remoting/Connection;Ljava/util/List;Ljava/util/List;Ljava/util/concurrent/Executor;Lorg/hornetq/api/core/SimpleString;)V from class org.hornetq.core.protocol.core.impl.CoreProtocolManager

  at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:272) ~[netty-all-4.0.20.Final.jar:4.0.20.Final]

  at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:149) ~[netty-all-4.0.20.Final.jar:4.0.20.Final]

  at org.hornetq.core.protocol.ProtocolHandler$ProtocolDecoder.channelRead(ProtocolHandler.java:110) ~[hornetq-server-2.4.1.Final.jar:na]

  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:332) ~[netty-all-4.0.20.Final.jar:4.0.20.Final]

  at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:318) ~[netty-all-4.0.20.Final.jar:4.0.20.Final]

  at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:787) ~[netty-all-4.0.20.Final.jar:4.0.20.Final]

  at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:125) ~[netty-all-4.0.20.Final.jar:4.0.20.Final]

  at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:507) [netty-all-4.0.20.Final.jar:4.0.20.Final]

  at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:464) [netty-all-4.0.20.Final.jar:4.0.20.Final]

  at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:378) [netty-all-4.0.20.Final.jar:4.0.20.Final]

  at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:350) [netty-all-4.0.20.Final.jar:4.0.20.Final]

  at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116) [netty-all-4.0.20.Final.jar:4.0.20.Final]

  at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]

Caused by: java.lang.IllegalAccessError: tried to access method org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.<init>(Lorg/hornetq/core/protocol/core/impl/PacketDecoder;Lorg/hornetq/spi/core/remoting/Connection;Ljava/util/List;Ljava/util/List;Ljava/util/concurrent/Executor;Lorg/hornetq/api/core/SimpleString;)V from class org.hornetq.core.protocol.core.impl.CoreProtocolManager

  at org.hornetq.core.protocol.core.impl.CoreProtocolManager.createConnectionEntry(CoreProtocolManager.java:89) ~[hornetq-server-2.4.1.Final.jar:na]

  at org.hornetq.core.remoting.server.impl.RemotingServiceImpl.connectionCreated(RemotingServiceImpl.java:516) ~[hornetq-server-2.4.1.Final.jar:na]

  at org.hornetq.core.remoting.impl.netty.NettyAcceptor$Listener.connectionCreated(NettyAcceptor.java:685) ~[hornetq-server-2.4.1.Final.jar:na]

  at org.hornetq.core.remoting.impl.netty.NettyAcceptor$HornetQServerChannelHandler.createConnection(NettyAcceptor.java:648) ~[hornetq-server-2.4.1.Final.jar:na]

  at org.hornetq.core.protocol.ProtocolHandler$ProtocolDecoder.decode(ProtocolHandler.java:155) ~[hornetq-server-2.4.1.Final.jar:na]

  at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:241) ~[netty-all-4.0.20.Final.jar:4.0.20.Final]

Moving client jar in the same bundle as the server fixed my problem.