4 Replies Latest reply on Jul 1, 2014 4:52 AM by Thomas Cataldo

    Failed to connect to embedded hornetq

    Thomas Cataldo Newbie

      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 ?

        • 1. Re: Failed to connect to embedded hornetq
          Justin Bertram Master

          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?
          • 2. Re: Failed to connect to embedded hornetq
            Thomas Cataldo Newbie

            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);

            • 3. Re: Failed to connect to embedded hornetq
              Justin Bertram Master

              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.

              • 4. Re: Failed to connect to embedded hornetq
                Thomas Cataldo Newbie

                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.