[AMQ-5819] Failover Transport - Sleep for Reconnect Delay happens twice per iteration

• Type: Bug
• Status: Resolved
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 5.10.0, 5.10.1, 5.10.2, 5.11.0, 5.11.1
• Fix Version/s: 5.13.3, 5.14.0
• Component/s: JMS client
• Assignee: Timothy A. Bish
• Reporter: Eric Wyles
• Created: 02/Jun/15 15:52
• Updated: 15/Apr/16 16:51
• Resolved: 15/Apr/16 16:51

Description

When the failover transport is attempting to reconnect, it appears to sleep two different times, resulting in more than the expected reconnect delay.

To reproduce:

• start a jms client with brokerUrl: failover:(tcp://hostname:61616)?randomize=false&warnAfterReconnectAttempts=1
• turn on debug logging for logger 'org.apache.activemq.transport.failover.FailoverTransport'
• Once the application has connected, stop the broker on hostname

While the broker is down, observe the logs from org.apache.activemq.transport.failover.FailoverTransport, and you will see the following pattern for each iteration:

=====================
WARN - Failed to connect to [tcp://hostname:61616] after: n attempt(s) continuing to retry.
DEBUG - Waiting <reconnectDelay> ms before attempting connection
– sleep happens here
DEBUG - urlList connectionList:[tcp://hostname:61616], from: [tcp://hostname:61616]
DEBUG - Waiting <reconnectDelay> ms before attempting connection
— sleep happens here
DEBUG - Attempting nth connect to: tcp://hostname:61616
DEBUG - Connect fail to: tcp://hostname:61616, reason: java.net.ConnectException: Connection refused: connect
=====================

The above sequence is repeated for as long as the broker is down, with the exponent applied to the reconnectDelay in between the above two instances of sleep. In the configuration above, once the maxReconnectDelay is reached (30 seconds) it is actually 1 minute between attempts to reconnect to the broker. Log output with timestamps is shown below, and you can see that it is 1 minute between attempting the 13th connection and attempting to 14th connection, even though maxReconnectDelay is 30 seconds:

log4j.appender.CONSOLE.layout.ConversionPattern=%d [%C:%-4L] %-5p - %m%n
=====================
2015-06-02 10:39:19,824 [org.apache.activemq.transport.failover.FailoverTransport:1024] DEBUG - Attempting 13th connect to: tcp://hostname:61616
2015-06-02 10:39:20,860 [org.apache.activemq.transport.failover.FailoverTransport:1075] DEBUG - Connect fail to: tcp://hostname:61616, reason: java.net.ConnectException: Connection refused: connect
2015-06-02 10:39:20,860 [org.apache.activemq.transport.failover.FailoverTransport:1119] WARN - Failed to connect to [tcp://hostname:61616] after: 14 attempt(s) continuing to retry.
2015-06-02 10:39:20,860 [org.apache.activemq.transport.failover.FailoverTransport:1135] DEBUG - Waiting 30000 ms before attempting connection
2015-06-02 10:39:50,868 [org.apache.activemq.transport.failover.FailoverTransport:814 ] DEBUG - urlList connectionList:[tcp://hostname:61616], from: [tcp://hostname:61616]
2015-06-02 10:39:50,868 [org.apache.activemq.transport.failover.FailoverTransport:1000] DEBUG - Waiting 30000 ms before attempting connection.
2015-06-02 10:40:20,870 [org.apache.activemq.transport.failover.FailoverTransport:1024] DEBUG - Attempting 14th connect to: tcp://hostname:61616
=====================