Failed to connect to embedded hornetq
tcataldobm Jun 30, 2014 4:20 PMHi,
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 ?