kv/kvserver: TestRaftRemoveRace failed [port reuse]

[cockroach-teamcity]

kv/kvserver.TestRaftRemoveRace failed with artifacts on release-25.4 @ 5cbf2f4dc70fed406dcba2e7c936ff529a082e57:

Failed with:

=== RUN   TestRaftRemoveRace
    test_log_scope.go:171: test logs captured to: /artifacts/tmp/_tmp/3badd79dc476285a5b1104ad1a94c4a5/logTestRaftRemoveRace238071261
    test_log_scope.go:82: use -show-logs to present logs inline

Fatal entries found in Cockroach logs:

F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1  match(26) is out of range [lastIndex(0)]. Was the raft log corrupted, truncated, or lost?
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !goroutine 15534 [running]:
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !runtime/debug.Stack()
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	GOROOT/src/runtime/debug/stack.go:26 +0x64
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/util/debugutil.Stack(...)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/util/debugutil/debugutil.go:63
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(_, {{{0x4004e639b0, 0x24}, {0x736477e, 0x1}, {0x736477d, 0x1}, {0x7271777, 0x6}, {0x736477e, ...}}, ...})
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/util/log/clog.go:292 +0xc4
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x833bc78, 0x4010d4af00}, 0x3, 0x4, 0xf, 0x0?, {0x7520327, 0x5a}, {0x40096c5640, 0x2, ...})
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/util/log/channels.go:104 +0x44c
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/util/log/channels.go:34
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/util/log.loggerKvExec.FatalfDepth(...)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	bazel-out/aarch64-fastbuild/bin/pkg/util/log/log_channels_generated.go:7077
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftLogger).Panicf(0x4011ab2080, {0x7520327, 0x5a}, {0x40096c5640, 0x2, 0x2})
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/raft.go:114 +0x9c
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/raft.(*raft).checkMatch(0x400a5a9d40, 0x1a)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/raft/raft.go:2422 +0x100
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/raft.(*raft).handleAppendEntries(0x400a5a9d40, {0x3, 0x2, 0x1, 0x6, 0x6, 0x1a, {0x4010d48c90, 0x1, 0x1}, ...})
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/raft/raft.go:2336 +0x2c
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/raft.stepFollower(0x400a5a9d40, {0x3, 0x2, 0x1, 0x6, 0x6, 0x1a, {0x4010d48c90, 0x1, 0x1}, ...})
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/raft/raft.go:2236 +0x3a0
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/raft.(*raft).Step(0x400a5a9d40, {0x3, 0x2, 0x1, 0x6, 0x6, 0x1a, {0x4010d48c90, 0x1, 0x1}, ...})
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/raft/raft.go:1760 +0xef8
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/raft.(*RawNode).Step(0x10?, {0x3, 0x2, 0x1, 0x6, 0x6, 0x1a, {0x4010d48c90, 0x1, 0x1}, ...})
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/raft/rawnode.go:144 +0xe8
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).stepRaftGroupRaftMuLocked.func1(0x4010d26b80)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/replica_raft.go:736 +0x3b0
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).withRaftGroupLocked(0x4005b23b08, 0x487580?)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/replica_raft.go:2232 +0x40
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).withRaftGroup(0x4005b23b08, 0x400e175a90)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/replica_raft.go:2269 +0x74
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).stepRaftGroupRaftMuLocked(0x4005b23b08, 0x4008328420)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/replica_raft.go:663 +0x6c
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRaftRequestWithReplica(0x0?, {0x833bc78, 0x4010d4b040}, 0x4005b23b08, 0x4008328420)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/store_raft.go:477 +0x2a4
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRequestQueue.func1({0x40058a1808?, 0x833bc78?}, 0x4008beb860?)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/store_raft.go:701 +0x38
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).withReplicaForRequest(0x40058a2288?, {0x833bc78, 0x4008beb860}, 0x4008328420, 0x400e175e58)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/store_raft.go:432 +0xbc
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRequestQueue(0x40058a1808, {0x833bc78, 0x4008beb860}, 0x4f)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/store_raft.go:699 +0x150
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker(0x400b592a80, {0x833bc78, 0x4008beb860}, {0x8363c20, 0x40058a1808}, 0x400b5e6008)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/scheduler.go:398 +0x1d8
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2({0x833bc78, 0x4008beb860}, 0x0?)
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/scheduler.go:314 +0xe0
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !created by github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start in goroutine 15319
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !	pkg/kv/kvserver/scheduler.go:328 +0x168
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !For more context, check log files in: /artifacts/tmp/_tmp/3badd79dc476285a5b1104ad1a94c4a5/logTestRaftRemoveRace238071261
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !****************************************************************************
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !This node experienced a fatal error (printed above), and as a result the
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !process is terminating.
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !Fatal errors can occur due to faulty hardware (disks, memory, clocks) or a
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !problem in CockroachDB. With your help, the support team at Cockroach Labs
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !will try to determine the root cause, recommend next steps, and we can
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !improve CockroachDB based on your report.
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !Please submit a crash report by following the instructions here:
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !    https://github.com/cockroachdb/cockroach/issues/new/choose
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !If you would rather not post publicly, please contact us directly at:
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !    support@cockroachlabs.com
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !
F251114 15:42:06.400817 15534 15@raft/raft.go:2422  [T1,Vsystem,n2,s2,r79/2:{-}] 1 !The Cockroach Labs team appreciates your feedback.

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-56972

[pav-kv]

What’s weird in this failure is that the TestCluster is started with 10 nodes, and in normal runs I can see all 10 nodes have completed the replica loading phase (printed stuff like loaded replica ID for 0/0 replicas). But in this run only 2 nodes went through this, and as soon as n2 started (with no replicas, which explains the 0 lastIndex) it got this raft message with a wrong non-zero Match. There is also nothing in kv-distribution channel (normally, I would expect the config changes and applied snapshots there, of which this tests does a lot).

It’s possible that it’s one of those flakes where the message was sent to this port / RPC server from an unrelated cluster in TC.

[pav-kv]

Also, stressed this test 100k times on gceworker and some 10k locally, no luck.

[pav-kv]

Tentatively removing the release-blocker. We should fix port reuse in tests. For example:

1. Make all TestClusters use the reusable listeners by default, and only release the ports after the entire cluster is shut down.
2. Authenticate nodes to cluster/test ID when they exchange messages.