package runs import ( "bytes" "context" "crypto/rand" "encoding/hex" "errors" "fmt" "log/slog" "net/url" "os" "path/filepath" "strings" "sync" "testing" "time" "github.com/jackc/pgx/v5" "textmachine/platform/internal/ingest" "textmachine/platform/internal/money" "textmachine/platform/internal/pgstore" "textmachine/platform/internal/pricing" "textmachine/platform/internal/runner" ) // The reconciler is mostly a decision, and its decisions are tested next door without a database. // What these tests add is the part no fake can prove: that the decision, the read model and the // MONEY end up consistent — a run that finished has its hold settled, and one that was interrupted // gets a second attempt with what is left rather than a second full reservation. func sweepDB(t *testing.T) (*pgstore.Store, context.Context) { t.Helper() admin := os.Getenv("TM_PLATFORM_TEST_DSN") if admin == "" { t.Skip("TM_PLATFORM_TEST_DSN not set: the reconciler's money path needs a live Postgres") } ctx := t.Context() var suffix [6]byte if _, err := rand.Read(suffix[:]); err != nil { t.Fatal(err) } name := "tm_runs_test_" + hex.EncodeToString(suffix[:]) conn, err := pgx.Connect(ctx, admin) if err != nil { t.Fatalf("connect: %v", err) } if _, err := conn.Exec(ctx, "create database "+pgx.Identifier{name}.Sanitize()); err != nil { conn.Close(ctx) t.Skipf("cannot create a scratch database (%v): grant CREATEDB or point the DSN at one", err) } t.Cleanup(func() { c, cancel := context.WithTimeout(context.Background(), 15*time.Second) defer cancel() _, _ = conn.Exec(c, "drop database if exists "+pgx.Identifier{name}.Sanitize()+" with (force)") conn.Close(c) }) u, err := url.Parse(admin) if err != nil { t.Fatal(err) } u.Path = "/" + name if err := pgstore.Migrate(ctx, u.String()); err != nil { t.Fatalf("migrate: %v", err) } s, err := pgstore.Open(ctx, u.String()) if err != nil { t.Fatal(err) } t.Cleanup(s.Close) return s, ctx } // fixture is one funded account with one book on disk and a service wired to it. type fixture struct { svc *Service store *pgstore.Store ctx context.Context runner *fakeRunner engine *fakeEngine workdir string now time.Time } func newFixture(t *testing.T, balance string, chapters int) *fixture { t.Helper() store, ctx := sweepDB(t) now := time.Now().UTC().Truncate(time.Millisecond) if _, err := store.Pool().Exec(ctx, `insert into users (id, email) values ('u1','u1@example.org')`); err != nil { t.Fatal(err) } amount, err := money.ParseUSD(balance) if err != nil { t.Fatal(err) } if _, err := store.Grant(ctx, "u1", amount, "test", "seed", "", now); err != nil { t.Fatal(err) } workdir := t.TempDir() if _, err := store.AddBook(ctx, pgstore.NewBook{OwnerID: "u1", Title: "蛊真人", SourceLang: "zh", TargetLang: "ru", ChapterCount: chapters, Workdir: workdir, Now: now}); err != nil { t.Fatal(err) } model, err := pricing.New(pricing.DefaultPerChapter) if err != nil { t.Fatal(err) } // The engine answers a committed AND a reserved figure from the start: the spawn reads the book's // meter BEFORE it starts anything, and a book that has never run reads zero for both. f := &fixture{store: store, ctx: ctx, runner: &fakeRunner{}, engine: &fakeEngine{report: ingest.StatusReport{Spend: usd(0), Reserved: usd(0)}}, workdir: workdir, now: now} f.svc = service(t, f.runner, f.engine, now) f.svc.Store = store f.svc.Pricing = model return f } func (f *fixture) bookID(t *testing.T) string { t.Helper() lib, err := f.store.ListBooks(f.ctx, "u1", 10, "") if err != nil || len(lib.Books) != 1 { t.Fatalf("library: %+v (%v)", lib, err) } return lib.Books[0].ID } func (f *fixture) live(t *testing.T) pgstore.LiveRun { t.Helper() live, err := f.store.ListLiveRuns(f.ctx) if err != nil { t.Fatal(err) } if len(live) != 1 { t.Fatalf("%d live runs, want 1", len(live)) } return live[0] } func (f *fixture) account(t *testing.T) pgstore.Account { t.Helper() a, err := f.store.ReadAccount(f.ctx, "u1") if err != nil { t.Fatal(err) } return a } // The whole loop: admit, spawn, the unit ends, the run finishes and the money settles at what the // engine actually spent — with the rest of the hold given back. func TestARunThatEndsIsFinishedAndSettledAtWhatTheEngineSpent(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if got := f.account(t); got.Reserved != f.svc.Pricing.Ceiling(100) { t.Fatalf("the hold was not taken before the spawn: reserved %s", got.Reserved.USD()) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } if len(f.runner.starts()) != 1 { t.Fatalf("%d units started", len(f.runner.starts())) } // A second delivery of the same queue job must NOT put a second engine on the book. if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } if n := len(f.runner.starts()); n != 1 { t.Fatalf("a retried queue job started %d units", n) } // The unit ends cleanly, and the engine reports what it spent. live := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(live.RunID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } spent := money.MicroUSD(1_234_567) f.engine.set(ingest.StatusReport{TotalUnits: 100, Done: 100, Spend: usd(spent), Reserved: usd(0)}, nil) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } _, card, err := f.store.GetBook(f.ctx, "u1", f.bookID(t)) if err != nil { t.Fatal(err) } if card == nil || card.Status != "ready" || card.FinishedAt == nil { t.Fatalf("run after the unit ended: %+v", card) } acct := f.account(t) if acct.Reserved != 0 { t.Errorf("the hold is still open after settlement: %s", acct.Reserved.USD()) } if want := money.MicroUSD(10_000_000) - spent; acct.Balance != want { t.Errorf("balance %s, want %s — settled at what the engine spent, not at the ceiling", acct.Balance.USD(), want.USD()) } if acct.Balance != acct.LedgerSum { t.Errorf("the cached balance and the ledger disagree: %s vs %s", acct.Balance.USD(), acct.LedgerSum.USD()) } } // Two callers legitimately reach the spawn at once: the queue worker that was handed the run, and // the reconciler that finds it unspawned on its next pass. Exactly one may create a unit — the other // would put a second engine on a book whose project file the first holds an exclusive lock on. func TestOnlyOneOfTwoConcurrentSpawnersStartsTheEngine(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) } live := f.live(t) var wg sync.WaitGroup errs := make([]error, 8) for i := range errs { wg.Add(1) go func() { defer wg.Done() errs[i] = f.svc.spawnAttempt(f.ctx, live) }() } wg.Wait() for i, err := range errs { if err != nil { t.Errorf("spawner %d: %v", i, err) } } if n := len(f.runner.starts()); n != 1 { t.Fatalf("%d units started for one attempt, want exactly 1", n) } if got := f.live(t); got.RunID != run.ID || got.UnitName == "" { t.Errorf("after the race the attempt carries %+v", got) } } // A settlement figure that cannot be read leaves the hold OPEN for the next sweep. The alternative — // settling against a guess — is the one outcome nobody can undo. func TestASettlementThatCannotBeReadLeavesTheHoldOpen(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: "u", Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } // The report carries no committed figure: absent is NOT zero (PD-40), and treating it as zero // would release the whole hold and charge nothing. f.engine.set(ingest.StatusReport{TotalUnits: 10, Done: 10}, nil) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } if got := f.account(t); got.Reserved != f.svc.Pricing.Ceiling(10) { t.Fatalf("the hold was resolved without a figure: reserved %s", got.Reserved.USD()) } open, err := f.store.UnsettledRuns(f.ctx) if err != nil { t.Fatal(err) } if len(open) != 1 { t.Fatalf("the unsettled run is not listed for a retry: %+v", open) } // Now the engine can answer, and the same sweep resolves it. spent := money.MicroUSD(200_000) f.engine.set(ingest.StatusReport{TotalUnits: 10, Done: 10, Spend: usd(spent), Reserved: usd(0)}, nil) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } if got := f.account(t); got.Reserved != 0 { t.Errorf("reserved %s after a successful retry", got.Reserved.USD()) } } // A reboot takes every transient unit with it and runs no ExecStopPost, so an interrupted run has // neither a marker nor a unit. It is restarted (unified backlog row 138) with what is LEFT of its // budget — reserving the full ceiling again would let one run spend it twice. func TestARunInterruptedByARebootComesBackWithTheBudgetItHasLeft(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } // Time passes and the machine reboots: the unit is gone, no marker was written, and the engine // reports what it managed to spend before it died. spent := money.MicroUSD(900_000) f.engine.set(ingest.StatusReport{TotalUnits: 100, Done: 30, Spend: usd(spent), Reserved: usd(0)}, nil) f.runner.alive = false f.svc.Now = func() time.Time { return f.now.Add(2 * time.Hour) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } live := f.live(t) if live.AttemptNo != 2 { t.Fatalf("the interrupted run was not restarted: attempt %d", live.AttemptNo) } budget := f.svc.Pricing.Ceiling(100) if want := budget - spent; live.Ceiling != want { t.Errorf("the second attempt reserved %s, want %s — the budget minus what was already spent", live.Ceiling.USD(), want.USD()) } if n := len(f.runner.starts()); n != 2 { t.Fatalf("%d units started in all, want the original and the restart", n) } acct := f.account(t) if acct.Balance != acct.LedgerSum { t.Errorf("balance %s and ledger %s disagree after a restart", acct.Balance.USD(), acct.LedgerSum.USD()) } // $10 − $0.9 spent − the new hold. if want := money.MicroUSD(10_000_000) - spent - live.Ceiling; acct.Balance != want { t.Errorf("balance %s, want %s", acct.Balance.USD(), want.USD()) } } // An interrupted run whose budget is gone cannot be resumed, and the honest state for that is // `paused` with the reason the contract has a word for — not `failed`. func TestAnInterruptedRunWithNothingLeftIsPausedRatherThanFailed(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 engine spent the whole ceiling before the machine went down. spent := f.svc.Pricing.Ceiling(10) f.engine.set(ingest.StatusReport{TotalUnits: 10, Done: 10, Spend: usd(spent), Reserved: usd(0)}, nil) f.svc.Now = func() time.Time { return f.now.Add(2 * time.Hour) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } _, card, err := f.store.GetBook(f.ctx, "u1", f.bookID(t)) if err != nil { t.Fatal(err) } if card == nil || card.Status != "paused" { t.Fatalf("a run with no budget left: %+v", card) } if n := len(f.runner.starts()); n != 1 { t.Errorf("%d units started: a run with no budget must not be respawned", n) } } // The tailer, the sink and the cursor, driven by the reconciler rather than by a test calling them // directly: this is what proves the journal path is actually wired into the sweep. func TestTheSweepMaterializesWhateverTheJournalHasGained(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } f.runner.alive = true journal := filepath.Join(f.workdir, ingest.JournalFile) body := `{"seq":1,"type":"hello","data":{"stream_version":"1.0","engine_run_id":"eng-1","book_id":"b"}}` + "\n" + `{"seq":2,"type":"progress","data":{"draft":{"done":7,"total":20},"edit":{"done":1,"total":20}}}` + "\n" if err := os.WriteFile(journal, []byte(body), 0o600); err != nil { t.Fatal(err) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } book, _, err := f.store.GetBook(f.ctx, "u1", f.bookID(t)) if err != nil { t.Fatal(err) } if book.Progress.DraftDone != 7 || book.Progress.EditDone != 1 { t.Fatalf("progress after the sweep: %+v", book.Progress) } live := f.live(t) if live.EngineRunID != "eng-1" || live.Position.LastSeq != 2 || live.Position.Offset != int64(len(body)) { t.Errorf("cursor after the sweep: %+v", live.Position) } // Sweeping again re-reads nothing and changes nothing: at-least-once is the norm and the cursor // is what makes it free. if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } again, _, err := f.store.GetBook(f.ctx, "u1", f.bookID(t)) if err != nil { t.Fatal(err) } if again.Progress.DraftDone != 7 { t.Errorf("a second sweep changed the projection: %+v", again.Progress) } } // A deadlock Postgres broke must not stop the projection — driven through the WHOLE path, because // the decision itself is pinned next door on a pure function and a table test cannot notice that the // decision stopped being consulted. // // ⚠ That gap was real: a reviewer removed the branch in drainJournal that asks, and the table test // passed. So this one manufactures an ACTUAL deadlock: a transaction takes the two rows in the // inverted order while the materializer takes them in the package's order, and Postgres kills a // side. When it kills ours, the sweep must come back with a transient error and an attempt that is // still being materialized. func TestADeadlockDoesNotStopTheProjection(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } f.runner.alive = true journal := filepath.Join(f.workdir, ingest.JournalFile) // The handshake is materialized FIRST and on its own. It is the one line that does not go through // Apply — it binds the engine's run id with a statement of its own — so a contended attempt row // would block the tailer before it had taken the book lock, and there would be no cycle to break. body := `{"seq":1,"type":"hello","data":{"stream_version":"1.0","engine_run_id":"eng-1","book_id":"b"}}` + "\n" if err := os.WriteFile(journal, []byte(body), 0o600); err != nil { t.Fatal(err) } if _, err := f.svc.drainJournal(f.ctx, f.live(t)); err != nil { t.Fatal(err) } pool := f.store.Pool() var victim error for seq := 2; seq <= 9 && victim == nil; seq++ { // One fresh line per round: a round our side loses rolls back, a round it wins moves the cursor. line := fmt.Sprintf(`{"seq":%d,"type":"progress","data":{"draft":{"done":%d,"total":10}}}`, seq, seq-1) + "\n" fh, err := os.OpenFile(journal, os.O_APPEND|os.O_WRONLY, 0o600) if err != nil { t.Fatal(err) } if _, err := fh.WriteString(line); err != nil { t.Fatal(err) } if err := fh.Close(); err != nil { t.Fatal(err) } live := f.live(t) // The inverted order: the attempt first, the book second. Nothing in the package does this — // that is the point, it is the shape the package's own order exists to prevent. evil, err := pool.Begin(f.ctx) if err != nil { t.Fatal(err) } var id int64 if err := evil.QueryRow(f.ctx, `select id from run_attempts where id = $1 for update`, live.AttemptID).Scan(&id); err != nil { t.Fatal(err) } drained := make(chan error, 1) go func() { _, err := f.svc.drainJournal(f.ctx, live) drained <- err }() waitBlocked(t, f) var bookID string evilErr := evil.QueryRow(f.ctx, `select id from books where id = $1 for update`, live.BookID).Scan(&bookID) // The inverted transaction is over the moment the deadlock resolved, and it is let go BEFORE the // materializer is waited on: it holds the attempt row, and a materializer that goes on to touch // that row — which is exactly what the defect does — would otherwise hang instead of failing. _ = evil.Rollback(f.ctx) err = <-drained // Asserted every round, not only at the end: a quarantine here is the defect, and catching it // on the round that caused it is the difference between a failure and a hang. if got := f.live(t); got.Quarantined { t.Fatalf("the projection was quarantined over a lock that resolved itself: %v", err) } switch { case pgstore.IsTransient(err): victim = err // ours was the side Postgres killed: that is the round this test is about case evilErr == nil && err == nil: t.Fatal("no deadlock was produced: the two transactions did not contend") } } if victim == nil { t.Fatal("Postgres killed the other side in every round; the branch under test was never reached") } if got := f.live(t); got.Quarantined { t.Fatalf("a deadlock stopped the projection of a live run for good: %v", victim) } // And the very next sweep materializes the line the deadlock cost us. if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } book, _, err := f.store.GetBook(f.ctx, "u1", f.bookID(t)) if err != nil { t.Fatal(err) } if book.Progress.DraftDone == 0 { t.Errorf("the sweep after the deadlock materialized nothing: %+v", book.Progress) } } // waitBlocked waits until some transaction of this test database is waiting for a lock. func waitBlocked(t *testing.T, f *fixture) { t.Helper() deadline := time.Now().Add(20 * time.Second) for { var blocked int if err := f.store.Pool().QueryRow(f.ctx, ` select count(*) from pg_stat_activity where datname = current_database() and wait_event_type = 'Lock'`).Scan(&blocked); err != nil { t.Fatal(err) } if blocked > 0 { return } if time.Now().After(deadline) { t.Fatal("nothing ever blocked on a lock") } time.Sleep(10 * time.Millisecond) } } // A journal that contradicts itself quarantines the ATTEMPT and leaves the RUN alone: the engine is // spending money the account reserved, and our inability to read its journal is not a reason to // throw that away. func TestAContradictoryJournalQuarantinesTheProjectionAndNotTheRun(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } f.runner.alive = true journal := filepath.Join(f.workdir, ingest.JournalFile) hello := `{"seq":1,"type":"hello","data":{"stream_version":"1.0","engine_run_id":"eng-1","book_id":"b"}}` + "\n" first := hello + `{"seq":2,"type":"progress","data":{"draft":{"done":7,"total":20}}}` + "\n" if err := os.WriteFile(journal, []byte(first), 0o600); err != nil { t.Fatal(err) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } // The same seq comes back saying something else, and the byte hint is dropped so the reader meets // it where its cursor stands. rewritten := hello + `{"seq":2,"type":"progress","data":{"draft":{"done":99,"total":20}}}` + "\n" if err := os.WriteFile(journal, []byte(rewritten), 0o600); err != nil { t.Fatal(err) } if _, err := f.store.Pool().Exec(f.ctx, `update run_attempts set last_offset = 0`); err != nil { t.Fatal(err) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } live := f.live(t) if !live.Quarantined { t.Fatal("a journal that contradicted itself did not quarantine the attempt") } book, card, err := f.store.GetBook(f.ctx, "u1", f.bookID(t)) if err != nil { t.Fatal(err) } if card == nil || card.FinishedAt != nil { t.Errorf("the run was ended over a projection failure: %+v", card) } if book.Progress.DraftDone != 7 { t.Errorf("the contradicting figure was materialized anyway: %+v", book.Progress) } if got := f.account(t); got.Reserved == 0 { t.Error("the hold was released while the engine is still running") } } // The engine's committed figure is a LIFETIME total for the book, so the second run of a book must // be charged for what IT spent and not for what the first one did. // // ⚠ Written after an adversarial review measured the opposite: two runs costing $1.00 and $0.50 were // charged $2.50 between them. The overcharge was bounded by the hold, so it never exceeded what was // reserved — and the ledger recorded it as "capped at the hold", which reads as an engine overspend // rather than as the platform's own arithmetic. func TestASecondRunOnABookIsChargedOnlyForWhatItSpent(t *testing.T) { f := newFixture(t, "10", 500) book := f.bookID(t) lifetime := money.MicroUSD(0) f.engine.set(ingest.StatusReport{Spend: usd(lifetime), Reserved: usd(0)}, nil) runOnce := func(spend money.MicroUSD) { t.Helper() run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: book, CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } live := f.live(t) // The book's lifetime meter climbs; what this run cost is the difference. lifetime += spend f.engine.set(ingest.StatusReport{Spend: usd(lifetime), Reserved: usd(0)}, nil) if err := runner.WriteMarker(f.svc.markerPath(live.RunID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } } runOnce(money.MicroUSD(1_000_000)) runOnce(money.MicroUSD(500_000)) acct := f.account(t) if want := money.MicroUSD(10_000_000 - 1_500_000); acct.Balance != want { t.Fatalf("balance %s after two runs costing $1.00 and $0.50, want %s", acct.Balance.USD(), want.USD()) } if acct.Reserved != 0 { t.Errorf("a hold is still open: %s", acct.Reserved.USD()) } if acct.Balance != acct.LedgerSum { t.Errorf("balance %s and ledger %s disagree", acct.Balance.USD(), acct.LedgerSum.USD()) } } // ceilingJudge is a fake engine start that judges `--ceiling-usd` THE WAY THE ENGINE DOES, in two // steps that both matter: // // - opening the book for writing ZEROES every leftover `reserved_usd` (store.Open → // recoverReservations), so what the platform read through the read-only status channel is gone // before a single reservation is judged; // - every reservation is then compared against the book's CUMULATIVE committed + reserved, so a // cap that is not strictly above what the book stands at denies the first one and the process // exits 1 having done nothing (ledger.go Reserve). // // It exists because a fake that merely records the argument cannot fail: the platform handed the // engine the INCREMENT for two whole packs and every test passed, because no test modelled the one // rule that makes the two numbers different. type ceilingJudge struct { *fakeRunner meter func() meter denied []money.MicroUSD } func (c *ceilingJudge) Start(ctx context.Context, s runner.Spec) error { got, err := ceilingArg(s.Args) if err != nil { return err } // The recovery pass, modelled: reserved is gone by the time anything is compared. standing := c.meter().committed if got <= standing { c.denied = append(c.denied, got) return fmt.Errorf("engine: reservation denied: book ceiling %s is at or below what the book stands at (%s)", got.USD(), standing.USD()) } return c.fakeRunner.Start(ctx, s) } func ceilingArg(args []string) (money.MicroUSD, error) { for i, a := range args { if a == "--ceiling-usd" && i+1 < len(args) { return money.ParseUSD(args[i+1]) } } return 0, errors.New("engine: --ceiling-usd is required and was not passed") } // The engine's ceiling flag is a CUMULATIVE book cap, not a run budget (D39.122): it overrides // `ceilings.book_usd` and is judged against everything the book has ever committed or reserved. So // the second run of a book must be told the sum, and handing it the increment denies its first // reservation — the engine exits 1 and the platform can only report a `failed` run that did no work. // // ⚠ Written after acceptance measured exactly that, on both sides of the seam. func TestTheSecondRunOfABookIsGivenTheCumulativeCapAndNotItsOwnIncrement(t *testing.T) { f := newFixture(t, "10", 500) lifetime := money.MicroUSD(0) judge := &ceilingJudge{fakeRunner: f.runner, meter: func() meter { return meter{committed: lifetime} }} f.svc.Runner = judge runOnce := func(spend money.MicroUSD) { t.Helper() run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatalf("the engine refused the ceiling it was given: %v", err) } live := f.live(t) lifetime += spend f.engine.set(ingest.StatusReport{Spend: usd(lifetime), Reserved: usd(0)}, nil) if err := runner.WriteMarker(f.svc.markerPath(live.RunID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } } runOnce(money.MicroUSD(3_000_000)) runOnce(money.MicroUSD(2_000_000)) if len(judge.denied) != 0 { t.Fatalf("the engine denied %v: the argument was the increment, not the cumulative cap", judge.denied) } starts := f.runner.starts() if len(starts) != 2 { t.Fatalf("%d units started", len(starts)) } // $3 already committed by run one, plus run two's own $3 of increment. second, err := ceilingArg(starts[1].Args) if err != nil { t.Fatal(err) } if want := money.MicroUSD(6_000_000); second != want { t.Errorf("the second run was given %s, want %s", second.USD(), want.USD()) } // And what was actually sent is what was written down, because the meter it was computed from // keeps moving and the question "what limit did that process have" has to stay answerable. var stored int64 if err := f.store.Pool().QueryRow(f.ctx, ` select ceiling_arg_micro_usd from run_attempts order by id desc limit 1`).Scan(&stored); err != nil { t.Fatal(err) } if money.MicroUSD(stored) != second { t.Errorf("the attempt records a ceiling of %s and the engine got %s", money.MicroUSD(stored).USD(), second.USD()) } } // A resumed attempt is a new process against a book whose meter the interrupted one MOVED, so its // cap is recomputed from a fresh reading — and the reservation the dead process left behind must NOT // inflate it. // // That leftover is the interesting half, and it is why this test exists next to the one above. // `tmctl status` reports it, because the read-only path deliberately skips the recovery pass; the // resumed engine's own `store.Open` then zeroes it before judging anything. Counting it would hand // the resume that much room BEYOND its hold: the engine stops late, settlement caps at the hold, and // the account underpays. See meter.bookCap — named deviation from D39.122, PD-158. func TestAResumeIsGivenACapComputedFromTheMeterAsItStandsNow(t *testing.T) { f := newFixture(t, "10", 500) m := meter{} judge := &ceilingJudge{fakeRunner: f.runner, meter: func() meter { return m }} f.svc.Runner = judge run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } // The machine goes down: $0.90 committed, and $0.20 the dead process never released. m = meter{committed: 900_000, reserved: 200_000} f.engine.set(ingest.StatusReport{Spend: usd(m.committed), Reserved: usd(m.reserved)}, nil) f.svc.Now = func() time.Time { return f.now.Add(2 * time.Hour) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } starts := f.runner.starts() if len(starts) != 2 { t.Fatalf("%d units started, want the original and the resume", len(starts)) } resumed, err := ceilingArg(starts[1].Args) if err != nil { t.Fatal(err) } remaining := f.svc.Pricing.Ceiling(100) - m.committed if want := m.committed + remaining; resumed != want { t.Errorf("the resume was given %s, want %s — what the book stands at plus what is left of the budget", resumed.USD(), want.USD()) } if resumed >= m.committed+m.reserved+remaining { t.Errorf("the leftover reservation inflated the cap to %s: the engine clears it at start, so that is headroom beyond the hold", resumed.USD()) } if len(judge.denied) != 0 { t.Errorf("the engine denied the resume's ceiling: %v", judge.denied) } } // A settlement that DEFERRED can be overtaken: the run is finished, so nothing stops the account // from starting another run on the same book, and the figure the retry then reads is the BOOK's // lifetime counter, which the second run has been moving. // // ⚠ Measured before the bound existed: a run that cost $0.10 was charged $2.10 — its own spend plus // everything its successor had spent by the time the retry landed — and the successor then paid that // same amount again. Found by two independent reviewers of this pack, reproduced by both. func TestADeferredSettlementIsNotChargedForTheNextRunOfTheSameBook(t *testing.T) { f := newFixture(t, "10", 500) book := f.bookID(t) run1, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: book, CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run1.ID); err != nil { t.Fatal(err) } live1 := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(live1.RunID, live1.AttemptNo), runner.Marker{Unit: live1.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } // The engine cannot be asked at the moment the run ends, so the settlement defers — the ordinary // deferral, already pinned elsewhere. What matters here is what happens NEXT. f.engine.set(ingest.StatusReport{}, errors.New("tmctl: status: database is locked")) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } // The book has cost $0.10 in all, and a second run starts on it. f.engine.set(ingest.StatusReport{Spend: usd(100_000), Reserved: usd(0)}, nil) run2, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: book, CeilingChapters: 100}) if err != nil { t.Fatalf("a second run on a book whose predecessor is unsettled: %v", err) } if err := f.svc.Spawn(f.ctx, run2.ID); err != nil { t.Fatal(err) } // The second run spends $2.00 and is still going when the first one's settlement is retried. f.engine.set(ingest.StatusReport{Spend: usd(2_100_000), Reserved: usd(0)}, nil) f.runner.alive = true if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } spent1, err := f.store.RunSpent(f.ctx, run1.ID) if err != nil { t.Fatal(err) } if want := money.MicroUSD(100_000); spent1 != want { t.Fatalf("the first run was charged %s for work that cost %s", spent1.USD(), want.USD()) } // ...and the second run then pays for its own, once. live2 := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(live2.RunID, live2.AttemptNo), runner.Marker{Unit: live2.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } spent2, err := f.store.RunSpent(f.ctx, run2.ID) if err != nil { t.Fatal(err) } if want := money.MicroUSD(2_000_000); spent2 != want { t.Errorf("the second run was charged %s, want %s", spent2.USD(), want.USD()) } acct := f.account(t) if want := money.MicroUSD(10_000_000 - 2_100_000); acct.Balance != want { t.Errorf("balance %s after two runs costing $2.10 between them, want %s", acct.Balance.USD(), want.USD()) } if acct.Reserved != 0 { t.Errorf("a hold is still open: %s", acct.Reserved.USD()) } if acct.Balance != acct.LedgerSum { t.Errorf("balance %s and ledger %s disagree", acct.Balance.USD(), acct.LedgerSum.USD()) } } // A book meter that reads BELOW an attempt's own baseline is not a refund — it is a project database // that was replaced — so the attempt settles at nothing. Silently charging nothing is the part that // is not acceptable: a settlement of zero has to be findable in a log rather than in a balance. func TestAMeterThatWentBackwardsSettlesAtNothingAndSaysSo(t *testing.T) { f := newFixture(t, "10", 500) var log bytes.Buffer f.svc.Log = slog.New(slog.NewTextHandler(&log, &slog.HandlerOptions{Level: slog.LevelWarn})) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } // The attempt starts on a book that has already cost $1.00... f.engine.set(ingest.StatusReport{Spend: usd(1_000_000), Reserved: usd(0)}, nil) 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(live.RunID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } // ...and the database it was translating is replaced by an older copy. f.engine.set(ingest.StatusReport{Spend: usd(200_000), Reserved: usd(0)}, nil) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } acct := f.account(t) if acct.Balance != money.MicroUSD(10_000_000) { t.Errorf("balance %s: a meter that went backwards must not charge and must not refund", acct.Balance.USD()) } if acct.Reserved != 0 { t.Errorf("the hold is still open: %s", acct.Reserved.USD()) } if !strings.Contains(log.String(), "below this attempt's own baseline") { t.Errorf("a settlement of nothing was silent; the log said: %s", log.String()) } if strings.Contains(log.String(), "1.000000") || strings.Contains(log.String(), "0.200000") { t.Errorf("the line carries money: %s", log.String()) } } // A restart while the engine's figure cannot be read must NOT open a second reservation: the first // one is still open, and nothing would ever come back for it. // // ⚠ Also written after an adversarial review measured it: a $3.00 run showed $6.00 reserved and ended // with $3.00 reserved permanently, listed by nothing. func TestARestartIsDeferredWhileTheInterruptedAttemptIsUnsettled(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } held := f.account(t).Reserved if held == 0 { t.Fatal("nothing was reserved") } // The machine rebooted and the engine can no longer be asked. f.engine.set(ingest.StatusReport{}, errors.New("tmctl: config: no such file")) f.svc.Now = func() time.Time { return f.now.Add(2 * time.Hour) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } if got := f.account(t).Reserved; got != held { t.Fatalf("reserved %s after a deferred restart, want the original %s", got.USD(), held.USD()) } if live := f.live(t); live.AttemptNo != 1 { t.Fatalf("a second attempt was opened on an unsettled one: attempt %d", live.AttemptNo) } // Once the engine answers again the run restarts, with the budget its predecessor left. spent := money.MicroUSD(900_000) f.engine.set(ingest.StatusReport{Spend: usd(spent), Reserved: usd(0)}, nil) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } live := f.live(t) if live.AttemptNo != 2 { t.Fatalf("attempt %d after the engine came back", live.AttemptNo) } acct := f.account(t) if want := f.svc.Pricing.Ceiling(100) - spent; live.Ceiling != want { t.Errorf("the new attempt reserved %s, want %s", live.Ceiling.USD(), want.USD()) } if acct.Balance != acct.LedgerSum { t.Errorf("balance %s and ledger %s disagree", acct.Balance.USD(), acct.LedgerSum.USD()) } } // An attempt that was replaced leaves its reservation open while its RUN goes on. A list keyed on the // run being over never looked at it again — the hold stayed reserved for the life of the account. func TestAnInterruptedAttemptsHoldIsStillFoundWhileItsRunGoesOn(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } live := f.live(t) // Close the attempt behind the reconciler's back, as an operator or a crash-repair would, leaving // its reservation open and the run alive. if _, err := f.store.Pool().Exec(f.ctx, `update run_attempts set ended_at = now() where id = $1`, live.AttemptID); err != nil { t.Fatal(err) } open, err := f.store.UnsettledRuns(f.ctx) if err != nil { t.Fatal(err) } if len(open) != 1 || open[0].AttemptNo != 1 { t.Fatalf("the stranded hold is not listed: %+v", open) } } // A run that was admitted and never started cost nothing, so its hold comes back WHOLE. Without this // the money of a run that never ran stays reserved for the life of the account. func TestTheHoldOfARunThatNeverStartedComesBackWhole(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } live := f.live(t) if live.UnitName != "" { t.Fatal("the attempt was spawned; this test is about one that never was") } if err := runner.WriteMarker(f.svc.markerPath(run.ID, live.AttemptNo), runner.Marker{Unit: "u", Result: "exit-code", Code: "exited", Status: "1"}); err != nil { t.Fatal(err) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } acct := f.account(t) if acct.Reserved != 0 { t.Errorf("reserved %s for a run that never started", acct.Reserved.USD()) } if acct.Balance != money.MicroUSD(10_000_000) { t.Errorf("balance %s: a run that never started must cost nothing", acct.Balance.USD()) } } // A unit that CANNOT be created must leave the attempt retryable. The claim used to survive the // failure, and a recorded unit name with no unit and no marker is exactly the shape of an interrupted // run — so every sweep restarted the run, settled, took a fresh hold and failed to spawn again, and a // run whose engine never started ate its whole ceiling a sweep at a time. func TestAUnitThatCannotBeCreatedDoesNotEatTheRunsBudget(t *testing.T) { f := newFixture(t, "10", 500) f.runner.startErr = errors.New("Failed to start transient scope unit") run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err == nil { t.Fatal("a failed spawn was reported as success") } held := f.account(t).Reserved f.svc.Now = func() time.Time { return f.now.Add(2 * time.Hour) } for range 6 { if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } } live := f.live(t) if live.AttemptNo != 1 { t.Fatalf("six sweeps of a run that never started produced attempt %d", live.AttemptNo) } if got := f.account(t).Reserved; got != held { t.Errorf("reserved %s after six failed spawns, want the original %s", got.USD(), held.USD()) } if got := f.account(t).Balance; got != money.MicroUSD(10_000_000)-held { t.Errorf("balance %s: a run whose engine never started must cost nothing", got.USD()) } } // A spawn that reported failure did not necessarily fail: systemd-run can be killed after it has // already asked for the unit, and then an engine is running while the platform believes none is. The // claim is given back so the attempt can be retried — and the RE-claim must keep the baseline the // first one recorded, because the meter it would read now includes work this very attempt has done. // // ⚠ Found by an outside-the-map reviewer of this pack, reading the path rather than the report. func TestAReclaimedAttemptKeepsTheBaselineItFirstRecorded(t *testing.T) { f := newFixture(t, "10", 500) f.runner.startErr = errors.New("Failed to start transient scope unit: connection timed out") run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err == nil { t.Fatal("the spawn reported success") } live := f.live(t) if live.UnitName != "" { t.Fatal("the claim was not given back") } // The unit was created after all, and the engine it holds has spent $0.40 by the next sweep. f.engine.set(ingest.StatusReport{Spend: usd(400_000), Reserved: usd(0)}, nil) f.runner.startErr = nil f.svc.Now = func() time.Time { return f.now.Add(2 * time.Hour) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } var baseline, stored *int64 if err := f.store.Pool().QueryRow(f.ctx, ` select spend_baseline_micro_usd, ceiling_arg_micro_usd from run_attempts where id = $1`, live.AttemptID).Scan(&baseline, &stored); err != nil { t.Fatal(err) } if baseline == nil || stored == nil { t.Fatal("the attempt has no baseline at all") } if *baseline != 0 { t.Errorf("the re-claim moved the baseline to %s; the attempt would then be billed the difference from its own work", money.MicroUSD(*baseline).USD()) } // And the limit the engine was HANDED on the retry is the one the row records. Recomputing it from // a counter the first claim's own engine has been moving hands that engine a second, larger limit // and leaves the forensic column describing neither. starts := f.runner.starts() if len(starts) != 1 { t.Fatalf("%d units started", len(starts)) } handed, err := ceilingArg(starts[0].Args) if err != nil { t.Fatal(err) } if handed != money.MicroUSD(*stored) { t.Errorf("the retry handed the engine %s and the row records %s", handed.USD(), money.MicroUSD(*stored).USD()) } if want := f.svc.Pricing.Ceiling(100); handed != want { t.Errorf("the retry handed %s, want the limit the first claim decided (%s)", handed.USD(), want.USD()) } } // A journal that cannot be read stops the PROJECTION and nothing else. One malformed line used to // abort the reconcile before the exit marker was even looked at, so the run stayed "translating" // forever with its hold reserved — the engine long gone and the marker on disk. func TestAnUnreadableJournalDoesNotStopTheRunFromFinishing(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } if err := os.WriteFile(filepath.Join(f.workdir, ingest.JournalFile), []byte("this is not an event at all\n"), 0o600); err != nil { t.Fatal(err) } live := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(live.RunID, live.AttemptNo), runner.Marker{Unit: live.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } spent := money.MicroUSD(400_000) f.engine.set(ingest.StatusReport{Spend: usd(spent), Reserved: usd(0)}, nil) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } _, card, err := f.store.GetBook(f.ctx, "u1", f.bookID(t)) if err != nil { t.Fatal(err) } if card == nil || card.FinishedAt == nil { t.Fatalf("a run whose journal is unreadable never finished: %+v", card) } if got := f.account(t); got.Reserved != 0 { t.Errorf("its hold is still open: %s", got.Reserved.USD()) } } // The settlement's TWO deferral branches are different code and both must leave the money alone: the // status call failing, and the report carrying no figure. Only the second was pinned, and the first // is the commoner one. func TestAFailedStatusCallLeavesTheMoneyExactlyWhereItWas(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: "u", Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } held := f.account(t).Reserved f.engine.set(ingest.StatusReport{}, errors.New("tmctl: status: database is locked")) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } if got := f.account(t).Reserved; got != held { t.Errorf("reserved %s after a failed status call, want the original %s", got.USD(), held.USD()) } open, err := f.store.UnsettledRuns(f.ctx) if err != nil { t.Fatal(err) } if len(open) != 1 { t.Fatalf("the run is not on the settlement worklist: %+v", open) } var settled *time.Time if err := f.store.Pool().QueryRow(f.ctx, `select settled_at from runs where id=$1`, run.ID).Scan(&settled); err != nil { t.Fatal(err) } if settled != nil { t.Error("a run was stamped settled although its money never resolved") } } // A run that cannot be resumed on the CURRENT balance is paused with the reason the contract has a // word for — not left live to be retried on every sweep for the rest of its life. func TestAnInterruptedRunThatTheBalanceCannotCarryIsPaused(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } // The engine spent almost nothing, but the rest of the balance went elsewhere while the run was // down, so the restart cannot reserve what is left of the budget. spent := money.MicroUSD(100_000) f.engine.set(ingest.StatusReport{Spend: usd(spent), Reserved: usd(0)}, nil) if _, err := f.store.Adjust(f.ctx, "u1", money.MicroUSD(-9_000_000), "test", "elsewhere", "spent", f.now); err != nil { t.Fatal(err) } f.svc.Now = func() time.Time { return f.now.Add(2 * time.Hour) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } _, card, err := f.store.GetBook(f.ctx, "u1", f.bookID(t)) if err != nil { t.Fatal(err) } if card == nil || card.Status != "paused" || card.PausedReason != "credit_exhausted" { t.Fatalf("a run the balance cannot carry: %+v", card) } } // Lines read and NOT applied still move the byte hint. Without that they are re-read on every sweep // for the life of the run — the case the code names and the one no test reached, because a sweep that // applies events moves the hint through the sink instead. func TestASweepOverAlreadyAppliedLinesStillMovesTheByteHint(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } f.runner.alive = true body := `{"seq":1,"type":"hello","data":{"stream_version":"1.0","engine_run_id":"eng-1","book_id":"b"}}` + "\n" + `{"seq":2,"type":"progress","data":{"draft":{"done":1,"total":10}}}` + "\n" if err := os.WriteFile(filepath.Join(f.workdir, ingest.JournalFile), []byte(body), 0o600); err != nil { t.Fatal(err) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } // Drop the hint but keep the seq, which is what a lost hint looks like. The next sweep re-reads // every line, applies none of them — and must still leave the hint at the end of the file. if _, err := f.store.Pool().Exec(f.ctx, `update run_attempts set last_offset = 0`); err != nil { t.Fatal(err) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } if got := f.live(t); got.Position.Offset != int64(len(body)) { t.Errorf("the byte hint is at %d after a duplicate-only sweep, want %d", got.Position.Offset, len(body)) } } // The spawn reads the book's meter BEFORE it starts anything, and a meter it cannot read REFUSES the // attempt: with no baseline the settlement charges this run for everything the book has ever cost, // and with no reserved figure the engine is handed a cap below its own ledger. Starting anyway is // how a run gets paid for and billed wrong; starting one sweep later costs a sweep. // // ⚠ The refusal itself was built and left unpinned, and a mutation that answered "zero, no error" // survived the whole battery. func TestAnAttemptWhoseMeterCannotBeReadIsNotStartedAtAll(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } for _, tc := range []struct { name string rep ingest.StatusReport err error }{ {"the call fails", ingest.StatusReport{}, errors.New("tmctl: status: database is locked")}, {"no committed figure", ingest.StatusReport{Reserved: usd(0)}, nil}, {"no reserved figure", ingest.StatusReport{Spend: usd(0)}, nil}, } { f.engine.set(tc.rep, tc.err) if err := f.svc.Spawn(f.ctx, run.ID); err == nil { t.Fatalf("%s: the attempt was started anyway", tc.name) } if n := len(f.runner.starts()); n != 0 { t.Fatalf("%s: %d units started", tc.name, n) } if live := f.live(t); live.UnitName != "" { t.Fatalf("%s: the attempt was claimed with unit %q, so no later sweep will retry it", tc.name, live.UnitName) } } // The engine answers again and the same attempt starts, which is what makes the refusal a delay // rather than a lost run. f.engine.set(ingest.StatusReport{Spend: usd(0), Reserved: usd(0)}, nil) if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } if n := len(f.runner.starts()); n != 1 { t.Fatalf("%d units started once the engine could be read", n) } } // A marker left behind by an earlier run of the SAME attempt is read as this one's ending the moment // the reconciler looks — a run that has just been started is finished and settled while its engine // is alive and spending. The names carry the attempt number, so this needs a re-run of one attempt; // "only then" is not "never", and the clearing was built and left unpinned. func TestAStaleExitMarkerIsClearedBeforeTheUnitStarts(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } live := f.live(t) // The leftover: attempt 1 of this run ended once before, and its marker is still on disk. marker := f.svc.markerPath(live.RunID, live.AttemptNo) if err := runner.WriteMarker(marker, runner.Marker{Unit: unitName(live.RunID, live.AttemptNo), Result: "exit-code", Code: "exited", Status: "1"}); err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } if _, err := runner.ReadMarker(marker); !errors.Is(err, runner.ErrNoMarker) { t.Fatalf("the stale marker survived the spawn: %v", err) } f.runner.alive = true if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } _, card, err := f.store.GetBook(f.ctx, "u1", f.bookID(t)) if err != nil { t.Fatal(err) } if card == nil || card.FinishedAt != nil { t.Fatalf("a run whose engine had just been started was finished from an old marker: %+v", card) } if got := f.account(t).Reserved; got == 0 { t.Error("its hold was resolved while the engine is running") } } // The sweep reconciles from a list it read BEFORE working through it, and a run can be spawned, // spend and exit inside that window — a fast run with other runs ahead of it in the pass. The // settlement's "admitted and never started" branch must therefore re-check the row, not the // snapshot, or the hold of a run that really spent money comes back whole. // // ⚠ Measured by acceptance: an attempt that spent $0.50 was charged $0.000000. func TestAStaleSnapshotDoesNotGiveBackTheHoldOfAnAttemptThatSpent(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } stale := f.live(t) if stale.UnitName != "" || stale.SpendBaseline != nil { t.Fatalf("the snapshot must predate the spawn: %+v", stale) } // Meanwhile the queue worker starts the run, the engine spends $0.50 and the unit exits. if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } fresh := f.live(t) if err := runner.WriteMarker(f.svc.markerPath(fresh.RunID, fresh.AttemptNo), runner.Marker{Unit: fresh.UnitName, Result: "exit-code", Code: "exited", Status: "0"}); err != nil { t.Fatal(err) } spent := money.MicroUSD(500_000) f.engine.set(ingest.StatusReport{TotalUnits: 100, Done: 100, Spend: usd(spent), Reserved: usd(0)}, nil) // The sweep finally reaches this run, carrying the snapshot it started with. if err := f.svc.reconcile(f.ctx, stale); err != nil { t.Fatal(err) } if got := f.account(t); got.Balance == money.MicroUSD(10_000_000) { t.Fatal("the whole hold came back for an attempt that spent $0.50") } // The next sweep, with a snapshot that has the unit in it, settles at what was actually spent. if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } acct := f.account(t) if want := money.MicroUSD(10_000_000) - spent; acct.Balance != want { t.Errorf("balance %s, want %s", acct.Balance.USD(), want.USD()) } if acct.Reserved != 0 { t.Errorf("a hold is still open: %s", acct.Reserved.USD()) } if acct.Balance != acct.LedgerSum { t.Errorf("balance %s and ledger %s disagree", acct.Balance.USD(), acct.LedgerSum.USD()) } } // Unified backlog row 139: a run is PINNED to the engine build it started with, and a resume stays on // it. The engine is deployed more often than a translation finishes, so the quiet behaviour would be // for a resumed run to continue under a program nobody chose for it. func TestAResumeStaysOnTheEngineBuildTheRunStartedWith(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } started := f.svc.Cfg.EngineBinary if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } if got := f.runner.starts()[0].Binary; got != started { t.Fatalf("the first attempt ran %q, want the configured build", got) } // The engine is redeployed while the run is down. f.svc.Cfg.EngineBinary = "/opt/engine/2026.09.01/tmctl" spent := money.MicroUSD(100_000) f.engine.set(ingest.StatusReport{Spend: usd(spent), Reserved: usd(0)}, nil) f.svc.Now = func() time.Time { return f.now.Add(2 * time.Hour) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } starts := f.runner.starts() if len(starts) != 2 { t.Fatalf("%d units started", len(starts)) } if got := starts[1].Binary; got != started { t.Errorf("the resumed attempt ran %q, want the pinned %q", got, started) } if got := f.live(t).EngineBinary; got != started { t.Errorf("the new attempt records %q as its build", got) } } // ...and moving to another build is allowed, but only by saying so. func TestAResumeMovesToANewEngineBuildOnlyWhenItIsAllowed(t *testing.T) { f := newFixture(t, "10", 500) f.svc.Cfg.AllowEngineVersionChange = true run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } if err := f.svc.Spawn(f.ctx, run.ID); err != nil { t.Fatal(err) } next := "/opt/engine/2026.09.01/tmctl" f.svc.Cfg.EngineBinary = next spent := money.MicroUSD(100_000) f.engine.set(ingest.StatusReport{Spend: usd(spent), Reserved: usd(0)}, nil) f.svc.Now = func() time.Time { return f.now.Add(2 * time.Hour) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } starts := f.runner.starts() if len(starts) != 2 || starts[1].Binary != next { t.Fatalf("the resumed attempt ran %q, want the new build", starts[len(starts)-1].Binary) } } // Cross-family review of the acceptance dofix (M3): the same hold, on the host that actually produces // this case. An attempt is unspawned BECAUSE the engine could not be run — and settlement used to ask // that same engine for a committed spend before it would give the money back, so every pass failed on // the call and the hold of a run that never ran stayed reserved for good. func TestTheHoldOfARunThatNeverStartedComesBackOnAHostWhoseEngineCannotAnswer(t *testing.T) { f := newFixture(t, "10", 500) run, err := f.svc.Start(f.ctx, StartRequest{UserID: "u1", BookID: f.bookID(t), CeilingChapters: 100}) if err != nil { t.Fatal(err) } live := f.live(t) if live.UnitName != "" { t.Fatal("the attempt was spawned; this test is about one that never was") } f.engine.set(ingest.StatusReport{}, errors.New("tmctl status: exec: no such file or directory")) if err := runner.WriteMarker(f.svc.markerPath(run.ID, live.AttemptNo), runner.Marker{Unit: "u", Result: "exit-code", Code: "exited", Status: "1"}); err != nil { t.Fatal(err) } if err := f.svc.Sweep(f.ctx); err != nil { t.Fatal(err) } acct := f.account(t) if acct.Reserved != 0 { t.Fatalf("reserved %s: the hold of a run that never started waits on an engine that cannot answer", acct.Reserved.USD()) } if acct.Balance != money.MicroUSD(10_000_000) { t.Errorf("balance %s: a run that never started must cost nothing", acct.Balance.USD()) } if f.engine.called() != 0 { t.Errorf("the engine was asked %d times about an attempt that never reached it", f.engine.called()) } }