release-26.2.1-rc: kv/kvserver: TestStoreMetrics failed

[cockroach-teamcity]

kv/kvserver.TestStoreMetrics failed with artifacts on release-26.2.1-rc @ 7797103d26398f23c60599f86df401d6454dadb0:

=== RUN   TestStoreMetrics
    test_log_scope.go:172: test logs captured to: /artifacts/tmp/_tmp/3fe72dd26006841c1f679405fff92eae/logTestStoreMetrics3500105969
    test_log_scope.go:82: use -show-logs to present logs inline
    test_server_shim.go:146: using test tenant configuration from testserver factory defaults
    client_metrics_test.go:331: condition failed to evaluate within 45s: replica still exists on dest 0
        
        goroutine dump: /artifacts/tmp/_tmp/3fe72dd26006841c1f679405fff92eae/goroutine_dump_2501131889.txt
    panic.go:615: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/3fe72dd26006841c1f679405fff92eae/logTestStoreMetrics3500105969
--- FAIL: TestStoreMetrics (53.91s)

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

[pav-kv]

/investigate

[github-actions]

Investigation: TestStoreMetrics

Investigated failure: #170677
Failure SHA: 7797103d26398f23c60599f86df401d6454dadb0
Confidence: moderate

What This Test Does

TestStoreMetrics creates a 3-node test cluster with manual replication, performs KV operations (increments, range key tombstones, a deliberately failing CPut transaction, and a replica removal), then verifies that store-level MVCC metrics match recomputed values from the engine. Part of the test transfers the lease away from store 0 and removes its voter replica, then waits for the replica to be fully destroyed on store 0.

Where the Failure Occurs

The test fails at client_metrics_test.go:331 with:

condition failed to evaluate within 45s: replica still exists on dest 0

After calling RemoveLeaseHolderOrFatal (which transfers the lease from store 0 to store 1 and removes the voter from store 0), the test uses SucceedsSoon (45s default timeout) to wait for GetReplica to return a RangeNotFoundError, indicating the replica has been fully destroyed. This never happens.

Analysis

Hypothesis: Removed LEARNER replica on n1 never receives the raft entry for its own removal, and the replica GC queue scanner doesn't reach it within 45s (likely cause, moderate confidence)

The removal sequence from the kv-distribution log shows:

1. At 18:23:15.114, n2 proposes ENTER_JOINT to demote (n1,s1):1 to VOTER_DEMOTING_LEARNER
2. At 18:23:15.123, n2 proposes LEAVE_JOINT, making n1 a LEARNER
3. At 18:23:15.125, n2 proposes the SIMPLE remove of (n1,s1):1LEARNER
4. At 18:23:15.132, n2 proposes the final config change

There is no log on n1 of applying the ChangeReplicasTrigger to remove itself ("removing replica due to ChangeReplicasTrigger" never appears). This means n1 never received or applied the raft entry containing its own removal.

This can happen because:

• After the SIMPLE remove is applied by the raft group on n2 and n3, n1 is no longer part of the group. The raft leader (n2) stops sending MsgApp entries to n1.
• If n1 didn't receive the MsgApp for the SIMPLE remove before n2 applied it, n1 will never learn about its removal through raft.
• The LEARNER n1 won't proactively send raft messages (learners are passive), so the ReplicaTooOldError fast-path for removal (store_raft.go:643) doesn't trigger.

The only remaining cleanup mechanism is the replica GC queue scanner. The scanner visits all replicas in sequence, paced to complete within the ScanInterval. The test does not configure ScanInterval, so the default of 10 minutes applies. With ~83 replicas on n1 (all system ranges), the scanner visits one replica approximately every 7.2 seconds. In the worst case, if the scanner just passed r83, it won't revisit it for up to 10 minutes — far exceeding the 45-second SucceedsSoon timeout.

When the scanner does visit r83, replicaIsSuspect() returns true (n1's local descriptor shows itself as a LEARNER, which triggers the suspect check at replica_gc_queue.go:199), and ReplicaGCQueueSuspectCheckInterval (3s) will have elapsed, so the replica would be queued and GC'd promptly — but the scanner has to reach it first.

Recommendation:

1. Add ScanInterval: 100 * time.Millisecond (or similar short interval) to the test's TestServerArgs so the scanner visits all replicas quickly. Many other tests that rely on queue-based processing set short scan intervals.
2. Alternatively, after RemoveLeaseHolderOrFatal, explicitly enqueue r83 into the replica GC queue on store 0 to force fast cleanup.
3. Or use ManuallyEnqueue to trigger the replicaGCQueue on the specific replica.

Related Issues and PRs

Issue/PR	Status	Relationship
#169370	Open	Same test, different failure mode: intent count != 0 (line 327). Prior investigation confirmed it's caused by system transactions holding intents on store 0.
#166114	Closed	Same test, different failure mode: block.cache.hits = 0. Root cause was reproposal loop (#166424).
#164776	Closed	Same test, same cache hits failure. Fixed by bumping cache size.
ed75024021f	Merged	Added DisableRefreshReasonNewLeaderOrConfigChange knob to deflake the cache hits failure mode. Present in the failure SHA.

Timeline

• 18:23:06: Test cluster starts (n1, n2, n3)
• 18:23:07: Range r83 replicated to all 3 stores
• 18:23:07–18:23:13: verifyStatsOnServers cycles: servers 1 and 2 stopped/restarted multiple times
• 18:23:15.114: n2 proposes removal of n1 from r83 (ENTER_JOINT → LEAVE_JOINT → SIMPLE remove)
• 18:23:18.218: First SucceedsSoon retry: "replica still exists on dest 0"
• 18:24:00.263: 45s timeout expires, test fails. n1 never applied the removal.

Detailed evidence and investigation notes

Log Excerpts

The kv-distribution log shows the complete removal sequence on n2:

I260520 18:23:15.114482 ... [n2,s2,r83/2] change replicas (add [] remove [(n1,s1):1VOTER_DEMOTING_LEARNER])
I260520 18:23:15.115947 ... [n2,s2,r83/2] proposing ENTER_JOINT(r1 l1)
I260520 18:23:15.117093 ... [n2,s2,r83/2] change replicas (add [] remove [])
I260520 18:23:15.123909 ... [n2,s2,r83/2] proposing LEAVE_JOINT: after=[(n1,s1):1LEARNER (n2,s2):2 (n3,s3):3]
I260520 18:23:15.125411 ... [n2,s2,r83/2] change replicas (add [] remove [(n1,s1):1LEARNER])
I260520 18:23:15.132816 ... [n2,s2,r83/2] proposing SIMPLE(r1) [(n1,s1):1LEARNER]: after=[(n3,s3):3 (n2,s2):2]

The main log shows the SucceedsSoon polling starting 3 seconds later and continuing for 45 seconds without the replica being removed:

I260520 18:23:18.218418 ... SucceedsSoon: replica still exists on dest 0
I260520 18:23:19.219386 ... SucceedsSoon: replica still exists on dest 0
... (every second for 45 seconds)
I260520 18:23:59.242517 ... SucceedsSoon: replica still exists on dest 0
I260520 18:24:00.263312 ... TestCluster quiescing nodes

No log entry for "removing replica due to ChangeReplicasTrigger" appears on n1, confirming n1 never applied the self-removal.

Health alerts throughout the failure window:

W260520 18:23:16.578977 ... [n1,summaries] health alerts detected: ranges.underreplicated@s1=82

This shows n1 has 82 underreplicated ranges (all system ranges, since n2/n3 are freshly restarted). r83 is the user scratch range.

Code References

• Test failure point: client_metrics_test.go:331-339
• RemoveLeaseHolderOrFatal: testcluster.go:1355-1374 — transfers lease then removes voter
• Self-removal path: replica_application_result.go:671-706 — calls removeInitializedReplicaRaftMuLocked when applying ChangeReplicasTrigger
• replicaIsSuspect: replica_gc_queue.go:186-249 — detects learners as suspect
• Default scan interval: server/config.go:67 — defaultScanInterval = 10 * time.Minute
• ReplicaTooOld fast path: store_raft.go:624-643 — only triggers if the removed replica sends raft messages and gets an error response

Things Ruled Out

• Same failure mode as kv/kvserver: TestStoreMetrics failed #169370 (intent count): This is a different failure point (line 331 vs 327). The current failure is about the replica not being destroyed, not about intent counts.
• Same failure mode as release-26.2: kv/kvserver: TestStoreMetrics failed #166114/kv/kvserver: TestStoreMetrics failed #164776 (block cache hits): Completely different error. The DisableRefreshReasonNewLeaderOrConfigChange fix from ed75024 is present and addresses the cache hits issue.
• Recent code changes to the test: The most recent change to client_metrics_test.go in the failure SHA's history is ed75024 (deflake for reproposal loop), which is unrelated to replica removal.
• Raft message delivery failure due to gRPC issues: While there are closed timestamp connection drops in the logs, these are normal during server restarts and don't affect raft message delivery for the removal entries.

Other Failure Occurrences

This is the first occurrence with the "replica still exists on dest 0" failure mode. Issue #169370 (open, master) has three occurrences, all with the "expected intent count to be zero" failure mode — a completely different root cause. Issues #166114 and #164776 had the "block.cache.hits" failure mode, also different.

Tooling Feedback

• The test's detailed logs (captured to /artifacts/tmp/_tmp/.../logTestStoreMetrics.../) did not include verbose raft-level logging (e.g. MsgApp delivery, raft state transitions for r83 on n1). Having raft trace logs for the specific range would have made it trivial to confirm whether n1 received the removal entry.
• The goroutine dump did not contain identifiable information about r83's raft group state on n1, which would have been valuable to confirm whether the replica was quiesced, a candidate, or still a follower.

---

Workflow run

---

Was this investigation helpful? Leave a 👍 or 👎 on this comment.