kv/kvserver: TestStoreRangeGossipOnSplits failed

[cockroach-teamcity]

kv/kvserver.TestStoreRangeGossipOnSplits failed on master @ c7892cff8c9d62d0ad22aa9cd04c30dae49d1ed0:

=== RUN   TestStoreRangeGossipOnSplits
    test_log_scope.go:172: test logs captured to: outputs.zip/logTestStoreRangeGossipOnSplits441427212
    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_split_test.go:3026: gossiped range count 121 more than 1 away from expected 131
    client_split_test.go:3032: -- test log scope end --
test logs left over in: outputs.zip/logTestStoreRangeGossipOnSplits441427212
--- FAIL: TestStoreRangeGossipOnSplits (12.17s)

Parameters:

• attempt=1
• race=true
• run=3
• shard=17

Help

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

/cc @cockroachlabs/kv-triage

Improve this report!

Jira issue: CRDB-68712

[angeladietz]

/investigate

[github-actions]

Investigation: kv/kvserver.TestStoreRangeGossipOnSplits

Investigated failure: issue body (EngFlow 97a11331-4564-4870-86de-ebec90960ae6, race=true, run=3, shard=17)
Failure SHA: c7892cff8c9d62d0ad22aa9cd04c30dae49d1ed0
Confidence: high

What This Test Does

TestStoreRangeGossipOnSplits
verifies that a store re-gossips its StoreDescriptor when its range count grows
past a threshold. It overrides the capacity-delta fraction to 50%, registers a
gossip callback on the store-descriptor key, splits ranges one at a time, and
asserts that every gossip event it observes lands within ±1 of the predicted
trigger point lastRangeCount + ceil(max(0.5*lastRangeCount, 5)).

Where the Failure Occurs

client_split_test.go:3026:

client_split_test.go:3026: gossiped range count 121 more than 1 away from expected 131

The cluster booted with 87 ranges (87 range descriptors in the node log), so
the test's baseline was lastRangeCount = 87 and its predicted trigger point was
87 + ceil(87*0.5) = 131. The gossip event it actually received carried
RangeCount = 121.

Analysis

Hypothesis 1 — the observed gossip came from the unconditional 10-second
periodic store gossip, not from the range-count capacity-delta trigger the test
is trying to measure. Confidence: high.

The test disables the lease, load, IO-threshold and disk-unhealthy capacity-delta
triggers via StoreGossipTestingKnobs, so it assumes range count is the only
thing that can cause a store-descriptor gossip. That assumption is wrong:
Node.startGossiping
runs a time.Ticker at gossip.StoresInterval (10 s) that calls
Node.gossipStores
→ Store.GossipStore(ctx, false /* useCached */). This path goes straight to
GossipStore/AddInfoProto and never consults
shouldGossipOnCapacityDelta —
so none of the test's Disable*CapacityGossip knobs suppress it.

Converging evidence:

1. The range-count trigger provably did not fire. With lastGossiped = 87
   and fraction 0.5, deltaExceedsThreshold needs |cur-87| >= 43.5, i.e.
   cur >= 131. The test only ever reached 122 ranges (last split created r122).
   At 121 the fractional delta is 34/87 = 0.39 < 0.5.
2. Every other reactive trigger is knob-disabled (lease / load / IO-threshold /
   disk-unhealthy). Grepping the tree, the only remaining callers of
   Store.GossipStore are node.go:1059 (one-shot at store bootstrap) and
   node.go:1125 (the periodic gossipStores).
3. Timing matches to within ~50 ms. n.startGossiping is invoked at
   node.go:820,
   immediately before the started with attributes [] log line at
   13:35:56.907. First ticker fire ≈ 13:36:06.907. The gossiped descriptor
   carried RangeCount = 121, which was only true between 13:36:06.85
   (r121 created) and 13:36:06.92 (r122 created); the test aborted by
   13:36:06.99.
4. No capacity-delta gossip was logged at all. The test sets
   SetVModule("store_gossip=2"), and asyncGossipStore logs
   gossiping on <reason> at V(2). There is not a single store_gossip.go line
   in any of the captured logs — consistent with "the delta path never fired".
   (Caveat: this is not a positive control; I can't prove from this run alone
   that the vmodule took effect.)

Why it's flaky rather than always-failing. The test must complete 44 splits
before the 10 s tick. In this run, server startup was pathologically slow under
the race detector: serving sql connections only at 13:36:04.785, ~7.9 s
after node start, with a logged has held latch for 7.6s on r5 (/System/tsd).
That left only ~2.1 s of split time, and at ~62 ms/split under race the test
managed just 35 splits (87 → 122) before the tick landed. On a healthy run the
server is up in 1–2 s, leaving ~8 s — plenty for 44 splits.

Ruled out: a race between two concurrent GossipStore calls desynchronising
the store's lastGossiped from the test's view. The error message itself pins
the test's baseline at 87 (expected 131 ⟹ lastRangeCount = 87), and
GossipStore writes lastGossiped from the very descriptor it publishes, so no
divergence is needed to explain the data.

Recommendations (roughly in order of preference):

• Assert on the trigger, not the effect. Surface the reason string from
  shouldGossipOnCapacityDelta through a testing knob and only evaluate gossip
  events whose reason contains range-count. This makes the test immune to every
  out-of-band gossip source, present and future.
• Alternatively, add a testing knob to suppress (or greatly lengthen) the periodic
  Node.gossipStores loop for this test. Note gossip.StoresInterval is a
  const today, so it would need to become a variable or a Node-level knob.
• Weaker but cheap: have the test ignore gossip events whose range count is still
  below the predicted trigger point, and only assert on the first event at or
  above it. All four recent failures report a count below 131, so this alone would
  have suppressed every one of them — at the cost of no longer catching
  gossip-too-early regressions.

Related Issues and PRs

• #174146 (closed
  2026-09-04) — same failure mode: gossiped range count 123 more than 1 away from expected 131, race=true, 11.95 s. Closed as fixed by
  cockroachlabs/cockroach PR sql: Create a suite of benchmarks for aggregation functions #4139 (the disk-unhealthy capacity-gossip knob).
  That commit (9fc206aad49, 2026-09-03) is an ancestor of the failure SHA,
  so that fix did not address this failure mode.
• #173348 (closed
  2026-08-19) — gossiped range count 99 ... expected 131, race=true, 18.97 s.
• #171773 (closed
  2026-06-19) — gossiped range count 124 ... expected 131, race=true, 12.07 s.
• Older history (2016–2024): #117221,
  #95566, and a long tail
  of 2017 stress failures — this test has a decade-long flake history.

All four recent failures share the identical signature: expected 131, observed
below 131 (99 / 121 / 123 / 124), always race=true, always run 2 or 3. The
consistent "early, never late" direction is the signature of an out-of-band
gossip event, not of a missed or coalesced one.

Timeline

Time (UTC)	Event
13:35:56.512	loaded 87 replicas → baseline range count 87
13:35:56.907	startGossiping ticker created (node.go:820 / :1096); 10 s tick armed
13:35:57.05	node_join; startup gossipStores publishes descriptor with RangeCount 87
13:35:57–13:36:04	startup stall — has held latch for 7.6s on r5 (/System/tsd)
13:36:04.785	serving sql connections; StartServerOnly returns
13:36:04.794	first split ("00" → r88)
13:36:06.818	split "33" → r121
13:36:06.90	predicted first gossipStores tick — gossips RangeCount 121
13:36:06.880	split "34" → r122 (last)
13:36:06.92–.99	test receives 121, t.Errorf, loop exits, shutdown

Recent history of the test file shows repeated deflake attempts targeting
capacity-delta triggers (9fc206aad49 disk-unhealthy knob, 0eaced84ad2
store_gossip verbosity bump) — none of which touch the periodic path.

Detailed evidence and investigation notes

Log Excerpts

Baseline range count:

I260922 13:35:56.512619 ... kvstorage/init.go:675 [T1,Vsystem,n1,s1] 31  loaded 87 replicas
I260922 13:35:56.905426 ... server/node.go:728  [T1,Vsystem,n1] 35  initialized store s1 in 491ms (87 replicas)
I260922 13:35:56.907299 ... server/node.go:837  [T1,Vsystem,n1] 36  started with attributes []

(n.startGossiping(workersCtx, n.stopper) is node.go:820, i.e. ~immediately before line 837.)

Startup stall that compressed the split window:

W260922 13:36:04.747733 ... spanlatch/manager.go:793 [T1,Vsystem,n1,s1,r5/1:/System{/tsd-tse},raft] 283
  Merge [/System/tsd/...] has held latch for 7.6s. Some possible causes are slow disk
  reads, slow raft replication, and expensive request processing.
I260922 13:36:04.785574 ... server_sql.go:2198 [T1,Vsystem,n1] 285  serving sql connections

Split window (35 splits in ~2.1 s, ~62 ms each):

I260922 13:36:04.793795 ... replica_command.go:585  186  initiating a split of this range at key "00" [r88] (test)
...
I260922 13:36:06.818787 ... replica_command.go:585  287  initiating a split of this range at key "33" [r121] (test)
I260922 13:36:06.879862 ... replica_command.go:585  290  initiating a split of this range at key "34" [r122] (test)
I260922 13:36:06.918501 ... cmd_end_transaction.go:1455 [... r121/1:{33-/Table/0}] 292  falling back to accurate stats

Nothing from store_gossip.go appears in any log file despite SetVModule("store_gossip=2").

Code References

The unconditional periodic path, which bypasses all the test's knobs:

// pkg/server/node.go:1096
storesTicker := time.NewTicker(gossip.StoresInterval)   // 10s
...
case <-storesTicker.C:
    n.gossipStores(ctx)

// pkg/server/node.go:1123
func (n *Node) gossipStores(ctx context.Context) {
    if err := n.stores.VisitStores(func(s *kvserver.Store) error {
        return s.GossipStore(ctx, false /* useCached */)
    }); err != nil { ... }
}

The threshold the test models,
store_gossip.go:486
and
deltaExceedsThreshold:

exceeds = deltaAbsolute >= requiredMinDelta && deltaFraction >= requiredDeltaFraction
// old=87, requiredMinDelta=5, requiredDeltaFraction=0.5  =>  needs cur >= 131

Things Ruled Out

• Range-count delta trigger firing early. Arithmetic rules it out: at 121 the
  fraction is 0.39, below the 0.5 override.
• Lease-count / load / IO-threshold / disk-unhealthy triggers. All four are
  explicitly disabled by StoreGossipTestingKnobs in the test, and the
  corresponding update* flags are forced to false before the reason string is
  built.
• Two concurrent GossipStore calls desynchronising lastGossiped from the
  test's view. Would require the store's lastGossiped.RangeCount to be ~80
  while the test saw 87; the expected 131 in the message pins the test's
  baseline at 87, and no divergence is needed to explain the observation.
• A dropped/coalesced gossip event. The callback sends on an unbuffered
  channel, so events block rather than being lost, and a missed event would
  produce a count above 131, not below. All four recent failures are below.
• MaxStoreGossipFrequency override (0 ms). This only removes a rate limit;
  it cannot cause gossip that the delta check rejected.
• A recent regression. This test has failed with the same signature
  intermittently since at least 2026-06, and with related signatures since 2016.
  Nothing in the recent history of client_split_test.go or store_gossip.go
  correlates with the current failures.

Other Failure Occurrences

This issue thread contains a single failure. Cross-thread comparison is in
Related Issues and PRs above: #174146, #173348 and #171773 all report
expected 131 with an observed count below it, under race=true, with runtimes
of 12–19 s. I treat them as the same failure mode. I attempted to download the
artifacts for #174146 (EngFlow invocation 2ae95962-…) to confirm the 10-second
alignment a second time, but the CAS blobs have been garbage-collected
(HTTP 404), so that cross-check is unavailable.

Tooling Feedback

• python3 is not in the allowlist, so the engflow_artifacts.py invocation shown
  in .github/prompts/investigate.md is denied; only
  .claude/skills/engflow-artifacts/run.sh works. Worth updating the prompt's
  examples to use run.sh.
• EngFlow CAS blobs for builds older than a few weeks are garbage-collected, which
  blocked the cross-check against issue kv/kvserver: TestStoreRangeGossipOnSplits failed #174146's artifacts. Not fixable here, but
  worth knowing: historical artifact comparison has a short shelf life.
• The engflow-artifacts downloader writes the HTTP error body into the output
  file on a 404 and still reports "Saved to …", so a failed download looks like a
  successful one until you inspect the file. A non-zero exit on HTTP errors would
  help.
• No blocked commands beyond the python3 case above.

---

Workflow run

---

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

---

Generated by claude-opus-5 at high effort. Use /investigate fable-5-1 max to go deeper.

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