[
https://issues.apache.org/jira/browse/CASSANDRA-14424?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jason Harvey updated CASSANDRA-14424:
-------------------------------------
Description:
Noticing this behaviour on a brand new 3.11.2 ring:
# Restart a random node in the ring.
# 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.
# 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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-01a9db9f868b4130d.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-01a9db9f868b4130d.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-01a9db9f868b4130d.reddit.ue1.snooguts.net/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, 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 40% of the time a given node in the ring is restarted.
was:
Noticing this behaviour on a brand new 3.11.2 ring:
# Restart a random node in the ring.
# 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.
# 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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-01a9db9f868b4130d.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-01a9db9f868b4130d.reddit.ue1.snooguts.net/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 -
cass-r2-bravo-01a9db9f868b4130d.reddit.ue1.snooguts.net/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, 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 40% of the time a given node in the ring is restarted.
> Gossip EchoMessages not being handled somewhere after node restart
> ------------------------------------------------------------------
>
> Key: CASSANDRA-14424
> URL: https://issues.apache.org/jira/browse/CASSANDRA-14424
> Project: Cassandra
> Issue Type: Bug
> Environment: cassandra 3.11.2 - brand new ring.
> ubuntu 16.04
> AWS
> Reporter: Jason Harvey
> Priority: Major
>
> Noticing this behaviour on a brand new 3.11.2 ring:
> # Restart a random node in the ring.
> # 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.
> # 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 -
> cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
> cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
> cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
> cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
> cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
> cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
> cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
> cass-r2-bravo-0d090fef242998a23.reddit.ue1.snooguts.net/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 -
> cass-r2-bravo-01a9db9f868b4130d.reddit.ue1.snooguts.net/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 -
> cass-r2-bravo-01a9db9f868b4130d.reddit.ue1.snooguts.net/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 -
> cass-r2-bravo-01a9db9f868b4130d.reddit.ue1.snooguts.net/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, 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 40% of the time a given node in the ring is
> restarted.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
