Nauman Hameed created AMQ-8154:
----------------------------------
Summary: 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
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 sensed the absence of primary, 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)
