package runs import ( "context" "errors" "testing" "time" "textmachine/platform/internal/ingest" "textmachine/platform/internal/money" "textmachine/platform/internal/pgstore" "textmachine/platform/internal/runner" ) // stuck_settlement_test.go: the OTHER half of a stall — a run that ended and whose money never // closed (register row PD-385). // // The state is grown the way the live probe found it and never written by hand: a run is admitted, // spawned, ends with a marker, and the engine then cannot give a committed figure. Everything below // follows from that, because a fixture that INSERTS the state proves the queries agree with a shape // no producer makes. // // What was wrong: the reconciler has two phases sharing one failure counter, and every operator // surface was built for the live phase alone — `StalledRuns` joined `a.ended_at is null` with // `r.finished_at is null`, the gauge repeated the predicate, and `AbandonRun` read // `finished_at is null` and answered ErrNoRun. So the ERROR logged at the threshold named // `tmplatformctl runs`, and `tmplatformctl runs` answered "no run is failing to reconcile" over a // frozen hold, with no handle at all — the only way out was SQL in production. // stuckSettlement grows one run to the threshold: ended, unsettled, and past StalledAfter failures. // It returns the run and the clock the caller should keep working on. func stuckSettlement(t *testing.T, f *fixture) (string, time.Time) { t.Helper() run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), Chapters: order(10)}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } live := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(run.ID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } // The engine answers, and its report carries no committed figure. Absent is not zero (PD-40), so // the settlement cannot be computed — and on a real deployment this shape is permanent: the pinned // binary removed at a rollout, or an attempt written before the baseline column existed. f.engine.set(ingest.StatusReport{TotalUnits: 10, Done: 10}, nil) // One pass per failure, each past the last one's backoff. The backoff doubles from a minute, so a // clock that walks in hours is comfortably past every one of them. clock := f.now for i := 0; i <= StalledAfter; i++ { clock = f.now.Add(time.Duration(i+1) * time.Hour) f.svc.Now = func() time.Time { return clock } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } } a := f.lastAttempt(t, run.ID) if a.ReconcileFailures < StalledAfter { t.Fatalf("the fixture reached %d failures, want at least %d: this is not the state the test "+ "is about, and every assertion below would pass against a healthy run", a.ReconcileFailures, StalledAfter) } return run.ID, clock } // The three surfaces of the THRESHOLD see it, and they see which half it is. // // Each of the three is asserted separately because each was blind separately, and because the log // line an operator follows names only one of them: a fix that taught the table and left the gauge at // zero would still page nobody. // // Mutations caught: restoring `a.ended_at is null` to StalledRuns; restoring // `a.ended_at is null and r.finished_at is null` to the gauge; dropping the open-reservation join, // which would list every finished run ever. func TestARunWhoseSettlementIsStuckReachesTheOperatorsSurfaces(t *testing.T) { f := newFixture(t, "10", 500) runID, clock := stuckSettlement(t, f) stalled, err := f.store.StalledRuns(f.ctx, StalledAfter) if err != nil { t.Fatal(err) } if len(stalled) != 1 || stalled[0].RunID != runID { t.Fatalf("`runs --stalled` shows %+v, want the run whose settlement is stuck: the ERROR "+ "logged at the threshold sends an operator to this command", stalled) } if !stalled[0].Settling { t.Error("the row does not say which half of the stall it is: the remedy differs, and a " + "`settling` row's engine is already gone") } if stalled[0].HeldMicroUSD == 0 { t.Error("the row shows no hold: what is frozen is the only reason this row is worth printing") } obs, err := f.store.Observe(f.ctx, StalledAfter) if err != nil { t.Fatal(err) } if obs.StalledRuns != 1 { t.Errorf("tm_platform_runs_stalled reads %d, want 1: the one gauge that names a HANDLE stayed "+ "at zero over a frozen hold while oldest_open_hold_seconds climbed", obs.StalledRuns) } if obs.OldestHoldSeconds <= 0 { t.Error("the hold gauge reads nothing: the fixture is not holding money and proves nothing") } _ = clock } // THE LIVE HALF of the same disease, which pack P11 did not reach (register row PD-424): a run that // is still LIVE and whose settlement is permanently blocked. // // The chain, reproduced rather than written by hand: the unit vanishes without a marker → the sweep // calls `restart` → `settle` cannot compute the money and answers `settlementBlocked` WITHOUT an // error → the old code discarded that verdict and walked into `reopen`, which refuses to open an // attempt over an unclosed hold and answers `deferred` → `case deferred: return nil` → the pass reads // as a SUCCESS and even clears the deferral. Every surface stayed clean over a frozen hold that the // engine was poked about every fifteen seconds, forever, and the only way out was the user pressing // Stop — which nobody told them. // // The design question the row said had to be answered first is answered by this test's expectations: // a settlement that cannot be COMPUTED is a failure of the phase that owns it, it is COUNTED, and the // count carries the run to the operator's surfaces like any other stall. // // Mutations caught: discarding settle's verdict in `restart`; clearing the deferral on a pass that // could not restart; deferring a blocked settlement on the LIVE phase's half-hour backoff instead of // the settlement cap, which would put the user's own resume behind it. func TestALiveRunWhoseSettlementIsBlockedIsCountedAndReachesTheOperator(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), Chapters: order(10)}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } // The unit is gone and left NO marker — a reboot, or a kill from outside — so the run is still // live and the reconciler's remedy is a restart. f.runner.alive = false // …and the engine cannot give a committed figure, so the money of the attempt being closed cannot // be computed. Absent is not zero (PD-40). f.engine.set(ingest.StatusReport{TotalUnits: 10, Done: 10}, nil) clock := f.now for i := 0; i <= StalledAfter; i++ { clock = f.now.Add(time.Duration(i+1) * time.Hour) f.svc.Now = func() time.Time { return clock } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } } a := f.lastAttempt(t, run.ID) if a.ReconcileFailures < StalledAfter { t.Fatalf("after %d passes over a blocked settlement the count is %d, want at least %d: the"+ " passes are being read as successful, so the hold stays frozen and no surface ever says so", StalledAfter+1, a.ReconcileFailures, StalledAfter) } // The run is STILL LIVE — this is the population P11 did not reach — and it is now visible. live := f.live(t) if live.RunID != run.ID { t.Fatalf("the run is no longer live: %+v", live) } stalled, err := f.store.StalledRuns(f.ctx, StalledAfter) if err != nil { t.Fatal(err) } if len(stalled) != 1 || stalled[0].RunID != run.ID { t.Fatalf("`runs --stalled` shows %+v, want the live run whose settlement is blocked", stalled) } if stalled[0].HeldMicroUSD == 0 { t.Error("the row shows no hold, and the frozen hold is the whole reason it is worth printing") } // It is the LIVE half, and the row says so. That matters for the remedy an operator reaches for: // a `settling` row's engine is already gone, this one's run is still the live row of its book — // and it also says PD-418's state is not what this fix makes reachable (that one needs a // PREVIOUS attempt that ended unsettled, which `reopen` still refuses to create). if stalled[0].Settling { t.Error("the row calls itself a settling one: this is a LIVE run whose restart is blocked, and" + " an operator sent to the settling remedy would be looking for an engine that is still there") } obs, err := f.store.Observe(f.ctx, StalledAfter) if err != nil { t.Fatal(err) } if obs.StalledRuns != 1 { t.Errorf("tm_platform_runs_stalled reads %d, want 1: nothing pages an operator over a live"+ " run that cannot be restarted", obs.StalledRuns) } // The deferral is on the SETTLEMENT's schedule. The live phase doubles to half an hour, and the // open reservation is the user's own resume gate — so a blockage they can do nothing about must // not also hold their resume for thirty minutes. var after *time.Time if err := f.store.Pool().QueryRow(f.ctx, `select reconcile_after from run_attempts where id = $1`, a.AttemptID).Scan(&after); err != nil { t.Fatal(err) } if after == nil { t.Fatal("the run was not deferred at all: it is retried on every pass forever") } if wait := after.Sub(clock); wait > settlementBackoffCap { t.Errorf("the next look at this run is in %s, past the settlement cap of %s", wait, settlementBackoffCap) } } // A settlement that CLOSED is not in the plain operator table, which is the open-reservation half of // the settling predicate. // // ⚠ THIS TEST DOES NOT PIN THE FLOOR, and an earlier version of this comment claimed it did // ("mutation caught: using `atLeast` unchanged"). It cannot: the fixture's single sweep settles the // run, so the reservation is CLOSED and the row is excluded by the join whatever the floor says — // the mutation it named would have walked straight through. The floor is pinned where a row with // exactly one failure exists to be counted or not: `TestASettlementInFlightIsNotInTheOperatorsTable` // in cmd/tmplatformctl, which asserts BOTH sides of it. // // Mutation caught: dropping the open-reservation requirement from the settling half, which would // list every finished run this deployment has ever had. func TestASettlementThatHasNotFailedIsNotAnOperatorsProblem(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), Chapters: order(10)}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } live := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(run.ID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } // The run ends and its money closes on the same pass, which is the ordinary shape. f.engine.set(statusSpending(money.MicroUSD(100_000)), nil) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } all, err := f.store.StalledRuns(f.ctx, 0) if err != nil { t.Fatal(err) } if len(all) != 0 { t.Errorf("plain `runs` lists %+v: nothing is live and nothing failed, so this table is "+ "printing healthy work", all) } } // The handle. An operator can end the stall, the money comes back whole, and the run stops being // unsettled — which is the half of "make it visible" that makes the visibility worth anything. // // ⚠ The hold comes back WHOLE and that is the decision: the missing thing IS the engine's figure, so // there is no number this platform could justify charging. The alternative shipped today is money // frozen for good. // // Mutations caught: AbandonRun answering ErrNoRun on a finished run (the shipped behaviour); // releasing the hold without stamping `settled_at`, which leaves the run on the worklist for good; // leaving `reconcile_after` set (PD-391's class, one level down). func TestAnOperatorCanEndAStuckSettlementAndTheMoneyComesBack(t *testing.T) { f := newFixture(t, "10", 500) runID, clock := stuckSettlement(t, f) before := f.account(t) if before.Reserved != fixtureHold(10) { t.Fatalf("reserved %s before the verdict, want the run's own hold", before.Reserved.USD()) } verdict, err := f.store.AbandonRun(f.ctx, pgstore.AbandonOrder{RunID: runID, Reason: "the engine build was removed at a rollout", ReleaseHold: false, Now: clock}) if err != nil { t.Fatalf("a run whose settlement is stuck could not be abandoned: %v — this is the state with "+ "no handle at all, and the operator's only remaining move is raw SQL in production", err) } if verdict != pgstore.AbandonedSettlement { t.Errorf("the verdict is %q, want %q: the command has to say which of the two it did, or the "+ "message it prints is about a run that never ended", verdict, pgstore.AbandonedSettlement) } after := f.account(t) if after.Reserved != 0 { t.Errorf("reserved %s after the verdict, want nothing: the hold is what the operator came for", after.Reserved.USD()) } if after.Balance != before.Balance+fixtureHold(10) { t.Errorf("balance %s -> %s, want the hold back whole", before.Balance.USD(), after.Balance.USD()) } if after.Balance != after.LedgerSum { t.Errorf("the cached balance and the ledger disagree after the verdict: %s vs %s", after.Balance.USD(), after.LedgerSum.USD()) } // Off every surface it was on, and off the worklist for good. stalled, err := f.store.StalledRuns(f.ctx, StalledAfter) if err != nil { t.Fatal(err) } if len(stalled) != 0 { t.Errorf("the run is still listed as stalled after the operator ended it: %+v", stalled) } open, err := f.store.UnsettledRuns(f.ctx, clock.Add(time.Hour)) if err != nil { t.Fatal(err) } if len(open) != 0 { t.Errorf("the run is still on the settlement worklist: %+v — nothing will ever close it, so "+ "it would be read forever", open) } var settled *time.Time if err := f.store.Pool().QueryRow(f.ctx, `select settled_at from runs where id = $1`, runID).Scan(&settled); err != nil { t.Fatal(err) } if settled == nil { t.Error("the run is still recorded as unsettled: this branch takes it out of the settlement " + "list, so nothing else will ever stamp the column") } // Twice is refused, and refused with the state it is actually in rather than "no such run". if _, err := f.store.AbandonRun(f.ctx, pgstore.AbandonOrder{RunID: runID, Reason: "again", ReleaseHold: false, Now: clock}); !errors.Is(err, pgstore.ErrMoneyAlreadyClosed) { t.Errorf("a second verdict answered %v, want %v", err, pgstore.ErrMoneyAlreadyClosed) } } // The OTHER promise `run abandon` makes, and PD-391: "its hold comes back whole on the next sweep". // // It was false for the whole population the command exists for. `AbandonRun` ended the run and its // attempt and left `run_attempts.reconcile_after` where it was — and `UnsettledRuns` filters on that // column, so the settlement sweep stepped over the run it had just been told to finish. A run that // reaches an operator is by construction one that has been deferred: `deferItem` writes // now + backoff(failures+1), and at five failures the backoff is pinned at its thirty-minute cap. So // the credit stayed debited, `tm_platform_oldest_open_hold_seconds` kept climbing AFTER the operator // acted, and what they read was "I did it and nothing happened" — the CLI's sentence and the // runbook's copy of it both saying otherwise. // // ⚠ The pin PD-361 left behind proves something weaker and that is why this one exists: it abandons // a run created by `Start` and abandoned in the next breath, whose `reconcile_failures` is 0 and // whose `reconcile_after` is NULL — so the column it must clear is already clear. // // Mutation caught: dropping `reconcile_after = null` from AbandonRun's update. func TestAbandoningAStalledRunGivesTheHoldBackOnTheNextSweepAndNotIn30Minutes(t *testing.T) { f := newFixture(t, "20", 500) // The population the handle is for: an attempt that never became a process, whose spawn fails on // every pass (register row PD-162 — a book whose directory was removed refuses every spawn, // forever, with the hold open). Never spawned means no unit and no baseline, which is the only // shape AbandonRun admits. run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), Chapters: order(10)}) if err != nil { t.Fatal(err) } // The spawn is refused BEFORE anything is claimed: the meter cannot be read, so there is no // baseline to record and no unit to name — which is the only shape AbandonRun admits, and the // reason the refusal has to come from here rather than from systemd. A `Start` that failed would // leave the spend baseline behind as its tombstone, and the guard would rightly refuse. f.engine.set(ingest.StatusReport{}, errors.New("tmctl: status: no such project directory")) clock := f.now for i := 0; i <= StalledAfter; i++ { clock = f.now.Add(time.Duration(i+1) * time.Hour) f.svc.Now = func() time.Time { return clock } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } } live := f.lastAttempt(t, run.ID) if live.ReconcileFailures < StalledAfter { t.Fatalf("the fixture reached %d failures, want at least %d: without a deferral on the row "+ "this test cannot observe the column it is about", live.ReconcileFailures, StalledAfter) } // The deferral itself, read from the row: LiveRun carries the count and not the deadline, and the // deadline is the column this test is about. var deferred *time.Time if err := f.store.Pool().QueryRow(f.ctx, `select reconcile_after from run_attempts where id = $1`, live.AttemptID).Scan(&deferred); err != nil { t.Fatal(err) } if deferred == nil || !deferred.After(clock) { t.Fatalf("the attempt carries no deferral into the future (%v at %v): the fixture is not the "+ "state every run that reaches an operator is in", deferred, clock) } before := f.account(t) // The operator's verdict, WITHOUT the flag — that is, taking the CLI at its word that the hold // comes back on the next sweep. if _, err := f.store.AbandonRun(f.ctx, pgstore.AbandonOrder{RunID: run.ID, Reason: "the workdir was removed", ReleaseHold: false, Now: clock}); err != nil { t.Fatal(err) } // The next sweep. The clock does NOT move: thirty minutes of it is exactly what the operator was // promised they would not have to wait. if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } after := f.account(t) if after.Reserved != 0 { t.Errorf("reserved %s → %s: the hold did not come back on the next sweep. The attempt is "+ "still serving the deferral it carried into the verdict, so the settlement list steps "+ "over it for up to thirty minutes while the CLI and the runbook both say otherwise", before.Reserved.USD(), after.Reserved.USD()) } if after.Balance != before.Balance+fixtureHold(10) { t.Errorf("balance %s → %s, want the hold back whole", before.Balance.USD(), after.Balance.USD()) } if after.Balance != after.LedgerSum { t.Errorf("the cached balance and the ledger disagree: %s vs %s", after.Balance.USD(), after.LedgerSum.USD()) } } // A settlement that fails ONCE is retried on the very next pass, and only then starts backing off. // // The deferral is not only the platform's rate limit on the engine — it is the USER's resume gate: // `reopen` refuses to start the next attempt while the previous one's hold is open, so every minute // the settlement waits is a minute their resume is answered 409. The commonest single failure is // transient (the engine host mid-restart, the project file still held by the process that is // exiting) and it used to clear fifteen seconds later; a backoff that started at a minute would have // made this pack a regression for the ordinary case while fixing the pathological one. // // Mutation caught: settlementDelay returning backoff(1) for the first failure — that is, the obvious // version of PD-384's fix. func TestTheFirstFailedSettlementIsRetriedAtOnceAndTheSecondBacksOff(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), Chapters: order(10)}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } live := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(run.ID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } f.engine.set(ingest.StatusReport{TotalUnits: 10, Done: 10}, nil) // no committed figure if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } // Counted — that is the whole of PD-384 — and due again NOW, which is what keeps the user's // fifteen seconds. a := f.lastAttempt(t, run.ID) if a.ReconcileFailures != 1 { t.Fatalf("the first blocked settlement counted %d failures, want 1", a.ReconcileFailures) } open, err := f.store.UnsettledRuns(f.ctx, f.svc.now()) if err != nil { t.Fatal(err) } if len(open) != 1 { t.Fatalf("the settlement is not due on the next pass after ONE failure: %+v — a transient "+ "engine hiccup would hold the user's own resume for a minute", open) } // The SECOND failure does back off: by then "transient" has stopped being the explanation. if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } if a := f.lastAttempt(t, run.ID); a.ReconcileFailures != 2 { t.Fatalf("the second pass counted %d failures, want 2", a.ReconcileFailures) } if open, err := f.store.UnsettledRuns(f.ctx, f.svc.now()); err != nil || len(open) != 0 { t.Errorf("the settlement is still due immediately after two failures (%+v, %v): nothing "+ "then rate-limits the engine call", open, err) } } // The one blocked case the code calls PERMANENT is the one an operator most needs counted, and it // had no test: an attempt that ran WITHOUT a spend baseline. Flipping its verdict from // `settlementBlocked` to `settlementRaced` passes everything else, and quietly restores PD-384 for // the only case that can never resolve on its own — the column does not appear on a row already // written. // // Mutation caught: `return settlementRaced, nil` on the no-baseline branch of settle. func TestASettlementWithNoBaselineIsCountedRatherThanTreatedAsARace(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), Chapters: order(10)}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } live := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(run.ID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } // An attempt from before the baseline column existed: it HAS a unit, so it reached the engine and // cannot be released as unspawned, and it has no baseline, so its cost cannot be priced at all. if _, err := f.store.Pool().Exec(f.ctx, `update run_attempts set spend_baseline_micro_usd = null where run_id = $1`, run.ID); err != nil { t.Fatal(err) } f.engine.set(statusSpending(money.MicroUSD(100_000)), nil) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } a := f.lastAttempt(t, run.ID) if a.ReconcileFailures == 0 { t.Fatal("an attempt that can never be priced counted no failures: the threshold is " + "unreachable for it, so nobody is ever told, and its hold is frozen for good — which is " + "exactly PD-384") } if got := f.account(t).Reserved; got == 0 { t.Error("the hold was resolved for an attempt whose cost cannot be known") } } // PD-391 one level down: the SETTLEMENT branch of the verdict clears the deferral too. Without it the // run drops off the settlement worklist while its `reconcile_after` still points into the future, // and the operator's own table — which reads the same column for NEXT TRY — keeps describing a retry // that will never come. // // Mutation caught: dropping `reconcile_after = null` from abandonSettlement's update. func TestAbandoningAStuckSettlementClearsItsDeferralToo(t *testing.T) { f := newFixture(t, "10", 500) runID, clock := stuckSettlement(t, f) var before *time.Time if err := f.store.Pool().QueryRow(f.ctx, ` select a.reconcile_after from run_attempts a where a.run_id = $1`, runID).Scan(&before); err != nil { t.Fatal(err) } if before == nil || !before.After(clock) { t.Fatalf("the fixture carries no deferral into the future (%v at %v): it cannot observe the "+ "column this test is about", before, clock) } if _, err := f.store.AbandonRun(f.ctx, pgstore.AbandonOrder{RunID: runID, Reason: "the engine build was removed", ReleaseHold: false, Now: clock}); err != nil { t.Fatal(err) } var after *time.Time if err := f.store.Pool().QueryRow(f.ctx, ` select a.reconcile_after from run_attempts a where a.run_id = $1`, runID).Scan(&after); err != nil { t.Fatal(err) } if after != nil { t.Errorf("the abandoned settlement still carries a deferral to %v: the operator's table reads "+ "that column for NEXT TRY and would go on promising a retry of a run nothing will retry", after) } } // The five-minute cap binds the RECONCILIATION phase too, when the attempt it defers has already // ended. // // `finish`, `finishStopped` and `restart` all close the attempt and then settle inside a pass of the // reconciliation phase, so a settlement error can surface there — and that phase's own backoff caps // at THIRTY minutes. An ended attempt with an open hold is the user's resume gate (`reopen` refuses // over it), so half an hour of it is exactly what the shorter cap exists to prevent, and applying // the cap only in `settleOne` left the promise true for one of the two doors. // // Mutation caught: dropping the AttemptEnded check from reconcileOne, which restores the 30 minutes. func TestAnEndedAttemptIsNeverDeferredPastTheSettlementCap(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), Chapters: order(10)}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } live := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(run.ID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } f.engine.set(ingest.StatusReport{TotalUnits: 10, Done: 10}, nil) // no committed figure // Walk the failure count high enough that the LIVE backoff would be at its own cap. clock := f.now for i := 0; i <= StalledAfter+2; i++ { clock = f.now.Add(time.Duration(i+1) * time.Hour) f.svc.Now = func() time.Time { return clock } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } } a := f.lastAttempt(t, run.ID) if a.ReconcileFailures <= StalledAfter { t.Fatalf("the fixture counted %d failures, want more than %d so the backoff is at its cap", a.ReconcileFailures, StalledAfter) } var after *time.Time if err := f.store.Pool().QueryRow(f.ctx, `select reconcile_after from run_attempts where id = $1`, a.AttemptID).Scan(&after); err != nil { t.Fatal(err) } if after == nil { t.Fatal("the attempt carries no deferral at all") } if got := after.Sub(clock); got > settlementBackoffCap { t.Errorf("an ENDED attempt is deferred %v, want at most %v: its open hold is what `reopen` "+ "refuses to start the next attempt over, so every minute of this is a minute the user's "+ "resume answers 409", got, settlementBackoffCap) } } // A SHUTDOWN must not invent a settlement failure. // // Stopping the daemon cancels every item in flight, so `settle` comes back with `context.Canceled` // while the item's own budget is untouched — and the deferral is written on a context deliberately // detached from the cancellation, so it COMMITS. Without a guard the count and the backoff both // climb on every restart, on runs nothing was wrong with; five restarts would reach the operator's // threshold and page somebody about a healthy installation. The reconciliation phase next door // refuses this explicitly ("writes failures a restart invented") and this phase had lost the guard. // // Mutation caught: dropping the `ctx.Err() != nil` return from settleOne. func TestAStoppedDaemonDoesNotInventASettlementFailure(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), Chapters: order(10)}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } live := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(run.ID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } f.engine.set(ingest.StatusReport{TotalUnits: 10, Done: 10}, nil) // the settlement cannot be computed if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } before := f.lastAttempt(t, run.ID).ReconcileFailures if before == 0 { t.Fatal("the ordinary pass counted nothing: this fixture cannot observe what a shutdown adds") } // Now the daemon stops mid-pass: the sweep's context is already cancelled when the settlement // phase reaches this attempt. stopped, cancel := context.WithCancel(f.ctx) cancel() f.svc.Now = func() time.Time { return f.now.Add(time.Hour) } _ = f.svc.Sweep(stopped) if after := f.lastAttempt(t, run.ID).ReconcileFailures; after != before { t.Errorf("a stopped daemon moved the failure count %d → %d: that is a failure a RESTART "+ "invented, and five of them reach the threshold and page an operator about an "+ "installation that is working", before, after) } }