Skip to content

test(consensus): deflake TestWALRoundsSkipper - #1457

Open
lklimek wants to merge 1 commit into
v1.8-devfrom
fix/deflake-wal-rounds-skipper
Open

test(consensus): deflake TestWALRoundsSkipper#1457
lklimek wants to merge 1 commit into
v1.8-devfrom
fix/deflake-wal-rounds-skipper

Conversation

@lklimek

@lklimek lklimek commented Sep 11, 2026

Copy link
Copy Markdown
Collaborator

Issue being fixed or feature implemented

TestWALRoundsSkipper (internal/consensus) is a pre-existing timing flake, independent of any other in-flight change. It has caused unrelated CI failures on at least #1391, #1393 and #1410.

The WAL-generating node is the sole validator in this test, so it proposes every round, and replayPrevoter forces nil votes until round 10 — heights 3-5 can only commit at round 10. The test's genesis gives round 10 only a 30.5ms propose timeout. Under CPU contention (as on a shared CI runner, especially with -race), that timer can fire before the node finishes building its own proposal, so it prevotes nil and the round advances to 11:

  • at height 5, stopConsensusAtHeight(5, 11) then halts consensus and the test times out after 60s waiting for 5 blocks — the exact signature seen in CI;
  • at heights 3-4, the commit lands past maxRound and a replay-order assertion fails instead.

What was done?

internal/consensus/replay_test.go only, test-only change, no production code touched:

  1. Propose-timeout override. UnsafeProposeTimeoutOverride = 10s on the WAL generator node. This is a node-local setting (not a consensus parameter, not part of ConsensusHash), so it does not change blocks, the WAL, or replay behavior — it only removes the race between the timer and the node's own (single-proposer) proposal.
  2. A second, pre-existing flake this exposed. Once the test reliably survives past round 10 under load, the replaying State and its WAL keep logging asynchronously (their context-cancellation watchers) slightly after the test itself returns, which used to panic the test binary (panic: Log in goroutine after TestWALRoundsSkipper has completed). Fixed with a small mutex-guarded logger wrapper that is muted by the test's first-registered cleanup (which runs last, LIFO), closing the check-then-log gap.
  3. New regression test, TestWALRoundsSkipperSlowProposer: its app deliberately holds PrepareProposal at round 10 for 3x the genesis propose timeout, reproducing the CI failure mode on demand.

How Has This Been Tested?

  • Root cause reproduced locally with -v, matching CI's exact failure signature (same "prevoted for nil" sequence, same height/round).
  • Confirmed not a regression from any other change: A/B between two branches under identical load gave statistically equal failure rates (e.g. 25/30 vs 27/30 failures at 1 CPU).
  • TestWALRoundsSkipperSlowProposer: 12/12 FAIL (60s timeout) with the override reverted, 12/12 PASS with it in place.
  • Harsh A/B of TestWALRoundsSkipper itself (10 runs/side, 1 CPU, 3 rounds) on the final code: 30/30 PASS with the fix, 4/30 PASS without.
  • Full, unfiltered go test -mod=readonly -timeout=5m -race ./internal/consensus/... on this branch (based on v1.8-dev): ok, 102.8s, exit 0.
  • make lint: 0 new issues vs origin/v1.8-dev. gofmt clean. go vet clean.

Breaking Changes

None. Test-only change.

Checklist:

  • I have performed a self-review of my own code
  • I have commented my code, particularly in hard-to-understand areas
  • I have added or updated relevant unit/integration/functional/e2e tests
  • I have made corresponding changes to the documentation

🤖 Generated with Claude Code

The WAL generator node is the only validator, so it proposes every round,
and replayPrevoter makes heights 3 to 5 commit only at round 10. The test
genesis gives round 10 a 30.5ms propose timeout. On a loaded runner (-race,
-coverprofile, several packages at once) that timer fires before the node's
own proposal is complete, so it prevotes nil and moves to round 11:
- at height 5, stopConsensusAtHeight(5, 11) halts consensus and the test
  times out after 60s ("waited too long for tendermint to produce 5
  blocks"), which is the failure seen on #1391, #1393 and #1410;
- at height 3 or 4, the commit lands past maxRound and the round assertion
  fails.

Give the generator a 10s propose timeout. With a single proposer, a round
moves on as soon as the proposal is complete, so a longer timeout only
removes the race. UnsafeProposeTimeoutOverride is node-local and not a
consensus parameter, so the blocks are unchanged.

TestWALRoundsSkipperSlowProposer pins this. Its app holds PrepareProposal at
round 10 for three times the genesis propose timeout. Without the override
it fails every run; with it, it passes every run.

Once the test survives load, a second pre-existing flake surfaces. The
replaying State and its WAL keep running after Stop/Wait: receiveRoutine
exits only when it sees its context cancelled, and the services' ctx
watchers log asynchronously. Their logs through NewTestingLogger then land
after the test completes and panic the binary ("Log in goroutine after
TestWALRoundsSkipper has completed"). The test now logs through a writer
that is muted, under a lock, by its first-registered cleanup.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@coderabbitai

coderabbitai Bot commented Sep 11, 2026

Copy link
Copy Markdown
Contributor

Important

Review skipped

Auto reviews are disabled on this repository. Please check the settings in the CodeRabbit UI or the .coderabbit.yaml file in this repository. To trigger a single review, invoke the @coderabbitai review command.

⚙️ Run configuration

Configuration used: Path: .coderabbit.yaml

Review profile: CHILL

Plan: Advanced

Run ID: 9774466d-1c63-48a2-9302-fd266f6e8d80

You can disable this status message by setting the reviews.review_status to false in the CodeRabbit configuration file.

Use the checkbox below for a quick retry:

  • 🔍 Trigger review

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

Comment @coderabbitai help to get the list of available commands.

@thepastaclaw

thepastaclaw commented Sep 11, 2026

Copy link
Copy Markdown

✅ Final review complete — no blockers (commit 7cb69e4) · triage: low

@thepastaclaw thepastaclaw left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Final validation — Phase 1 + Phase 2

The node-local timeout override and slow-proposer regression test address the proposal timing race without changing production consensus behavior. One residual teardown suggestion is confirmed at head 7cb69e4: focused Makefile-driven testing reproduced TempDir cleanup failures in 2 of 60 executions, and race-enabled testing reproduced the same failure in 1 of 4 executions. The working tree remains unchanged.

🟡 1 suggestion(s)

Review provenance

Source: reviewer 1: glm-5.3-flash (agent: phase1-reviewer, role: general); reviewer 2: glm-5.3-flash (agent: phase1-reviewer, role: tenderdash-consensus-security); reviewer 3: gpt-6-astra (agent: phase2-reviewer, role: general); reviewer 4: gpt-6-astra (agent: phase2-reviewer, role: tenderdash-consensus-security); final verifier: gpt-6-astra (agent: astra-verifier, role: final-verifier)

  • Triage: low by gpt-6-astra (effort low) — This is a contained test-only change in internal/consensus that adjusts a node-local timeout, adds a logger synchronization safeguard, and introduces a regression test without modifying production consensus behavior or any critical surface.
  • Phase 1 reviewers: glm-5.3-flash — general (completed, effort high); agent phase1-reviewer, glm-5.3-flash — tenderdash-consensus-security (completed, effort high); agent phase1-reviewer
  • Phase 1 model: glm-5.3-flash — zai quota: 5h 100% left, weekly 24% left; passed over gemini-3.8-flash-high (antigravity below 15% reserve: weekly 38% left, 5h 8% left)
  • Fresh verifier: gpt-6-astra — final-verifier; agent astra-verifier
  • Phase 2 reviewers: gpt-6-astra — general (completed, effort medium); agent phase2-reviewer, gpt-6-astra — tenderdash-consensus-security (completed, effort medium); agent phase2-reviewer
🤖 Prompt for all review comments with AI agents
These findings are from an automated code review. Verify each finding against the current code and only fix it if needed.

In `internal/consensus/replay_test.go`:
- [SUGGESTION] internal/consensus/replay_test.go:1498: Stop replay-side file writes before temporary-directory cleanup
  The muted logger prevents post-test logging panics, but the replaying State can still race temporary-directory removal. BaseService.Stop closes the channel used by cs.Wait without joining receiveRoutine; canceling the test context likewise does not wait for an in-flight proposal or signing operation to finish. FilePV signing persists state through WriteFileAtomic under the replay configuration's data directory. On this exact head, `make test PACKAGES='./internal/consensus -run ^TestWALRoundsSkipper -count=30 -timeout=5m'` reproduced `TempDir RemoveAll cleanup: unlinkat .../003/test-chain-.../data: directory not empty` once in each test, and a race-enabled run reproduced it again in SlowProposer. This is directly relevant to the PR's deflake goal and affects the newly added regression test. Quiesce replay-side processing and wait for its WAL shutdown before removing its directories. If using a bounded stop predicate, stop after the required height-6 block, when State.Height reaches 7; copying the generator's stopConsensusAtHeight(chainLen+1, 0) would stop at height 6 before that block commits. Also account for the stopFn path skipping receiveRoutine's onExit, and note that the existing wal.Wait cleanup waits on the separately opened reader WAL, not cs.wal.

ctx = dash.ContextWithProTxHash(ctx, proTxHash)

cs := newStateWithConfigAndBlockStore(ctx, t, log.NewTestingLogger(t), cfg, state, privVal, app, blockStore)
cs := newStateWithConfigAndBlockStore(ctx, t, logger, cfg, state, privVal, app, blockStore)

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Suggestion: Stop replay-side file writes before temporary-directory cleanup

The muted logger prevents post-test logging panics, but the replaying State can still race temporary-directory removal. BaseService.Stop closes the channel used by cs.Wait without joining receiveRoutine; canceling the test context likewise does not wait for an in-flight proposal or signing operation to finish. FilePV signing persists state through WriteFileAtomic under the replay configuration's data directory. On this exact head, make test PACKAGES='./internal/consensus -run ^TestWALRoundsSkipper -count=30 -timeout=5m' reproduced TempDir RemoveAll cleanup: unlinkat .../003/test-chain-.../data: directory not empty once in each test, and a race-enabled run reproduced it again in SlowProposer. This is directly relevant to the PR's deflake goal and affects the newly added regression test. Quiesce replay-side processing and wait for its WAL shutdown before removing its directories. If using a bounded stop predicate, stop after the required height-6 block, when State.Height reaches 7; copying the generator's stopConsensusAtHeight(chainLen+1, 0) would stop at height 6 before that block commits. Also account for the stopFn path skipping receiveRoutine's onExit, and note that the existing wal.Wait cleanup waits on the separately opened reader WAL, not cs.wal.

source: glm-5.3-flash (phase1-reviewer: general, tenderdash-consensus-security)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants