Skip to content

test(lifecycle-poc): wait for the live status on the recovery path, don't instant-read it - #2832

Merged
devarismeroxa merged 1 commit into
mainfrom
fix/flaky-lifecycle-poc-recovery-status-assertion
Aug 29, 2026
Merged

test(lifecycle-poc): wait for the live status on the recovery path, don't instant-read it#2832
devarismeroxa merged 1 commit into
mainfrom
fix/flaky-lifecycle-poc-recovery-status-assertion

Conversation

@devarismeroxa

Copy link
Copy Markdown
Contributor

Tier 3 (test files only — no production code touched).

Fixes the TestServiceLifecycle_Recovery_TransientErrorRecovers failure seen on main at
run 32785888309
(service_test.go:778: Running != Recovering). The commit that failed was docs-only and the next
commit passed, so this is a flake, not a regression.

Root cause

Neither watermark the test waits on is ordered after the status write it then asserts.

statusRecorder.UpdateStatus appends the status and runs its hook before delegating to
pipeline.Service, which is what actually calls Instance.SetStatus. So waitForRecovered's
"Running after a Recovering" fires strictly before pl.GetStatus() can return Running, with a
whole UpdateStatus (a Get, two metrics updates, a store write) still in flight.

waitForRecordsAcked adds no delay either: runPipeline does close(registered) — releasing every
worker goroutine — before it calls UpdateStatus(StatusRunning), so the recovered run can read,
write and ack its whole record set while the status write is still pending.

The identical instant assertion is sound on the initial start (and in pkg/lifecycle) because
ls.Start returns only after runPipeline's status write completes. A recovery restart runs on
the tomb's cleanup goroutine, and nothing in the test goroutine is synchronized with it. The
assertion was passing on a ~microsecond margin that a 4-core CI runner under -race -shuffle=on
loses to a single goroutine preemption.

Ruled out: this is not a second recovery. Both dispensers are .Times(2) with no over-call
reported (a second recovery needs a third dispense), and the three missing Teardowns are the
recovered run's own plugins — run 2 was alive and healthy when is.Equal called FailNow.
Everything after line 778 is cascade.

Fix

waitForRecovered now also polls the live pl.GetStatus() until it reports Running, so the helper
means what its name says. A genuine second recovery is still caught: the helper does not latch past
it, and the AC-7 exact-sequence assertion would fail on [Running Recovering Running Recovering …].

Four sites carried the same unsound pattern; all are fixed. The fourth
(TestServiceLifecycle_Recovery_LiveEntryPublishedBeforeRunningStatus) has no waitForRecovered
call and was the most exposed, because close(release) only lets the status write proceed while the
records it then waits on were already acked during the freeze.

Perturbation proof

Could not reproduce naturally on a 16-core M-series box: 3840 runs of the race binary
(24x40 at -cpu=1,4; 64x30 at GOMAXPROCS=1) all green. So the preemption was injected directly — a
sleep in statusRecorder between recording the status and delegating (injection not committed):

injection before after
200ms, 4 tests, -race -count=10 40/40 FAIL (byte-identical to CI) 40/40 PASS
20ms, same 80-run matrix 46/80 FAIL 0/80 PASS

Package green at -race -count=3 -shuffle=on; golangci-lint reports 0 issues.

Relationship to prior fixes

Not a recurrence of the #2746/#2806 production bugs — those were about runningPipelines holding
a dead run, and 4ec2b5f is intact. It is the same class as the async assertion fixed in 34bf97d,
and that commit is where the fourth site was introduced: the PR that fixed one async assertion
shipped a new one of the same kind. waitForRecovered itself dates to a61d4bc (#2718).

Not fixed here

A Tier-1 production ordering finding surfaced during this work and is filed separately rather than
folded in — see the linked issue. It needs its own PR with a deterministic regression test.

Roadmap: v0.20 WS9-B (flaky tests fixed at cause, never masked).

@devarismeroxa
devarismeroxa requested a review from a team as a code owner August 25, 2026 00:04
@devarismeroxa devarismeroxa added this to the v0.20.0 milestone Aug 25, 2026
devarismeroxa added a commit that referenced this pull request Aug 27, 2026
…ace (#2835)

TestSIGKILL_RecoveryLoop_CrashDuringRecoveredRun failed on PR #2832's CI run
32792092690 with "not true: committedAtKill < cfg.total" (recovery_test.go:300).
That assertion is a vacuity guard and it fired correctly: the SIGKILL did not
land mid-run, so the test refused to pass while not exercising the crash it
claims to.

Cause: the kill was gated on childProcess.waitForReadCount(30) - a LAGGING,
parent-side observation of a child that keeps producing while the parent is
descheduled. The child free-ran to total (60) at paceMS 3, so the window
between "the parent last saw 30 READ lines" and "SIGKILL actually lands" only
had to exceed the ~150ms of remaining production plus the 10ms persister
debounce for the child to finish before it died. Locally a 400ms stall
injected into that window reproduces the CI failure verbatim, first try; 200ms
still passes. That is a ~0.3s margin, not the orders of magnitude the sibling
CrashDuringBackoff scenario enjoys, and `tests/chaos (race, x3)` on a loaded
runner exceeds it.

Fix - the same shape as #2534's (sigkill_test.go's mid-snapshot case, whose
precondition was made structurally true with a 600s persister debounce rather
than a wider margin), applied to the production side:

  - recovery_child.go gains a holdAt seam: a ceiling on how far this process's
    source may ever produce. Once holdAt is sent, produceLoop prints LC_HELD
    and stops for good. Inert at 0, which is what every other scenario and the
    graceful restart child leave it at; parseLCChildEnv rejects the
    combinations that could only ever manifest as an opaque timeout.
  - The kill is now gated on the child's DURABLE upstream commit watermark
    (read off the same on-disk marker the assertion reads, written via
    fsync+atomic-rename so a cross-process reader never sees a torn value),
    not on a read count.

Both guards are now structural. Lower bound: the watermark passing failAt is
positive proof the recovered run is producing, since the first run provably
never sends failAt. Upper bound: holdAt (20) < total (60) caps what this
process can ever commit, however long the parent is descheduled. The kill
point is bracketed in [10, 20]; every value in that interval gives the
identical verdict, so it tunes in-flight depth, not pass/fail.

The test still tests what it says: the SIGKILL lands during the recovered run,
after the induced failure and restart, with records in flight (the cap is a
ceiling, not the trigger - the kill fires at watermark 10 while the producer
is still on its way to 20).

Regression test: TestRecoveryChild_HoldAt_CapsProductionBelowTotal waits for
the ceiling, then stalls 400ms - the exact window that reproduced the flake -
and asserts the child has not moved. Verified to fail without the fix (the
child free-runs to READ 60 and the LC_HELD wait times out) and pass with it.

Verification:
  - Injected-stall repro: 400ms fails identically to CI pre-fix; post-fix a
    3s stall (7.5x) passes 10/10.
  - Soak under real CPU contention (24 spinners, load avg 61): 100/100 across
    both tests. Pre-fix the same soak was 20/20 green, i.e. brute-force
    repetition cannot measure this flake - which is why the bound, not a
    repetition count, is the evidence.
  - Full tests/chaos package green under -race; golangci-lint clean.

Tier 3: test-harness only. No engine or data-path code is touched, and the
seam is inert unless a test sets it.

Refs #2832


Claude-Session: https://claude.ai/code/session_016xE861dwb3MLgqEdWRECLY

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
…on't instant-read it

TestServiceLifecycle_Recovery_TransientErrorRecovers failed on a DOCS-ONLY
push to main (run 32785888309, sha 7486372; the next docs commit c073543
passed). The failure was:

    service_test.go:778: Running != Recovering
    panic.go:615: persister did not drain within 10s (see #2746)
    controller.go:97: missing call(s) to *mock.SourcePlugin.Teardown
    controller.go:97: missing call(s) to *mock.DestinationPlugin.Teardown x2

This is a test-synchronization defect, not a recovery bug. Evidence: at the
failing assertion the recorded status sequence is exactly
[Running Recovering Running] - ONE recovery, not two - while the live
instance still reads Recovering. Both dispensers are .Times(2) and neither
reported an over-call, and the three missing Teardowns are precisely the
recovered run's own plugins, i.e. run 2 was alive and healthy when the
assertion aborted the test. Everything after line 778 (the persister
drain panic, the "run didn't finish" lines, the missing Teardowns) is
fallout from is.Equal calling FailNow while the pipeline was still running.

Root cause: neither watermark the test waits on is ordered after the status
write it then asserts.

  - statusRecorder.UpdateStatus appends the status and runs its hook BEFORE
    delegating to pipeline.Service, which is what calls Instance.SetStatus.
    So waitForRecovered's "Running after a Recovering" fires strictly before
    pl.GetStatus() returns Running, with a whole UpdateStatus call (Get, two
    metrics updates, store write) still to go.
  - runPipeline closes `registered` - releasing every worker goroutine - and
    only then calls UpdateStatus(StatusRunning). The recovered run can
    therefore read, write and ack its entire record set while that status
    write is still in flight, so waitForRecordsAcked returns immediately and
    adds no delay either.

Unlike the initial start (ls.Start returns only after runPipeline's status
write completes, which is why the same instant assertion is sound there and
in pkg/lifecycle), a recovery restart runs on the tomb's cleanup goroutine:
nothing in the test goroutine is synchronized with it. The assertion was
passing on the ~microsecond margin between the recorder entry and SetStatus,
which a 4-core CI runner under `-race -shuffle=on` with docker sidecars can
lose to a single goroutine preemption.

Fix (test-only, no production change): waitForRecovered now also polls the
live pl.GetStatus() until it reports Running, so it means what its name says.
A genuine second recovery is still caught - the helper does not latch past
it, and the AC-7 exact-sequence assertion at the end of each test would fail
on [Running Recovering Running Recovering ...].

Four call sites carried the same unsound pattern, all fixed:
  - TestServiceLifecycle_Recovery_TransientErrorRecovers
  - TestServiceLifecycle_NSource_TransientErrorOneSource_Recovers
  - TestServiceLifecycle_NxM_TransientErrorOneSource_RecoversAllSourcesAndDestinations
  - TestServiceLifecycle_Recovery_LiveEntryPublishedBeforeRunningStatus
The last one has no waitForRecovered call - it freezes the window with the
onUpdate hook - and is the MOST exposed of the four, because close(release)
only lets the status write proceed while the records it then waits on were
already acked during the freeze. It gets waitForStatus instead. It was added
by 34bf97d ("...and one async assertion behind three flaky tests"), which
shipped a new assertion of the same class it was fixing; waitForRecovered
itself dates to a61d4bc (#2718).

This is polling a watermark, not a widened timeout, a retry or a sleep: the
deadline (5s, unchanged from the existing helpers) only bounds the failure
message.

Perturbation proof. The flake could NOT be reproduced naturally on an M-series
16-core box: 3840 runs of the race-enabled binary (24x40 at -cpu=1,4 and
64x30 at GOMAXPROCS=1) were all green, so the CI signature was reproduced by
injecting the scheduler preemption directly - a sleep in statusRecorder
between recording the status and delegating to the wrapped service. With
200ms injected, across all four tests at -race -count=10:

    before fix: 40/40 FAIL, byte-identical to the CI output
    after fix:  40/40 PASS

At 20ms the same 80-run matrix went 46/80 FAIL -> 0/80 PASS. Package green at
`go test ./pkg/lifecycle-poc/... -race -count=3 -shuffle=on`; golangci-lint
clean. The injection is not committed; it is reproducible by setting
rec.onUpdate to sleep on the nth==2 StatusRunning, the seam that already
exists for TestServiceLifecycle_Recovery_LiveEntryPublishedBeforeRunningStatus.

Tier 3 (test-only). No existing issue tracks this test; #2534 is the umbrella
flaky-suite issue.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_016xE861dwb3MLgqEdWRECLY
@devarismeroxa
devarismeroxa force-pushed the fix/flaky-lifecycle-poc-recovery-status-assertion branch from 3958e00 to cfe22c6 Compare August 27, 2026 22:12
@devarismeroxa
devarismeroxa merged commit ab8f184 into main Aug 29, 2026
15 of 16 checks passed
@devarismeroxa
devarismeroxa deleted the fix/flaky-lifecycle-poc-recovery-status-assertion branch August 29, 2026 19:07
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.

1 participant