Getting exception in log during failback and no message is processed - Remote queue binding has already been bound in the post office
veenaonnet Apr 25, 2014 8:40 AMHi,
I am using HornetQ 2.4 with JBoss with collocated topology with replication in paging mode.
Scenario is -
Node 1: Started - HornetQ live started
Node 2: Started - HornetQ live started
Node 2:Stopped
Node1 - HornetQ backup started
Node 2 - Started - Attempts failback
At this point
Node 2 shows error
[org.hornetq.core.server] (Thread-1 (hornetq-netty-threads-564058766)) HQ224018: Failed to create session: HornetQSessionCreationException[errorType=SESSION_CREATION_REJECTED message=HQ119034: Server not started]
at org.hornetq.core.protocol.core.impl.HornetQPacketHandler.handleCreateSession(HornetQPacketHandler.java:122) [hornetq-server-2.4.0-SNAPSHOT.jar:]
at org.hornetq.core.protocol.core.impl.HornetQPacketHandler.handlePacket(HornetQPacketHandler.java:78) [hornetq-server-2.4.0-SNAPSHOT.jar:]
at org.hornetq.core.protocol.core.impl.ChannelImpl.handlePacket(ChannelImpl.java:631) [hornetq-core-client-2.4.0-SNAPSHOT.jar:]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:547) [hornetq-core-client-2.4.0-SNAPSHOT.jar:]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.bufferReceived(RemotingConnectionImpl.java:523) [hornetq-core-client-2.4.0-SNAPSHOT.jar:]
at org.hornetq.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:629) [hornetq-server-2.4.0-SNAPSHOT.jar:]
at org.hornetq.core.remoting.impl.netty.HornetQChannelHandler.channelRead(HornetQChannelHandler.java:74) [hornetq-core-client-2.4.0-SNAPSHOT.jar:]
at io.netty.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:338) [netty-all-4.0.12.Final.jar:]
at io.netty.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:324) [netty-all-4.0.12.Final.jar:]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:153) [netty-all-4.0.12.Final.jar:]
at io.netty.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:338) [netty-all-4.0.12.Final.jar:]
at io.netty.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:324) [netty-all-4.0.12.Final.jar:]
at io.netty.handler.codec.ByteToMessageDecoder.handlerRemoved(ByteToMessageDecoder.java:110) [netty-all-4.0.12.Final.jar:]
However HornetQ server gets started after that
2014-04-25 01:57:26,108 INFO [org.hornetq.core.server] (MSC service thread 1-27) HQ221007: Server is now live
2014-04-25 01:57:26,108 INFO [org.hornetq.core.server] (MSC service thread 1-27) HQ221001: HornetQ Server version 2.4.0.SNAPSHOT (Andromedian Fly, 123) [991862ea-cc57-11e3-899d-217962e95a1d]
2014-04-25 01:57:26,112 INFO [org.hornetq.core.server] (ServerService Thread Pool -- 66) HQ221003: trying to deploy queue jms.queue.FileMoveJobs
2014-04-25 01:57:26,170 INFO [org.jboss.as.messaging] (ServerService Thread Pool -- 66) JBAS011601: Bound messaging object to jndi name java:/queue/FileMoveJobs
2014-04-25 01:57:26,171 INFO [org.hornetq.core.server] (ServerService Thread Pool -- 88) HQ221003: trying to deploy queue jms.topic.Notification
2014-04-25 01:57:26,211 INFO [org.jboss.as.messaging] (ServerService Thread Pool -- 88) JBAS011601: Bound messaging object to jndi name java:/topic/Notification
2014-04-25 01:57:26,211 INFO [org.hornetq.core.server] (ServerService Thread Pool -- 87) HQ221003: trying to deploy queue jms.queue.UpdateClosedCaptionStructureJobs
2014-04-25 01:57:26,233 INFO [org.jboss.as.messaging] (ServerService Thread Pool -- 87) JBAS011601: Bound messaging object to jndi name java:/queue/UpdateClosedCaptionStructureJobs
2014-04-25 01:57:26,233 INFO [org.hornetq.core.server] (ServerService Thread Pool -- 61) HQ221003: trying to deploy queue jms.queue.SynchronizeFolderJobs
2014-04-25 01:57:26,240 INFO [org.jboss.as.connector.deployment] (MSC service thread 1-10) JBAS010406: Registered connection factory java:/JmsXA
2014-04-25 01:57:26,249 INFO [org.hornetq.core.server] (Thread-10 (HornetQ-server-HornetQServerImpl::serverUUID=991862ea-cc57-11e3-899d-217962e95a1d-1200323700)) HQ221027: Bridge ClusterConnectionBridge@57d9b2a4 [name=sf.msf-cluster-10.4.167.99.7389f807-cc48-11e3-9d7d-4daadff738e7, queue=QueueImpl[name=sf.msf-cluster-10.4.167.99.7389f807-cc48-11e3-9d7d-4daadff738e7, postOffice=PostOfficeImpl [server=HornetQServerImpl::serverUUID=991862ea-cc57-11e3-899d-217962e95a1d]]@4a9e9396 targetConnector=ServerLocatorImpl (identity=(Cluster-connection-bridge::ClusterConnectionBridge@57d9b2a4 [name=sf.msf-cluster-10.4.167.99.7389f807-cc48-11e3-9d7d-4daadff738e7, queue=QueueImpl[name=sf.msf-cluster-10.4.167.99.7389f807-cc48-11e3-9d7d-4daadff738e7, postOffice=PostOfficeImpl [server=HornetQServerImpl::serverUUID=991862ea-cc57-11e3-899d-217962e95a1d]]@4a9e9396 targetConnector=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-27], discoveryGroupConfiguration=null]]::ClusterConnectionImpl@1472723337[nodeUUID=991862ea-cc57-11e3-899d-217962e95a1d, connector=TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-28, address=jms, server=HornetQServerImpl::serverUUID=991862ea-cc57-11e3-899d-217962e95a1d])) [initialConnectors=[TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-27], discoveryGroupConfiguration=null]] is connected
At this time it seems that Node1 is also trying to start the bridge due to the first error on Node 2
Node 1:
2014-04-25 01:57:26,116 WARN [org.hornetq.core.server] (Thread-23 (HornetQ-server-HornetQServerImpl::serverUUID=null-172395014)) HQ222098: Server is starting, retry to create the session for bridge sf.msf-cluster-10.4.167.99.a595a484-cb70-11e3-aae2-af4ddcb5b420
2014-04-25 01:57:26,178 INFO [org.hornetq.core.server] (Thread-28 (HornetQ-server-HornetQServerImpl::serverUUID=null-172395014)) HQ221027: Bridge ClusterConnectionBridge@3fe12713 [name=sf.msf-cluster-10.4.167.99.991862ea-cc57-11e3-899d-217962e95a1d, queue=QueueImpl[name=sf.msf-cluster-10.4.167.99.991862ea-cc57-11e3-899d-217962e95a1d, postOffice=PostOfficeImpl [server=HornetQServerImpl::serverUUID=7389f807-cc48-11e3-9d7d-4daadff738e7]]@56cc7128 targetConnector=ServerLocatorImpl (identity=(Cluster-connection-bridge::ClusterConnectionBridge@3fe12713 [name=sf.msf-cluster-10.4.167.99.991862ea-cc57-11e3-899d-217962e95a1d, queue=QueueImpl[name=sf.msf-cluster-10.4.167.99.991862ea-cc57-11e3-899d-217962e95a1d, postOffice=PostOfficeImpl [server=HornetQServerImpl::serverUUID=7389f807-cc48-11e3-9d7d-4daadff738e7]]@56cc7128 targetConnector=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-28], discoveryGroupConfiguration=null]]::ClusterConnectionImpl@277207633[nodeUUID=7389f807-cc48-11e3-9d7d-4daadff738e7, connector=TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-27, address=jms, server=HornetQServerImpl::serverUUID=7389f807-cc48-11e3-9d7d-4daadff738e7])) [initialConnectors=[TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-28], discoveryGroupConfiguration=null]] is connected
2014-04-25 01:57:27,137 INFO [org.hornetq.core.server] (Thread-21 (HornetQ-server-HornetQServerImpl::serverUUID=null-172395014)) HQ221027: Bridge ClusterConnectionBridge@6e98d7c1 [name=sf.msf-cluster-10.4.167.99.a595a484-cb70-11e3-aae2-af4ddcb5b420, queue=QueueImpl[name=sf.msf-cluster-10.4.167.99.a595a484-cb70-11e3-aae2-af4ddcb5b420, postOffice=PostOfficeImpl [server=HornetQServerImpl::serverUUID=7389f807-cc48-11e3-9d7d-4daadff738e7]]@747cf8a0 targetConnector=ServerLocatorImpl (identity=(Cluster-connection-bridge::ClusterConnectionBridge@6e98d7c1 [name=sf.msf-cluster-10.4.167.99.a595a484-cb70-11e3-aae2-af4ddcb5b420, queue=QueueImpl[name=sf.msf-cluster-10.4.167.99.a595a484-cb70-11e3-aae2-af4ddcb5b420, postOffice=PostOfficeImpl [server=HornetQServerImpl::serverUUID=7389f807-cc48-11e3-9d7d-4daadff738e7]]@747cf8a0 targetConnector=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-28], discoveryGroupConfiguration=null]]::ClusterConnectionImpl@277207633[nodeUUID=7389f807-cc48-11e3-9d7d-4daadff738e7, connector=TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-27, address=jms, server=HornetQServerImpl::serverUUID=7389f807-cc48-11e3-9d7d-4daadff738e7])) [initialConnectors=[TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-28], discoveryGroupConfiguration=null]] is connected
2014-04-25 01:57:33,062 WARN [org.hornetq.core.server] (Thread-52 (HornetQ-client-global-threads-107449287)) HQ222139: MessageFlowRecordImpl [nodeID=a595a484-cb70-11e3-aae2-af4ddcb5b420, connector=TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-28, queueName=sf.msf-cluster-10.4.167.99.a595a484-cb70-11e3-aae2-af4ddcb5b420, queue=QueueImpl[name=sf.msf-cluster-10.4.167.99.a595a484-cb70-11e3-aae2-af4ddcb5b420, postOffice=PostOfficeImpl [server=HornetQServerImpl::serverUUID=7389f807-cc48-11e3-9d7d-4daadff738e7]]@747cf8a0, isClosed=false, firstReset=true]::Remote queue binding 7a9c07e8-e1d1-4f59-b6a0-927fb8b61544991862ea-cc57-11e3-899d-217962e95a1d has already been bound in the post office. Most likely cause for this is you have a loop in your cluster due to cluster max-hops being too large or you have multiple cluster connections to the same nodes using overlapping addresses
and then it shows errors for all the messages
2014-04-25 01:57:33,063 ERROR [org.hornetq.core.server] (Thread-52 (HornetQ-client-global-threads-107449287)) HQ224037: cluster connection Failed to handle message: java.lang.IllegalStateException: Cannot find binding for 1dadda13-b432-4004-b1df-e180d77245a5991862ea-cc57-11e3-899d-217962e95a1d on ClusterConnectionImpl@277207633[nodeUUID=7389f807-cc48-11e3-9d7d-4daadff738e7, connector=TransportConfiguration(name=netty, factory=org-hornetq-core-remoting-impl-netty-NettyConnectorFactory) ?port=5445&host=10-4-167-27, address=jms, server=HornetQServerImpl::serverUUID=7389f807-cc48-11e3-9d7d-4daadff738e7]
at org.hornetq.core.server.cluster.impl.ClusterConnectionImpl$MessageFlowRecordImpl.doConsumerCreated(ClusterConnectionImpl.java:1396) [hornetq-server-2.4.0-SNAPSHOT.jar:]
at org.hornetq.core.server.cluster.impl.ClusterConnectionImpl$MessageFlowRecordImpl.onMessage(ClusterConnectionImpl.java:1143) [hornetq-server-2.4.0-SNAPSHOT.jar:]
at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:1117) [hornetq-core-client-2.4.0-SNAPSHOT.jar:]
at org.hornetq.core.client.impl.ClientConsumerImpl.access$500(ClientConsumerImpl.java:57) [hornetq-core-client-2.4.0-SNAPSHOT.jar:]
at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:1252) [hornetq-core-client-2.4.0-SNAPSHOT.jar:]
Is it because bridge is started by 2 different threads(2 different nodes at the same time) with same addresses? Is it some race condition?
Laos, is there any reason because of which HornetQ server did not start first time on Node2 after failback?
Please note that failback is working fine normally.This issue is not seen always.
Please let me know how to solve it?
Regards,
Veena