[
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 [[email protected]] - 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)
