erikgrinaker
commented
1 year ago Something's pretty messed up here. Looks like we're losing r1 meta availability somehow. n1 rebalances away its r1 replica at 11:53:20:
I230704 11:53:20.598003 49673 13@kv/kvserver/allocator/plan/replicate.go:900 ⋮ [T1,n1,replicate,s1,r1/1:‹/{Min-System/NodeL…}›] 4044 rebalancing ‹voter› n1,s1 to n6,s6: ‹[1*:14752, 6:14750, 3:14750, 4:14750, 5:14742]›
I230704 11:53:20.598819 49673 13@kv/kvserver/replica_command.go:2352 ⋮ [T1,n1,replicate,s1,r1/1:‹/{Min-System/NodeL…}›] 4045 change replicas (add [(n6,s6):7LEARNER] remove []): existing descriptor r1:‹/{Min-System/NodeLiveness}› [(n1,s1):1, (n7,s7):6, (n4,s4):3, (n9,s9):4, (n8,s8):5, next=7, gen=12]
I230704 11:53:20.607565 49673 13@kv/kvserver/replica_raft.go:396 ⋮ [T1,n1,s1,r1/1:‹/{Min-System/NodeL…}›] 4046 proposing SIMPLE(l7) [(n6,s6):7LEARNER]: after=[(n1,s1):1 (n7,s7):6 (n4,s4):3 (n9,s9):4 (n8,s8):5 (n6,s6):7LEARNER] next=8
I230704 11:53:20.688360 49700 13@kv/kvserver/store_snapshot.go:1596 ⋮ [T1,n1,s1,r1/1:‹/{Min-System/NodeL…}›] 4047 streamed INITIAL snapshot e9d45910 at applied index 14759 to (n6,s6):7LEARNER with 1.1 MiB in 0.04s @ 31 MiB/s: kvs=9203 rangeKVs=0, rate-limit: 32 MiB/s, queued: 0.04s
I230704 11:53:20.709957 49673 13@kv/kvserver/replica_command.go:2352 ⋮ [T1,n1,replicate,s1,r1/1:‹/{Min-System/NodeL…}›] 4048 change replicas (add [(n6,s6):7VOTER_INCOMING] remove [(n1,s1):1VOTER_DEMOTING_LEARNER]): existing descriptor r1:‹/{Min-System/NodeLiveness}› [(n1,s1):1, (n7,s7):6, (n4,s4):3, (n9,s9):4, (n8,s8):5, (n6,s6):7LEARNER, next=8, gen=13]
I230704 11:53:20.714175 49673 13@kv/kvserver/replica_raft.go:396 ⋮ [T1,n1,s1,r1/1:‹/{Min-System/NodeL…}›] 4049 proposing ENTER_JOINT(r1 l1 v7) [(n6,s6):7VOTER_INCOMING], [(n1,s1):1VOTER_DEMOTING_LEARNER]: after=[(n1,s1):1VOTER_DEMOTING_LEARNER (n7,s7):6 (n4,s4):3 (n9,s9):4 (n8,s8):5 (n6,s6):7VOTER_INCOMING] next=8
I230704 11:53:20.735057 49673 13@kv/kvserver/replica_command.go:2352 ⋮ [T1,n1,replicate,s1,r1/1:‹/{Min-System/NodeL…}›] 4050 change replicas (add [] remove []): existing descriptor r1:‹/{Min-System/NodeLiveness}› [(n1,s1):1VOTER_DEMOTING_LEARNER, (n7,s7):6, (n4,s4):3, (n9,s9):4, (n8,s8):5, (n6,s6):7VOTER_INCOMING, next=8, gen=14]
I230704 11:53:20.755340 49673 13@kv/kvserver/replica_command.go:2352 ⋮ [T1,n1,replicate,s1,r1/1:‹/{Min-System/NodeL…}›] 4051 change replicas (add [] remove [(n1,s1):1LEARNER]): existing descriptor r1:‹/{Min-System/NodeLiveness}› [(n1,s1):1LEARNER, (n7,s7):6, (n4,s4):3, (n9,s9):4, (n8,s8):5, (n6,s6):7, next=8, gen=15]
I230704 11:53:20.776110 185 kv/kvserver/store_remove_replica.go:151 ⋮ [T1,n1,s1,r1/1:‹/{Min-System/NodeL…}›,raft] 579 removing replica r1/1Then about a minute later we start seeing the first signs of r1 unavailability:
W230704 11:54:10.395697 39032 kv/kvclient/kvcoord/dist_sender.go:1808 ⋮ [T1,n1,replicaGC,s1,r393/1:‹/Table/106/1/5{88784…-92470…}›] 767 slow range RPC: have been waiting 60.00s (1 attempts) for RPC Scan [/Meta2/Table/106/1/‹5887846884665536192›/‹NULL›,/System‹/›‹"›‹"›) to r1:‹/{Min-System/NodeLiveness}› [(n1,s1):1, (n7,s7):6, (n4,s4):3, (n9,s9):4, (n8,s8):5, next=7, gen=12]; resp: ‹(err: context deadline exceeded)›Notice that this is not 60 seconds after the replica was removed at 11:53:20, the request began around 11:53:10. The only suspect log entry we see at that time is this one:
W230704 11:53:09.815397 38115 kv/kvserver/intentresolver/intent_resolver.go:502 ⋮ [-] 506 failed to push during intent resolution: {<nil> 0 {‹0xc007ae1748›} ‹index:0 › 1688471589.815357569,0}We keep seeing signs of r1 unavailability throughout the cluster until the test times out an hour later. However, r1 is alive and well with leader/leaseholder on n6:
"raft_state": {
"replica_id": 7,
"hard_state": {
"term": 7,
"vote": 7,
"commit": 17837
},
"lead": 7,
"state": "StateLeader",
"applied": 17837,
"progress": {
"3": {
"match": 17837,
"next": 17838,
"state": "StateReplicate"
},
"4": {
"match": 17837,
"next": 17838,
"state": "StateReplicate"
},
"5": {
"match": 17837,
"next": 17838,
"state": "StateReplicate"
},
"6": {
"match": 17837,
"next": 17838,
"state": "StateReplicate"
},
"7": {
"match": 17837,
"next": 17838,
"state": "StateReplicate"
}
}
},
"state": {
"raft_applied_index": 17837,
"lease_applied_index": 16610,
"desc": {
"range_id": 1,
"end_key": "BABsaXZlbmVzcy0=",
"internal_replicas": [
{
"node_id": 6,
"store_id": 6,
"replica_id": 7,
"type": 0
},
{
"node_id": 7,
"store_id": 7,
"replica_id": 6,
"type": 0
},
{
"node_id": 4,
"store_id": 4,
"replica_id": 3,
"type": 0
},
{
"node_id": 9,
"store_id": 9,
"replica_id": 4,
"type": 0
},
{
"node_id": 8,
"store_id": 8,
"replica_id": 5,
"type": 0
}
],
"next_replica_id": 8,
"generation": 16,
"sticky_bit": {}
},
"lease": {
"start": {
"wall_time": 1688471600725422293
},
"expiration": {
"wall_time": 1688475527720524070
},
"replica": {
"node_id": 6,
"store_id": 6,
"replica_id": 7,
"type": 0
},
"deprecated_start_stasis": {
"wall_time": 1688475527720524070
},
"proposed_ts": {
"wall_time": 1688475521720524070
},
"sequence": 2,
"acquisition_type": 2
},We must somehow have stopped gossiping r1 or something. However, we see fresh gossip info for r1 pointing to n6, here from n1:
"first-range": {
"value": {
"raw_bytes": "7ujJvAMIARIAGgsEAGxpdmVuZXNzLSIICAYQBhgHIAAiCAgHEAcYBiAAIggIBBAEGAMgACIICAkQCRgEIAAiCAgIEAgYBSAAKAgwEDoA",
"timestamp": {
"wall_time": 1688475521220175881
}
},
"orig_stamp": 1688475521220177273,
"ttl_stamp": 9223372036854775807,
"hops": 2,
"node_id": 6,
"peer_id": 3
}, 
blathers-crl[bot]
tbg
cockroach-teamcity
roachtest.failover/chaos/read-only failed with artifacts on master @ 428dc9da6a320de218460de6c6c8807caa4ded98:
Parameters:
ROACHTEST_arch=amd64,ROACHTEST_cloud=gce,ROACHTEST_cpu=2,ROACHTEST_encrypted=false,ROACHTEST_fs=ext4,ROACHTEST_localSSD=false,ROACHTEST_ssd=0Help
See: [roachtest README](https://github.com/cockroachdb/cockroach/blob/master/pkg/cmd/roachtest/README.md) See: [How To Investigate \(internal\)](https://cockroachlabs.atlassian.net/l/c/SSSBr8c7)
/cc @cockroachdb/kv-triage
This test on roachdash | Improve this report!
Jira issue: CRDB-29407