storage: range failed to catch up due to invalid term

[ajwerner]

Describe the problem

@mberhault observed a CREATE DATABASE command hang. Upon further investigation it was discovered that range 3 was hung in redirectOnOrAcquireLease.

From logspy we observed that the replica was refusing to apply raft entries it was sent due to a term mismatch.

I190423 18:17:41.330605 176 storage/raft.go:142  [n3,s3,r3/2:/System/{NodeLive…-tsd}] raft ready (must-sync=false)
  Outgoing Message[0]: 2->1 MsgAppResp Term:9 Log:0/396611 Rejected (Hint: 396611)

I190423 18:17:41.330576 176 vendor/go.etcd.io/etcd/raft/raft.go:1317  [n3,s3,r3/2:/System/{NodeLive…-tsd}] 2 [logterm: 7, index: 396611] rejected msgApp [logterm: 8, index: 396611] from 1

The replica in question believed that it was in term 7. We also observed that the range had no log entries due to a snapshot.

us-west1-node-0000> I190420 23:13:50.610694 7971602 storage/replica_raftstorage.go:814  [n3,s3,r3/2:/System/{NodeLive…
-tsd}] applying Raft snapshot at index 396611 (id=dc7d62ba, encoded size=76009, 1 rocksdb batches, 0 log entries)
us-west1-node-0000> I190420 23:13:50.616660 7971602 storage/replica_raftstorage.go:820  [n3,s3,r3/2:/System/{NodeLive…-tsd}] applied Raft snapshot in 6ms [clear=1ms batch=0ms entries=0ms commit=4ms]

Interestingly we were able to confirm from other replicas that the hung replica should have had a term of at least 8 for the log position in question. The replica in question must have determined its term here:

cockroach/pkg/storage/replica_raftstorage.go

Lines 254 to 260 in 91abab1

	if r.mu.lastIndex == i && r.mu.lastTerm != invalidLastTerm {
	return r.mu.lastTerm, nil
	}
	// Try to retrieve the term for the desired entry from the entry cache.
	if e, ok := r.store.raftEntryCache.Get(r.RangeID, i); ok {
	return e.Term, nil
	}

We also notice that raft snapshots which contain no raft entries set the term to invalid term.

cockroach/pkg/storage/replica_raftstorage.go

Line 908 in 43c3cf3

var lastTerm uint64

This implies that the incorrect term was derived from an entry in the raftentry.Cache. This observation lead us to realize that there was no code to clear the cache when receiving a snapshot.

[bdarnell]

Some of the flakes in the overloaded scrub test (#35985) didn't make any progress at all (leading to OOM). I guessed that this might be some kind of deadlock, but maybe it's the same issue. I wonder if the overloaded tpcc scenario is still flaky with this fixed.