yuris/life-service
1
0
Fork 0
Code Issues Pull requests Projects Releases 6 Packages 1 Wiki Activity Actions

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

Merged
yuris merged 1 commit from feat/issue-82-flake into main 2026-09-23 06:11:46 +00:00
Conversation 1 Commits 1 Files changed 1 +20 -9
yuris commented 2026-09-23 06:03:11 +00:00
Owner
Copy link

Summary

Fixes the intermittent test abort/failure in tests/proposal_apply_tests.rs::every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key that caused cargo test to fail-fast and truncate the test suite.

Closes #82

Captured Failure

When the test failed, cargo test aborted with:

thread 'every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key' panicked at tests/proposal_apply_tests.rs:1035:5:
assertion `left == right` failed: REPLAY FAILED: error=Some(ErrorItem { code: "idempotency_conflict", message: "Operation 'op_full_apply' was already recorded with a different request (recorded sha256:625c952872a3b5cca8d242525601c0f83970fdc93f935cb75cd7533f039a88d9, incoming sha256:028d11f43e8f0d108c2e12a0c1a7b441d07194f0e4be3b6bbae54eee9355a873)", retryable: false, operation_id: Some("op_full_apply"), details: None }) data=Some(Object {"operation_id": String("op_full_apply"), "operation_state": String("applied")})
  left: Error
 right: Ok

Under cargo test's default fail-fast behavior, any single test panic causes cargo test to immediately stop executing remaining test suites, truncating the run and leaving a smaller passed count (e.g. 632 instead of the full 782/791) that appeared green to anything merely summing test result lines without checking the exit code or suite count.

Root Cause

In tests/proposal_apply_tests.rs:

  1. Env::apply_with_key constructed approval payloads by calling approval_body(digest) on each invocation.
  2. approval_body(digest) formats the current time into approval.reviewed_at: 
    "reviewed_at": Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Secs, true),
    which truncates to integer seconds.
  3. The server computes a canonical request fingerprint in src/history/fingerprint.rs::compute_fingerprint by hashing the request body, including approval.reviewed_at. Per the_same_key_with_a_changed_request_is_an_idempotency_conflict, a changed review timestamp represents a distinct semantic approval and is intentionally treated as an idempotency conflict.
  4. When every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key performed its same-key replay: 
    // Initial apply
let (status, envelope) = env.apply_with_key(id, key, digest).await;
...
// A same-key replay reports the recorded outcome without a second write.
let (_, replay) = env.apply_with_key(id, key, digest).await;
    If the clock ticked over to the next second during the ~50-100ms between the initial apply and the replay, apply_with_key regenerated approval_body with a different reviewed_at. The incoming request fingerprint no longer matched the recorded operation's fingerprint (request_hash != fingerprint), returning idempotency_conflict (HTTP 409, ResponseStatus::Error) instead of the recorded Ok outcome.
  5. This failure mode was 100% reproducible by inserting a 1.1s delay before the replay call.

Fix

  1. Added Env::apply_with_approval(&self, proposal_id, operation_id, body: Value) to allow caller-controlled approval payloads.
  2. Made Env::apply_with_key delegate to apply_with_approval(proposal_id, operation_id, approval_body(digest)).
  3. Updated the tests verifying same-key replays (every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key, a_step_that_conflicts_stops_the_apply_without_rolling_anything_back, and a_replayed_apply_without_a_recorded_outcome_reports_its_recorded_progress) to generate the approval body once and reuse the exact identical payload for both the initial apply and the replay call.
  4. Preserved all product fingerprinting semantics and existing conflict assertions unchanged.

Verification

  1. Forced 1.1s delay reproduction:
    • Before fix: 100% failure (left: Error, right: Ok, idempotency_conflict).
    • After fix: 100% pass (finished in 1.16s, test result: ok. 1 passed).
  2. 20-run loop of affected binary:
    cargo test --test proposal_apply_tests
    • All 20/20 runs passed (21 passed each run, 0 failed).
  3. Plain full suite execution (no --no-fail-fast):
    cargo test
    • Exit code: 0
    • 44 test suites completed (46 test result lines).
    • Total passed: 791, 0 failed, 0 ignored.
  4. Code cleanliness:
    • cargo fmt --check — clean (exit 0).
    • cargo clippy --all-targets -- -D warnings — clean (exit 0).
## Summary Fixes the intermittent test abort/failure in `tests/proposal_apply_tests.rs::every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key` that caused `cargo test` to fail-fast and truncate the test suite. Closes #82 ## Captured Failure When the test failed, `cargo test` aborted with: ```text thread 'every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key' panicked at tests/proposal_apply_tests.rs:1035:5: assertion `left == right` failed: REPLAY FAILED: error=Some(ErrorItem { code: "idempotency_conflict", message: "Operation 'op_full_apply' was already recorded with a different request (recorded sha256:625c952872a3b5cca8d242525601c0f83970fdc93f935cb75cd7533f039a88d9, incoming sha256:028d11f43e8f0d108c2e12a0c1a7b441d07194f0e4be3b6bbae54eee9355a873)", retryable: false, operation_id: Some("op_full_apply"), details: None }) data=Some(Object {"operation_id": String("op_full_apply"), "operation_state": String("applied")}) left: Error right: Ok ``` Under `cargo test`'s default fail-fast behavior, any single test panic causes `cargo test` to immediately stop executing remaining test suites, truncating the run and leaving a smaller passed count (e.g. 632 instead of the full 782/791) that appeared green to anything merely summing `test result` lines without checking the exit code or suite count. ## Root Cause In `tests/proposal_apply_tests.rs`: 1. `Env::apply_with_key` constructed approval payloads by calling `approval_body(digest)` on each invocation. 2. `approval_body(digest)` formats the current time into `approval.reviewed_at`: ```rust "reviewed_at": Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Secs, true), ``` which truncates to integer seconds. 3. The server computes a canonical request fingerprint in `src/history/fingerprint.rs::compute_fingerprint` by hashing the request body, including `approval.reviewed_at`. Per `the_same_key_with_a_changed_request_is_an_idempotency_conflict`, a changed review timestamp represents a distinct semantic approval and is intentionally treated as an idempotency conflict. 4. When `every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key` performed its same-key replay: ```rust // Initial apply let (status, envelope) = env.apply_with_key(id, key, digest).await; ... // A same-key replay reports the recorded outcome without a second write. let (_, replay) = env.apply_with_key(id, key, digest).await; ``` If the clock ticked over to the next second during the ~50-100ms between the initial apply and the replay, `apply_with_key` regenerated `approval_body` with a different `reviewed_at`. The incoming request fingerprint no longer matched the recorded operation's fingerprint (`request_hash != fingerprint`), returning `idempotency_conflict` (HTTP 409, `ResponseStatus::Error`) instead of the recorded `Ok` outcome. 5. This failure mode was 100% reproducible by inserting a 1.1s delay before the replay call. ## Fix 1. Added `Env::apply_with_approval(&self, proposal_id, operation_id, body: Value)` to allow caller-controlled approval payloads. 2. Made `Env::apply_with_key` delegate to `apply_with_approval(proposal_id, operation_id, approval_body(digest))`. 3. Updated the tests verifying same-key replays (`every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key`, `a_step_that_conflicts_stops_the_apply_without_rolling_anything_back`, and `a_replayed_apply_without_a_recorded_outcome_reports_its_recorded_progress`) to generate the approval body once and reuse the exact identical payload for both the initial apply and the replay call. 4. Preserved all product fingerprinting semantics and existing conflict assertions unchanged. ## Verification 1. **Forced 1.1s delay reproduction:** - Before fix: 100% failure (`left: Error, right: Ok`, `idempotency_conflict`). - After fix: 100% pass (finished in 1.16s, `test result: ok. 1 passed`). 2. **20-run loop of affected binary:** `cargo test --test proposal_apply_tests` - All 20/20 runs passed (21 passed each run, 0 failed). 3. **Plain full suite execution (no `--no-fail-fast`):** `cargo test` - Exit code: 0 - 44 test suites completed (46 test result lines). - Total passed: 791, 0 failed, 0 ignored. 4. **Code cleanliness:** - `cargo fmt --check` — clean (exit 0). - `cargo clippy --all-targets -- -D warnings` — clean (exit 0).
The proposal apply tests intermittently failed during replay with an
idempotency conflict (HTTP 409 / ResponseStatus::Error) instead of
returning the recorded outcome. The root cause was that `env.apply_with_key`
regenerated the approval payload via `approval_body(digest)`, which formats
`Utc::now()` down to whole seconds. When the second boundary ticked between
the initial apply and the replay, `reviewed_at` changed, altering the
canonical request fingerprint and triggering a genuine idempotency conflict.

Introduce `apply_with_approval` on `Env` to allow tests verifying same-key
same-payload replays to resend the exact approval body they started with.

Closes #82
yuris commented 2026-09-23 06:10:45 +00:00
Author
Owner
Copy link

Verdict: APPROVE

The pull request cleanly fixes the root cause of the intermittent test failure and suite truncation in tests/proposal_apply_tests.rs. The fix correctly reuses the exact approval bytes across replay calls rather than freezing the clock globally or weakening any assertion, and leaves product code completely untouched.

Per-criterion Evaluation

Acceptance Criterion Status Evidence
A reproduction that fails reliably (or a measured rate over a bounded loop) is recorded in the issue or the PR MET PR body documents a 100% failure reproduction when forcing a 1.1s delay across integer-second boundaries, capturing the exact assertion panic at tests/proposal_apply_tests.rs:1035 (left: Error, right: Ok, idempotency_conflict).
The root cause is named, not merely made rarer MET Root cause is precisely identified: approval_body(digest) generates reviewed_at with 1-second precision using Utc::now(). When initial apply and replay calls straddled a second boundary, the request body differed, producing a different SHA-256 fingerprint in compute_fingerprint. The server correctly answered 409 idempotency_conflict, failing the replay assertion. The fix resends the identical approval payload rather than regenerating it.
The fix is proven by a bounded loop (e.g. 20 consecutive green runs of the affected binary) with the observed counts reported MET PR reports 20/20 green runs (21 passed each run). Independent reviewer verification confirmed 20/20 consecutive green runs of cargo test --test proposal_apply_tests (21 passed, 0 failed on every iteration).
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 MET Plain cargo test executes cleanly to completion with exit code 0, reporting all 798 passed tests across 45 test result lines without early termination.

Key Review Focus Areas

  1. "Reuse the exact bytes you sent" vs "freeze the clock globally":

    • The fix implements "reuse the exact bytes you sent".
    • approval_body(digest) continues to generate dynamic timestamps using Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Secs, true). The clock is not frozen globally.
    • A new helper Env::apply_with_approval(&self, proposal_id, operation_id, body: Value) allows callers to provide the exact JSON payload. Replay tests create the approval body once and supply it to both the initial apply and the replay.
    • This preserves realistic timestamp formatting coverage while eliminating spurious payload drift.

  2. Integrity of the_same_key_with_a_changed_request_is_an_idempotency_conflict:

    • The test was left untouched in the diff (lines 976–999).
    • It performs an initial apply via env.apply_with_key, then issues a second request with the same key but an explicitly altered timestamp (reviewed_at: "2030-04-08T06:10:00Z").
    • Because approval_body was not made deterministic or frozen to a fixed value, this test continues to genuinely produce a divergent request body, correctly receives HTTP 409 idempotency_conflict, and verifies 0 additional calendar writes. Verified passing in isolation.

  3. Reconciling the "abort" symptom with the captured "panic":

    • Issue #82 described the flake as "aborting a plain cargo test run intermittently, truncating the suite" and hypothesized a process-level abort (exit without assertion).
    • In reality, Cargo's default behavior across multi-binary test suites is --fail-fast. When assert_eq!(replay.status, ResponseStatus::Ok) panicked on 409 idempotency_conflict, the proposal_apply_tests binary exited 101. Cargo immediately aborted execution of subsequent test binaries, truncating the run and leaving an incomplete pass count (e.g. 632 instead of 782+).
    • The captured panic fully explains the truncated suite symptom. There is no residual nondeterminism, poisoned lock, or secondary abort.

  4. Appropriate scope and level of the fix:

    • The author added Env::apply_with_approval and updated all three replay tests in tests/proposal_apply_tests.rs:
      • a_step_that_conflicts_stops_the_apply_without_rolling_anything_back
      • every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key
      • a_replayed_apply_without_a_recorded_outcome_reports_its_recorded_progress
    • Single-shot apply calls retain env.apply_with_key or env.apply (which generates fresh UUIDs per call). No remaining replay tests regenerate payloads mid-test.

  5. Diff cleanliness and production safety:

    • 100% tests-only diff (tests/proposal_apply_tests.rs, 20 insertions, 9 deletions).
    • Zero lines of production code in src/ were touched.
    • Zero assertions were removed, weakened, or bypassed.

Findings

  • None. No defects, blockers, or regressions identified.

Verification I Ran

All checks executed from worktree /Users/yurisasc/Development/Other/life-service/.worktrees/issue-82-flake (head eefb0a3, base main at 255ce17):

  1. 20-run loop of affected binary:

    for i in $(seq 1 20); do
  nix develop --command cargo test --test proposal_apply_tests
done
    • Result: 20/20 runs passed. Each run: 21 passed; 0 failed; 0 ignored.

  2. Full test suite execution (plain cargo test, default fail-fast):

    nix develop --command cargo test
    • Result: Exit 0. 45 test result: ok lines completed. Total passed: 798 passed, 0 failed, 0 ignored.

  3. Targeted test of idempotency conflict path:

    nix develop --command cargo test --test proposal_apply_tests the_same_key_with_a_changed_request_is_an_idempotency_conflict
    • Result: Exit 0. 1 passed; 0 failed.

  4. Clippy check:

    nix develop --command cargo clippy --all-targets -- -D warnings
    • Result: Exit 0. Clean (no warnings).

  5. Format check:

    nix develop --command cargo fmt --check
    • Result: Exit 0. Clean.

PR-body Claims

  • Claim: "Total passed: 791, 0 failed, 0 ignored."
    • Review note: On the rebased head against main@255ce17 (which incorporates PR #83's 7 new tests in tests/issue45_pagination_tests.rs), the suite now reports 798 passed, 0 failed. The PR author's 791 figure accurately reflected the baseline prior to PR #83.
  • Claim: "When the test failed, cargo test aborted with: ... assertion left == right failed: REPLAY FAILED: error=Some(ErrorItem { code: "idempotency_conflict" ... })"
    • Review note: The assertion on main was assert_eq!(replay.status, ResponseStatus::Ok). The message REPLAY FAILED: error=... was formatted in the author's reproduction harness to capture payload details on failure. The failure mode and panic are authentic.

Anything I Could Not Check

  • Forced-delay reproduction run: Tracked files were not modified during this review to respect the read-only constraint. Because compute_fingerprint hashes the whole body including approval.reviewed_at (formatted with second precision), a >= 1.0s delay deterministically triggers the conflict prior to the fix. Analytical verification confirms the mechanism.
## Verdict: APPROVE The pull request cleanly fixes the root cause of the intermittent test failure and suite truncation in `tests/proposal_apply_tests.rs`. The fix correctly reuses the exact approval bytes across replay calls rather than freezing the clock globally or weakening any assertion, and leaves product code completely untouched. --- ### Per-criterion Evaluation | Acceptance Criterion | Status | Evidence | | :--- | :---: | :--- | | **A reproduction that fails reliably (or a measured rate over a bounded loop) is recorded in the issue or the PR** | **MET** | PR body documents a 100% failure reproduction when forcing a 1.1s delay across integer-second boundaries, capturing the exact assertion panic at `tests/proposal_apply_tests.rs:1035` (`left: Error, right: Ok`, `idempotency_conflict`). | | **The root cause is named, not merely made rarer** | **MET** | Root cause is precisely identified: `approval_body(digest)` generates `reviewed_at` with 1-second precision using `Utc::now()`. When initial apply and replay calls straddled a second boundary, the request body differed, producing a different SHA-256 fingerprint in `compute_fingerprint`. The server correctly answered 409 `idempotency_conflict`, failing the replay assertion. The fix resends the identical approval payload rather than regenerating it. | | **The fix is proven by a bounded loop (e.g. 20 consecutive green runs of the affected binary) with the observed counts reported** | **MET** | PR reports 20/20 green runs (21 passed each run). Independent reviewer verification confirmed 20/20 consecutive green runs of `cargo test --test proposal_apply_tests` (21 passed, 0 failed on every iteration). | | **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** | **MET** | Plain `cargo test` executes cleanly to completion with exit code 0, reporting all 798 passed tests across 45 test result lines without early termination. | --- ### Key Review Focus Areas 1. **"Reuse the exact bytes you sent" vs "freeze the clock globally":** - The fix implements "reuse the exact bytes you sent". - `approval_body(digest)` continues to generate dynamic timestamps using `Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Secs, true)`. The clock is not frozen globally. - A new helper `Env::apply_with_approval(&self, proposal_id, operation_id, body: Value)` allows callers to provide the exact JSON payload. Replay tests create the approval body once and supply it to both the initial apply and the replay. - This preserves realistic timestamp formatting coverage while eliminating spurious payload drift. 2. **Integrity of `the_same_key_with_a_changed_request_is_an_idempotency_conflict`:** - The test was left untouched in the diff (lines 976–999). - It performs an initial apply via `env.apply_with_key`, then issues a second request with the same key but an explicitly altered timestamp (`reviewed_at: "2030-04-08T06:10:00Z"`). - Because `approval_body` was not made deterministic or frozen to a fixed value, this test continues to genuinely produce a divergent request body, correctly receives HTTP 409 `idempotency_conflict`, and verifies 0 additional calendar writes. Verified passing in isolation. 3. **Reconciling the "abort" symptom with the captured "panic":** - Issue #82 described the flake as "aborting a plain `cargo test` run intermittently, truncating the suite" and hypothesized a process-level abort (exit without assertion). - In reality, Cargo's default behavior across multi-binary test suites is `--fail-fast`. When `assert_eq!(replay.status, ResponseStatus::Ok)` panicked on 409 `idempotency_conflict`, the `proposal_apply_tests` binary exited 101. Cargo immediately aborted execution of subsequent test binaries, truncating the run and leaving an incomplete pass count (e.g. 632 instead of 782+). - The captured panic fully explains the truncated suite symptom. There is no residual nondeterminism, poisoned lock, or secondary abort. 4. **Appropriate scope and level of the fix:** - The author added `Env::apply_with_approval` and updated all three replay tests in `tests/proposal_apply_tests.rs`: - `a_step_that_conflicts_stops_the_apply_without_rolling_anything_back` - `every_step_applied_marks_the_proposal_applied_and_replays_under_the_same_key` - `a_replayed_apply_without_a_recorded_outcome_reports_its_recorded_progress` - Single-shot apply calls retain `env.apply_with_key` or `env.apply` (which generates fresh UUIDs per call). No remaining replay tests regenerate payloads mid-test. 5. **Diff cleanliness and production safety:** - 100% tests-only diff (`tests/proposal_apply_tests.rs`, 20 insertions, 9 deletions). - Zero lines of production code in `src/` were touched. - Zero assertions were removed, weakened, or bypassed. --- ### Findings - None. No defects, blockers, or regressions identified. --- ### Verification I Ran All checks executed from worktree `/Users/yurisasc/Development/Other/life-service/.worktrees/issue-82-flake` (head `eefb0a3`, base `main` at `255ce17`): 1. **20-run loop of affected binary:** ```bash for i in $(seq 1 20); do nix develop --command cargo test --test proposal_apply_tests done ``` - **Result:** 20/20 runs passed. Each run: 21 passed; 0 failed; 0 ignored. 2. **Full test suite execution (plain `cargo test`, default fail-fast):** ```bash nix develop --command cargo test ``` - **Result:** Exit 0. 45 `test result: ok` lines completed. Total passed: **798 passed**, 0 failed, 0 ignored. 3. **Targeted test of idempotency conflict path:** ```bash nix develop --command cargo test --test proposal_apply_tests the_same_key_with_a_changed_request_is_an_idempotency_conflict ``` - **Result:** Exit 0. 1 passed; 0 failed. 4. **Clippy check:** ```bash nix develop --command cargo clippy --all-targets -- -D warnings ``` - **Result:** Exit 0. Clean (no warnings). 5. **Format check:** ```bash nix develop --command cargo fmt --check ``` - **Result:** Exit 0. Clean. --- ### PR-body Claims - **Claim:** `"Total passed: 791, 0 failed, 0 ignored."` - **Review note:** On the rebased head against `main@255ce17` (which incorporates PR #83's 7 new tests in `tests/issue45_pagination_tests.rs`), the suite now reports **798 passed, 0 failed**. The PR author's 791 figure accurately reflected the baseline prior to PR #83. - **Claim:** `"When the test failed, cargo test aborted with: ... assertion left == right failed: REPLAY FAILED: error=Some(ErrorItem { code: "idempotency_conflict" ... })"` - **Review note:** The assertion on `main` was `assert_eq!(replay.status, ResponseStatus::Ok)`. The message `REPLAY FAILED: error=...` was formatted in the author's reproduction harness to capture payload details on failure. The failure mode and panic are authentic. --- ### Anything I Could Not Check - **Forced-delay reproduction run:** Tracked files were not modified during this review to respect the read-only constraint. Because `compute_fingerprint` hashes the whole body including `approval.reviewed_at` (formatted with second precision), a >= 1.0s delay deterministically triggers the conflict prior to the fix. Analytical verification confirms the mechanism.
yuris changed title from fix(tests): stop proposal-apply suite aborting on replay under timestamp drift to fix(tests): reuse the approval bytes so a proposal-apply replay cannot drift into a fingerprint conflict 2026-09-23 06:11:45 +00:00
yuris merged commit 6d7428838a into main 2026-09-23 06:11:46 +00:00
Sign in to join this conversation.
Reviewers
No reviewers
Labels
Clear labels
No items
No labels
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
yuris/life-service!84
No description provided.