Gossip EchoMessages not being handled somewhere after node restart

Noticing this behaviour on a brand new 3.11.2 ring:

1. Restart a random node in the ring.
2. When that node comes back up, around 30% of the time it sees a single other node down. No other node in the ring sees that node is down.
3. After 10-20 minutes, the DOWN node suddenly appears UP to the restarted node.

 

After digging through tracing logs, here's what I know:

 

The node seen as DOWN has not gone down, but simply hasn't been seen as UP yet. The restarted node is attempting to `markAlive()` the target node. Relevant logs from the restarted node's POV:

 

INFO [GossipStage:1] 2018-04-27 14:03:50,950 Gossiper.java:1053 - Node /10.0.225.147 has restarted, now UP
INFO [GossipStage:1] 2018-04-27 14:03:50,969 StorageService.java:2292 - Node /10.0.225.147 state jump to NORMAL
INFO [HANDSHAKE-/10.0.225.147] 2018-04-27 14:03:50,976 OutboundTcpConnection.java:560 - Handshaking version with /10.0.225.147
INFO [GossipStage:1] 2018-04-27 14:03:50,977 TokenMetadata.java:479 - Updating topology for /10.0.225.147
INFO [GossipStage:1] 2018-04-27 14:03:50,977 TokenMetadata.java:479 - Updating topology for /10.0.225.147

 

(note that despite the Gossip seeing the DOWN node as 'UP', nodetool status still shows it as 'DOWN', as markAlive has not completed, and will not actually be seen as 'UP' for 20 more minutes)

 

The restarted node is repeatedly sending Echo messages to the DOWN node as part of the `markAlive()` call. The DOWN node is receiving those, and claims to be sending a response. However, the restarted node is not marking the DOWN node as UP even after the DOWN node sends the Echo response.

 

Relevant logs from the restarted node's POV:

 

TRACE [GossipStage:1] 2018-04-27 14:11:28,792 MessagingService.java:945 - 10.0.103.45 sending ECHO to 99248@/10.0.225.147
TRACE [GossipTasks:1] 2018-04-27 14:11:29,792 MessagingService.java:945 - 10.0.103.45 sending GOSSIP_DIGEST_SYN to 99631@/10.0.225.147
TRACE [GossipStage:1] 2018-04-27 14:11:29,792 MessagingService.java:945 - 10.0.103.45 sending ECHO to 99632@/10.0.225.147
TRACE [GossipStage:1] 2018-04-27 14:11:29,793 MessagingService.java:945 - 10.0.103.45 sending GOSSIP_DIGEST_ACK2 to 99633@/10.0.225.147
TRACE [GossipStage:1] 2018-04-27 14:11:29,793 MessagingService.java:945 - 10.0.103.45 sending ECHO to 99635@/10.0.225.147
TRACE [GossipStage:1] 2018-04-27 14:11:31,794 MessagingService.java:945 - 10.0.103.45 sending ECHO to 100348@/10.0.225.147
TRACE [GossipStage:1] 2018-04-27 14:11:33,750 MessagingService.java:945 - 10.0.103.45 sending ECHO to 101157@/10.0.225.147
TRACE [GossipStage:1] 2018-04-27 14:11:35,412 MessagingService.java:945 - 10.0.103.45 sending ECHO to 101753@/10.0.225.147

 

 

Relevant logs from the DOWN node's POV:

 

TRACE [GossipStage:1] 2018-04-27 14:18:16,500 EchoVerbHandler.java:39 - Sending a EchoMessage reply /10.0.103.45
TRACE [GossipStage:1] 2018-04-27 14:18:16,500 MessagingService.java:945 - 10.0.225.147 sending REQUEST_RESPONSE to 328389@/10.0.103.45
TRACE [GossipStage:1] 2018-04-27 14:18:17,679 EchoVerbHandler.java:39 - Sending a EchoMessage reply /10.0.103.45
TRACE [GossipStage:1] 2018-04-27 14:18:17,679 MessagingService.java:945 - 10.0.225.147 sending REQUEST_RESPONSE to 329412@/10.0.103.45
TRACE [GossipStage:1] 2018-04-27 14:18:18,680 EchoVerbHandler.java:39 - Sending a EchoMessage reply /10.0.103.45
TRACE [GossipStage:1] 2018-04-27 14:18:18,680 MessagingService.java:945 - 10.0.225.147 sending REQUEST_RESPONSE to 330185@/10.0.103.45

 

 

The metrics on the restarted node show that the MessagingService has a large number of TimeoutsPerHost for the DOWN node, and all other nodes have 0 timeouts.

 

 

Eventually, `realMarkAlive()` is called and the restarted node finally sees DOWN node as coming up, and it spams several UP messages when this happens:

 

 

INFO [RequestResponseStage-7] 2018-04-27 14:19:27,210 Gossiper.java:1019 - InetAddress /10.0.225.147 is now UP
INFO [RequestResponseStage-11] 2018-04-27 14:19:27,210 Gossiper.java:1019 - InetAddress /10.0.225.147 is now UP
INFO [RequestResponseStage-11] 2018-04-27 14:19:27,210 Gossiper.java:1019 - InetAddress /10.0.225.147 is now UP
INFO [RequestResponseStage-11] 2018-04-27 14:19:27,210 Gossiper.java:1019 - InetAddress /10.0.225.147 is now UP
INFO [RequestResponseStage-11] 2018-04-27 14:19:27,210 Gossiper.java:1019 - InetAddress /10.0.225.147 is now UP
INFO [RequestResponseStage-11] 2018-04-27 14:19:27,210 Gossiper.java:1019 - InetAddress /10.0.225.147 is now UP
INFO [RequestResponseStage-12] 2018-04-27 14:19:27,210 Gossiper.java:1019 - InetAddress /10.0.225.147 is now UP
INFO [RequestResponseStage-11] 2018-04-27 14:19:27,210 Gossiper.java:1019 - InetAddress /10.0.225.147 is now UP
INFO [RequestResponseStage-12] 2018-04-27 14:19:27,211 Gossiper.java:1019 - InetAddress /10.0.225.147 is now UP

 

 

 

A tcpdump shows no packet loss or other oddities between these two hosts. The restarted node is sending Echo messages, and the DOWN node is ACKing them.

 

The fact that a burst comes through at the very end suggests to me that perhaps the Echo messages are getting queued up somewhere.

 

The issue happens roughly 30% of the time a given node in the ring is restarted.