kv/kvserver: TestBackpressureNotAppliedWhenReducingRangeSize failed

[cockroach-teamcity]

kv/kvserver.TestBackpressureNotAppliedWhenReducingRangeSize failed on master @ ecfb74b7ad75327f11814966a2cdab1b9793a549:

Fatal error:

panic: test timed out after 15m0s
running tests:
	TestBackpressureNotAppliedWhenReducingRangeSize (14m44s)
	TestBackpressureNotAppliedWhenReducingRangeSize/no_backpressure_when_much_larger_on_new_node (14m25s)

Stack:

goroutine 19275 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2366 +0x385
created by time.goFunc
	GOROOT/src/time/sleep.go:177 +0x2d

Log preceding fatal error

* 
* goroutine 15151 [select]:
* github.com/cockroachdb/cockroach/pkg/util/retry.(*Retry).Next(0xc007b5fbf8)
* 	pkg/util/retry/retry.go:128 +0x1fd
* github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).getOrCreateReplica(0xc006de0008, {0x91cb610, 0xc00dcaa1e0}, 0x4b, 0x1, 0xc00b227a20)
* 	pkg/kv/kvserver/store_create_replica.go:73 +0x225
* github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).withReplicaForRequest(0xc006de0a48?, {0x91cb610, 0xc00dcaa1e0}, 0xc00b227a00, 0xc007b5fdd8)
* 	pkg/kv/kvserver/store_raft.go:405 +0x5a
* github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRequestQueue(0xc006de0008, {0x91cb610, 0xc00dcaa1e0}, 0x4b)
* 	pkg/kv/kvserver/store_raft.go:679 +0x1c9
* github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker(0xc0013e6310, {0x91cb610, 0xc00dcaa1e0}, {0x91efa80, 0xc006de0008}, 0xc00bc48008)
* 	pkg/kv/kvserver/scheduler.go:397 +0x1c3
* github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2({0x91cb610?, 0xc00dcaa1e0?})
* 	pkg/kv/kvserver/scheduler.go:319 +0x45
* github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2({0x77d596e, 0xb})
* 	pkg/util/stop/stopper.go:500 +0x21d
* created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx in goroutine 15093
* 	pkg/util/stop/stopper.go:489 +0x47c
* 
* goroutine 15033 [select]:
* github.com/cockroachdb/pebble/vfs.(*diskHealthCheckingFile).startTicker.func1()
* 	external/com_github_cockroachdb_pebble/vfs/disk_health.go:254 +0xbc
* created by github.com/cockroachdb/pebble/vfs.(*diskHealthCheckingFile).startTicker in goroutine 14979
* 	external/com_github_cockroachdb_pebble/vfs/disk_health.go:249 +0x58
* 
* goroutine 15087 [select]:
* github.com/cockroachdb/pebble/vfs.(*diskHealthCheckingFile).startTicker.func1()
* 	external/com_github_cockroachdb_pebble/vfs/disk_health.go:254 +0xbc
* created by github.com/cockroachdb/pebble/vfs.(*diskHealthCheckingFile).startTicker in goroutine 14979
* 	external/com_github_cockroachdb_pebble/vfs/disk_health.go:249 +0x58
* 
* goroutine 15025 [select]:
* github.com/cockroachdb/cockroach/pkg/util/admission.(*WorkQueue).startClosingEpochs.func1()
* 	pkg/util/admission/work_queue.go:501 +0x14d
* created by github.com/cockroachdb/cockroach/pkg/util/admission.(*WorkQueue).startClosingEpochs in goroutine 14979
* 	pkg/util/admission/work_queue.go:472 +0x4f
* 
* goroutine 19009 [select, 2 minutes]:
* database/sql.(*DB).connectionOpener(0xc00d86e4e0, {0x91cb060, 0xc00d8a0dc0})
* 	GOROOT/src/database/sql/sql.go:1246 +0x87
* created by database/sql.OpenDB in goroutine 14979
* 	GOROOT/src/database/sql/sql.go:824 +0x14c
* 
* goroutine 18240 [select]:
* github.com/cockroachdb/cockroach/pkg/util/admission.initWorkQueue.func2()
* 	pkg/util/admission/work_queue.go:424 +0x85
* created by github.com/cockroachdb/cockroach/pkg/util/admission.initWorkQueue in goroutine 14979
* 	pkg/util/admission/work_queue.go:421 +0x3be
* 
*

Parameters:

• attempt=1
• run=18
• shard=20

Help

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

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-47534

[tbg]

Different failure mode from #113032, where it was likely OOM.
Test seems to consume a lot of memory. Need to take another look, but unlikely to be release blocker.

[tbg]

This is actually a timeout on test teardown.

log.txt

It looks like this subtest passed, but it's stuck on stopping the testCluster - we can tell from this part of the stack dump:

* goroutine 14979 [semacquire, 2 minutes]:
* sync.runtime_Semacquire(0xc00f5ac7e0?)
* 	GOROOT/src/runtime/sema.go:62 +0x25
* sync.(*WaitGroup).Wait(0x0?)
* 	GOROOT/src/sync/waitgroup.go:116 +0x48
* github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).stopServers(0xc004585808, {0x91cab70, 0xe010d80})
* 	pkg/testutils/testcluster/testcluster.go:161 +0x272
* github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).Start.func3()
* 	pkg/testutils/testcluster/testcluster.go:483 +0x25
* github.com/cockroachdb/cockroach/pkg/util/stop.CloserFn.Close(0xc00a424000?)
* 	pkg/util/stop/stopper.go:104 +0x12
* github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Stop(0xc00a424000, {0x91ca7f0, 0xe010d80})
* 	pkg/util/stop/stopper.go:565 +0x131
* github.com/cockroachdb/cockroach/pkg/kv/kvserver_test.TestBackpressureNotAppliedWhenReducingRangeSize.func5(0xc00bb74000)
* 	pkg/kv/kvserver/client_replica_backpressure_test.go:217 +0x3c3

cockroach/pkg/kv/kvserver/client_replica_backpressure_test.go

Lines 197 to 217 in ecfb74b

	t.Run("no backpressure when much larger on new node", func(t *testing.T) {
	tc, args, tdb, tablePrefix, unblockSplits, _ := setup(t, 1)
	defer tc.Stopper().Stop(ctx)
	defer unblockSplits()
	// We didn't want to have to load too much data into these ranges because
	// it makes the testing slower so let's lower the threshold at which we'll
	// consider the range to be way over the backpressure limit from megabytes
	// down to kilobytes.
	tdb.Exec(t, "SET CLUSTER SETTING kv.range.backpressure_byte_tolerance = '1 KiB'")
	tdb.Exec(t, "ALTER TABLE foo CONFIGURE ZONE USING "+
	"range_max_bytes = $1, range_min_bytes = $2", min_range_max_bytes, dataSize/10)
	waitForSpanConfig(t, tc, tablePrefix, min_range_max_bytes)
	// Then we'll add a new server and move the table there.
	moveTableToNewStore(t, tc, args, tablePrefix)
	// Don't observe backpressure.
	tdb.Exec(t, "UPSERT INTO foo VALUES ($1, $2)",
	rRand.Intn(10000000), val)
	})

This is a single-node cluster, which thankfully rules out some of the complicated interactions that can occur with multiple servers. We can just look at which goroutines are still around.

~/crdb/scripts/sgrep /Stopper/ log.txt  | pbcopy

points squarely at this stack:

goroutine 15151 [select]:
github.com/cockroachdb/cockroach/pkg/util/retry.(*Retry).Next(0xc0083e9bf8)
        pkg/util/retry/retry.go:128 +0x1fd
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).getOrCreateReplica(0xc006de0008, {0x91cb610, 0xc00dcaa1e0}, 0x4b, 0x1, 0xc00b227a20)
        pkg/kv/kvserver/store_create_replica.go:73 +0x225
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).withReplicaForRequest(0xc006de0a48?, {0x91cb610, 0xc00dcaa1e0}, 0xc00b227a00, 0xc0083e9dd8)
        pkg/kv/kvserver/store_raft.go:405 +0x5a
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRequestQueue(0xc006de0008, {0x91cb610, 0xc00dcaa1e0}, 0x4b)
        pkg/kv/kvserver/store_raft.go:679 +0x1c9
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker(0xc0013e6310, {0x91cb610, 0xc00dcaa1e0}, {0x91efa80, 0xc006de0008}, 0xc00bc48008)
        pkg/kv/kvserver/scheduler.go:397 +0x1c3
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2({0x91cb610?, 0xc00dcaa1e0?})
        pkg/kv/kvserver/scheduler.go:319 +0x45
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2({0x77d596e, 0xb})
        pkg/util/stop/stopper.go:500 +0x21d
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx in goroutine 15093
        pkg/util/stop/stopper.go:489 +0x47c

I've pulled on this for a while now, and it's interesting. Something unexpected is definitely going on, not anything I can explain by the test. So I think this is a real bug, perhaps not a new one, but still something I should keep pushing on.

I'll write up my notes so far before EOD.

[tbg]

This has been a fun one so far. I have a lengthy chat with Claude (inside of cursor), but unfortunately there isn't an easy way to export it¹, so I'll condense things down.

The basic issue is that we're stuck in an infinite loop in getOrCreateReplica on shutdown:

cockroach/pkg/kv/kvserver/store_create_replica.go

Lines 72 to 87 in ecfb74b

	for {
	r.Next()
	r, created, err := s.tryGetOrCreateReplica(
	ctx,
	rangeID,
	replicaID,
	creatingReplica,
	)
	if errors.Is(err, errRetry) {
	continue
	}
	if err != nil {
	return nil, false, err
	}
	return r, created, err
	}

So, we're getting errRetry. This happens in three cases:

1. competing entry in s.mu.creatingReplicas (lost race).
   2.there is a replica, but replicaID is stale, so it gets gc'ed and we loop around (ref)
2. the replica is pending removal, i.e. destroyStatus is set (ref)

I can rule out 1. because if we lost the race, the other goroutine will definitely have removed the entry from the map again (via defer()). We don't see any other goroutines on the Store. So, it's not 1.

I also don't think it's 2. because in the logs we don't remove and re-add a replicas.

So it's likely 3. There is strong evidence for this. From the livelocked stack,

getOrCreateReplica(0xc006de0008, {0x91cb610, 0xc00dcaa1e0}, 0x4b, 0x1, 0xc00b227a20)
pkg/kv/kvserver/store_create_replica.go:73 +0x225

Note that 0x4b is the rangeID, 0x1 is the replicaID. That's r75/1. Now look at these logs:

I250209 06:24:47.945977 19057 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n1,s1,r75/1:‹/{Table/104-Max}›] 415  removing replica r75/1
I250209 06:24:48.066452 14979 testutils/testcluster/testcluster.go:149 ⋮ [-] 416  TestCluster quiescing nodes

That first log message is from removeInitializedReplicaRaftMuLocked and it makes sense to see it - the distribution logs show that r75/1 is removed, as the test moves r75 from n1 to n2.

cockroach/pkg/kv/kvserver/store_remove_replica.go

Line 152 in ecfb74b

log.Infof(ctx, "removing replica r%d/%d", rep.RangeID, rep.replicaID)

I'm not 100% sure who calls this method in that case, but I would generally expect the caller to come through HandleRaftResponse (r75/1 reaches out to the sibling replica on s2, that replica sends a ReplicaTooOldError, and we call in with DestroyData: true:

cockroach/pkg/kv/kvserver/store_raft.go

Lines 623 to 627 in ecfb74b

	repl.mu.Unlock()
	nextReplicaID := tErr.ReplicaID + 1
	return s.removeReplicaRaftMuLocked(ctx, repl, nextReplicaID, RemoveOptions{
	DestroyData: true,
	})

Now here's the interesting bit. In removeInitializedReplicaRaftMuLocked, most errors are handled via log.Fatalf, and we don't hit that. But some errors also return up the stack. There isn't any stopped check in this method (i.e. it wouldn't just bail out half-way through if the store is quiescing), but if the method had run to completion, we would have hit additional logging here:

cockroach/pkg/kv/kvserver/store_remove_replica.go

Lines 180 to 184 in ecfb74b

	if opts.DestroyData {
	if err := rep.destroyRaftMuLocked(ctx, nextReplicaID); err != nil {
	return nil, err
	}
	}

which has

cockroach/pkg/kv/kvserver/replica_destroy.go

Lines 141 to 152 in ecfb74b

	if r.IsInitialized() {
	log.Infof(ctx, "removed %d (%d+%d) keys in %0.0fms [clear=%0.0fms commit=%0.0fms]",
	ms.KeyCount+ms.SysCount, ms.KeyCount, ms.SysCount,
	commitTime.Sub(startTime).Seconds()*1000,
	preTime.Sub(startTime).Seconds()*1000,
	commitTime.Sub(preTime).Seconds()*1000)
	} else {
	log.Infof(ctx, "removed uninitialized range in %0.0fms [clear=%0.0fms commit=%0.0fms]",
	commitTime.Sub(startTime).Seconds()*1000,
	preTime.Sub(startTime).Seconds()*1000,
	commitTime.Sub(preTime).Seconds()*1000)
	}

We never see this logging, and since there isn't another early return in this segment:

cockroach/pkg/kv/kvserver/store_remove_replica.go

Lines 152 to 183 in ecfb74b

	log.Infof(ctx, "removing replica r%d/%d", rep.RangeID, rep.replicaID)
	s.mu.Lock()
	if it := s.getOverlappingKeyRangeLocked(desc); it.repl != rep {
	// This is a fatal error because uninitialized replicas shouldn't make it
	// this far. This method will need some changes when we introduce GC of
	// uninitialized replicas.
	s.mu.Unlock()
	log.Fatalf(ctx, "replica %+v unexpectedly overlapped by %+v", rep, it.item)
	}
	// Adjust stats before calling Destroy. This can be called before or after
	// Destroy, but this configuration helps avoid races in stat verification
	// tests.
	s.metrics.subtractMVCCStats(ctx, rep.tenantMetricsRef, rep.GetMVCCStats())
	s.metrics.ReplicaCount.Dec(1)
	s.mu.Unlock()
	// The replica will no longer exist, so cancel any rangefeed registrations.
	rep.disconnectRangefeedWithReason(
	kvpb.RangeFeedRetryError_REASON_REPLICA_REMOVED,
	)
	// Mark the replica as destroyed and (optionally) destroy the on-disk data
	// while not holding Store.mu. This is safe because we're holding
	// Replica.raftMu and the replica is present in Store.mu.replicasByKey
	// (preventing any concurrent access to the replica's key range).
	rep.disconnectReplicationRaftMuLocked(ctx)
	if opts.DestroyData {
	if err := rep.destroyRaftMuLocked(ctx, nextReplicaID); err != nil {
	return nil, err
	}

it follows that we must have hit the return nil, err on line 182 (i.e. an error returned from destroyRaftMuLocked).

I don't see any error path here that it reasonably could have hit: it's really just working on the engine, and judging from the goroutines that exist, the engine is still open. (Also, if there were some shutdown race, we'd expect to hit errors more frequently).

But since I don't see another way this could all play out like this, I have to assume there is an error generated somewhere on that path, and returned up the stack.

That error would then be placed in a 1-buffered channel

cockroach/pkg/kv/kvserver/raft_transport.go

Lines 694 to 696 in ecfb74b

	if err := incomingMessageHandler.HandleRaftResponse(ctx, resp); err != nil {
	return err
	}

where it would be consumed here, but note that this may exit early on drain and not actually read from the channel:

cockroach/pkg/kv/kvserver/raft_transport.go

Lines 789 to 800 in ecfb74b

	select {
	case <-t.stopper.ShouldQuiesce():
	return nil
	case <-raftIdleTimer.C:
	raftIdleTimer.Read = true
	return nil
	case err := <-errCh:
	return err
	case req := <-q.reqs:

which could explain why I don't see this fire:

cockroach/pkg/kv/kvserver/raft_transport.go

Lines 1066 to 1068 in ecfb74b

	if err := t.processQueue(q, stream, class); err != nil {
	log.Warningf(ctx, "while processing outgoing Raft queue to node %d: %s:", toNodeID, err)
	}

While this seems like a valid sequence of events that explains what we see here, I find it strange. The fact that the system is draining "right after replicaGC" does not play a role in the above analysis, its only importance is to make sure the log message is swallowed. If we had drained the server later, we would've gotten the log message and the same hung test. Yet, the two are very close to each other, which, you know, it just seems odd.

So I think there might be more going on here, some sequence in which the drain plays a more prominent role. But I could be wrong.

Footnotes

1. (you can get the JSON from sqlite3 ~/Library/Application\ Support/Cursor/User/globalStorage/state.vscdb "select value from cursorDiskKV where value like '%incredibly%' limit 1;" > ~/Downloads/out.json but too much work to format) ↩