There are three things that happened here: 1. Your master broker stopped sending messages to this slave for 30 seconds. (Did any other slaves experience a similar disconnect?) This caused the slave to abort the connection. This could happen due to network perturbations, but I'd expect both sides to time out their respective side of the connection, so that sounds less likely to me. More likely is that something caused the master broker to stop responding for some reason; that could be an unidentified bug in the broker code, a long full garbage collect (or a continual series of them, like what Kevin Burton has observed), or some other OS performance bottleneck (maybe you're persisting messages to a file store that's on a disk that suddenly gets hit with lots of I/O contention, for example). What actually caused the problem is hard to figure out after the fact but worth digging into if this starts happening repeatedly. And I'd recommend that if it happens again, you check that full garbage collects aren't occurring, by using JConsole or jstat -gc, or by configuring GC logging on the broker's JVM. 2. It appeared to take ~15 seconds for the master to disconnect the connection to the slave; in the meantime, it rejected the connection attempts because it thought the slave was still connected. This would be even harder to figure out the root cause for, but it worked itself out quickly, so maybe that's OK. 3. You got lots of messages that got treated as duplicates, which sounds a lot like https://issues.apache.org/jira/browse/AMQ-5274, which is fixed in the not-yet-released 5.11.0. Does that bug description match your setup? If so, you could either use a snapshot version right away or (if your organization will only let you use released versions of software) you can live with the bug for now and then upgrade to 5.11.0 when it gets released. Or you could patch the fix onto your current broker version and use it right away, if your organization is comfortable with that sort of thing.
Tim On Sun, Jan 11, 2015 at 10:49 AM, nyariz <nyari.zol...@smartfront.hu> wrote: > The log lines I posted are from the master side. The slave side log > messages > are also interesting: > > INFO 2015.01.10 14:00:30,077 > org.apache.activemq.network.DemandForwardingBridgeSupport - Network > connection between vm://BALASSIBroker#114 and tcp:///10.36.0.20:62000 > @40819 > shutdown due to a local error: > org.apache.activemq.transport.InactivityIOException: Channel was inactive > for too (>30000) long: tcp://10.36.0.20:62000 > INFO 2015.01.10 14:00:30,083 > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing > network > connection from vm://BALASSIBroker?async=false&network=true to > tcp://10.36.0.20:62000 > WARN 2015.01.10 14:00:30,185 > org.apache.activemq.broker.TransportConnection - Failed to add Connection > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-14:2 > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already > connected from vm://BALASSIBroker#116 > at > > org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242) > at > > org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231) > at > org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92) > at > org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92) > at > > org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91) > 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.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97) > at > > org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759) > at > org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139) > at > > org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291) > at > > org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145) > 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.iterate(VMTransport.java:247) > at > > org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133) > at > org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48) > at > > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:745) > INFO 2015.01.10 14:00:30,189 > org.apache.activemq.network.DemandForwardingBridgeSupport - Network > connection between vm://BALASSIBroker#118 and tcp:///10.36.0.20:62000 > @54620 > shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: > BALASSIBroker - Client: > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already > connected from vm://BALASSIBroker#116 > INFO 2015.01.10 14:00:30,197 > org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker > bridge to PERCMASTERBroker stopped > INFO 2015.01.10 14:00:31,192 > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing > network > connection from vm://BALASSIBroker?async=false&network=true to > tcp://10.36.0.20:62000 > WARN 2015.01.10 14:00:31,266 > org.apache.activemq.broker.TransportConnection - Failed to add Connection > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-15:2 > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already > connected from vm://BALASSIBroker#116 > at > > org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242) > at > > org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231) > at > org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92) > at > org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92) > at > > org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91) > 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.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97) > at > > org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759) > at > org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139) > at > > org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291) > at > > org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145) > 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.iterate(VMTransport.java:247) > at > > org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133) > at > org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48) > at > > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:745) > INFO 2015.01.10 14:00:31,273 > org.apache.activemq.network.DemandForwardingBridgeSupport - Network > connection between vm://BALASSIBroker#122 and tcp:///10.36.0.20:62000 > @54621 > shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: > BALASSIBroker - Client: > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already > connected from vm://BALASSIBroker#116 > INFO 2015.01.10 14:00:31,284 > org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker > bridge to PERCMASTERBroker stopped > INFO 2015.01.10 14:00:33,276 > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing > network > connection from vm://BALASSIBroker?async=false&network=true to > tcp://10.36.0.20:62000 > WARN 2015.01.10 14:00:33,345 > org.apache.activemq.broker.TransportConnection - Failed to add Connection > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-16:2 > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already > connected from vm://BALASSIBroker#116 > at > > org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242) > at > > org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231) > at > org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92) > at > org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92) > at > > org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91) > 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.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97) > at > > org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759) > at > org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139) > at > > org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291) > at > > org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145) > 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.iterate(VMTransport.java:247) > at > > org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133) > at > org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48) > at > > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:745) > INFO 2015.01.10 14:00:33,348 > org.apache.activemq.network.DemandForwardingBridgeSupport - Network > connection between vm://BALASSIBroker#126 and tcp:///10.36.0.20:62000 > @54622 > shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: > BALASSIBroker - Client: > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already > connected from vm://BALASSIBroker#116 > INFO 2015.01.10 14:00:33,356 > org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker > bridge to PERCMASTERBroker stopped > INFO 2015.01.10 14:00:37,352 > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing > network > connection from vm://BALASSIBroker?async=false&network=true to > tcp://10.36.0.20:62000 > WARN 2015.01.10 14:00:37,426 > org.apache.activemq.broker.TransportConnection - Failed to add Connection > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-17:2 > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already > connected from vm://BALASSIBroker#116 > at > > org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242) > at > > org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231) > at > org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92) > at > org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92) > at > > org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91) > 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.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97) > at > > org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759) > at > org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139) > at > > org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291) > at > > org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145) > 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.iterate(VMTransport.java:247) > at > > org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133) > at > org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48) > at > > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:745) > INFO 2015.01.10 14:00:37,428 > org.apache.activemq.network.DemandForwardingBridgeSupport - Network > connection between vm://BALASSIBroker#130 and tcp:///10.36.0.20:62000 > @54624 > shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: > BALASSIBroker - Client: > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already > connected from vm://BALASSIBroker#116 > INFO 2015.01.10 14:00:37,436 > org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker > bridge to PERCMASTERBroker stopped > INFO 2015.01.10 14:00:40,084 > org.apache.activemq.network.DemandForwardingBridgeSupport - Network Could > not shutdown in a timely manner > WARN 2015.01.10 14:00:40,091 > org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an > exception processing local command > java.net.SocketException: Socket closed > at > java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:121) > at java.net.SocketOutputStream.write(SocketOutputStream.java:159) > at > > org.apache.activemq.transport.tcp.TcpBufferedOutputStream.write(TcpBufferedOutputStream.java:96) > at java.io.DataOutputStream.write(DataOutputStream.java:107) > at > > org.apache.activemq.openwire.v10.BaseDataStreamMarshaller.tightMarshalByteSequence2(BaseDataStreamMarshaller.java:431) > at > > org.apache.activemq.openwire.v10.MessageMarshaller.tightMarshal2(MessageMarshaller.java:182) > at > > org.apache.activemq.openwire.v10.ActiveMQMessageMarshaller.tightMarshal2(ActiveMQMessageMarshaller.java:89) > at > > org.apache.activemq.openwire.v10.ActiveMQTextMessageMarshaller.tightMarshal2(ActiveMQTextMessageMarshaller.java:89) > at > > org.apache.activemq.openwire.OpenWireFormat.marshal(OpenWireFormat.java:243) > at > > org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:175) > at > > org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:304) > at > > org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:286) > at > > org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:85) > at > > org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.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.network.DemandForwardingBridgeSupport.serviceLocalCommand(DemandForwardingBridgeSupport.java:968) > at > > org.apache.activemq.network.DemandForwardingBridgeSupport$2.onCommand(DemandForwardingBridgeSupport.java:177) > 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.oneway(ResponseCorrelator.java:60) > at > > org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1365) > at > > org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:884) > at > > org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:930) > at > > org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133) > at > org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48) > at > > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:745) > INFO 2015.01.10 14:00:40,095 > org.apache.activemq.broker.TransportConnector > - Connector vm://BALASSIBroker stopped > INFO 2015.01.10 14:00:40,095 > org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker > bridge to PERCMASTERBroker stopped > INFO 2015.01.10 14:00:45,432 > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing > network > connection from vm://BALASSIBroker?async=false&network=true to > tcp://10.36.0.20:62000 > INFO 2015.01.10 14:00:45,433 > org.apache.activemq.broker.TransportConnector > - Connector vm://BALASSIBroker started > INFO 2015.01.10 14:00:45,505 > org.apache.activemq.network.DemandForwardingBridgeSupport - Network > connection between vm://BALASSIBroker#134 and tcp:///10.36.0.20:62000 > @54625 > (PERCMASTERBroker) has been established. > WARN 2015.01.10 14:01:06,015 > org.apache.activemq.broker.region.cursors.AbstractStoreCursor - > org.apache.activemq.broker.region.cursors.QueueStorePrefetch@61ee20ea > :Consumer.BALASSI.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=0,cacheEnabled=true,maxBatchSize:1,hasSpace:true > - cursor got duplicate: > ID:Perc-Smartfront1-33556-1418679846629-5:1:2:1:19939, 4 > WARN 2015.01.10 14:01:06,017 org.apache.activemq.broker.region.Queue - > duplicate message from store > ID:Perc-Smartfront1-33556-1418679846629-5:1:2:1:19939, redirecting for dlq > processing > WARN 2015.01.10 14:01:06,071 > org.apache.activemq.broker.region.cursors.AbstractStoreCursor - > org.apache.activemq.broker.region.cursors.QueueStorePrefetch@61ee20ea > :Consumer.BALASSI.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=false,size=1,cacheEnabled=true,maxBatchSize:1,hasSpace:true > - cursor got duplicate: > ID:Perc-Smartfront1-33556-1418679846629-5:1:17:1:14867, 4 > WARN 2015.01.10 14:01:06,072 org.apache.activemq.broker.region.Queue - > duplicate message from store > ID:Perc-Smartfront1-33556-1418679846629-5:1:17:1:14867, redirecting for dlq > processing > > Thanks, > Zoltan > > > > -- > View this message in context: > http://activemq.2283324.n4.nabble.com/ActiveMQ-embedded-broker-100-cpu-usage-tp4689765p4689774.html > Sent from the ActiveMQ - User mailing list archive at Nabble.com. >
