kv/kvserver: TestAdminRelocateRange failed

[cockroach-teamcity]

kv/kvserver.TestAdminRelocateRange failed with artifacts on master @ 571bfa3afb3858ae84d8a8fcdbb0a38e058402a5:

=== RUN   TestAdminRelocateRange
    test_log_scope.go:79: test logs captured to: /artifacts/tmp/_tmp/751d67000aac5f3394c2369309253f02/logTestAdminRelocateRange2871936122
    test_log_scope.go:80: use -show-logs to present logs inline
    client_relocate_range_test.go:238: 
        	Error Trace:	client_relocate_range_test.go:189
        	            				client_relocate_range_test.go:238
        	Error:      	Not equal: 
        	            	expected: 3
        	            	actual  : 2
        	Test:       	TestAdminRelocateRange
        	Messages:   	wrong number of atomic changes
    client_relocate_range_test.go:238: all changes:
    client_relocate_range_test.go:238: 1: [{ADD_VOTER n4,s4} {REMOVE_VOTER n1,s1}]
    client_relocate_range_test.go:238: 2: [{ADD_VOTER n6,s6} {REMOVE_VOTER n3,s3}]
    panic.go:661: -- test log scope end --
--- FAIL: TestAdminRelocateRange (1.93s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/kv

This test on roachdash | Improve this report!

Jira issue: CRDB-17542

[adityamaru]

Saw this flake again - https://teamcity.cockroachdb.com/viewLog.html?buildId=6010818&tab=buildResultsDiv&buildTypeId=Cockroach_UnitTests_BazelUnitTests

[cockroach-teamcity]

kv/kvserver.TestAdminRelocateRange failed with artifacts on master @ 158ebe679bee1386df875ef8a175963bc6ac0cd1:

=== RUN   TestAdminRelocateRange
    test_log_scope.go:162: test logs captured to: /artifacts/tmp/_tmp/751d67000aac5f3394c2369309253f02/logTestAdminRelocateRange1850405510
    test_log_scope.go:80: use -show-logs to present logs inline
    client_relocate_range_test.go:238: 
        	Error Trace:	client_relocate_range_test.go:189
        	            				client_relocate_range_test.go:238
        	Error:      	Not equal: 
        	            	expected: 3
        	            	actual  : 2
        	Test:       	TestAdminRelocateRange
        	Messages:   	wrong number of atomic changes
    client_relocate_range_test.go:238: all changes:
    client_relocate_range_test.go:238: 1: [{ADD_VOTER n4,s4} {REMOVE_VOTER n1,s1}]
    client_relocate_range_test.go:238: 2: [{ADD_VOTER n6,s6} {REMOVE_VOTER n3,s3}]
    panic.go:500: -- test log scope end --
--- FAIL: TestAdminRelocateRange (2.21s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

[adityamaru]

This test is fairly flaky even though we've not seen recent pings to this isse - https://teamcity.cockroachdb.com/project.html?projectId=Cockroach_Ci_TestsGcpLinuxX8664BigVm&buildTypeId=&tab=testDetails&testNameId=-5086970665568297757&order=TEST_STATUS_DESC&branch_Cockroach_Ci_TestsGcpLinuxX8664BigVm=__all_branches__&itemsCount=50, we're going to skip this until its stabilized.

[kvoli]

When stressing, after a few hundred runs this test fails.

The end result is correct:

relocate (s1,s2,s3) -> (s4,s5,s6)

However one of the atomic swaps fails

s2 -> sx

due to the incoming voter (s5) being in StateProbe preventing it from receiving the lease, while the demoting learner (s2) is currently the leaseholder:

I220906 21:32:55.924113 13 kv/kvserver_test/client_relocate_range_test.go:59  [-] 359  AdminRelocateRange failed with error: while carrying out changes [{ADD_VOTER n5,s5} {REMOVE_VOTER n2,s2}]: refusing to transfer lease to (n5,s5):5VOTER_INCOMING because target may need a Raft snapshot: replica in StateProbe

This same behavior occurs with s2 being removed as the leaseholder, however with s6 being added instead.

The response to a replicia being in state probe is expected, however why is the replica which swaps with the leaseholder (voter incoming) behind - when it was just streamed a snapshot.

[andrewbaptist]

I don't know enough about the raft state machine, but it's possible that all replicas transition through StateProbe before getting to state StateReplicate. Generally, this should be a "fast" transition, and it likely is in this test also, however, it is possible to catch it between these two states.

Looking at AdminRelocateRange, it ends up calling AdminChangeReplicas which then calls initializeRaftLearners and finally sendSnapshot. This indeed waits until the snapshot has been delivered. What I can't tell is how the transition from StateProbe to StateReplicate happens. My guess is that it waits for a consensus of peers to ack the msg. This seems like it could happen after the snapshot is received...

[nvanbenschoten]

I think @andrewbaptist is on the right track. When a snapshot is completed successfully, CRDB calls etcd/raft's RawNode.ReportSnapshot from Replica.reportSnapshotStatus. This transitions the follower to StateProbe here. As referenced in this comment, etcd/raft will then wait until the MsgAppResp that is sent out by the follower when applying the snapshot is received before transitioning to StateReplicate.

So there does seem to be a race here if the snapshot response races ahead of the MsgAppResp and then the outgoing leaseholder begins to transfer the lease before it has received the MsgAppResp.

I don't understand why etcd/raft was designed this way. Why wait for the MsgAppResp instead of transitioning straight to StateReplicate on RawNode.ReportSnapshot? Is it because ReportSnapshot is only intended to indicate that the snapshot has been sent and not that it has been applied? Is it because snapshots can be ignored if they are redundant or from an old term and the leader wants to use its existing MsgAppResp handling logic to deal with these cases instead of duplicating them? @tbg @bdarnell do you have any recollection of this?

I ask because I wonder whether it would be worth avoiding this race by either synthesizing a MsgAppResp in Replica.reportSnapshotStatus or sending back the corresponding MsgAppResp in the SnapshotResponse so that it can be handed to etcd/raft directly in Replica.reportSnapshotStatus (under raftMu) to avoid the race. We do wait for snapshot application before calling ReportSnapshot on the leader, so both of these options are available to us.

[tbg]

https://github.com/etcd-io/etcd/blob/bb1619f893cccb13acc4fca850f3677735f18b9a/raft/raft.go#L1251-L1262

Why wait for the MsgAppResp instead of transitioning straight to StateReplicate on RawNode.ReportSnapshot

That is a good question. This decision was made very early in the life of raft¹ and I don't see a justification for it. At the time it was likely just as good to do either. Today, at least in CRDB, it seems a lot better to move to replicating state directly, which we already do (thanks to changes we made) on the MsgAppResp path².

Looking at this code I think there's an actual problem that is unrelated to the issue at hand but is worse. What raft really wants when it asks for a snapshot is for a snapshot at a particular index³. We ignore that and send a snapshot at whatever the index is when we call GetSnapshot⁴. However, raft remembers the original index in the peer's progress, and so it has an effect in ReportSnapshot: the leader will consider the peer having caught up to the requested index, where it is actually caught up to some other index.

So if we ended up sending a snapshot that has a lower index than what raft requested, we'd have the leader believe that entries that are not in fact reflected on the followers state actually made it there. You can from that derive scenarios in which raft "commits" an entry that isn't on a quorum. Now without delegated follower snaps, this couldn't happen (applied index doesn't move backwards within an instance of the progress) but could it happen with delegation? The leaseholder is asked for a snapshot at 100, it asks a follower that is behind to send a snapshot and so it does, but maybe it only has applied the log up to index 50 and thus sends a snapshot at 50. To the best of my knowledge, there is no protection here - DelegatedSnapshotRequest does not carry a "min index"[^5]. I think this is a real issue, filed #87581.

I like the first alternative in this issue, which is to fix it at the level of raft. If we end up deciding to do that, we should also move straight to StateReplicate.

However, I think for 22.2 we need a more targeted solution. We could insert a bounded wait for the follower to leave StateProbe as part of the snapshot sending step.

Footnotes

1. https://github.com/etcd-io/etcd/commit/67194c0b2272f7363ff05e7ad66246743e548c46#diff-b9adbc46e4a317ffbb3d11a66c38d6b9af41a09170d77d87efbd96d115da452fR608 ↩

2. https://github.com/etcd-io/etcd/blob/bb1619f893cccb13acc4fca850f3677735f18b9a/raft/raft.go#L1251-L1262 ↩

3. https://github.com/etcd-io/etcd/blob/bb1619f893cccb13acc4fca850f3677735f18b9a/raft/raft.go#L452-L470 ↩

4. https://github.com/cockroachdb/cockroach/blob/3fe8ffc7f854b6ff9689735dbb1e6ba6e661e027/pkg/kv/kvserver/replica_raftstorage.go#L435-L440 ↩

[bdarnell]

My recollection is that the split between ReportSnapshot and MsgAppResp was intended to permit things like delegated snapshots at a different index: raft asks for a snapshot without specifying exactly when, a snapshot is sent, and then the receiving node reports its new state. However, this was incompletely thought out and as @tbg says it got things exactly backwards. We should be getting the matched index from MsgAppResp instead of from when we sent the snapshot (or enforce that the delegated snapshot is not sent at an index that's too low), while it should be fine to optimistically go to StateReplicate (StateReplicate vs StateProbe is just a performance optimization).

[nvanbenschoten]

We could insert a bounded wait for the follower to leave StateProbe as part of the snapshot sending step.

This is interesting, as it hints at an answer to the question of "why do both ReportSnapshot and MsgAppResp transition out of StateSnapshot?" Naively, I would question why we can't get rid of ReportSnapshot, at least for successful snapshots.

Would it be correct to say that the reason we need ReportSnapshot(SnapshotFinish) is because the main raft transport can be lossy, but etcd/raft won't retry a snapshot on its own, so we need some reliable way to indicate that the snapshot attempt is complete?

If so, then maybe the "sending back the corresponding MsgAppResp in the SnapshotResponse so that it can be handed to etcd/raft directly in Replica.reportSnapshotStatus (under raftMu) to avoid the race" alternative is worth exploring further.

This relates to:

However, I think for 22.2 we need a more targeted solution. We could insert a bounded wait for the follower to leave StateProbe as part of the snapshot sending step.

If we had such a delay to allow the MsgAppResp to propagate, would we even want to call ReportSnapshot(SnapshotFinish)? Could we just wait for the follower to leave StateSnapshot?

[tbg]

Would it be correct to say that the reason we need ReportSnapshot(SnapshotFinish) is because the main raft transport can be lossy, but etcd/raft won't retry a snapshot on its own, so we need some reliable way to indicate that the snapshot attempt is complete?

Yes, that's exactly right. In StateSnapshot raft ceases to communicate with the follower at all, so if we mess it up it's deadlock time. (Except of course the way we set up the raft snap queue, it will just send another snapshot down the line and hopefully things will clear up that way since the MsgAppResp won't be lost every time).

I would like to get to the point where ReportSnapshot is just a performance optimization, even on a lossy transport. For example, let raft treat StateSnapshot exactly like StateProbing; the follower is periodically contacted (with an empty MsgApp) and so it will, once it has gotten a snap, either accept or send a rejection hint that sets the leader straight to whatever the actual index is. There would still be marginal value in calling ReportSnapshot to have raft try faster, but we really shouldn't give it an index that we promise is durable on the follower (after all, that sort of thing is better kept inside of raft) but the index would be a hint for the leader on a good log index to probe (assuming it's in advance of what the leader tracks, i.e. ~always). (I have to double check if we're promising durability as is, I think it's interpreted more as a hint, but anyway, this is the way things should work; passing a bogus index shouldn't cause correctness issues).

If so, then maybe the "sending back the corresponding MsgAppResp in the SnapshotResponse so that it can be handed to etcd/raft directly in Replica.reportSnapshotStatus (under raftMu) to avoid the race" alternative is worth exploring further.

That seems like a good short-term solution that walks us towards adding that index to ReportSnapshot that doesn't require raft changes. Unfortunately, it's not obvious that we can pull the MsgAppResp out of raft; we can't call .Ready in the apply snapshot code because that method is not idempotent. We'd have to call ReadyWithoutAdvance but that's not currently exported, so we're looking at a small raft change anyway. And even then, there might be other messages waiting so there is some awkward sifting through data that should better not happen.

I think I still favor making raft transition immediately to StateReplicate (via StateProbe) in (*Progress).BecomeProbe here: https://github.com/etcd-io/etcd/blob/6332731ea7db68fa3a058d45deaedbae371ae3f4/raft/raft.go#L1328-L1330

After we call ReportSnapshot, we are in StateProbe and have a nonzero Match, but we might as well be in StateReplicate, and that would prevent the problem. I think it would also prevent #87553, since the MsgAppResp(rej=true) would be discarded in StateReplicate (or should at least), since raft can tell that it must be a stale message. (I think it could do that in StateProbe too, but still, we need StateReplicate to do the lease transfer).

[tbg]

Most recent comment here: #87581 (comment)

I'm back to being in favor of what Nathan originally suggested, which is transporting the MsgAppResp to the leader so that it can be r.Step'ed into the state machine right after ReportSnapshot. This will move from StateSnapshot to StateProbe to StateReplicate and so we wouldn't see StateProbe in the subsequent step.

[tbg]

re: the flakiness level, yeah it does seem extremely reduced (if not to practically zero). The historical flake reports in the issue above took ~2s to run, meaning they weren't on super overloaded machines. I'm currently stressing this test at an intensity that closely reflects that (~288 runs over 10 minutes) and have yet to see a failure, stressing with higher --cpu until my gceworker ran out of memory also didn't lead to a repro. Still, I'm not going to unskip this until the above failure mode is impossible.

[tbg]

The combination of #106793 and (for a possibly much rarer failure mode) etcd-io/raft#84 should likely fix this issue "holistically". Since both are on Pavel's docket for review and realistically speaking they may only merge after my departure, I'm assigning this issue to Pavel.