kv/kvserver: TestSplitTriggerMeetsUnexpectedReplicaID failed

[cockroach-teamcity]

kv/kvserver.TestSplitTriggerMeetsUnexpectedReplicaID failed with artifacts on master @ a5158c4c93e9dca858b38ef7e94321f0a0a2b5c5:

=== RUN   TestSplitTriggerMeetsUnexpectedReplicaID
    test_log_scope.go:79: test logs captured to: /artifacts/tmp/_tmp/751d67000aac5f3394c2369309253f02/logTestSplitTriggerMeetsUnexpectedReplicaID2403169547
    test_log_scope.go:80: use -show-logs to present logs inline

Help

See also: How To Investigate a Go Test Failure (internal)
Parameters in this failure:

• TAGS=bazel,gss,deadlock

/cc @cockroachdb/kv

This test on roachdash | Improve this report!

[tbg]

#74013

[tbg]

Nevermind, finally found the right place to check:

panic: close of closed channel [recovered]
	panic: close of closed channel [recovered]
	panic: close of closed channel

goroutine 59872246 [running]:
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Recover(0xc0099e4630, {0x545adf8, 0xc02157ce70})
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:251 +0x94
panic({0x3cd0980, 0x537f5b0})
	GOROOT/src/runtime/panic.go:1038 +0x215
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Recover(0xc0099e4630, {0x545adf8, 0xc02157cf60})
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:251 +0x94
panic({0x3cd0980, 0x537f5b0})
	GOROOT/src/runtime/panic.go:1038 +0x215
github.com/cockroachdb/pebble/sstable.(*writeQueue).finish(...)
	github.com/cockroachdb/pebble/sstable/external/com_github_cockroachdb_pebble/sstable/write_queue.go:108
github.com/cockroachdb/pebble/sstable.(*Writer).Close(0xc013f8a000)
	github.com/cockroachdb/pebble/sstable/external/com_github_cockroachdb_pebble/sstable/writer.go:1047 +0xc7
github.com/cockroachdb/cockroach/pkg/storage.(*SSTWriter).Close(...)
	github.com/cockroachdb/cockroach/pkg/storage/sst_writer.go:296
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*multiSSTWriter).Close(0xc0013cf028)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_snapshot.go:221 +0x2a
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*kvBatchSnapshotStrategy).Receive(_, {_, _}, {_, _}, {{0x1d, 0x10, 0xc01c6c4230, 0xc0104b4fc0, 0xc01037f7f0, ...}, ...})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_snapshot.go:283 +0xbdc
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).receiveSnapshot(0xc00e844000, {0x545adf8, 0xc02157cf60}, 0xc01d96c900, {0x7f7f425cd778, 0xc01c9cd750})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_snapshot.go:679 +0x5c5
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).HandleSnapshot.func1({0x545adf8, 0xc02157cf60})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:82 +0x145
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc0099e4630, {0x545adf8, 0xc02157cf60}, {0x40bb2e0, 0xc02157cea0}, 0xc000401c48)
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:344 +0xdd
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).HandleSnapshot(0xc00e844000, {0x545adf8, 0xc02157ce70}, 0xc01d96c900, {0x7f7f425cd750, 0xc01c9cd750})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:72 +0xcc
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).RaftSnapshot.func1.1({0x54c19d0, 0xc01c9cd750}, 0xc018879400, {0x545adf8, 0xc02157ce70})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/raft_transport.go:434 +0x13a
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).RaftSnapshot.func1({0x545adf8, 0xc02157ce70})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/raft_transport.go:435 +0x45
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:494 +0x16f
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:483 +0x445
I220130 11:28:49.080785 1 (gostd) testmain.go:1530  [-] 1  Test //pkg/kv/kvserver:kvserver_test exited with error code 2

Same as #75718

[tbg]

I was thinking this had to be another "use after stopped" case, but HandleSnapshot has a task:

cockroach/pkg/kv/kvserver/store_raft.go

Lines 65 to 84 in 410ef29

	// HandleSnapshot reads an incoming streaming snapshot and applies it if
	// possible.
	func (s *Store) HandleSnapshot(
	ctx context.Context, header *SnapshotRequest_Header, stream SnapshotResponseStream,
	) error {
	ctx = s.AnnotateCtx(ctx)
	const name = "storage.Store: handle snapshot"
	return s.stopper.RunTaskWithErr(ctx, name, func(ctx context.Context) error {
	s.metrics.RaftRcvdMessages[raftpb.MsgSnap].Inc(1)
	if s.IsDraining() {
	return stream.Send(&SnapshotResponse{
	Status: SnapshotResponse_ERROR,
	Message: storeDrainingMsg,
	})
	}
	return s.receiveSnapshot(ctx, header, stream)
	})
	}

[tbg]

The only case in which we double-close (which I thought could be triggering this issue) is in this path:

cockroach/pkg/kv/kvserver/store_snapshot.go

Lines 276 to 285 in 1335460

	if req.Final {
	// We finished receiving all batches and log entries. It's possible that
	// we did not receive any key-value pairs for some of the key ranges, but
	// we must still construct SSTs with range deletion tombstones to remove
	// the data.
	dataSize, err := msstw.Finish(ctx)
	if err != nil {
	return noSnap, errors.Wrapf(err, "finishing sst for raft snapshot")
	}
	msstw.Close()

It's unlikely that we really hit that (we don't generate broken UUIDs) but also, Close is idempotent:

cockroach/pkg/storage/sst_writer.go

Lines 286 to 298 in 1a8fb57

	// Close finishes and frees memory and other resources. Close is idempotent.
	func (fw *SSTWriter) Close() {
	if fw.fw == nil {
	return
	}
	// pebble.Writer *does* return interesting errors from Close... but normally
	// we already called its Close() in Finish() and we no-op here. Thus the only
	// time we expect to be here is in a deferred Close(), in which case the caller
	// probably is already returning some other error, so returning one from this
	// method just makes for messy defers.
	_ = fw.fw.Close()
	fw.fw = nil
	}

So at this point this looks like a problem with pebble/sstable.Writer which apparently can panic upon Close.

cc @cockroachdb/storage

[sumeerbhola]

@bananabrick this looks related to your recent change

[ajwerner]

See also #75687.

[bananabrick]

@tbg I'm going to update the pebble code to not panic during a double Close. However, that channel can only be closed when Writer.Close is called on the sstable writer. Which means that the test is closing the Writer twice.

I'm looking into whether pebble incorrectly causes the Writer to be closed twice.