Flaky: proposal_apply_tests aborts a plain `cargo test` run intermittently, truncating the suite #82

New issue

Closed

opened 2026-09-23 05:32:04 +00:00 by yuris · 0 comments

yuris commented

2026-09-23 05:32:04 +00:00

Owner

Context

Found while verifying the #53 follow-up (PR #81). Pre-existing — it reproduces on main@37c8101, which predates the follow-up work.

tests/proposal_apply_tests.rs::every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key intermittently aborts a plain cargo test run instead of failing an assertion.

Evidence

Paired loop of 10 runs on main@37c8101: 8/10 green on the affected binary; the same loop on the PR head gave 9/10 — i.e. the flake is not introduced by that PR.
Hit once during the #53 slice's own verification (which is why the full count there was taken with --no-fail-fast).
Hit once during a coordinator verification run on main at 1dfffa8: the summed pass count came out at 632 instead of the true 782, because cargo's default fail-fast stops the remaining test binaries once one fails. The re-run with a clean machine reported 782 passed / 0 failed, exit 0.

Why it matters

A flake that aborts rather than fails is worse than an ordinary flaky assertion:

It silently truncates the suite. Any verification that reads a summed pass count (as this project's review process does) can report a smaller-but-green number and look healthy, which is exactly how the 632 reading slipped through.
cargo test stops early, so unrelated suites never run in that invocation.

What to investigate

Reproduce deterministically first: loop the single binary (nix develop --command cargo test --test proposal_apply_tests) and record the failure rate, then loop the single test.
The symptom is an abort, not a panic — so look for a process-level exit (spawned child killed, port bind race, SQLite busy/lock timeout, or a tokio runtime shutdown racing an in-flight task) rather than a plain assertion.
The test drives a full apply-and-replay through the real router, journal worker and a mock CalDAV backend, so the likely candidates are shared-port binding, a mock-state mutex, or the database worker's shutdown path.
Check whether the same root cause explains other intermittent failures in the suite (any test that spins a listener on a fixed port).

Root cause (found and fixed)

The test helper regenerated the approval body for every call, and that body's approval.reviewed_at is formatted with second precision (Utc::now().to_rfc3339_opts(SecondsFormat::Secs, true)). When the initial apply and the same-key replay straddled a second boundary, the body — and therefore the request fingerprint — changed, so the service correctly answered 409 idempotency_conflict. The test panicked at tests/proposal_apply_tests.rs:1035; cargo's default fail-fast then stopped the remaining test binaries, which is why a summed count read 632 instead of the true total. My original "abort" framing was wrong and the reviewer reconciled it: it was a panic (binary exit 101) causing truncation, not a signal, and no residual nondeterminism remains.

Reproduction: 100% failure (exit 101) when a ≥1.0 s delay forces the second boundary to be crossed; naturally 8–9 runs in 10 green.

Fix (tests-only, PR #84): reuse the exact approval bytes across the replay instead of regenerating them — a new Env::apply_with_approval helper used by all three replay tests. The clock is not frozen globally, so the_same_key_with_a_changed_request_is_an_idempotency_conflict still constructs a genuinely divergent body and still gets its 409. No assertion weakened; no production code touched.

Verified: reviewer's own 20/20 consecutive green runs of cargo test --test proposal_apply_tests (21 passed each), plus a plain cargo test completing the full suite (798 passed, exit 0) — the truncation failure mode is gone.

Acceptance criteria

A reproduction that fails reliably (or a measured rate over a bounded loop) is recorded in the issue or the PR.
The root cause is named, not merely made rarer.
The fix is proven by a bounded loop (e.g. 20 consecutive green runs of the affected binary) with the observed counts reported.
A plain cargo test (no --no-fail-fast) reports the full suite total, so a truncated run can no longer be mistaken for a green one.

## Context Found while verifying the #53 follow-up (PR #81). Pre-existing — it reproduces on `main@37c8101`, which predates the follow-up work. `tests/proposal_apply_tests.rs::every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key` intermittently aborts a plain `cargo test` run instead of failing an assertion. ## Evidence - Paired loop of 10 runs on `main@37c8101`: **8/10 green** on the affected binary; the same loop on the PR head gave 9/10 — i.e. the flake is not introduced by that PR. - Hit once during the #53 slice's own verification (which is why the full count there was taken with `--no-fail-fast`). - Hit once during a coordinator verification run on `main` at `1dfffa8`: the summed pass count came out at **632** instead of the true **782**, because cargo's default fail-fast stops the remaining test binaries once one fails. The re-run with a clean machine reported 782 passed / 0 failed, exit 0. ## Why it matters A flake that *aborts* rather than fails is worse than an ordinary flaky assertion: 1. It silently truncates the suite. Any verification that reads a summed pass count (as this project's review process does) can report a smaller-but-green number and look healthy, which is exactly how the 632 reading slipped through. 2. `cargo test` stops early, so unrelated suites never run in that invocation. ## What to investigate - Reproduce deterministically first: loop the single binary (`nix develop --command cargo test --test proposal_apply_tests`) and record the failure rate, then loop the single test. - The symptom is an abort, not a panic — so look for a process-level exit (spawned child killed, port bind race, SQLite `busy`/lock timeout, or a tokio runtime shutdown racing an in-flight task) rather than a plain assertion. - The test drives a full apply-and-replay through the real router, journal worker and a mock CalDAV backend, so the likely candidates are shared-port binding, a mock-state mutex, or the database worker's shutdown path. - Check whether the same root cause explains other intermittent failures in the suite (any test that spins a listener on a fixed port). ## Root cause (found and fixed) The test helper regenerated the approval body for every call, and that body's `approval.reviewed_at` is formatted with **second** precision (`Utc::now().to_rfc3339_opts(SecondsFormat::Secs, true)`). When the initial apply and the same-key replay straddled a second boundary, the body — and therefore the request fingerprint — changed, so the service correctly answered 409 `idempotency_conflict`. The test panicked at `tests/proposal_apply_tests.rs:1035`; cargo's default fail-fast then stopped the remaining test binaries, which is why a summed count read **632** instead of the true total. My original "abort" framing was wrong and the reviewer reconciled it: it was a panic (binary exit 101) causing truncation, not a signal, and no residual nondeterminism remains. Reproduction: 100% failure (exit 101) when a ≥1.0 s delay forces the second boundary to be crossed; naturally 8–9 runs in 10 green. Fix (tests-only, PR #84): reuse the exact approval bytes across the replay instead of regenerating them — a new `Env::apply_with_approval` helper used by all three replay tests. The clock is **not** frozen globally, so `the_same_key_with_a_changed_request_is_an_idempotency_conflict` still constructs a genuinely divergent body and still gets its 409. No assertion weakened; no production code touched. Verified: reviewer's own 20/20 consecutive green runs of `cargo test --test proposal_apply_tests` (21 passed each), plus a plain `cargo test` completing the full suite (798 passed, exit 0) — the truncation failure mode is gone. ## Acceptance criteria - [x] A reproduction that fails reliably (or a measured rate over a bounded loop) is recorded in the issue or the PR. - [x] The root cause is named, not merely made rarer. - [x] The fix is proven by a bounded loop (e.g. 20 consecutive green runs of the affected binary) with the observed counts reported. - [x] A plain `cargo test` (no `--no-fail-fast`) reports the full suite total, so a truncated run can no longer be mistaken for a green one.

yuris referenced this issue

2026-09-23 05:54:02 +00:00

feat(api): bounded materialized page snapshots for paged reads #83

yuris referenced this issue from a commit

2026-09-23 06:02:59 +00:00

fix(tests): reuse approval payload across proposal apply replays

yuris referenced this issue from a pull request that will close it,

2026-09-23 06:03:11 +00:00

fix(tests): reuse the approval bytes so a proposal-apply replay cannot drift into a fingerprint conflict #84

yuris referenced this issue

2026-09-23 06:10:45 +00:00

fix(tests): reuse the approval bytes so a proposal-apply replay cannot drift into a fingerprint conflict #84