[jira] [Comment Edited] (CASSANDRA-14155) [TRUNK] Gossiper somewhat frequently hitting an NPE on node startup with dtests at org.apache.cassandra.gms.Gossiper.isSafeForStartup(Gossiper.java:769)

2018-12-21 Thread Ariel Weisberg (JIRA)


[ 
https://issues.apache.org/jira/browse/CASSANDRA-14155?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16726920#comment-16726920
 ] 

Ariel Weisberg edited comment on CASSANDRA-14155 at 12/21/18 5:22 PM:
--

Got the endpoint state map + some additional logging during the shadow round.

Container 5 , rolling upgrade ssl test 
https://circleci.com/gh/aweisberg/cassandra/2329#artifacts/containers/99
https://2329-26126838-gh.circle-artifacts.com/5/dtest_upgrade_no_vnodes_logs/1545411075201_test_rolling_upgrade_with_internode_ssl/node1_debug.log
{noformat}
java.lang.AssertionError: previous (Gossip ApplicationState.HOST_ID for this 
node) is null: Messages = Starting shadow gossip round to check for endpoint 
collision at 127.0.0.2:7000
Sending shadow round GOSSIP DIGEST SYN to seeds [127.0.0.1:7000, 127.0.0.3:7000]
Received a regular ack from 127.0.0.1:7000, can now exit shadow round, epStates 
= {127.0.0.2:7000=EndpointState: HeartBeatState = HeartBeat: generation = 
154535, version = 2147483647, AppStateMap = {}, 
127.0.0.1:7000=EndpointState: HeartBeatState = HeartBeat: generation = 
1545333481, version = 123, AppStateMap = {}}
at org.apache.cassandra.gms.Gossiper.isSafeForStartup(Gossiper.java:834)
at 
org.apache.cassandra.service.StorageService.checkForEndpointCollision(StorageService.java:556)
at 
org.apache.cassandra.service.StorageService.prepareToJoin(StorageService.java:835)
at 
org.apache.cassandra.service.StorageService.initServer(StorageService.java:693)
at 
org.apache.cassandra.service.StorageService.initServer(StorageService.java:644)
at 
org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:369)
at 
org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:581)
at 
org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:670)
{noformat}

https://2329-26126838-gh.circle-artifacts.com/5/dtest_upgrade_no_vnodes_logs/1545411075201_test_rolling_upgrade_with_internode_ssl/node2_debug.log
{noformat}
java.lang.AssertionError: previous (Gossip ApplicationState.HOST_ID for this 
node) is null: Messages = Starting shadow gossip round to check for endpoint 
collision at 127.0.0.2:7000
Sending shadow round GOSSIP DIGEST SYN to seeds [127.0.0.1:7000, 127.0.0.3:7000]
Received a regular ack from 127.0.0.1:7000, can now exit shadow round, 
epStateMap {127.0.0.3:7000=EndpointState: HeartBeatState = HeartBeat: 
generation = 1545410617, version = 240, AppStateMap = {}, 
127.0.0.2:7000=EndpointState: HeartBeatState = HeartBeat: generation = 
1545410603, version = 2147483647, AppStateMap = {}, 
127.0.0.1:7000=EndpointState: HeartBeatState = HeartBeat: generation = 
1545410741, version = 123, AppStateMap = {}}, epStates = 
{127.0.0.3:7000=EndpointState: HeartBeatState = HeartBeat: generation = 
1545410617, version = 240, AppStateMap = {}, 127.0.0.2:7000=EndpointState: 
HeartBeatState = HeartBeat: generation = 1545410603, version = 2147483647, 
AppStateMap = {}, 127.0.0.1:7000=EndpointState: HeartBeatState = HeartBeat: 
generation = 1545410741, version = 123, AppStateMap = {}}
at org.apache.cassandra.gms.Gossiper.isSafeForStartup(Gossiper.java:834)
at 
org.apache.cassandra.service.StorageService.checkForEndpointCollision(StorageService.java:556)
at 
org.apache.cassandra.service.StorageService.prepareToJoin(StorageService.java:835)
at 
org.apache.cassandra.service.StorageService.initServer(StorageService.java:693)
at 
org.apache.cassandra.service.StorageService.initServer(StorageService.java:644)
at 
org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:369)
at 
org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:581)
at 
org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:670)
{noformat}


was (Author: aweisberg):
Got the endpoint state map + some additional logging during the shadow round.

{noformat}
java.lang.AssertionError: previous (Gossip ApplicationState.HOST_ID for this 
node) is null: Messages = Starting shadow gossip round to check for endpoint 
collision at 127.0.0.2:7000
Sending shadow round GOSSIP DIGEST SYN to seeds [127.0.0.1:7000, 127.0.0.3:7000]
Received a regular ack from 127.0.0.1:7000, can now exit shadow round, epStates 
= {127.0.0.2:7000=EndpointState: HeartBeatState = HeartBeat: generation = 
154535, version = 2147483647, AppStateMap = {}, 
127.0.0.1:7000=EndpointState: HeartBeatState = HeartBeat: generation = 
1545333481, version = 123, AppStateMap = {}}
at org.apache.cassandra.gms.Gossiper.isSafeForStartup(Gossiper.java:834)
at 
org.apache.cassandra.service.StorageService.checkForEndpointCollision(StorageService.java:556)
at 
org.apache.cassandra.service.StorageService.prepareToJoin(StorageService.java:835)
a

[jira] [Comment Edited] (CASSANDRA-14155) [TRUNK] Gossiper somewhat frequently hitting an NPE on node startup with dtests at org.apache.cassandra.gms.Gossiper.isSafeForStartup(Gossiper.java:769)

2018-01-25 Thread Jason Brown (JIRA)

[ 
https://issues.apache.org/jira/browse/CASSANDRA-14155?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16340340#comment-16340340
 ] 

Jason Brown edited comment on CASSANDRA-14155 at 1/26/18 12:19 AM:
---

*WHAT IS HAPPENING?*
 So, the obvious is that we aren't finding the {{HOST_ID}} in the endpoint's 
state, but where is that data coming from? With CASSANDRA-10134 (in c* 3.6), we 
began [performing a shadow round of 
gossip|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/service/StorageService.java#L507]
 on every bounce of a node. The shadow round data comes from any peer in the 
node's seed list. To hit the NPE state, the shadow round data provided by the 
seed must contain an entry in the Map for the node's {{InetAddress}}, but must 
not contain the {{HOST_ID}}, and as I suspeect, no A\{{pplicationStates}}; see 
next section.

(Note that CASSANDRA-12653, committed to 3.11, moved the collected shadow round 
state from {{Gossiper#endpointStateMap}} to 
{{Gossiper#endpointShadowStateMap}}. However, I do not believe that will affect 
the observed behavior here).

*HOW ARE WE GETTING INTO THIS STATE?*
 Barring some kind of Byzantine failure, my best guess is this: assume three 
nodes, A-B-C, and C is the node that hits the NPE. C contacts it's seed nodes 
(in this example, at a minimum B), and the response from B is the first one 
processed. Given the explaination above of how C processes B's shadow round 
data, I think B itself has just left it's own shadow round (by getting a 
response back to it's own shadow round, which assumably comes from A in this 
exmaple).

Then, on B:
 - in {{StorageService#prepareToJoin()}}, we 
[{{loadRingState()}}|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/service/StorageService.java#L788].
 This will insert into C's {{Gossiper#endpointStateMap}} all of the peers (via 
{{InetAddress}}) that we knew about before the bounce. NOTE: we do not add in 
any previously known {{ApplicationState}}s. Thus, {{Gossiper#endpointStateMap}} 
contains {{InetAddress}} es which point to 'empty' {{EndpointState}} s (no 
populated {{ApplicationState}} s).
 - We then start the 
[{{Gossiper}}|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/service/StorageService.java#L792],
 after which we will start processing any incoming gossip message.
 - If the first incoming gossip message is a SYN from C, we will happily send 
back everything we know about the cluster. In the case of B, which has just 
bounced, it basically only knows the {{InetAddress}} es, of peers - no 
{{ApplicationStates}}

Then, C gets back the (more or less) empty gossip data from B, and because it 
["sees" it's own address in that 
shadowRoundData|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/gms/Gossiper.java#L766],
 it assumes it should also see metadata ({{ApplicationState}} s) about it 
itself. That's when it looks up the {{HOST_ID}}, and [naively tries to 
dereference 
it|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/gms/Gossiper.java#L788]
 - causing the NPE in this case.

*SOLUTION:*
 I don't think we can change the distributed race on restart necessarily 
without larger structural changes, but we can change how a node determines if 
it can exit the shadow round. As we're basically only checking for a previous 
{{HOST_ID}} for the current node in the shadow round data, I propose we add a 
check to {{Gossiper@maybeFinishShadowRound()}} that, in addtion to the existing 
checks, loks if the data contains the {{HOST_ID}} for the current node. If so, 
exit the shadow round as usual; else, keep waiting for a more complete set of 
gossip data.
||14155||
|[branch|https://github.com/jasobrown/cassandra/tree/14155]|
|[utests & 
dtests|https://circleci.com/gh/jasobrown/workflows/cassandra/tree/14155]|

For convenience, here's comparison against trunk (obviosuly, ignore the 
circleci yaml): [compare against 
trunk|https://github.com/apache/cassandra/compare/trunk...jasobrown:14155]

NOTE: this patch is against trunk, but I think we'll also need it for 3.11


was (Author: jasobrown):
*WHAT IS HAPPENING?*
 So, the obvious is that we aren't finding the {{HOST_ID}} in the endpoint's 
state, but where is that data coming from? With CASSANDRA-10134 (in c* 3.6), we 
began [performing a shadow round of 
gossip|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/service/StorageService.java#L507]
 on every bounce of a node. The shadow round data comes from any peer in the 
node's seed list. To hit the NPE state, the shadow round data provided by the 
seed must contain an entry in the Map for the node's {{InetAddress}}, but must 
not contain the {{HOST_ID}}, and as I suspeect, no A{{pplicationStates}}; see 
next section.

(Note that CASSANDRA-12653, committed to 3.11