kvserver: unxpected replication change from 3 to 2 voters

[tbg]

Describe the problem

When @aliher1911 and I looked into unhappy restore2TB runs in the context of #61396, we noticed unexpected replication changes. From a three-voter configuration, for some reason we're demoting a voter:

[n7,s7,r39158/4:x] change replicas (add ‹[]› remove ‹[(n5,s5):1VOTER_DEMOTING_LEARNER]›): existing descriptor r39158:‹/Table/54/1/52061454{-/0}› [(n5,s5):1, (n7,s7):4, (n10,s10):3, next=5, gen=744, sticky=1617706884.328040814,0]

At that point, in the full snippet, the range goes unavailable because one of the two remaining voters (s10) is waiting for a snapshot.

To Reproduce

Run the restore2TB/nodes=10 roachtest.

This should reproduce on any SHA preceding #64060, such as
d85d49d, when running restore2TB.
It may not always happen but we saw it frequently, at least in
"unhappy" runs (as characterized by large pending snapshot counts).

Expected behavior

With 10 live nodes and atomic replication changes, there should never be a
reason to move from a three-voter to a two-voter configuration.o The only
explanation I have is that n5 might have been considered dead for 5 minutes
which would possibly trigger this issue (?!) but this is esssentially ruled out
by the full snippet, which indicates that n5 was live a minute after the
botched replication change (and it is thus unlikely to have been non-live for
the preceding minutes).

@aliher1911 if you have full logs from any of these experiments, mind going
through them to see if you have other examples of such replication changes,
and if so, posting the complete log directory (Google Drive).

Additional data / screenshots

Environment:

Additional context
Add any other context about the problem here.

cc @cockroachdb/kv

[aliher1911]

I have full logs from that run still and I'll check if other runs have it just in case. Will upload later.

[tbg]

Another instance observed by David in https://cockroachlabs.slack.com/archives/C0KB9Q03D/p1619132965163200?thread_ts=1619132965.163200&cid=C0KB9Q03D

[aayushshah15]

I could reproduce this scenario pretty readily with a log.Fatal inside changeReplicasImpl when it was about to execute such a change. @dt also noticed this today and, on his cluster, the range log for the unfortunate range looked like the following (notice the 4th item from the top):

It seemed to indicate that the caller of ChangeReplicas (whoever it was) was explicitly asking it to remove just that voter. The Reason: admin request part is also important because it tells us that it cannot be the allocator somehow making an incorrect decision, as the allocator would indicate something like range over-replicated as the Reason.

This pointed fingers at the callers of AdminRelocateRange (or a bug inside AdminRelocateRange itself, but I ruled this out). Sure enough, it turns out it's the store rebalancer calling AdminRelocateRange with slices that contain duplicate targets:

rebalancing r44266 (0.09 qps) from (n9,s9):1,(n5,s5):2,(n4,s4):3 to ‹[n10,s10 n8,s8 n8,s8]› to better balance load

I see what the bug is, it was introduced in #61600. I'm misusing a slice (:sweat:). I'll get a fix out for it asap.

Tobi, do you think we should mark this a release blocker until then?

---

Another unfortunate (but not "new") thing is that because of this check, the store rebalancer seems to let itself relocate replicas with very low QPS (notice the QPS in my example^). This doesn't seem "bad" per se, because presumably the replicate queue would eventually do the same thing, but feels to me like the store rebalancer should not be concerning itself with such a thing.

[aliher1911]

Logs from the run where we observed this behaviour: drive link
@tbg @aayushshah15

[tbg]

Very nice, @aayushshah15! I'll mark this as a GA-blocker. It could well be a release blocker too - someone using a beta to test resilience might get miffed - but I think that is less than likely and if so should be easy to pin down if they contact us.