kv/kvserver: TestStoreRangeSplitRaceUninitializedRHS failed

[cockroach-teamcity]

kv/kvserver.TestStoreRangeSplitRaceUninitializedRHS failed with artifacts on master @ ba16357c4968ec68b2d0afda7862331f22e14e8c:

=== RUN   TestStoreRangeSplitRaceUninitializedRHS
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestStoreRangeSplitRaceUninitializedRHS222619826
    test_log_scope.go:74: use -show-logs to present logs inline
    testcluster.go:335: pq: setting updated but timed out waiting to read new value
    panic.go:636: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestStoreRangeSplitRaceUninitializedRHS222619826
W210615 14:20:48.009869 977027 server/node.go:783  [n1,summaries] 13  health alerts detected: {Alerts:[{StoreID:1 Category:METRICS Description:ranges.underreplicated Value:37}]}
--- FAIL: TestStoreRangeSplitRaceUninitializedRHS (20.95s)

Reproduce

To reproduce, try:

make stressrace TESTS=TestStoreRangeSplitRaceUninitializedRHS PKG=./pkg/kv/kvserver TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

• GOFLAGS=-json

/cc @cockroachdb/kv tbg

This test on roachdash | Improve this report!

Jira issue: CRDB-8060

[tbg]

W210615 14:20:47.827240 980525 sql/set_cluster_setting.go:322 ⋮ [n1,client=‹127.0.0.1:38682›,hostssl,user=root] 115 SET CLUSTER SETTING ‹"kv.range_merge.queue_enabled"› timed out waiting for value ‹"false"›, observed ‹"true"›

cockroach/pkg/sql/set_cluster_setting.go

Lines 307 to 328 in 9048076

	if _, ok := n.setting.(*settings.VersionSetting); ok && n.value == nil {
	// The "version" setting doesn't have a well defined "default" since it
	// is set in a startup migration.
	return nil
	}
	errNotReady := errors.New("setting updated but timed out waiting to read new value")
	var observed string
	err := retry.ForDuration(10*time.Second, func() error {
	observed = n.setting.Encoded(&execCfg.Settings.SV)
	if observed != expectedEncodedValue {
	return errNotReady
	}
	return nil
	})
	if err != nil {
	log.Warningf(
	params.ctx, "SET CLUSTER SETTING %q timed out waiting for value %q, observed %q",
	n.name, expectedEncodedValue, observed,
	)
	}
	return err
	}

Maybe the 10s just wasn't enough for gossip propagation, this is a race build.

[tbg]

This is from StartTestCluster btw, so nothing to do with the test really, except perhaps the fact that this test sets aggressive raft cfgs:

cockroach/pkg/kv/kvserver/client_split_test.go

Lines 2068 to 2074 in 6b9168d

	RaftConfig: base.RaftConfig{
	// An aggressive tick interval lets groups communicate more and thus
	// triggers test failures much more reliably. We can't go too aggressive
	// or race tests never make any progress.
	RaftTickInterval: 100 * time.Millisecond,
	RaftElectionTimeoutTicks: 2,
	RaftHeartbeatIntervalTicks: 1,

The logs look clean though, so it looks like the cluster is healthy. Not sure. Likely a fluke.

[cockroach-teamcity]

kv/kvserver.TestStoreRangeSplitRaceUninitializedRHS failed with artifacts on master @ 40b50c952aaa90e0ac565c859c1076a77c9a64be:

=== RUN   TestStoreRangeSplitRaceUninitializedRHS
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestStoreRangeSplitRaceUninitializedRHS849579772
    test_log_scope.go:74: use -show-logs to present logs inline
    testcluster.go:334: pq: setting updated but timed out waiting to read new value
    panic.go:632: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestStoreRangeSplitRaceUninitializedRHS849579772
--- FAIL: TestStoreRangeSplitRaceUninitializedRHS (18.98s)

Reproduce

To reproduce, try:

make stressrace TESTS=TestStoreRangeSplitRaceUninitializedRHS PKG=./pkg/kv/kvserver TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

• GOFLAGS=-json

/cc @cockroachdb/kv tbg

This test on roachdash | Improve this report!

[kvoli]

The test is still flaky when running with --stress, failing reliably in under 30 runs. The issue as far as I can tell is that the test sends MsgVote requests to the RHS side of the split every microsecond, until the split completes without error. This can cause the send queue to fill up and RaftTransport().SendAsync() to return false, which fails the test due to this test assertion.

Logs

W230315 19:25:01.200371 2888 kv/kvserver/raft_transport.go:542 ⋮ [T1,n2] 449  raft send queue to n1 is full
client_split_test.go:2149: transport failed to send vote request

Decreasing the frequency of MsgVote requests to 4 microseconds makes the test pass reliably, however I'm not certain if this is because we no longer see the race condition, which we want to test.

I think I may need more expertise to say whether this is expected.