kv/kvserver: TestRaftTracing failed

[cockroach-teamcity]

kv/kvserver.TestRaftTracing failed on release-25.2 @ 8b09c04432af7832135fb4085bbb02a20662a500:

        	            	  | github.com/cockroachdb/cockroach/pkg/testutils.RunValues[...].func1
        	            	  | 	pkg/testutils/subtest.go:23
        	            	  | testing.tRunner
        	            	  | 	GOROOT/src/testing/testing.go:1690
        	            	  | runtime.goexit
        	            	  | 	src/runtime/asm_amd64.s:1700
        	            	Wraps: (2) unable to find regexp 6 ("(?ms)ack-ing replication success to the client") in remaining string:
        	            	  |
        	            	  |  [71-72]
        	            	  |      6.034ms      1.183ms            event:kv/kvserver/replica_raft.go:1315 [n1,s1,r75/1:/{Table/Max-Max}] applied entries [71-72]
        	            	  |      6.105ms      0.071ms            event:kv/kvserver/replica_raft.go:1315 [n1,s1,r75/1:/{Table/Max-Max}] unregistered log index 72 from tracing
        	            	  |      4.895ms     -1.210ms            === operation:local proposal _verbose:1 node:1 store:1 range:75/1:/{Table/Max-Max} raft:
        	            	  |      5.511ms      0.616ms            event:kv/kvserver/app_batch.go:116 [n1,s1,r75/1:/{Table/Max-Max},raft] applying command
        	            	  |      5.865ms      0.354ms            event:kv/kvserver/replica_application_state_machine.go:185 [n1,s1,r75/1:/{Table/Max-Max},raft] LocalResult (reply: (err: <nil>), *kvpb.PutResponse, #encountered intents: 0, #acquired locks: 0, #resolved locks: 0#updated txns: 0 #end txns: 0, PopulateBarrierResponse:false RepopulateSubsumeResponse:false GossipFirstRange:false MaybeGossipSystemConfig:false MaybeGossipSystemConfigIfHaveFailure:false MaybeAddToSplitQueue:false MaybeGossipNodeLiveness:<nil> 
        	            	  |
        	            	  |
        	            	  | after having matched:
        	            	  |
        	            	  |      0.000ms      0.000ms    === operation:test _verbose:1
        	            	  |      0.000ms      0.000ms    [executeWriteBatch: {count: 1, duration 6ms}]
        	            	  |      0.000ms      0.000ms    [raft trace: {count: 1, duration 4ms}]
        	            	  |      0.000ms      0.000ms    [local proposal: {count: 1, duration 1ms}]
        	            	  |      0.172ms      0.172ms    event:kv/kvserver/store_send.go:149 [n1,s1] executing Put [/Table/Max]
        	            	  |      0.255ms      0.083ms    event:kv/kvserver/replica_send.go:175 [n1,s1,r75/1:/{Table/Max-Max}] read-write path
        	            	  |      0.347ms      0.092ms    event:kv/kvserver/concurrency/concurrency_manager.go:258 [n1,s1,r75/1:/{Table/Max-Max}] sequencing request
        	            	  |      0.415ms      0.068ms    event:kv/kvserver/concurrency/concurrency_manager.go:339 [n1,s1,r75/1:/{Table/Max-Max}] acquiring latches
        	            	  |      0.494ms      0.079ms    event:kv/kvserver/concurrency/concurrency_manager.go:383 [n1,s1,r75/1:/{Table/Max-Max}] scanning lock table for conflicting locks
        	            	  |      0.515ms      0.021ms        === operation:executeWriteBatch _verbose:1 node:1 store:1 range:75/1:/{Table/Max-Max}
        	            	  |      0.515ms      0.000ms        [raft trace: {count: 1, duration 4ms}]
        	            	  |      0.515ms      0.000ms        [local proposal: {count: 1, duration 1ms}]
        	            	  |      0.667ms      0.152ms        event:kv/kvserver/replica_write.go:176 [n1,s1,r75/1:/{Table/Max-Max}] applied timestamp cache
        	            	  |      0.739ms      0.073ms        event:kv/kvserver/replica_write.go:432 [n1,s1,r75/1:/{Table/Max-Max}] executing read-write batch
        	            	  |      1.175ms      0.436ms        event:kv/kvserver/replica_evaluate.go:563 [n1,s1,r75/1:/{Table/Max-Max}] evaluated Put command header:<key:"\372" > value:<raw_bytes:"\000\000\000\000\003value-50" timestamp:<> > , txn=<nil> : resp=header:<> , err=<nil>
        	            	  |      1.266ms      0.091ms        event:kv/kvserver/replica_proposal.go:1050 [n1,s1,r75/1:/{Table/Max-Max}] need consensus on write batch with op count=1
        	            	  |      1.390ms      0.124ms        event:kv/kvserver/replica_raft.go:118 [n1,s1,r75/1:/{Table/Max-Max}] evaluated request
        	            	  |      1.494ms      0.105ms        event:kv/kvserver/replica_raft.go:173 [n1,s1,r75/1:/{Table/Max-Max}] proposing command to write 0 new keys, 1 new values, 0 new intents, write batch size=48 bytes
        	            	  |      1.576ms      0.081ms        event:kv/kvserver/replica_raft.go:287 [n1,s1,r75/1:/{Table/Max-Max}] acquiring proposal quota (199 bytes)
        	            	  |      1.677ms      0.102ms        event:kv/kvserver/replica_raft.go:482 [n1,s1,r75/1:/{Table/Max-Max}] submitting proposal to proposal buffer
        	            	  |      1.802ms      0.124ms        event:kv/kvserver/replica_proposal_buf.go:566 [n1,s1,r75/1:/{Table/Max-Max}] flushing proposal to Raft
        	            	  |      1.830ms      0.028ms            === operation:raft trace _verbose:1 node:1 store:1 range:75/1:/{Table/Max-Max}
        	            	  |      1.981ms      0.151ms            event:kv/kvserver/replica_proposal_buf.go:1192 [n1,s1,r75/1:/{Table/Max-Max}] registering local trace i72/958.82e4
        	            	  |      2.149ms      0.168ms            event:kv/kvserver/replica_raft.go:1988 [n1,s1,r75/1:/{Table/Max-Max}] 1->2 MsgApp Term:6 Log:6/71 Entries:[72-72]
        	            	  |      2.266ms      0.117ms            event:kv/kvserver/replica_raft.go:1988 [n1,s1,r75/1:/{Table/Max-Max}] 1->3 MsgApp Term:6 Log:6/71 Entries:[72-72]
        	            	  |      2.364ms      0.099ms            event:kv/kvserver/replica_raft.go:1250 [n1,s1,r75/1:/{Table/Max-Max}] appended entries [72-72] at leader term 6
        	            	  |      2.594ms      0.230ms            event:kv/kvserver/replica_raft.go:1967 [n1,s1,r75/1:/{Table/Max-Max}] synced log storage write at mark {Term:6 Index:72}
        	            	  |      4.612ms      2.018ms            event:kv/kvserver/replica_raft.go:671 [n1,s1,r75/1:/{Table/Max-Max}] 3->1 MsgAppResp Term:6 Index:72
        	            	  |      4.851ms      0.240ms            event:kv/kvserver/replica_raft.go:1112 [n1,s1,r75/1:/{Table/Max-Max}] applying entries
        	            	Error types: (1) *withstack.withStack (2) *errutil.leafError
        	Test:       	TestRaftTracing/lease-type=LeaseLeader
--- FAIL: TestRaftTracing/lease-type=LeaseLeader (5.83s)

Parameters:

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

Help

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

Same failure on other branches

• kv/kvserver: TestRaftTracing failed #152666 kv/kvserver: TestRaftTracing failed [A-testing C-bug C-test-failure O-robot P-3 T-kv X-duplicate X-nostale branch-release-25.3]

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-61596

[pav-kv]

Dup of #152666

[pav-kv]

/investigate

[github-actions]

Investigation: TestRaftTracing

Investigated failure: #165793 (issue body)
Failure SHA: 8b09c04432af7832135fb4085bbb02a20662a500
Confidence: high

What This Test Does

TestRaftTracing verifies that key events in the Raft replication path are recorded in a client-side tracing span. It sends 100 Put requests, and on the 50th one, attaches a recording span. After the Put completes, it checks that the trace contains a specific sequence of expected log messages, including "ack-ing replication success to the client".

Where the Failure Occurs

The test fails at client_raft_log_queue_test.go:213 because testutils.MatchInOrder cannot find regex 6 ("ack-ing replication success to the client") in the trace output. All preceding expected messages are matched, but the trace ends after "applying entries" and the LocalResult log without ever emitting the ack message.

Analysis

Hypothesis: The traced command is batched with a preceding non-trivial entry during application, bypassing the early-ack path (likely cause, high confidence)

The "ack-ing replication success to the client" message is logged only in replicatedCmd.AckSuccess, which is called from Task.AckCommittedEntriesBeforeApplication. This early-ack path only processes trivial commands (line 211: takeWhileCmdIter stops at the first non-trivial command).

When the traced Put (entry 72) is committed and applied together with a preceding entry (71) -- as shown in the trace output (applied entries [71-72]) -- and entry 71 is a non-trivial command (e.g., a background lease extension, config change, or other system operation), the takeWhileCmdIter in AckCommittedEntriesBeforeApplication stops before reaching entry 72. The traced command is never early-acked.

Instead, entry 72 goes through AckOutcomeAndFinish, which calls finishApplication and signalProposalResult but does not log the "ack-ing replication success" message. The client still gets the result, but the expected trace message is absent.

This is a race condition dependent on what other raft entries happen to be committed at the same time as the traced Put. Under the race detector (which slows down execution), timing changes make it more likely for entries to batch together.

This exact same failure mode has been identified before by @pav-kv in #148896, who noted that CanAckBeforeApplication could return false or the command could get batched in a way that skips the early-ack path.

Recommended fix: As @pav-kv suggested in #148896, replace the "ack-ing replication success to the client" expectation with "applied entries" (which is already asserted) or with a message that appears on both the early-ack and post-application paths. Alternatively, the test could be restructured to avoid the race by ensuring the traced request's entry is the only one being applied (e.g., by waiting for quiescence before sending the traced Put).

Related Issues and PRs

• kv/kvserver: TestRaftTracing failed #152666 — Same test, same failure mode, on release-25.3. Marked as dup of kv/kvserver: TestRaftTracing failed #148896. Still open.
• kv/kvserver: TestRaftTracing failed #148896 — Original investigation by @pav-kv on release-25.2. Same root cause identified. Closed but unfixed; @pav-kv noted a simple fix would be to exclude "ack-ing replication success" from expectations.
• kv/kvserver: TestRaftTracing failed #163031 — Same test failure on master (different failure: a data race during cluster startup). Closed.

All occurrences of TestRaftTracing failures in issues #165793, #152666, and #148896 show the identical error pattern: regex 6 ("ack-ing replication success to the client") is not found in the trace after entries are applied. These are all the same failure mode.

Timeline

This is a long-standing flake. The test was introduced as part of the raft tracing infrastructure. The root cause is an inherent race in how raft entry application batching interacts with the early-ack optimization:

• 2025-06-26: First investigated in kv/kvserver: TestRaftTracing failed #148896 by @pav-kv, root cause identified, simple fix proposed but not implemented.
• 2025-08-28: Recurred in kv/kvserver: TestRaftTracing failed #152666 on release-25.3.
• 2026-03-16: Recurred in kv/kvserver: TestRaftTracing failed #165793 on release-25.2 (this failure).

No code changes have been made to the test or the relevant application code paths on release-25.2 that would address this flake.

Detailed evidence and investigation notes

Log Excerpts

From the issue body, the trace output shows entries [71-72] being applied together:

 [71-72]
     6.034ms      1.183ms            event:kv/kvserver/replica_raft.go:1315 [n1,s1,r75/1:/{Table/Max-Max}] applied entries [71-72]
     6.105ms      0.071ms            event:kv/kvserver/replica_raft.go:1315 [n1,s1,r75/1:/{Table/Max-Max}] unregistered log index 72 from tracing
     4.895ms     -1.210ms            === operation:local proposal ...
     5.511ms      0.616ms            event:kv/kvserver/app_batch.go:116 [...,raft] applying command
     5.865ms      0.354ms            event:kv/kvserver/replica_application_state_machine.go:185 [...,raft] LocalResult ...

The trace ends after LocalResult — there is no "ack-ing replication success" message.

Code References

1. Early ack path — AckCommittedEntriesBeforeApplication: Only processes trivial commands via takeWhileCmdIter (line 211).

2. AckSuccess with log message — replicatedCmd.AckSuccess: Contains the "ack-ing replication success" log event at line 143.

3. Post-application ack (no log message) — replicatedCmd.AckOutcomeAndFinish: Calls finishApplication without the trace message.

4. CanAckBeforeApplication — replicatedCmd.CanAckBeforeApplication: Returns true for the non-transactional Put in question, but this method is only called if the command passes the trivial filter.

5. Trivial batching policy — trivialPolicy.maybeAdd: A batch is either all-trivial or one non-trivial command.

Things Ruled Out

• CanAckBeforeApplication returning false: For a non-transactional Put, IsIntentWrite() returns true (the PutRequest flags include isIntentWrite), AsyncConsensus is false, and there's no EndTxn. So CanAckBeforeApplication would return true if it were called.

• Lease changes / leader changes: The test sets RangeLeaseDuration to 24 hours and suppresses elections. The trace confirms n1 is both leader and leaseholder throughout. A lease change did not cause the issue.

• Test code bug: The test code is straightforward and the expected messages list is correct for the normal (early-ack) code path.

• Race detector data race: Issue kv/kvserver: TestRaftTracing failed #163031 showed a different failure (actual data race in cluster startup), but this failure (kv/kvserver: TestRaftTracing failed #165793) is the missing trace message pattern, not a data race.

Other Failure Occurrences

Issue	Branch	SHA	Failure Mode	Same?
#165793	release-25.2	8b09c04	Missing "ack-ing" in trace	Yes
#152666	release-25.3	59317ae	Missing "ack-ing" in trace	Yes
#148896	release-25.2	0780d51	Missing "ack-ing" in trace	Yes
#163031	master	2a299a8	Data race in cluster startup	No

Tooling Feedback

• EngFlow artifact download failed because the engflow_artifacts.py script was not present at the checked-out SHA (it exists only on master). For future investigations of release-branch failures, having the script available independently of the checked-out commit would be helpful.

Investigation workflow run

---

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