textmachine/platform/internal/runs/stuck_settlement_test.go

634 lines
29 KiB
Go

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), CeilingChapters: 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), CeilingChapters: 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), CeilingChapters: 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 != f.svc.Pricing.Ceiling(10) {
t.Fatalf("reserved %s before the verdict, want the run's own hold", before.Reserved.USD())
}
verdict, err := f.store.AbandonRun(f.ctx, runID, "the engine build was removed at a rollout", false, 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+f.svc.Pricing.Ceiling(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, runID, "again", false, 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), CeilingChapters: 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, run.ID, "the workdir was removed", false, 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+f.svc.Pricing.Ceiling(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), CeilingChapters: 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), CeilingChapters: 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, runID, "the engine build was removed", false, 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), CeilingChapters: 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), CeilingChapters: 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)
}
}