[
https://issues.apache.org/jira/browse/AMQ-4097?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Ron Koerner updated AMQ-4097:
-----------------------------
Description:
The situation is as follows:
- an external broker A connects
- time passes
- a lot of external brokers disconnect including A
- A reconnects (as well as all the other external brokers)
- wrong message about duplicate name is generated
In the log it looks like this:
{code}
2012-10-08 17:11:19,835 INFO .DemandForwardingBridgeSupport - Network
connection between vm://c04ptec#278 and tcp:///127.0.0.1:54191(cbox-56BU902442)
has been established. [StartLocalBridge: localBroker=vm://c04ptec#278]
...
... a lot more of the following with different ports
2012-10-08 17:37:01,958 WARN .DemandForwardingBridgeSupport - Network
connection between vm://c04ptec#278 and tcp:///127.0.0.1:54191 shutdown due to
a remote error: java.io.EOFException [ActiveMQ NIO Worker 193]
... more of these
2012-10-08 17:37:03,438 INFO emq.broker.TransportConnection - Started
responder end of duplex bridge cBox 56BU902442 to cBox
Proxy@ID:P013SPWMK1WN-39320-1349704902319-0:1 [ActiveMQ NIO Worker 215]
...
2012-10-08 17:37:03,922 WARN emq.broker.TransportConnection - Failed to add
Connection ID:c04ptec-51799-1349706422094-242:2, reason:
javax.jms.InvalidClientIDException: Broker: c04ptec - Client: cBox 56BU902442
to cBox Proxy_cbox-56BU902442_inbound_c04ptec already connected from
vm://c04ptec#278 [StartLocalBridge: localBroker=vm://c04ptec#478]
2012-10-08 17:37:03,923 INFO .DemandForwardingBridgeSupport - Network
connection between vm://c04ptec#478 and tcp:///127.0.0.1:56529 shutdown due to
a local error: javax.jms.InvalidClientIDException: Broker: c04ptec - Client:
cBox 56BU902442 to cBox Proxy_cbox-56BU902442_inbound_c04ptec already connected
from vm://c04ptec#278 [StartLocalBridge: localBroker=vm://c04ptec#478]
...
2012-10-08 17:37:04,036 INFO .DemandForwardingBridgeSupport - c04ptec bridge
to cbox-56BU902442 stopped [ActiveMQ Task-182]
...
2012-10-08 17:37:06,540 INFO emq.broker.TransportConnection - Started
responder end of duplex bridge cBox 56BU902442 to cBox
Proxy@ID:P013SPWMK1WN-39320-1349704902319-0:1 [ActiveMQ NIO Worker 207]
...
2012-10-08 17:37:06,548 WARN emq.broker.TransportConnection - Failed to add
Connection ID:c04ptec-51799-1349706422094-292:1, reason:
javax.jms.InvalidClientIDException: Broker: c04ptec - Client: cBox 56BU902442
to cBox Proxy_cbox-56BU902442_inbound_c04ptec already connected from
vm://c04ptec#278 [StartLocalBridge: localBroker=vm://c04ptec#570]
2012-10-08 17:37:06,548 INFO .DemandForwardingBridgeSupport - Network
connection between vm://c04ptec#570 and tcp:///127.0.0.1:56576 shutdown due to
a local error: javax.jms.InvalidClientIDException: Broker: c04ptec - Client:
cBox 56BU902442 to cBox Proxy_cbox-56BU902442_inbound_c04ptec already connected
from vm://c04ptec#278 [StartLocalBridge: localBroker=vm://c04ptec#570]
...
2012-10-08 17:37:06,559 INFO .DemandForwardingBridgeSupport - c04ptec bridge
to cbox-56BU902442 stopped [ActiveMQ Task-204]
...
2012-10-08 17:37:24,417 INFO .DemandForwardingBridgeSupport - c04ptec bridge
to cbox-56BU902442 stopped [ActiveMQ Task-73]
...
2012-10-08 17:37:25,103 INFO emq.broker.TransportConnection - Started
responder end of duplex bridge cBox 56BU902442 to cBox
Proxy@ID:P013SPWMK1WN-39320-1349704902319-0:1 [ActiveMQ NIO Worker 268]
...
2012-10-08 17:37:29,110 INFO .DemandForwardingBridgeSupport - Network
connection between vm://c04ptec#594 and tcp:///127.0.0.1:56656(cbox-56BU902442)
has been established. [StartLocalBridge: localBroker=vm://c04ptec#594]
...
2012-10-08 17:37:59,669 WARN .DemandForwardingBridgeSupport - Network
connection between vm://c04ptec#594 and tcp:///127.0.0.1:56656(cbox-56BU902442)
was interrupted during establishment. [StartLocalBridge:
localBroker=vm://c04ptec#594]
...
2012-10-08 17:38:09,005 INFO .DemandForwardingBridgeSupport - c04ptec bridge
to cbox-56BU902442 stopped [ActiveMQ Task-228]
...
2012-10-08 17:38:18,681 INFO emq.broker.TransportConnection - Started
responder end of duplex bridge cBox 56BU902442 to cBox
Proxy@ID:P013SPWMK1WN-39320-1349704902319-0:1 [ActiveMQ NIO Worker 292]
2012-10-08 17:38:18,681 WARN emq.broker.TransportConnection - Failed to add
Connection ID:P013SPWMK1WN-39320-1349704902319-152:1, reason:
javax.jms.InvalidClientIDException: Broker: c04ptec - Client: cBox 56BU902442
to cBox Proxy_cbox-56BU902442_outbound already connected from vm://c04ptec#594
[ActiveMQ NIO Worker 292]
2012-10-08 17:38:18,682 WARN er.TransportConnection.Service - Async error
occurred: javax.jms.InvalidClientIDException: Broker: c04ptec - Client: cBox
56BU902442 to cBox Proxy_cbox-56BU902442_outbound already connected from
vm://c04ptec#594 [ActiveMQ NIO Worker 292]
javax.jms.InvalidClientIDException: Broker: c04ptec - Client: cBox 56BU902442
to cBox Proxy_cbox-56BU902442_outbound already connected from vm://c04ptec#594
at
org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:222)
~[activemq-core-5.7-SNAPSHOT.jar:5.7-SNAPSHOT]
{code}
This repeats until the external broker is stopped and started manually.
I assume there is a race condition which shows up under high load
was:
The situation is as follows:
- an external broker A connects
- time passes
- a lot of external brokers disconnect including A
- A reconnects
- wrong message about duplicate name is generated
A logfile excerpt is attached.
> Broker-to-Broker Reconnect fails wrongly due to duplicate name
> --------------------------------------------------------------
>
> Key: AMQ-4097
> URL: https://issues.apache.org/jira/browse/AMQ-4097
> Project: ActiveMQ
> Issue Type: Bug
> Affects Versions: 5.7.0
> Environment: A central broker to which a lot (50+) of external
> brokers connect with a duplex bridge. A special routing/firewall is used
> which can affect timing but not order of TCP packets. This can be simulated
> by using socat.
> Reporter: Ron Koerner
>
> The situation is as follows:
> - an external broker A connects
> - time passes
> - a lot of external brokers disconnect including A
> - A reconnects (as well as all the other external brokers)
> - wrong message about duplicate name is generated
> In the log it looks like this:
> {code}
> 2012-10-08 17:11:19,835 INFO .DemandForwardingBridgeSupport - Network
> connection between vm://c04ptec#278 and
> tcp:///127.0.0.1:54191(cbox-56BU902442) has been established.
> [StartLocalBridge: localBroker=vm://c04ptec#278]
> ...
> ... a lot more of the following with different ports
> 2012-10-08 17:37:01,958 WARN .DemandForwardingBridgeSupport - Network
> connection between vm://c04ptec#278 and tcp:///127.0.0.1:54191 shutdown due
> to a remote error: java.io.EOFException [ActiveMQ NIO Worker 193]
> ... more of these
> 2012-10-08 17:37:03,438 INFO emq.broker.TransportConnection - Started
> responder end of duplex bridge cBox 56BU902442 to cBox
> Proxy@ID:P013SPWMK1WN-39320-1349704902319-0:1 [ActiveMQ NIO Worker 215]
> ...
> 2012-10-08 17:37:03,922 WARN emq.broker.TransportConnection - Failed to add
> Connection ID:c04ptec-51799-1349706422094-242:2, reason:
> javax.jms.InvalidClientIDException: Broker: c04ptec - Client: cBox 56BU902442
> to cBox Proxy_cbox-56BU902442_inbound_c04ptec already connected from
> vm://c04ptec#278 [StartLocalBridge: localBroker=vm://c04ptec#478]
> 2012-10-08 17:37:03,923 INFO .DemandForwardingBridgeSupport - Network
> connection between vm://c04ptec#478 and tcp:///127.0.0.1:56529 shutdown due
> to a local error: javax.jms.InvalidClientIDException: Broker: c04ptec -
> Client: cBox 56BU902442 to cBox Proxy_cbox-56BU902442_inbound_c04ptec already
> connected from vm://c04ptec#278 [StartLocalBridge:
> localBroker=vm://c04ptec#478]
> ...
> 2012-10-08 17:37:04,036 INFO .DemandForwardingBridgeSupport - c04ptec bridge
> to cbox-56BU902442 stopped [ActiveMQ Task-182]
> ...
> 2012-10-08 17:37:06,540 INFO emq.broker.TransportConnection - Started
> responder end of duplex bridge cBox 56BU902442 to cBox
> Proxy@ID:P013SPWMK1WN-39320-1349704902319-0:1 [ActiveMQ NIO Worker 207]
> ...
> 2012-10-08 17:37:06,548 WARN emq.broker.TransportConnection - Failed to add
> Connection ID:c04ptec-51799-1349706422094-292:1, reason:
> javax.jms.InvalidClientIDException: Broker: c04ptec - Client: cBox 56BU902442
> to cBox Proxy_cbox-56BU902442_inbound_c04ptec already connected from
> vm://c04ptec#278 [StartLocalBridge: localBroker=vm://c04ptec#570]
> 2012-10-08 17:37:06,548 INFO .DemandForwardingBridgeSupport - Network
> connection between vm://c04ptec#570 and tcp:///127.0.0.1:56576 shutdown due
> to a local error: javax.jms.InvalidClientIDException: Broker: c04ptec -
> Client: cBox 56BU902442 to cBox Proxy_cbox-56BU902442_inbound_c04ptec already
> connected from vm://c04ptec#278 [StartLocalBridge:
> localBroker=vm://c04ptec#570]
> ...
> 2012-10-08 17:37:06,559 INFO .DemandForwardingBridgeSupport - c04ptec bridge
> to cbox-56BU902442 stopped [ActiveMQ Task-204]
> ...
> 2012-10-08 17:37:24,417 INFO .DemandForwardingBridgeSupport - c04ptec bridge
> to cbox-56BU902442 stopped [ActiveMQ Task-73]
> ...
> 2012-10-08 17:37:25,103 INFO emq.broker.TransportConnection - Started
> responder end of duplex bridge cBox 56BU902442 to cBox
> Proxy@ID:P013SPWMK1WN-39320-1349704902319-0:1 [ActiveMQ NIO Worker 268]
> ...
> 2012-10-08 17:37:29,110 INFO .DemandForwardingBridgeSupport - Network
> connection between vm://c04ptec#594 and
> tcp:///127.0.0.1:56656(cbox-56BU902442) has been established.
> [StartLocalBridge: localBroker=vm://c04ptec#594]
> ...
> 2012-10-08 17:37:59,669 WARN .DemandForwardingBridgeSupport - Network
> connection between vm://c04ptec#594 and
> tcp:///127.0.0.1:56656(cbox-56BU902442) was interrupted during establishment.
> [StartLocalBridge: localBroker=vm://c04ptec#594]
> ...
> 2012-10-08 17:38:09,005 INFO .DemandForwardingBridgeSupport - c04ptec bridge
> to cbox-56BU902442 stopped [ActiveMQ Task-228]
> ...
> 2012-10-08 17:38:18,681 INFO emq.broker.TransportConnection - Started
> responder end of duplex bridge cBox 56BU902442 to cBox
> Proxy@ID:P013SPWMK1WN-39320-1349704902319-0:1 [ActiveMQ NIO Worker 292]
> 2012-10-08 17:38:18,681 WARN emq.broker.TransportConnection - Failed to add
> Connection ID:P013SPWMK1WN-39320-1349704902319-152:1, reason:
> javax.jms.InvalidClientIDException: Broker: c04ptec - Client: cBox 56BU902442
> to cBox Proxy_cbox-56BU902442_outbound already connected from
> vm://c04ptec#594 [ActiveMQ NIO Worker 292]
> 2012-10-08 17:38:18,682 WARN er.TransportConnection.Service - Async error
> occurred: javax.jms.InvalidClientIDException: Broker: c04ptec - Client: cBox
> 56BU902442 to cBox Proxy_cbox-56BU902442_outbound already connected from
> vm://c04ptec#594 [ActiveMQ NIO Worker 292]
> javax.jms.InvalidClientIDException: Broker: c04ptec - Client: cBox 56BU902442
> to cBox Proxy_cbox-56BU902442_outbound already connected from vm://c04ptec#594
> at
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:222)
> ~[activemq-core-5.7-SNAPSHOT.jar:5.7-SNAPSHOT]
> {code}
> This repeats until the external broker is stopped and started manually.
> I assume there is a race condition which shows up under high load
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
