You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@activemq.apache.org by "Matt Pavlovich (Jira)" <ji...@apache.org> on 2021/07/16 20:18:00 UTC
[jira] [Commented] (AMQ-8154) ActiveMQ broker fails to re-establish
connection with peer broker
[ https://issues.apache.org/jira/browse/AMQ-8154?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17382316#comment-17382316 ]
Matt Pavlovich commented on AMQ-8154:
-------------------------------------
Hello [~nauman.hameed@enghouse.com] - Have you tried this with a more recent version of ActiveMQ? 5.13.2 is quite dated. Please retest with 5.16.2 and report back if there is a reproduceable issue.
> ActiveMQ broker fails to re-establish connection with peer broker
> -----------------------------------------------------------------
>
> Key: AMQ-8154
> URL: https://issues.apache.org/jira/browse/AMQ-8154
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.13.2
> Reporter: Nauman Hameed
> Priority: Major
> Attachments: activemq.xml-primary, activemq.xml-secondary
>
>
> I am not too much familiar with ActiveMQ terminology so pardon my incorrect use of terms. I have two ActiveMQ brokers that connect to each other to exchange messages between two nodes of our software for resilience and failover. One broker acts as primary and other acts as secondary. Secondary broker connects to primary based on connection details in activemq.xml of secondary (see [^activemq.xml-secondary] ). The activemq.xml for primary is also attached for reference (see [^activemq.xml-primary] ).
> Recently the primary broker was re-started due to a machine reboot. Usually this is not a problem as the secondary is able to re-establish connection with primary once primary is up again. However, in this particular instance the secondary was unable to re-establish connection. Looking at logs of secondary, I notice following.
> # When secondary (AON-CUAC01-AMS1) sensed the absence of primary (AON-CUAC01-LON1), it logged a java.net.SocketException. Usually we see a java.io.IOException in secondary logs in case primary gets un-available.
> {code}
> 2021-02-16 19:31:12,713 | WARN | Network connection between vm://AON-CUAC01-AMS1#60 and tcp://AON-CUAC01-LON1/10.250.242.29:61616@58496 shutdown due to a remote error: java.net.SocketException: Software caused connection abort: socket write error | org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ InactivityMonitor Worker
> 2021-02-16 19:31:12,713 | DEBUG | The remote Exception was: java.net.SocketException: Software caused connection abort: socket write error | org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ InactivityMonitor Worker
> java.net.SocketException: Software caused connection abort: socket write error
> at java.net.SocketOutputStream.socketWrite0(Native Method)
> at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111)
> at java.net.SocketOutputStream.write(SocketOutputStream.java:155)
> at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.flush(TcpBufferedOutputStream.java:115)
> at java.io.DataOutputStream.flush(DataOutputStream.java:123)
> at org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:194)
> at org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:334)
> at org.apache.activemq.transport.AbstractInactivityMonitor.access$800(AbstractInactivityMonitor.java:41)
> at org.apache.activemq.transport.AbstractInactivityMonitor$4.run(AbstractInactivityMonitor.java:200)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> 2021-02-16 19:31:12,714 | DEBUG | stopping AON-CUAC01-AMS1 bridge to AON-CUAC01-LON1 | org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ BrokerService[AON-CUAC01-AMS1] Task-90
> {code}
> # When primary is up again, and secondary makes a connection attempt, it fails and reports InvalidClientIDException. Log also says *Broker12Bridge_AON-CUAC01-LON1_inbound_AON-CUAC01-AMS1 already connected from vm://AON-CUAC01-AMS1#60* which indicates an existing connection is still there for primary.
> {code}
> 2021-02-16 19:31:26,817 | INFO | Establishing network connection from vm://AON-CUAC01-AMS1?async=false to tcp://AON-CUAC01-LON1:61616 | org.apache.activemq.network.DiscoveryNetworkConnector | Simple Discovery Agent-19
> 2021-02-16 19:31:26,817 | DEBUG | binding to broker: AON-CUAC01-AMS1 | org.apache.activemq.transport.vm.VMTransportFactory | Simple Discovery Agent-19
> 2021-02-16 19:31:26,817 | INFO | Get Peer Broker Infos: | org.apache.activemq.broker.util.LoggingBrokerPlugin | Simple Discovery Agent-19
> 2021-02-16 19:31:26,817 | INFO | Connector vm://AON-CUAC01-AMS1 started | org.apache.activemq.broker.TransportConnector | Simple Discovery Agent-19
> 2021-02-16 19:31:26,817 | DEBUG | Initialized TaskRunnerFactory[ActiveMQ VMTransport: vm://AON-CUAC01-AMS1#78] using ExecutorService: null | org.apache.activemq.thread.TaskRunnerFactory | Simple Discovery Agent-19
> 2021-02-16 19:31:26,818 | DEBUG | Initialized TaskRunnerFactory[ActiveMQ VMTransport: vm://AON-CUAC01-AMS1#79] using ExecutorService: null | org.apache.activemq.thread.TaskRunnerFactory | ActiveMQ BrokerService[AON-CUAC01-AMS1] Task-110
> 2021-02-16 19:31:26,826 | DEBUG | Sending: WireFormatInfo { version=11, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, StackTraceEnabled=true, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=9223372036854775807, Host=AON-CUAC01-LON1, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000}, magic=[A,c,t,i,v,e,M,Q]} | org.apache.activemq.transport.WireFormatNegotiator | Simple Discovery Agent-19
> 2021-02-16 19:31:26,836 | DEBUG | Using min of local: WireFormatInfo { version=11, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, StackTraceEnabled=true, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=9223372036854775807, Host=AON-CUAC01-LON1, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000}, magic=[A,c,t,i,v,e,M,Q]} and remote: WireFormatInfo { version=11, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, StackTraceEnabled=true, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=9223372036854775807, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000}, magic=[A,c,t,i,v,e,M,Q]} | org.apache.activemq.transport.InactivityMonitor | ActiveMQ Transport: tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562
> 2021-02-16 19:31:26,836 | DEBUG | Received WireFormat: WireFormatInfo { version=11, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, StackTraceEnabled=true, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=9223372036854775807, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000}, magic=[A,c,t,i,v,e,M,Q]} | org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport: tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562
> 2021-02-16 19:31:26,836 | DEBUG | tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562 before negotiation: OpenWireFormat{version=11, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=9223372036854775807} | org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport: tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562
> 2021-02-16 19:31:26,836 | DEBUG | tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562 after negotiation: OpenWireFormat{version=11, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=9223372036854775807} | org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport: tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562
> 2021-02-16 19:31:26,836 | DEBUG | Ignoring remote command: WireFormatInfo { version=11, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, StackTraceEnabled=true, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=9223372036854775807, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000}, magic=[A,c,t,i,v,e,M,Q]} | org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ Transport: tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562
> 2021-02-16 19:31:26,837 | DEBUG | Setting up new connection id: AON-CUAC01-AMS1->AON-CUAC01-LON1-49164-1611665757700-28:1, address: vm://AON-CUAC01-AMS1#76, info: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = AON-CUAC01-AMS1->AON-CUAC01-LON1-49164-1611665757700-28:1, clientId = Broker12Bridge_AON-CUAC01-LON1_inbound_AON-CUAC01-AMS1, clientIp = null, userName = amqsystem, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = false, clientMaster = true, faultTolerant = false, failoverReconnect = false} | org.apache.activemq.broker.TransportConnection | triggerStartAsyncNetworkBridgeCreation: remoteBroker=tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562, localBroker= vm://AON-CUAC01-AMS1#76
> 2021-02-16 19:31:26,837 | INFO | Adding Connection: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = AON-CUAC01-AMS1->AON-CUAC01-LON1-49164-1611665757700-28:1, clientId = Broker12Bridge_AON-CUAC01-LON1_inbound_AON-CUAC01-AMS1, clientIp = vm://AON-CUAC01-AMS1#76, userName = amqsystem, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = false, clientMaster = true, faultTolerant = false, failoverReconnect = false} | org.apache.activemq.broker.util.LoggingBrokerPlugin | triggerStartAsyncNetworkBridgeCreation: remoteBroker=tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562, localBroker= vm://AON-CUAC01-AMS1#76
> 2021-02-16 19:31:26,838 | WARN | Failed to add Connection AON-CUAC01-AMS1->AON-CUAC01-LON1-49164-1611665757700-28:1 due to javax.jms.InvalidClientIDException: Broker: AON-CUAC01-AMS1 - Client: Broker12Bridge_AON-CUAC01-LON1_inbound_AON-CUAC01-AMS1 already connected from vm://AON-CUAC01-AMS1#60 | org.apache.activemq.broker.TransportConnection | triggerStartAsyncNetworkBridgeCreation: remoteBroker=tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562, localBroker= vm://AON-CUAC01-AMS1#76
> 2021-02-16 19:31:26,838 | DEBUG | Error occured while processing sync command: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = AON-CUAC01-AMS1->AON-CUAC01-LON1-49164-1611665757700-28:1, clientId = Broker12Bridge_AON-CUAC01-LON1_inbound_AON-CUAC01-AMS1, clientIp = vm://AON-CUAC01-AMS1#76, userName = amqsystem, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = false, clientMaster = true, faultTolerant = false, failoverReconnect = false}, exception: javax.jms.InvalidClientIDException: Broker: AON-CUAC01-AMS1 - Client: Broker12Bridge_AON-CUAC01-LON1_inbound_AON-CUAC01-AMS1 already connected from vm://AON-CUAC01-AMS1#60 | org.apache.activemq.broker.TransportConnection.Service | triggerStartAsyncNetworkBridgeCreation: remoteBroker=tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562, localBroker= vm://AON-CUAC01-AMS1#76
> javax.jms.InvalidClientIDException: Broker: AON-CUAC01-AMS1 - Client: Broker12Bridge_AON-CUAC01-LON1_inbound_AON-CUAC01-AMS1 already connected from vm://AON-CUAC01-AMS1#60
> at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:255)
> at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:98)
> at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:116)
> at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:98)
> at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:98)
> at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:98)
> at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:103)
> at org.apache.activemq.broker.util.LoggingBrokerPlugin.addConnection(LoggingBrokerPlugin.java:178)
> at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:98)
> at org.apache.activemq.security.SimpleAuthenticationBroker.addConnection(SimpleAuthenticationBroker.java:77)
> at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:103)
> at org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:817)
> at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
> at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:338)
> at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:188)
> 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:162)
> at org.apache.activemq.transport.vm.VMTransport.dispatch(VMTransport.java:154)
> at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:131)
> 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:468)
> at org.apache.activemq.network.DemandForwardingBridgeSupport.doStartLocalAndRemoteBridges(DemandForwardingBridgeSupport.java:421)
> at org.apache.activemq.network.DemandForwardingBridgeSupport.access$500(DemandForwardingBridgeSupport.java:105)
> at org.apache.activemq.network.DemandForwardingBridgeSupport$5.run(DemandForwardingBridgeSupport.java:336)
> at java.lang.Thread.run(Thread.java:748)
> 2021-02-16 19:31:26,838 | INFO | Network connection between vm://AON-CUAC01-AMS1#76 and tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562 shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: AON-CUAC01-AMS1 - Client: Broker12Bridge_AON-CUAC01-LON1_inbound_AON-CUAC01-AMS1 already connected from vm://AON-CUAC01-AMS1#60 | org.apache.activemq.network.DemandForwardingBridgeSupport | triggerStartAsyncNetworkBridgeCreation: remoteBroker=tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562, localBroker= vm://AON-CUAC01-AMS1#76
> 2021-02-16 19:31:26,838 | DEBUG | The local Exception was: javax.jms.InvalidClientIDException: Broker: AON-CUAC01-AMS1 - Client: Broker12Bridge_AON-CUAC01-LON1_inbound_AON-CUAC01-AMS1 already connected from vm://AON-CUAC01-AMS1#60 | org.apache.activemq.network.DemandForwardingBridgeSupport | triggerStartAsyncNetworkBridgeCreation: remoteBroker=tcp://AON-CUAC01-LON1/10.250.242.29:61616@58562, localBroker= vm://AON-CUAC01-AMS1#76
> javax.jms.InvalidClientIDException: Broker: AON-CUAC01-AMS1 - Client: Broker12Bridge_AON-CUAC01-LON1_inbound_AON-CUAC01-AMS1 already connected from vm://AON-CUAC01-AMS1#60
> at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:255)
> at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:98)
> at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:116)
> at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:98)
> at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:98)
> at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:98)
> at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:103)
> at org.apache.activemq.broker.util.LoggingBrokerPlugin.addConnection(LoggingBrokerPlugin.java:178)
> at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:98)
> at org.apache.activemq.security.SimpleAuthenticationBroker.addConnection(SimpleAuthenticationBroker.java:77)
> at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:103)
> at org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:817)
> at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
> at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:338)
> at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:188)
> 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:162)
> at org.apache.activemq.transport.vm.VMTransport.dispatch(VMTransport.java:154)
> at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:131)
> 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:468)
> at org.apache.activemq.network.DemandForwardingBridgeSupport.doStartLocalAndRemoteBridges(DemandForwardingBridgeSupport.java:421)
> at org.apache.activemq.network.DemandForwardingBridgeSupport.access$500(DemandForwardingBridgeSupport.java:105)
> at org.apache.activemq.network.DemandForwardingBridgeSupport$5.run(DemandForwardingBridgeSupport.java:336)
> at java.lang.Thread.run(Thread.java:748)
> 2021-02-16 19:31:26,838 | DEBUG | stopping AON-CUAC01-AMS1 bridge to AON-CUAC01-LON1 | org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ BrokerService[AON-CUAC01-AMS1] Task-112
> 2021-02-16 19:31:26,839 | DEBUG | Failure occurred soon after the discovery event was generated. It will be classified as a connection failure: [tcp://AON-CUAC01-LON1:61616, failed:true, connectionFailures:2] | org.apache.activemq.transport.discovery.simple.SimpleDiscoveryAgent | Simple Discovery Agent-20
> {code}
> # Secondary also starts showing following in the log for the existing connection.
> {code}
> 2021-02-16 19:31:33,723 | INFO | The connection to 'vm://AON-CUAC01-AMS1#60' is taking a long time to shutdown. | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[AON-CUAC01-AMS1] Task-90
> {code}
> Secondary continues to make connection attempts but keeps failing with InvalidClientIDException and the *taking a long time to shutdown* log also continues to appear.
> I have searched and I can see some issues that report similar errors but I am not sure if my scenario is same. This is partly because of my lack of ActiveMQ knowledge. I was wondering if this matches an existing reported issue that has been solved in later ActiveMQ versions?
--
This message was sent by Atlassian Jira
(v8.3.4#803005)