storage: TestNewTruncateDecision failed under stress [skipped]

[cockroach-teamcity]

SHA: https://github.com/cockroachdb/cockroach/commits/ca1ef4d4f8296b213c0b2b140f16e4a97931e6e7

Parameters:

TAGS=
GOFLAGS=-race -parallel=2

To repro, try:

# Don't forget to check out a clean suitable branch and experiment with the
# stress invocation until the desired results present themselves. For example,
# using stress instead of stressrace and passing the '-p' stressflag which
# controls concurrency.
./scripts/gceworker.sh start && ./scripts/gceworker.sh mosh
cd ~/go/src/github.com/cockroachdb/cockroach && \
stdbuf -oL -eL \
make stressrace TESTS=TestNewTruncateDecision PKG=github.com/cockroachdb/cockroach/pkg/storage TESTTIMEOUT=5m STRESSFLAGS='-maxtime 20m -timeout 10m' 2>&1 | tee /tmp/stress.log

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=1368520&tab=buildLog

=== RUN   TestNewTruncateDecision
I190701 12:12:45.945806 12152 util/stop/stopper.go:542  quiescing; tasks left:
1      [async] intent_resolver_ir_batcher
1      [async] intent_resolver_gc_batcher
I190701 12:12:45.946055 12152 util/stop/stopper.go:542  quiescing; tasks left:
1      [async] intent_resolver_ir_batcher
--- FAIL: TestNewTruncateDecision (0.24s)
    raft_log_queue_test.go:570: truncation should not have occurred, but truncatableIndexes changed from 1 -> 2
    raft_log_queue_test.go:573: truncation should not have occurred, but oldestIndex changed from 116 -> 117

Jira issue: CRDB-5625

[tbg]

Looks like an empty entry is proposed sometimes here:

cockroach/pkg/storage/replica_raft_quiesce.go

Lines 95 to 98 in 1ff3556

	// Propose an empty command which will wake the leader.
	data := encodeRaftCommand(raftVersionStandard, makeIDKey(), nil)
	_ = r.mu.internalRaftGroup.Propose(data)
	}

I initially thought this test had to have gotten flaky as a result of #38484 but I just reverted that locally and still get the repro, so now I'm thinking it's fallout from #38343

because this diff fixes it

diff --git a/pkg/storage/replica_raft.go b/pkg/storage/replica_raft.go
index 1266771077..22fa9b375a 100644
--- a/pkg/storage/replica_raft.go
+++ b/pkg/storage/replica_raft.go
@@ -428,13 +428,14 @@ func (r *Replica) handleRaftReadyRaftMuLocked(
        defer r.updateProposalQuotaRaftMuLocked(ctx, lastLeaderID)

        err := r.withRaftGroupLocked(true, func(raftGroup *raft.RawNode) (bool, error) {
-               if err := r.mu.proposalBuf.FlushLockedWithRaftGroup(raftGroup); err != nil {
+               nEnts, err := r.mu.proposalBuf.FlushLockedWithRaftGroup(raftGroup)
+               if err != nil {
                        return false, err
                }
                if hasReady = raftGroup.HasReady(); hasReady {
                        rd = raftGroup.Ready()
                }
-               return hasReady /* unquiesceAndWakeLeader */, nil
+               return hasReady && nEnts == 0 /* unquiesceAndWakeLeader */, nil
        })
        r.mu.Unlock()
        if err != nil {

What's happening is that the request that unquiesces the range sometimes flushes proposals, but then we were adding an extra empty proposal due to returning true from withRaftGroupLocked. The diff above prevents that extra entry (i.e. only sends it when there isn't already an entry).

I'll send a PR.

82444 runs so far, 0 failures, over 39m40s

[nvanbenschoten]

Nice job tracking this down!

[blathers-crl]

cc @cockroachdb/replication

[erikgrinaker]

This test no longer exists.

[erikgrinaker]

Oops, was looking at the wrong repo.