[AMQ-8154] ActiveMQ broker fails to re-establish connection with peer broker

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 5.13.2
• Component/s: Broker
• Assignee: Unassigned
• Reporter: Nauman Hameed
• Created: 23/Feb/21 14:21
• Updated: 16/Jul/21 20:17

Description

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.

1. 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.

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

1. 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.

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

1. Secondary also starts showing following in the log for the existing connection.

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

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?