storage: RHS HardState clobbering during splits

[irfansharif]

observed this curious behavior recently where we seem to clobber on-disk HardState; naively this should not happen. See #7600 for a strikingly similar occurrence.
The following diff adding some extra instrumentation, coupled with this test demonstrates the clobbering behavior.
They are both available on this branch, TestMinimal is just a simplified version of the existing TestStoreRangeSplitRaceUninitializedRHS test but with only one split operation for simplified, albeit hacky, logging.

commit fe0203a96d35d4ffd8c3ae6ba55da8b98f8b1651
Author: irfan sharif <[email protected]>
Date:   Tue Jun 27 00:38:53 2017 -0400

    storage: debug hardstate clobbering

diff --git a/pkg/storage/replica.go b/pkg/storage/replica.go
index f8a6dd9b0..e04324999 100644
--- a/pkg/storage/replica.go
+++ b/pkg/storage/replica.go
@@ -3112,6 +3112,9 @@ func (r *Replica) handleRaftReadyRaftMuLocked(
 	if err := batch.Commit(syncRaftLog.Get() && rd.MustSync); err != nil {
 		return stats, err
 	}
+	if !raft.IsEmptyHardState(rd.HardState) {
+		log.Infof(ctx, "set hs:  %+v", rd.HardState)
+	}
 	elapsed := timeutil.Since(start)
 	r.store.metrics.RaftLogCommitLatency.RecordValue(elapsed.Nanoseconds())
 
@@ -4195,10 +4198,27 @@ func (r *Replica) applyRaftCommand(
 	writer.Close()
 
 	start := timeutil.Now()
+
+	oldHS, err := loadHardState(ctx, r.store.Engine(), roachpb.RangeID(2))
+	if err != nil {
+		panic(err)
+	}
 	if err := batch.Commit(false); err != nil {
 		return enginepb.MVCCStats{}, roachpb.NewError(NewReplicaCorruptionError(
 			errors.Wrap(err, "could not commit batch")))
 	}
+
+	// This is the hard state received through raft.
+	newHS, err := loadHardState(ctx, r.store.Engine(), roachpb.RangeID(2))
+	if err != nil {
+		panic(err)
+	}
+
+	if newHS.Term < oldHS.Term || (newHS.Term == oldHS.Term && newHS.Commit < oldHS.Commit) {
+		log.Warningf(ctx, "previously: %+v", oldHS)
+		log.Warningf(ctx, "over-written with: %+v", newHS)
+		log.Warningf(ctx, "clobbered hard state: %s", pretty.Diff(newHS, oldHS))
+	}
 	elapsed := timeutil.Since(start)
 	r.store.metrics.RaftCommandCommitLatency.RecordValue(elapsed.Nanoseconds())
 	return rResult.Delta, nil
diff --git a/pkg/storage/replica_command.go b/pkg/storage/replica_command.go
index 9b173619a..ef33f4be2 100644
--- a/pkg/storage/replica_command.go
+++ b/pkg/storage/replica_command.go
@@ -3033,6 +3033,9 @@ func splitTrigger(
 		if err != nil {
 			return enginepb.MVCCStats{}, EvalResult{}, errors.Wrap(err, "unable to load hard state")
 		}
+
+		log.Warningf(ctx, "current hard state, deliver through raft: %+v", oldHS)
+
 		// Initialize the right-hand lease to be the same as the left-hand lease.
 		// Various pieces of code rely on a replica's lease never being unitialized,
 		// but it's more than that - it ensures that we properly initialize the

Observing the logs for make test PKG=./pkg/storage TESTFLAGS="-v" TESTS=TestMinimal:

I170627 16:43:16.470806 228 storage/replica.go:3116  [s1,r2/1:{-}] set hs:  {Term:9 Vote:2 Commit:0 XXX_unrecognized:[]}
I170627 16:43:16.470983 228 storage/replica.go:3116  [s1,r2/1:{-}] set hs:  {Term:10 Vote:2 Commit:0 XXX_unrecognized:[]}
W170627 16:43:16.471264 218 storage/replica_command.go:3037  [s1,r1/1:/M{in-ax}] current hard state, deliver through raft: {Term:10 Vote:2 Commit:0 XXX_unrecognized:[]}
I170627 16:43:16.471365 228 storage/replica.go:3116  [s1,r2/1:{-}] set hs:  {Term:11 Vote:2 Commit:0 XXX_unrecognized:[]}
I170627 16:43:16.471677 228 storage/replica.go:3116  [s1,r2/1:{-}] set hs:  {Term:12 Vote:2 Commit:0 XXX_unrecognized:[]}
I170627 16:43:16.472065 228 storage/replica.go:3116  [s1,r2/1:{-}] set hs:  {Term:13 Vote:2 Commit:0 XXX_unrecognized:[]}
W170627 16:43:16.472636 74 storage/replica.go:4218  [s1,r1/1:/M{in-ax}] previously: {Term:13 Vote:2 Commit:0 XXX_unrecognized:[]}
W170627 16:43:16.472677 74 storage/replica.go:4219  [s1,r1/1:/M{in-ax}] over-written with: {Term:10 Vote:2 Commit:10 XXX_unrecognized:[]}
W170627 16:43:16.472716 74 storage/replica.go:4220  [s1,r1/1:/M{in-ax}] clobbered hard state: [Term: 10 != 13 Commit: 10 != 0]
I170627 16:43:16.473938 228 storage/replica.go:3116  [s1,r2/1:{a-/Max}] set hs:  {Term:14 Vote:0 Commit:10 XXX_unrecognized:[]}
I170627 16:43:16.474799 155 storage/replica.go:3116  [s2,r2/2:{a-/Max}] set hs:  {Term:14 Vote:0 Commit:10 XXX_unrecognized:[]}

Important bit: clobbered hard state: [Term: 10 != 13 Commit: 10 != 0]
Also interesting to note is that following this we have set hs: {Term:14 Vote:0 Commit:10 XXX_unrecognized:[]}, not seeing the effect of the HardState reset.

[irfansharif]

From internal discussions, copied here:

I can reproduce this scenario under aggressive raft conditions (frequent elections, short timers) and split triggers similar to #7600 where you can have the following sequence of events:

• we have a range split in a multi node cluster
• before the split comes out of raft for all the nodes, one of the nodes that hasn’t received the split trigger receives a request for that range and thus creates an uninitialized replica (correct me here if I’m wrong)
• before the split trigger comes out of raft, it advances it’s HardState
  when the split trigger comes out of raft, it clobbers the HardState on disk that was being written to earlier.

is this last step correct? if so, is it because the earlier writes were by an uninitialized replica?

-- @irfansharif

I think we screwed this up when we switched to proposer-evaluated KV. See writeInitialState which calls synthesizeRaftState — it does that call precisely to avoid that scenario (before proposer-evaluated KV). Now I unfortunately don’t see anything that prevents this since the writeInitialState call has moved pre-Raft.

-- @tschottdorf

[irfansharif]

cc @bdarnell.

[tbg]

An obvious solution is to call sythesizeRaftState downstream of Raft, before committing the batch. Cc. @danhhz who needs something similar for sstable ingestion.

[tbg]

(in the longer run, we probably should look into going back to not writing the initial HardState ourselves as we did at one point in the past, though doing so has highlighted the concurrency subtleties of splits)

[tbg]

How frequently do you get this? I haven't gotten a failure in 4 minutes of make stress, trying stressrace now, but also already 4min in.

[irfansharif]

this behavior doesn't currently trigger any failures if that's what you're looking for, just curious observation when instrumenting as above. one way to panic when this happens is in replica_state.go: replicaStateLoader.setHardState. batch here is an engine.ReadWriter, so read the old value (if any), compare to the new and panic if new value has a lower term (or the same term and lower commit idx).

[tbg]

oh, right, forgot you had only warnings in the above diff. Thanks for the heads up!

[tbg]

Am I still messing it up? Haven't gotten a failure in ~5min. Maybe I'll just need to overload the machine more.

diff --git a/pkg/storage/replica_state.go b/pkg/storage/replica_state.go
index 708de1ea4..dcbc96337 100644
--- a/pkg/storage/replica_state.go
+++ b/pkg/storage/replica_state.go
@@ -455,6 +455,16 @@ func (rsl replicaStateLoader) loadHardState(
 func (rsl replicaStateLoader) setHardState(
        ctx context.Context, batch engine.ReadWriter, st raftpb.HardState,
 ) error {
+       var oldHS raftpb.HardState
+       if _, err := engine.MVCCGetProto(
+               ctx, batch, rsl.RaftHardStateKey(),
+               hlc.Timestamp{}, true, nil, &oldHS,
+       ); err != nil {
+               panic(err)
+       }
+       if oldHS.Term > st.Term || oldHS.Commit > st.Commit {
+               log.Fatalf(ctx, "from %+v to %+v", oldHS, st)
+       }
        return engine.MVCCPutProto(ctx, batch, nil,
                rsl.RaftHardStateKey(), hlc.Timestamp{}, nil, &st)
 }

[tbg]

Ah, the clobbering doesn't happen in setHardState (which is called during evaluation). It happens where you warn, and in fact clobbering happens almost every time.

[irfansharif]

whoops, right, during batch.ApplyRepr. and yes, very frequent.

[tbg]

Thanks for the prep work, that'll make fixing much more pleasant.

[tbg]

Ok, I have a working fix but it's a bit too hacky to merge right now. Essentially we now avoid writing the HardState in the split batch completely, but we synthesize it downstream of Raft, the key diff being this:

diff --git a/pkg/storage/store.go b/pkg/storage/store.go
index a183dd977..2413d9c1b 100644
--- a/pkg/storage/store.go
+++ b/pkg/storage/store.go
@@ -1847,6 +1847,24 @@ func splitPostApply(
                log.Fatal(ctx, err)
        }

+       {
+               var s storagebase.ReplicaState
+               s.TruncatedState = &roachpb.RaftTruncatedState{
+                       Term:  raftInitialLogTerm,
+                       Index: raftInitialLogIndex,
+               }
+               s.RaftAppliedIndex = s.TruncatedState.Index
+               oldHS, err := rightRng.raftMu.stateLoader.loadHardState(ctx, r.store.Engine())
+               if err != nil {
+                       log.Fatal(ctx, err)
+               }
+               if err := rightRng.raftMu.stateLoader.synthesizeHardState(
+                       ctx, r.store.Engine(), s, &oldHS,
+               ); err != nil {
+                       log.Fatal(ctx, err)
+               }
+       }
+
        // Finish initialization of the RHS.

        r.mu.Lock()

The full branch is here: https://github.com/tschottdorf/cockroach/tree/split-clobbering

I should be able to clean this up for 1.0.4.