InvalidClientIDException between network brokers

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

InvalidClientIDException between network brokers

kube
Hi,
   We have a three node network brokers set up and was working fine. (named respectably, mq01, mq02 and mq03)
Recently we decided to separate the connector for topic from the connector for queue,
and we started to see exceptions flooding in broker's log like the following:
javax.jms.InvalidClientIDException: Broker: mq01 - Client: queueOnly_mq02_inbound_mq01 already connected from vm://mq01#76162

1. The complete activemq.xml is attached at very bottom.
2. We are using ActiveMQ 5.9.0
3. The full stack trace is :
2014-05-12 14:47:51,140 | WARN | Failed to add Connection mq01->mq02-34867-1399699310371-38095:1 | org.apache.activemq.broker.TransportConnection | triggerStartAsyncNetworkBridgeCreation: remoteBroker=tcp://mq02.xxx.xxxxxxxx/192.168.42.33:61688@39099, localBroker= vm://mq01#76164
javax.jms.InvalidClientIDException: Broker: mq01 - Client: queueOnly_mq02_inbound_mq01 already connected from vm://mq01#76162
at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:243)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:90)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
at org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:733)
at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:292)
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
at org.apache.activemq.transport.vm.VMTransport.doDispatch(VMTransport.java:138)
at org.apache.activemq.transport.vm.VMTransport.dispatch(VMTransport.java:127)
at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:104)
at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
at org.apache.activemq.transport.ResponseCorrelator.asyncRequest(ResponseCorrelator.java:81)
at org.apache.activemq.transport.ResponseCorrelator.request(ResponseCorrelator.java:86)
at org.apache.activemq.network.DemandForwardingBridgeSupport.startLocalBridge(DemandForwardingBridgeSupport.java:420)
at org.apache.activemq.network.DemandForwardingBridgeSupport.doStartLocalAndRemoteBridges(DemandForwardingBridgeSupport.java:387)
at org.apache.activemq.network.DemandForwardingBridgeSupport.access$500(DemandForwardingBridgeSupport.java:73)
at org.apache.activemq.network.DemandForwardingBridgeSupport$5.run(DemandForwardingBridgeSupport.java:302)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)








***********************************************************************************************

<beans
  xmlns="http://www.springframework.org/schema/beans"
  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
  xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd
  http://activemq.apache.org/schema/core http://activemq.apache.org/schema/core/activemq-core.xsd">

   
    <bean class="org.springframework.beans.factory.config.PropertyPlaceholderConfigurer">
        <property name="locations">
            <value>file:${activemq.conf}/credentials.properties</value>
        </property>
    </bean>

   
    <bean id="logQuery" class="org.fusesource.insight.log.log4j.Log4jLogQuery"
          lazy-init="false" scope="singleton"
          init-method="start" destroy-method="stop">
    </bean>

   
    <broker xmlns="http://activemq.apache.org/schema/core" brokerName="${brokerName}" dataDirectory="${activemq.data}" networkConnectorStartAsync="true">

        <destinationPolicy>
            <policyMap>
              <policyEntries>
                <policyEntry topic=">" >
                  <pendingMessageLimitStrategy>
                    <constantPendingMessageLimitStrategy limit="1000"/>
                  </pendingMessageLimitStrategy>
                </policyEntry>
                                <policyEntry queue=">" enableAudit="false" queuePrefetch="10">
                                   <networkBridgeFilterFactory>
                                         <conditionalNetworkBridgeFilterFactory replayWhenNoConsumers="true"/>
                                   </networkBridgeFilterFactory>
                                <deadLetterStrategy>
                                   <individualDeadLetterStrategy queuePrefix="DLQ." useQueueForQueueMessages="true" />
                                </deadLetterStrategy>

                                </policyEntry>

              </policyEntries>
            </policyMap>
        </destinationPolicy>

        <managementContext>
            <managementContext createConnector="true"/>
        </managementContext>

        <persistenceAdapter>
            <kahaDB directory="${activemq.data}/kahadb" concurrentStoreAndDispatchQueues="false"/>
        </persistenceAdapter>


          <systemUsage>
            <systemUsage sendFailIfNoSpaceAfterTimeout="30000">
                <memoryUsage>
                    <memoryUsage percentOfJvmHeap="70" />
                </memoryUsage>
                <storeUsage>
                    <storeUsage limit="100 gb"/>
                </storeUsage>
                <tempUsage>
                    <tempUsage limit="50 gb"/>
                </tempUsage>
            </systemUsage>
        </systemUsage>

        <networkConnectors>
                        <networkConnector name="topicOnly" uri="multicast://default" networkTTL="3">
                                <dynamicallyIncludedDestinations>
                                        <topic physicalName=">"/>
                                </dynamicallyIncludedDestinations>
                        <excludedDestinations>
                                <topic physicalName="VirtualTopic.>"/>
                        </excludedDestinations>
                        </networkConnector>
                        <networkConnector name="queueOnly" uri="multicast://default" conduitSubscriptions="false" networkTTL="3">
                                <dynamicallyIncludedDestinations>
                        <queue physicalName=">"/>
                        </dynamicallyIncludedDestinations>
                        </networkConnector>
                </networkConnectors>


        <transportConnectors>
            <transportConnector name="default" uri="nio://0.0.0.0:61688" discoveryUri="multicast://default" updateClusterClients="true" rebalanceClusterClients="true" updateClusterClientsOnRemove="true"/>
                        <transportConnector name="stomp+nio" uri="stomp+nio://0.0.0.0:61613" discoveryUri="multicast://default" updateClusterClients="true" rebalanceClusterClients="true" updateClusterClientsOnRemove="true"/>
        </transportConnectors>

        <shutdownHooks>
            <bean xmlns="http://www.springframework.org/schema/beans" class="org.apache.activemq.hooks.SpringContextHook" />
        </shutdownHooks>

    </broker>


    <import resource="jetty.xml"/>

</beans>



**************************

Any input/help is very much appreciated.

thanks

Reply | Threaded
Open this post in threaded view
|

Re: InvalidClientIDException between network brokers

kube
After turning on the trace, here is that pattern we found.

1. connection issue detected at 2014-05-21 17:13:17,008 for vm://mq01#68026
2. MulticastDiscoveryAgent detected issue at 17:13:17,009, decides to wait for 5 seconds
3. Stopping connection at 2014-05-21 17:13:17,015
4. Stopping transport at 2014-05-21 17:13:17,016
5. Cleaning up connection resources: vm://mq01#68026 at 2014-05-21 17:13:17,016
6. remove connection id: mq01->mq02-46052-1400304319531-34022:1 at 2014-05-21 17:13:17,016
7. Unregistering MBean for consumer/producers starting from 2014-05-21 17:13:17,017
8. MulticastDiscoveryAgent kicking off recovery at 17:13:22, failed, InvalidClientIDException logged,  wating 5 seconds
9. MulticastDiscoveryAgent kicking off recovery at 17:13:28, failed, InvalidClientIDException logged,  wating 5 seconds
10. MulticastDiscoveryAgent kicking off recovery at 17:13:34, failed, InvalidClientIDException logged,  wating 5 seconds
11. Unregistering MBean for consumer/producers completed at 2014-05-21 17:13:37,975
12. Connection Stopped: vm://mq01#68026 at 2014-05-21 17:13:38,012
13. MulticastDiscoveryAgent kicking off recovery at 17:13:39, and succeeded


The InvalidClientIDException we saw is actually indicating:
1. connection stopping process is till going on, the  recovery attempts kicked of by MulticastDiscoveryAgent is not able to go through  (and shouldn't)
2. that fact that we saw 4  InvalidClientIDException in a row after a "connection issue" seems caused by the long running resource cleaning up(like MBeans/consumers)
3. from the log the cleaning process is done by a single thread, and it takes 40 milli seconds to unregister a subscription ( I am seeing remote consumers mostly).
for instance =====>
./mq01/tracemq01.log:2014-05-21 17:13:30,811 | DEBUG | mq01 removing consumer: mq01->mq02-46052-1400304319531-34022:1:1:274 for destination: queue://Template | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ BrokerService[mq01] Task-22226
./mq01/tracemq01.log:2014-05-21 17:13:30,849 | DEBUG | mq01 removing consumer: mq01->mq02-46052-1400304319531-34022:1:1:238 for destination: queue://Template | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ BrokerService[mq01] Task-22226

4. since we saw have 500+ remote consumers on it.
each time a connection issue happen, it takes  30~40 seconds to clean up the resources and reestablish new one.


Questions:
1. is 500+ consumers on single broker node consider to be too much for a broker?
2. is not the 30~40 per destination performance too slow? is it normal? any way to tune it up?  
3. shouldn't the clean up process running in parallel?