From 9cfe0808a514f311026e07c57be34d3523fc2c6a Mon Sep 17 00:00:00 2001 From: heaven Date: Fri, 14 Aug 2026 16:33:49 +0300 Subject: [PATCH] Emit the run-event journal from the engine, with distinguishable exit codes for a ceiling halt, a graceful stop and each refusal class --- backend/cmd/tmctl/backup.go | 5 +- backend/cmd/tmctl/exitcontract_test.go | 308 ++++++++ backend/cmd/tmctl/main.go | 107 ++- backend/internal/config/book.go | 12 + backend/internal/config/book_refusal_test.go | 95 +++ backend/internal/pipeline/bankunion_test.go | 2 +- backend/internal/pipeline/bookrun.go | 17 +- backend/internal/pipeline/escalation.go | 26 + backend/internal/pipeline/events.go | 577 +++++++++++++++ backend/internal/pipeline/manifest.go | 6 +- backend/internal/pipeline/refusal.go | 83 +++ backend/internal/pipeline/repair.go | 38 +- .../internal/pipeline/repair_budget_test.go | 118 +++ .../internal/pipeline/runevents_crash_test.go | 279 ++++++++ backend/internal/pipeline/runevents_test.go | 673 ++++++++++++++++++ backend/internal/pipeline/runner.go | 35 +- backend/internal/pipeline/stagerun.go | 46 +- backend/internal/pipeline/status.go | 59 +- .../pipeline/synthetic_stage_seam_test.go | 2 +- backend/internal/pipeline/terminologist.go | 8 +- backend/internal/pipeline/waverun.go | 18 + backend/internal/runevents/journal.go | 187 +++++ backend/internal/runevents/runevents.go | 230 ++++++ backend/internal/runevents/runevents_test.go | 271 +++++++ backend/internal/store/kill9_test.go | 2 +- backend/internal/store/ledger.go | 30 +- backend/internal/store/migrate.go | 23 + backend/internal/store/outbox.go | 216 ++++++ backend/internal/store/outbox_test.go | 316 ++++++++ backend/internal/store/store.go | 9 +- backend/internal/store/store_test.go | 4 +- 31 files changed, 3721 insertions(+), 81 deletions(-) create mode 100644 backend/cmd/tmctl/exitcontract_test.go create mode 100644 backend/internal/config/book_refusal_test.go create mode 100644 backend/internal/pipeline/events.go create mode 100644 backend/internal/pipeline/refusal.go create mode 100644 backend/internal/pipeline/repair_budget_test.go create mode 100644 backend/internal/pipeline/runevents_crash_test.go create mode 100644 backend/internal/pipeline/runevents_test.go create mode 100644 backend/internal/runevents/journal.go create mode 100644 backend/internal/runevents/runevents.go create mode 100644 backend/internal/runevents/runevents_test.go create mode 100644 backend/internal/store/outbox.go create mode 100644 backend/internal/store/outbox_test.go diff --git a/backend/cmd/tmctl/backup.go b/backend/cmd/tmctl/backup.go index 8e78fbc9..c6e3ca33 100644 --- a/backend/cmd/tmctl/backup.go +++ b/backend/cmd/tmctl/backup.go @@ -17,6 +17,7 @@ import ( "time" "textmachine/backend/internal/config" + "textmachine/backend/internal/pipeline" "textmachine/backend/internal/store" ) @@ -54,7 +55,9 @@ func backupCmd(cfgPath string, w io.Writer) error { func preflightBackup(cfgPath string, w io.Writer) error { book, err := config.LoadBook(cfgPath) if err != nil { - return err + // This runs BEFORE the runner, so it is the first thing a broken config meets — and a refusal + // classified here rather than collapsed onto exit 1 is the whole of PD-196 (see pipeline/refusal.go). + return pipeline.RefuseConfig(err) } // Only ABSENT means "fresh book". Any other stat error read that way silently skips the guard. if _, err := os.Stat(book.ProjectDB); err != nil { diff --git a/backend/cmd/tmctl/exitcontract_test.go b/backend/cmd/tmctl/exitcontract_test.go new file mode 100644 index 00000000..a7982fcc --- /dev/null +++ b/backend/cmd/tmctl/exitcontract_test.go @@ -0,0 +1,308 @@ +package main + +import ( + "encoding/json" + "errors" + "fmt" + "net/http" + "net/http/httptest" + "os" + "os/exec" + "path/filepath" + "strings" + "sync" + "syscall" + "testing" + "time" + + "textmachine/backend/internal/runevents" + "textmachine/backend/internal/store" +) + +// exitcontract_test.go drives the REAL binary, because the shell contract is only a contract at the +// shell: a supervisor learns how a run ended from the number the process exits with, and the acceptance +// of the platform's runner found that out the hard way — its fake probe died FROM the signal, so it +// never saw that the engine catches SIGTERM and left with 1 (PD-152). + +var ( + tmctlOnce sync.Once + tmctlPath string + tmctlErr error +) + +// buildTmctl compiles the CLI once for the whole package. +func buildTmctl(t *testing.T) string { + t.Helper() + tmctlOnce.Do(func() { + dir, err := os.MkdirTemp("", "tmctl-bin") + if err != nil { + tmctlErr = err + return + } + tmctlPath = filepath.Join(dir, "tmctl") + out, err := exec.Command("go", "build", "-o", tmctlPath, ".").CombinedOutput() + if err != nil { + tmctlErr = fmt.Errorf("build tmctl: %w\n%s", err, out) + } + }) + if tmctlErr != nil { + t.Fatal(tmctlErr) + } + return tmctlPath +} + +func exitCodeOf(t *testing.T, err error) int { + t.Helper() + if err == nil { + return 0 + } + var ee *exec.ExitError + if !errors.As(err, &ee) { + t.Fatalf("not an exit status: %v", err) + } + return ee.ExitCode() +} + +// slowProvider answers after `delay`, so a signal can arrive while a call is in flight. +func slowProvider(t *testing.T, delay time.Duration) *httptest.Server { + t.Helper() + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + time.Sleep(delay) + fmt.Fprint(w, `{"id":"fake","model":"fake-model","choices":[{"message":{"content":"ПЕРЕВОД"},"finish_reason":"stop"}], + "usage":{"prompt_tokens":100,"completion_tokens":50}}`) + })) + t.Cleanup(srv.Close) + return srv +} + +func journalOf(t *testing.T, bookPath string) []runevents.Envelope { + t.Helper() + body, err := os.ReadFile(filepath.Join(filepath.Dir(bookPath), runevents.JournalFile)) + if err != nil { + t.Fatalf("read journal: %v", err) + } + var out []runevents.Envelope + for _, l := range strings.Split(strings.TrimSpace(string(body)), "\n") { + if l == "" { + continue + } + var ev runevents.Envelope + if err := json.Unmarshal([]byte(l), &ev); err != nil { + t.Fatalf("malformed journal line %q: %v", l, err) + } + out = append(out, ev) + } + return out +} + +func lastOutcome(t *testing.T, envs []runevents.Envelope) string { + t.Helper() + if len(envs) == 0 { + t.Fatal("empty journal") + } + last := envs[len(envs)-1] + if last.Type != runevents.TypeFinished { + t.Fatalf("the stream's last line is %s, not the terminal event", last.Type) + } + var f runevents.Finished + if err := json.Unmarshal(last.Data, &f); err != nil { + t.Fatal(err) + } + return f.Outcome +} + +func TestACeilingHaltLeavesItsOwnExitCode(t *testing.T) { + // PD-113: the platform's contract calls this stop `paused` and forbids `failed`, and exit 1 was the + // only thing it had to go on. Since the ceiling argument is set flush against the hold (PD-158), this + // is the number that separates "the money ran out" from "the machine broke". + if testing.Short() { + t.Skip("builds and runs the binary") + } + bin := buildTmctl(t) + srv := slowProvider(t, 0) + bookPath := setupCLIProject(t, srv.URL) + raiseCeiling(t, bookPath, "ceilings: { book_usd: 0.0000001, day_usd: 2.0 }") + + err := exec.Command(bin, "translate", "--config", bookPath).Run() + if got := exitCodeOf(t, err); got != 4 { + t.Fatalf("a ceiling halt exited %d, want 4", got) + } + envs := journalOf(t, bookPath) + if got := lastOutcome(t, envs); got != runevents.OutcomeCeiling { + t.Fatalf("terminal outcome %q, want %q", got, runevents.OutcomeCeiling) + } + found := false + for _, ev := range envs { + if ev.Type == runevents.TypeCeiling { + found = true + } + } + if !found { + t.Fatal("the stream must carry the ceiling event too: the exit code and the event fail independently") + } +} + +func TestAGracefulStopLeavesItsOwnExitCode(t *testing.T) { + // The other half of row 165 and of PD-152: tmctl CATCHES SIGTERM, so it does not die from the signal — + // it winds down and exits. While that exit was 1, a host reboot closed every live run as `failed`. + if testing.Short() { + t.Skip("builds and runs the binary") + } + bin := buildTmctl(t) + srv := slowProvider(t, 3*time.Second) + bookPath := setupCLIProject(t, srv.URL) + + cmd := exec.Command(bin, "translate", "--config", bookPath) + cmd.Stderr = os.Stderr + if err := cmd.Start(); err != nil { + t.Fatal(err) + } + waitForJournal(t, bookPath) + if err := cmd.Process.Signal(syscall.SIGTERM); err != nil { + t.Fatal(err) + } + if got := exitCodeOf(t, cmd.Wait()); got != 5 { + t.Fatalf("a caught SIGTERM exited %d, want 5", got) + } + if got := lastOutcome(t, journalOf(t, bookPath)); got != runevents.OutcomeStopped { + t.Fatalf("terminal outcome %q, want %q", got, runevents.OutcomeStopped) + } +} + +func TestEveryRefusalClassHasItsOwnNumberInsideTheBand(t *testing.T) { + // PD-196: the platform's intake rejects a book as `source_unreadable` after five failures and deletes + // the upload. While every refusal was exit 1, an operator's typo in a hand-written book.yaml looked + // exactly like an unusable source. + if testing.Short() { + t.Skip("builds and runs the binary") + } + bin := buildTmctl(t) + srv := slowProvider(t, 0) + + t.Run("a broken config", func(t *testing.T) { + bookPath := setupCLIProject(t, srv.URL) + writeCLIFile(t, bookPath, "book_id: cli-book\n bad indentation: [\n") + if got := exitCodeOf(t, exec.Command(bin, "translate", "--config", bookPath).Run()); got != exitConfigInvalid { + t.Fatalf("exit %d, want %d", got, exitConfigInvalid) + } + }) + + t.Run("a source the config names but the host does not have", func(t *testing.T) { + // The CONFIG class, not the text class, and the difference is a user's file. A missing path says + // something about the deployment — a template naming a filename the upload route did not use, a + // mount that went away — and exit 11 is what an automated intake acts on by deleting the upload. + bookPath := setupCLIProject(t, srv.URL) + if err := os.Remove(filepath.Join(filepath.Dir(bookPath), "source.txt")); err != nil { + t.Fatal(err) + } + if got := exitCodeOf(t, exec.Command(bin, "translate", "--config", bookPath).Run()); got != exitConfigInvalid { + t.Fatalf("exit %d, want %d — a missing path must not be reported as the user's text being unusable", got, exitConfigInvalid) + } + }) + + t.Run("a source that exists but cannot be read", func(t *testing.T) { + // Passes the config's existence check and fails at the READ — a permission, an I/O error, a path + // that is not a file. Still the config/host class: nothing here says the user's text is bad, and + // exit 11 is what deletes it. + bookPath := setupCLIProject(t, srv.URL) + src := filepath.Join(filepath.Dir(bookPath), "source.txt") + if err := os.Remove(src); err != nil { + t.Fatal(err) + } + if err := os.Mkdir(src, 0o755); err != nil { // stat succeeds, every read fails + t.Fatal(err) + } + if got := exitCodeOf(t, exec.Command(bin, "translate", "--config", bookPath).Run()); got != exitConfigInvalid { + t.Fatalf("exit %d, want %d — an unreadable path must not be reported as the user's text being unusable", got, exitConfigInvalid) + } + }) + + t.Run("a source that reads but holds no book", func(t *testing.T) { + // The ONE thing the engine can assert about the TEXT with no configuration in the way: the bytes + // were read and cut, and there is nothing to translate. No `encoding`, `source_lang` or path + // setting explains an empty result from a successful read. + bookPath := setupCLIProject(t, srv.URL) + writeCLIFile(t, filepath.Join(filepath.Dir(bookPath), "source.txt"), " \n\n") + if got := exitCodeOf(t, exec.Command(bin, "translate", "--config", bookPath).Run()); got != exitSourceUnreadable { + t.Fatalf("exit %d, want %d", got, exitSourceUnreadable) + } + }) + + t.Run("a project another process holds", func(t *testing.T) { + bookPath := setupCLIProject(t, srv.URL) + held, err := store.Open(filepath.Join(filepath.Dir(bookPath), "cli-book.db")) + if err != nil { + t.Fatal(err) + } + defer held.Close() + if got := exitCodeOf(t, exec.Command(bin, "translate", "--config", bookPath).Run()); got != exitProjectLocked { + t.Fatalf("exit %d, want %d", got, exitProjectLocked) + } + }) + + // The band is the contract, not the individual numbers: a caller that treats [10,19] as "refused" + // stays safe when a class it has never heard of appears. + for _, code := range []int{exitConfigInvalid, exitSourceUnreadable, exitProjectLocked, exitRefusedOther} { + if code < refusalFirst || code > refusalLast { + t.Fatalf("refusal code %d is outside the band [%d,%d] every consumer keys on", code, refusalFirst, refusalLast) + } + } +} + +func TestTheCallerMayNameTheRun(t *testing.T) { + // Row 102: a run the platform spawned should be ONE trace, and the id is also the `engine_run_id` + // half of the seam's idempotency key — so letting the caller supply it makes that namespace theirs + // by construction instead of something they have to learn from the handshake. + if testing.Short() { + t.Skip("builds and runs the binary") + } + bin := buildTmctl(t) + srv := slowProvider(t, 0) + bookPath := setupCLIProject(t, srv.URL) + + cmd := exec.Command(bin, "translate", "--config", bookPath) + cmd.Env = append(os.Environ(), "TM_TRACE_ID=platform-run-42") + cmd.Stderr = os.Stderr + if err := cmd.Run(); err != nil { + t.Fatalf("run: %v", err) + } + envs := journalOf(t, bookPath) + var h runevents.Hello + if err := json.Unmarshal(envs[0].Data, &h); err != nil { + t.Fatal(err) + } + if h.EngineRunID != "platform-run-42" { + t.Fatalf("engine_run_id = %q, want the id the caller passed", h.EngineRunID) + } +} + +// raiseCeiling rewrites the fixture's ceilings line. +func raiseCeiling(t *testing.T, bookPath, line string) { + t.Helper() + body, err := os.ReadFile(bookPath) + if err != nil { + t.Fatal(err) + } + patched := strings.Replace(string(body), "ceilings: { book_usd: 1.0, day_usd: 2.0 }", line, 1) + if patched == string(body) { + t.Fatalf("the ceilings line moved; fixture needs updating:\n%s", body) + } + writeCLIFile(t, bookPath, patched) +} + +// waitForJournal blocks until the run has written its handshake, so a signal cannot arrive before the +// process has started working. +func waitForJournal(t *testing.T, bookPath string) { + t.Helper() + path := filepath.Join(filepath.Dir(bookPath), runevents.JournalFile) + deadline := time.Now().Add(30 * time.Second) + for { + if body, err := os.ReadFile(path); err == nil && strings.Contains(string(body), `"hello"`) { + return + } + if time.Now().After(deadline) { + t.Fatal("the run wrote no handshake in 30s") + } + time.Sleep(5 * time.Millisecond) + } +} diff --git a/backend/cmd/tmctl/main.go b/backend/cmd/tmctl/main.go index 437bc1a3..40c5048b 100644 --- a/backend/cmd/tmctl/main.go +++ b/backend/cmd/tmctl/main.go @@ -27,18 +27,65 @@ func main() { os.Exit(exitCode(err)) } -// exitCode maps a run() error onto the ratified shell contract (Milestone 2 / R1-FL-A): 0 clean · 2 -// completed-with-flags (acceptance allows N flags; a typed sentinel -// *pipeline.CompletedWithFlags, survives %w-wraps via errors.As) · 3 bank-mining -// signature stop (*pipeline.WaveSignatureStop — the run paused before the edit wave for owner -// sign; a DELIBERATE human-in-the-loop halt, not a crash) · 1 infra failure and everything else, -// including a flag-parse error. 3 is DISTINCT from both 2 (flagged chunks) and 1 (crash) so -// exit-code automation can tell a sign-boundary pause from a real failure — a human sees the -// stderr text either way, but a script that shipped "translate && export" must NOT treat the -// pause as success (exit 0) nor as an infra crash (exit 1). +// The refusal band. A code in [refusalFirst, refusalLast] means the invocation was TURNED DOWN before +// it did any work of its own — nothing reached a provider, nothing was spent, nothing was written — and +// the particular number names why. +// +// It is a BAND and not a list because the vocabulary is the engine's and it will grow: a caller looks up +// the number, and a class this build of the caller has never heard of still lands in the band and reads +// as "refused" rather than as "failed". That difference is the whole of PD-196 — the platform's intake +// rejects a book as `source_unreadable` after five failures and deletes the upload, and every refusal +// used to arrive as the same exit 1, so an operator's typo in a hand-written book.yaml was one step from +// destroying a user's file. A new class is a new constant here and in pipeline.RefusalClass; no consumer +// has to enumerate them to stay safe. +const ( + refusalFirst = 10 + refusalLast = 19 + + exitConfigInvalid = 10 // the configuration will not run: unreadable, unparseable, invalid, no key + exitSourceUnreadable = 11 // the BOOK's source cannot be read or decoded — the one class about the text + exitProjectLocked = 12 // another tmctl owns this project right now; come back later + exitRefusedOther = 19 // a refusal class this build of tmctl has no number for +) + +// refusalExit is the dictionary the band is read through. +var refusalExit = map[pipeline.RefusalClass]int{ + pipeline.RefusalBadConfig: exitConfigInvalid, + pipeline.RefusalSourceUnreadable: exitSourceUnreadable, + pipeline.RefusalProjectLocked: exitProjectLocked, +} + +// exitCode maps a run() error onto the ratified shell contract (Milestone 2 / R1-FL-A): +// +// 0 clean +// 1 infra failure and everything else, including a flag-parse error +// 2 completed-with-flags (acceptance allows N flags; the typed *pipeline.CompletedWithFlags, +// which survives %w-wraps via errors.As) +// 3 bank-mining signature stop (*pipeline.WaveSignatureStop — the run paused before the edit wave +// for owner sign; a DELIBERATE human-in-the-loop halt, not a crash) +// 4 ceiling halt (*pipeline.CeilingHalt — the book or day USD ceiling stopped the run) +// 5 graceful stop (SIGINT/SIGTERM was caught and the run wound down) +// 10-19 refusal band, see above +// +// 3 is DISTINCT from both 2 (flagged chunks) and 1 (crash) so exit-code automation can tell a +// sign-boundary pause from a real failure — a human sees the stderr text either way, but a script that +// shipped "translate && export" must NOT treat the pause as success (exit 0) nor as an infra crash. +// +// 4 and 5 exist for the same reason one level up, and they are money (row 165). A supervisor learns how +// a run ended from its exit code, so while a ceiling halt and a caught SIGTERM both mapped to 1 the +// platform recorded `failed` for both — for a stop its own contract calls `paused` and forbids calling +// `failed` (PD-113), and for the user's own stop and for an ordinary host reboot (PD-152). Since the +// ceiling argument is now set flush against the hold (PD-158), "the money ran out" and "the machine +// broke" were the same number at exactly the moment they became opposite facts. +// +// 5 reads a CANCELLED context because in tmctl the run context is cancelled by signal.NotifyContext and +// by nothing else (see run): a cancelled run is one somebody asked to stop. It is checked after the +// typed sentinels, so a run that reached its own terminal state before the signal keeps its own code. func exitCode(err error) int { var flagged *pipeline.CompletedWithFlags var sigStop *pipeline.WaveSignatureStop + var ceiling *pipeline.CeilingHalt + var refusal *pipeline.Refusal switch { case err == nil: return 0 @@ -46,11 +93,51 @@ func exitCode(err error) int { return 3 case errors.As(err, &flagged): return 2 + case errors.As(err, &ceiling): + return 4 + case errors.As(err, &refusal): + if code, ok := refusalExit[refusal.Class]; ok { + return code + } + return exitRefusedOther + case errors.Is(err, context.Canceled): + return 5 default: return 1 } } +// traceID is the identity of this invocation: its log axis, its request_log column, and — since the +// event seam exists — the `engine_run_id` half of the ratified idempotency key (engine_run_id, seq). +// +// It is ACCEPTED from the environment (row 102) and minted only when none was given. A run the platform +// spawned should be ONE trace end to end, and letting the caller name it means the idempotency namespace +// of the stream is the caller's by construction rather than something it has to learn from a handshake +// (the reader's own comment anticipates exactly this). The environment and not a flag: argv is the one +// channel this zone keeps deliberately free of run identity (PD-99), and a supervisor already has an +// Env for the unit. +// +// A value it cannot use is REFUSED rather than trimmed into something else: an id is compared, joined +// and stored, so silently correcting it would make two runs share a namespace. The shape is what a log +// axis and a database key can both carry — printable, no spaces, bounded. +func traceID() string { + v := os.Getenv("TM_TRACE_ID") + if v == "" { + return obs.NewTraceID() + } + if len(v) > 64 { + fmt.Fprintf(os.Stderr, "tmctl: TM_TRACE_ID is %d characters (max 64) — minting one instead\n", len(v)) + return obs.NewTraceID() + } + for _, c := range v { + if c <= ' ' || c > '~' { + fmt.Fprintln(os.Stderr, "tmctl: TM_TRACE_ID must be printable ASCII without spaces — minting one instead") + return obs.NewTraceID() + } + } + return v +} + func run() error { inv, err := parseInvocation(os.Args[1:], os.Stderr) if err != nil { @@ -65,7 +152,7 @@ func run() error { // LogBodies is decided once at admission (privacy by default): the content // of LLM exchanges reaches the logs only when LOG_LLM_BODIES=1 AND LOG_LEVEL=debug. ctx = obs.WithReqInfo(ctx, obs.ReqInfo{ - TraceID: obs.NewTraceID(), + TraceID: traceID(), LogBodies: os.Getenv("LOG_LLM_BODIES") == "1", }) diff --git a/backend/internal/config/book.go b/backend/internal/config/book.go index 944a6082..5538a295 100644 --- a/backend/internal/config/book.go +++ b/backend/internal/config/book.go @@ -110,6 +110,14 @@ type Book struct { // brief: it is deliberately absent from BriefHash and from the snapshot, so setting it never // re-pays anything by itself. RebillConsentUSD float64 `yaml:"rebill_consent_usd"` + + // Dir is the directory book.yaml was loaded from — the BOOK's directory, which is also where the + // run-event journal lives (D39.106 §2: `events.jsonl` in the book's directory, which is the + // platform's workdir for this run). Derived, never read from the file: `yaml:"-"` keeps the strict + // decoder from ever accepting a `dir:` key that would let a config claim a directory it is not in. + // It is NOT ProjectDB's directory — `project_db` may point anywhere, and the seam is anchored to + // the config the platform passed, not to a path inside it. + Dir string `yaml:"-"` } // BookCap are the ledger admission limits (Р7: the $ ceiling per book/day). @@ -137,6 +145,7 @@ func LoadBook(path string) (*Book, error) { return nil, fmt.Errorf("config: parse %s: %w", path, err) } dir := filepath.Dir(path) + b.Dir = dir resolve := func(p string) string { if p == "" || filepath.IsAbs(p) { return p @@ -177,6 +186,9 @@ func LoadBook(path string) (*Book, error) { if b.SourceFile == "" { bad("source_file is required") } else if _, err := os.Stat(b.SourceFile); err != nil { + // Deliberately NOT a verdict about the TEXT: a path that is missing, a permission or an I/O error + // is a fact about the configuration or the host, and the class that blames the user's text is the + // one an automated caller acts on by deleting their upload (PD-196, pipeline/refusal.go). bad("source_file %s is not readable: %v", b.SourceFile, err) } if b.GlossarySeed != "" { diff --git a/backend/internal/config/book_refusal_test.go b/backend/internal/config/book_refusal_test.go new file mode 100644 index 00000000..19653bcd --- /dev/null +++ b/backend/internal/config/book_refusal_test.go @@ -0,0 +1,95 @@ +package config + +import ( + "os" + "path/filepath" + "strings" + "testing" +) + +// book_refusal_test.go: the ONE distinction PD-196 rests on — "the text we were handed is unusable" +// against "the operator's config is broken". They have opposite repairs, and upstream the first one +// authorises deleting a user's upload while the second must not. + +func bookFixture(t *testing.T, sourceName string) string { + t.Helper() + dir := t.TempDir() + if sourceName != "" { + if err := os.WriteFile(filepath.Join(dir, sourceName), []byte("текст"), 0o644); err != nil { + t.Fatal(err) + } + } + path := filepath.Join(dir, "book.yaml") + body := ` +book_id: b +title: Т +source_lang: ja +target_lang: ru +genre: g +audience: a +venuti: 0.5 +honorifics: keep +transcription: polivanov +footnotes: minimal +pipeline: pipeline.yaml +models: models.yaml +source_file: source.txt +ceilings: { book_usd: 1.0 } +` + if err := os.WriteFile(path, []byte(body), 0o644); err != nil { + t.Fatal(err) + } + return path +} + +func TestAMissingSourceIsAnOrdinaryConfigProblem(t *testing.T) { + // It is deliberately NOT a verdict about the user's text. A path that is not there says something + // about the configuration or the host — a template naming a filename the upload route did not use, a + // mount that vanished — and the class that blames the text is the one an automated intake acts on by + // DELETING the upload (PD-196, pipeline/refusal.go). So this stays an ordinary problem, and the + // caller maps it to the config exit code. + path := bookFixture(t, "") // the source_file the config names is not there + err := loadErr(t, path) + if !strings.Contains(err.Error(), "source_file") || !strings.Contains(err.Error(), "not readable") { + t.Fatalf("the operator must be told which setting is wrong: %v", err) + } +} + +func TestEveryFaultIsReportedTogether(t *testing.T) { + // The aggregate is the contract: an operator fixing a hand-written config wants every complaint at + // once, not one per run. + path := bookFixture(t, "") + body, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if err := os.WriteFile(path, []byte(strings.Replace(string(body), "book_id: b", "book_id: \"\"", 1)), 0o644); err != nil { + t.Fatal(err) + } + msg := loadErr(t, path).Error() + if !strings.Contains(msg, "book_id") || !strings.Contains(msg, "source_file") { + t.Fatalf("want both faults named, got %v", msg) + } +} + +func loadErr(t *testing.T, path string) error { + t.Helper() + _, err := LoadBook(path) + if err == nil { + t.Fatal("this book must not load") + } + return err +} + +func TestTheBookRemembersTheDirectoryItWasLoadedFrom(t *testing.T) { + // The run-event journal lives in the BOOK's directory (D39.106 §2) — the directory of the config the + // caller passed, which is not necessarily the project database's. + path := bookFixture(t, "source.txt") + b, err := LoadBook(path) + if err != nil { + t.Fatal(err) + } + if b.Dir != filepath.Dir(path) { + t.Fatalf("Dir = %q, want %q", b.Dir, filepath.Dir(path)) + } +} diff --git a/backend/internal/pipeline/bankunion_test.go b/backend/internal/pipeline/bankunion_test.go index 1f220383..238eb620 100644 --- a/backend/internal/pipeline/bankunion_test.go +++ b/backend/internal/pipeline/bankunion_test.go @@ -68,7 +68,7 @@ func TestBankUnionRecoversASupersededSampling(t *testing.T) { RequestHash: "second-sampling", JobID: job.ID, ChunkIdx: 0, Attempt: 1, Stage: "draft", Role: roleTranslator, ModelRequested: "fake-model", ModelActual: "fake-model", ResponseText: second, UsageJSON: "{}", CostUSD: 0.01, FinishReason: "stop", - }); err != nil { + }, nil); err != nil { t.Fatal(err) } diff --git a/backend/internal/pipeline/bookrun.go b/backend/internal/pipeline/bookrun.go index 842679bd..b99a8a73 100644 --- a/backend/internal/pipeline/bookrun.go +++ b/backend/internal/pipeline/bookrun.go @@ -105,7 +105,20 @@ func (e *CompletedWithFlags) Error() string { // A bad chunk is flagged and the loop CONTINUES (D2); only an infra failure // (ceiling, config change without --resnapshot, unbilled call failure, store // error) aborts with an error, from which resume continues. +// +// It is also the boundary of the run-event seam (row 103): the journal is opened here rather than with +// the runner, because a run's identity IS the call's trace id and that lives on the context — and +// because a command that never runs a book (a dry-run redrive, a read-only projection) must leave no +// trace in a stream that describes runs. Every exit of the run passes through terminal() below, so the +// stream's last line says WHY it ended and a reader never has to do exit-code archaeology. func (r *Runner) TranslateBook(ctx context.Context) (*BookResult, error) { + r.openEvents(ctx) + res, err := r.translateBook(ctx) + r.events.terminal(res, err) + return res, err +} + +func (r *Runner) translateBook(ctx context.Context) (*BookResult, error) { // Ingest reads + normalizes the source (txt/epub) into ordered per-chapter text // and captures ruby readings (ingest.go), decoding the txt source per book.encoding // (auto/utf8/gb18030). Offline and deterministic ($0, no LLM). @@ -113,7 +126,7 @@ func (r *Runner) TranslateBook(ctx context.Context) (*BookResult, error) { // the identity of the bytes it was actually cut from, and the cut takes seconds on a large book. // nil = it could not be taken, which costs this run its manifest and nothing else. srcBefore := r.sourceFingerprintBeforeIngest(ctx) - doc, err := chunk.IngestEncoded(r.Book.SourceFile, r.Book.Encoding, r.Book.SourceLang) + doc, err := r.ingestSource() if err != nil { return nil, err } @@ -147,7 +160,7 @@ func (r *Runner) TranslateBook(ctx context.Context) (*BookResult, error) { chunks, chapterTexts := chunk.SplitChunksWithChapters(doc.Chapters, r.segBudget(), r.headingRule(), r.sentenceAbbrevs()) if len(chunks) == 0 { - return nil, fmt.Errorf("pipeline: source file %s produced no chunks after normalization", r.Book.SourceFile) + return nil, sourceHasNoContent(fmt.Errorf("pipeline: source file %s produced no chunks after normalization", r.Book.SourceFile)) } // The chapter/chunk manifest (backlog row 100): persisted HERE, where the split that every paid byte // is addressed against was just computed, so the artifact and the run can never describe different diff --git a/backend/internal/pipeline/escalation.go b/backend/internal/pipeline/escalation.go index 26cf5eaa..8b154d76 100644 --- a/backend/internal/pipeline/escalation.go +++ b/backend/internal/pipeline/escalation.go @@ -48,6 +48,24 @@ func (r *Runner) applyModelFloor(base int, model string) int { // book on every run (self-review finding). var errReserveCeiling = errors.New("reserve ceiling reached") +// CeilingHalt is the ceiling stop as a TYPE, so the two callers that must tell it from a crash can do so +// without reading prose: the CLI maps it to its own exit code (never 1 — the platform's contract forbids +// calling a resumable stop `failed`, PD-113) and the driver emits the stream's `ceiling` event from it. +// Scope names WHICH ceiling stopped the run, which is the diagnosis half of PD-157: a book's daily +// ceiling is one the platform neither sets nor sees, and today it cannot tell that stop from the one it +// chose itself. +// +// It WRAPS errReserveCeiling rather than replacing it, so every `errors.Is` that already degrades on a +// ceiling — the optional escalation hop, the repair sub-step, the terminology pass — keeps working +// unchanged. +type CeilingHalt struct { + Scope string // runevents.ScopeBook | runevents.ScopeDay + err error +} + +func (e *CeilingHalt) Error() string { return e.err.Error() } +func (e *CeilingHalt) Unwrap() error { return e.err } + // escalationBudgetRemains reports whether the book may still spend on a single-hop // fallback draft: escalation is OPT-IN via escalation.budget_usd (0 = disabled, the // boevoy default — a stage's escalate_to is inert until a premium budget is set), and @@ -56,6 +74,14 @@ var errReserveCeiling = errors.New("reserve ceiling reached") // budget and does NOT pre-estimate the hop's own cost, so a single hop may overshoot // the budget by up to its full cost; the NEXT chunk's escalation is then denied. Size // the budget with that worst case in mind — it bounds TOTAL escalation, not per-hop. +// +// ⚠ Row 135 (the per-call ceiling gate) deliberately stopped here. The row's target is GRANULARITY — +// "a gate on every paid call, not on a unit of work" — and this gate is already per call: a hop IS one +// call. What it does not do is PRICE the call it admits, which is a different tightening, and the +// overshoot it allows is documented above, pinned by three tests and therefore a ratified bound rather +// than an oversight. Changing it is a question for the orchestrator, not a side effect of this pack; +// the repair sub-step, which took ONE decision per unit and then bought several calls under it, is the +// gate the row named and the one this pack tightened. func (r *Runner) escalationBudgetRemains() (bool, error) { budget := r.Pipeline.Escal.BudgetUSD if budget <= 0 { diff --git a/backend/internal/pipeline/events.go b/backend/internal/pipeline/events.go new file mode 100644 index 00000000..349f22dc --- /dev/null +++ b/backend/internal/pipeline/events.go @@ -0,0 +1,577 @@ +package pipeline + +import ( + "context" + "errors" + "fmt" + "log/slog" + "path/filepath" + "sync" + "sync/atomic" + "time" + + "textmachine/backend/internal/chunk" + "textmachine/backend/internal/obs" + "textmachine/backend/internal/runevents" + "textmachine/backend/internal/store" +) + +// events.go: WHEN the run-event seam emits (row 103). The form lives in internal/runevents, the durable +// sequencing in internal/store (events_outbox); here is the driver's half — the call sites, the counters +// and the policy for a journal that cannot be written. +// +// ORDER, and it is the invariant: a fact is committed to SQLite, THEN its line is enqueued in the +// outbox, THEN the outbox is projected onto the file. Nothing is ever written to the journal that the +// database does not already hold, which is the direction that would cost money and lie to a user; the +// opposite direction — a fact committed whose line was lost to a crash — is bounded and named per event +// below, and its ratified repair channel is the `status --json` resync (D39.106 §2). +// +// The two events a lost line cannot hurt are `spend` (cumulative: the next line carries the total again) +// and `progress` (an assignment: the next line carries the counters again). The one it can is +// `unit_done`, which a reader FOLDS BY INCREMENT — see unitResolved. + +// emitter writes one process's region of a book's event journal. +// +// Everything is under one mutex, including the projection: the waves emit from N workers, and the reader +// cannot survive seq N+1 appearing above seq N. Under the mutex the projection always reads the outbox +// in sequence order, so it appends a dense prefix even when two workers commit concurrently (the write +// pool is single-connection, so a transaction sees MAX(seq)=N only after N's transaction committed). +type emitter struct { + mu sync.Mutex + store *store.Store + journal *runevents.Journal + log *slog.Logger + runID string + bookID string + now func() time.Time + lastSeen int64 // the highest seq already on the file + degraded bool // the journal refused a write; the run continues (PD-60) + // marks are the announce-once keys whose line has been enqueued but not yet confirmed on the file. + marks map[int64]string + + // waves is the live per-phase counter. nil until the driver knows the book's cut (beginWaves). + waves *waveCounters +} + +// openEmitter opens the book's journal, drops the previous processes' outbox rows and writes this +// process's handshake as its first line. runID is the process identity (the trace id) and is the half of +// the ratified idempotency key (engine_run_id, seq) that makes a resumed run a new stream in the same +// file rather than a corruption of the old one. +func openEmitter(st *store.Store, dir, runID, bookID string, log *slog.Logger) (*emitter, error) { + j, err := runevents.OpenJournal(dir) + if err != nil { + return nil, err + } + // The stream identity must be FRESH, and since row 102 the caller can supply it — so this is the one + // place that checks. Reusing an id that already wrote for this book is not a small mistake: the + // sequence continues from the previous process's numbers instead of restarting at 1, and the + // projection, whose cursor starts at zero, re-appends that entire previous stream before writing a + // handshake at some seq far past 1. A reader then re-applies every counting event it already applied + // and finally refuses the handshake. Measured on the real binary before this guard: two runs under + // one TM_TRACE_ID produced 33 lines, 15 of them byte-identical duplicates, and a hello at seq 16. + // + // The run is NOT stopped for it — a paid book must not die because a caller mislabelled it — so the + // stream takes a fresh identity and says so at ERROR. The caller's id keeps naming the run in the + // logs; only the seam's key changes. + if used, err := st.EventsUsed(runID); err != nil { + j.Close() + return nil, err + } else if used { + fresh := obs.NewTraceID() + log.Error("this run was given an id that has already written run events for this book; a stream identity must be unique per process, so the event stream announces itself under a fresh one (fix the caller: TM_TRACE_ID must be unique per invocation)", + "given", runID, "stream_id", fresh) + runID = fresh + } + if err := st.ForgetEvents(runID); err != nil { + j.Close() + return nil, err + } + e := &emitter{store: st, journal: j, log: log, runID: runID, bookID: bookID, now: time.Now, marks: map[int64]string{}} + e.emit(runevents.TypeHello, runevents.Hello{ + StreamVersion: runevents.StreamVersion, + EngineRunID: runID, + BookID: bookID, + ChunkerVersion: chunkerVersion, + }) + return e, nil +} + +func (e *emitter) close() error { + if e == nil { + return nil + } + return e.journal.Close() +} + +// emit enqueues one event and projects the journal. It never returns an error, and that is the answer to +// PD-60 ("what does the engine do when the journal cannot be written"), chosen explicitly because the +// row says both positions are legitimate and a silent third is not: +// +// the engine DEGRADES LOUDLY and keeps running. A paid book must not die because a freshness side-channel +// cannot be written — the money protection is the platform's hold and the engine's own ceiling, neither +// of which depends on this file (D39.106 §2) — and the two facts a reader most needs, the ceiling halt +// and the graceful stop, also travel as distinct exit codes, so they survive a journal that never opened. +// Nothing is dropped: the lines stay in the outbox, every later event retries the whole pending prefix, +// so a transient ENOSPC or EIO heals itself and the journal ends up complete and gap-free. If it never +// heals, the reader's ratified fallback is the `status --json` resync. +// +// The rejected alternative is to BLOCK or abort the run on a journal failure. It is legitimate — it keeps +// the projection exact — but it makes the availability of a status channel a precondition for translating +// a book that has already been paid for, and on the realistic failure (a full disk) the ledger's own +// writes are failing at the same moment and the run stops anyway, one layer lower and with a better error. +func (e *emitter) emit(t runevents.Type, data any) { + if e == nil { + return + } + e.mu.Lock() + defer e.mu.Unlock() + e.enqueue(t, data) + e.project() +} + +func (e *emitter) enqueue(t runevents.Type, data any) { + at := e.now() + if err := e.store.EnqueueEvent(e.runID, func(seq int64) ([]byte, error) { + return runevents.Line(seq, t, at, data) + }); err != nil { + e.log.Error("run-event outbox write failed; this event will not reach the platform's stream (the run continues; the resync channel is `tmctl status --json`)", + "event", string(t), "err", err) + } +} + +// project appends every stored line the file has not got yet, in sequence order, and only THEN records +// which announce-once events a reader has now seen. The order is the point: a line still in the outbox +// when a process dies has no ledger row, so the next process announces its unit again instead of +// assuming a reader was told. +func (e *emitter) project() { + caught := 0 + for { + lines, err := e.store.PendingEvents(e.runID, e.lastSeen, projectBatch) + if err != nil { + e.degrade("read the pending run events", err) + return + } + for _, l := range lines { + if err := e.journal.Append(l.Line); err != nil { + e.degrade("append to the run-event journal", err) + e.markAnnounced() // whatever DID land is still announced + return + } + e.lastSeen = l.Seq + // Per line, not per batch: what is left unmarked is what a crash makes a later process announce + // a second time, so the window is kept to a single transaction rather than the rest of the batch. + e.markAnnounced() + } + caught += len(lines) + if len(lines) < projectBatch { + break // drained: a short batch means there was nothing more to read + } + } + if e.degraded && caught > 0 { + e.degraded = false + e.log.Warn("the run-event journal is writable again; the pending events were caught up", + "caught_up", caught, "last_seq", e.lastSeen) + } + e.markAnnounced() +} + +// projectBatch bounds one read of the outbox. It matters only on the failure path: while the journal +// refuses writes the cursor cannot advance, so the unprojected prefix grows with every event and an +// unbounded read would re-materialize all of it on each one, under this mutex. Large enough that a +// healthy run always drains in one read, small enough that a degraded one costs a constant. +const projectBatch = 256 + +// markAnnounced records the announce-once events whose line is now on the file. +func (e *emitter) markAnnounced() { + if len(e.marks) == 0 { + return + } + landed := map[int64]string{} + for seq, key := range e.marks { + if seq <= e.lastSeen { + landed[seq] = key + } + } + if len(landed) == 0 { + return + } + if err := e.store.MarkAnnounced(e.runID, landed); err != nil { + // Not fatal and not silent: the cost of losing this write is that a later process announces those + // units a second time, which an at-least-once reader is required to absorb. + e.log.Error("could not record which run events have been delivered; a later run may announce them again", + "events", len(landed), "err", err) + return + } + for seq := range landed { + delete(e.marks, seq) + } +} + +// degrade reports the FIRST failure of a run of them and stays quiet afterwards: a full disk fails on +// every event, and a per-event ERROR line would bury the run's real output. +func (e *emitter) degrade(what string, err error) { + if e.degraded { + return + } + e.degraded = true + e.log.Error("could not "+what+"; the platform's live stream stalls here and resumes if this heals (the run continues — money is protected by the hold and the ceiling, not by this file; resync channel: `tmctl status --json`)", + "last_seq_on_file", e.lastSeen, "err", err) +} + +// spendLine is the money event, handed to the ledger so it rides the SAME transaction that settles the +// money (D39.106 §2 "the outbox row is written in the transaction of the checkpoint"). It is the one +// event for which that matters: a journal line claiming spend the ledger never booked is a divergence +// about money, not about a progress bar. +// +// It never fails the settle. A render failure returns "no event" rather than an error, because the +// alternative is a rolled-back settle for a call the provider has already billed — losing a paid +// checkpoint to protect an indicator is the wrong way round. +func (e *emitter) spendLine() *store.SpendLine { + if e == nil { + return nil + } + at := e.now() + return &store.SpendLine{RunID: e.runID, Line: func(seq int64, committedUSD float64) ([]byte, error) { + line, err := runevents.Line(seq, runevents.TypeSpend, at, + runevents.Spend{CommittedMicroUSD: runevents.MicroUSD(committedUSD)}) + if err != nil { + e.log.Error("could not render the spend event; the settle proceeds without it (the counter is cumulative — the next one carries the total again)", "err", err) + return nil, nil + } + return line, nil + }} +} + +// flush projects whatever the ledger enqueued inside its own transactions (the spend event). Called +// after a settle, so money freshness does not wait for the unit to finish. +func (e *emitter) flush() { + if e == nil { + return + } + e.mu.Lock() + defer e.mu.Unlock() + e.project() +} + +// waveCounters is the live per-phase progress, in OUTPUT UNITS — the granularity every engine read model +// counts in, so the stream and the `status --json` resync fold into one column on the same scale. +// +// `counted` starts as the units ALREADY resolved when this process opened the book, which is what makes +// the counter book-state rather than process-state: a resumed run walks every unit again at $0, and a +// counter that started at zero would walk a reader's progress bar backwards on every resume. +type waveCounters struct { + draft, edit runevents.Counter + counted map[unitWave]bool + // since/resolved are this PROCESS's throughput, which is what the stream's ETA is derived from: the + // wall clock since the run began working, and how many units it has resolved in it. A resumed run + // that replays everything at $0 resolves nothing and therefore offers no estimate, which is correct + // — it has measured nothing. + since time.Time + resolved int +} + +// eta is the seconds remaining at the rate this run has actually achieved, or 0 when nothing has been +// measured yet (the reader renders no estimate rather than "0 s left"). +func (w *waveCounters) eta(now time.Time) int { + left := (w.draft.Total - w.draft.Done) + (w.edit.Total - w.edit.Done) + if w.resolved == 0 || left <= 0 { + return 0 + } + eta := int(now.Sub(w.since).Seconds() / float64(w.resolved) * float64(left)) + if eta < 1 { + // Work remains, so the honest floor is a second: the field is optional in the wire form, and an + // omitted one does not leave the reader's column alone — it NULLS it (see runevents.Progress). + return 1 + } + return eta +} + +type unitWave struct { + wave string + chapter int + unit int +} + +// beginWaves seeds the counters from the store and announces them. Called once, when the driver knows +// the book's cut, before the first wave. +func (e *emitter) beginWaves(units []editUnit, shape waveShape, stored map[chunkKey][]store.ChunkStatus) { + if e == nil { + return + } + w := &waveCounters{counted: map[unitWave]bool{}, since: e.now()} + if shape.nDraft > 0 { + w.draft.Total = len(units) + } + if shape.nEdit > 0 { + w.edit.Total = len(units) + } + for _, u := range units { + draft, edit := shape.resolved(u, unitRows(u, stored)) + if draft { + w.counted[unitWave{runevents.WaveDraft, u.Chapter, u.FirstChunkIdx}] = true + w.draft.Done++ + } + if edit { + w.counted[unitWave{runevents.WaveEdit, u.Chapter, u.FirstChunkIdx}] = true + w.edit.Done++ + } + } + e.mu.Lock() + e.waves = w + e.mu.Unlock() + // No estimate yet: nothing has been measured, and inventing one from a previous run would be a + // number about work this process has not done. + e.emit(runevents.TypeProgress, runevents.Progress{Draft: w.draft, Edit: w.edit}) +} + +// unitResolved announces one output unit a WAVE has just finished with, and the counters it moved. +// +// Two different questions are asked here, and conflating them is what a first version got wrong: +// +// - HAS A READER BEEN TOLD? — answered by the announce-once ledger in the outbox, because a reader +// folds `unit_done` by INCREMENT and this is the vocabulary's only counting event. Re-announcing a +// unit a resumed run merely replayed at $0 would add a whole book to a chapter counter on every +// resume; NOT announcing one whose process died between the disposition and the insert would leave +// that chapter short forever. Only a durable ledger answers both, and it is why the once-rows +// outlive their run. +// - DOES THE COUNTER MOVE? — answered by what was already resolved when this process opened the book. +// The counters are BOOK state, not process state: a resumed run re-walks every finished unit, and a +// counter that started at zero would walk a reader's progress bar backwards. +// +// The two disagree exactly in the interesting cases, and each is then right on its own terms: a unit +// whose announcement was lost to a crash is re-announced but not re-counted, and a book translated +// before this ledger existed is announced for the first time without its counters jumping. +// +// ⚠ Residual, and it is the irreducible one: between the outbox commit below and the line reaching the +// file there is no transaction, so a process killed between those two adjacent statements loses that +// announcement for good. The class ENDS at the fold, not here — `unit_done` carries a stable +// (chapter, unit, wave) identity, so a reader that assigns instead of incrementing is exact under any +// delivery, which is what at-least-once delivery (D39.119 п.3) has always asked of a consumer. Raised +// as a diff with the pack. +func (e *emitter) unitResolved(wave string, chapter, unit int, shipped, flagged bool, reason string) { + if e == nil { + return + } + e.mu.Lock() + defer e.mu.Unlock() + at := e.now() + key := unitWave{wave, chapter, unit} + // The counters may be unavailable (their baseline read failed, beginRunEvents) — the ANNOUNCEMENT is + // not: it needs no baseline, a reader folds it per chapter, and dropping it would leave that chapter + // short forever. Only the progress line is skipped in that case. + w := e.waves + counts := false + if w != nil { + if counts = !w.counted[key]; counts { + w.counted[key] = true + if wave == runevents.WaveEdit { + w.edit.Done++ + } else { + w.draft.Done++ + } + w.resolved++ + } + } + onceKey := e.unitOnceKey(key) + announcing, seq, err := e.store.EnqueueOnce(e.runID, onceKey, func(seq int64) ([]byte, error) { + return runevents.Line(seq, runevents.TypeUnitDone, at, runevents.UnitDone{ + Chapter: chapter, Unit: unit, Wave: wave, Shipped: shipped, Flagged: flagged, Reason: reason, + }) + }) + if err != nil { + e.log.Error("run-event outbox write failed; this unit will not reach the platform's stream (the run continues; the resync channel is `tmctl status --json`)", + "event", string(runevents.TypeUnitDone), "wave", wave, "chapter", chapter, "unit", unit, "err", err) + } + if announcing { + e.marks[seq] = onceKey + } + if counts { + e.enqueue(runevents.TypeProgress, runevents.Progress{Draft: w.draft, Edit: w.edit, ETASeconds: w.eta(at)}) + } + if announcing || counts { + e.project() + } +} + +// unitOnceKey is the identity of one announcement. It carries the BOOK because the ledger lives in a +// project database and `project_db` may be shared by two books: without it the second book's units would +// collide with the first's keys and never be announced at all. +func (e *emitter) unitOnceKey(k unitWave) string { + return fmt.Sprintf("unit:%s:%s:%d:%d", e.bookID, k.wave, k.chapter, k.unit) +} + +// terminal writes the stream's last line — and, on a ceiling halt, the `ceiling` event before it. +// +// The ceiling is the whole of PD-113: the engine returns the stop as an ERROR, every unrecognised error +// maps to exit 1, and the platform then records `failed` for a stop its own contract says is `paused`. +// It travels twice by design — as this event and as its own exit code — because the two channels fail +// independently: a journal that could not be written still leaves the code, and a process killed before +// it exited still leaves the event. +func (e *emitter) terminal(res *BookResult, err error) { + if e == nil { + return + } + var halt *CeilingHalt + var sigStop *WaveSignatureStop + var refusal *Refusal + switch { + case errors.As(err, &refusal): + // A refusal did no work, so the stream gets no verdict about work. Writing `failed` here would + // have the exit code say "refused, nothing happened" while the stream said the run failed. + return + case errors.As(err, &halt): + e.emit(runevents.TypeCeiling, runevents.Ceiling{Halted: true, Scope: halt.Scope}) + e.emit(runevents.TypeFinished, runevents.Finished{Outcome: runevents.OutcomeCeiling}) + case errors.As(err, &sigStop): + // The bank_stop event itself was written where the stop happened, with its term count. + e.emit(runevents.TypeFinished, runevents.Finished{Outcome: runevents.OutcomeBankStop}) + case errors.Is(err, context.Canceled): + // In tmctl the run context is cancelled by SIGINT/SIGTERM and by nothing else (main.go's + // signal.NotifyContext), so this is the graceful stop, not a crash. + e.emit(runevents.TypeFinished, runevents.Finished{Outcome: runevents.OutcomeStopped}) + case err != nil: + e.emit(runevents.TypeFinished, runevents.Finished{Outcome: runevents.OutcomeFailed}) + case res != nil && res.Flagged > 0: + e.emit(runevents.TypeFinished, runevents.Finished{Outcome: runevents.OutcomeFlagged}) + default: + e.emit(runevents.TypeFinished, runevents.Finished{Outcome: runevents.OutcomeClean}) + } +} + +// openEvents starts this process's region of the book's journal, once per runner. +// +// A run without a trace id on its context is not an invocation the seam describes — the id IS the +// engine_run_id, half of the ratified idempotency key, and a reader refuses an empty one rather than +// collapsing every run into one namespace. tmctl always opens a traced context (main.go); an in-process +// caller that does not is driving the pipeline, not running a job, and writes no journal. +func (r *Runner) openEvents(ctx context.Context) { + if r.events != nil { + return + } + ri, ok := obs.ReqInfoFromContext(ctx) + if !ok || ri.TraceID == "" { + return + } + e, err := openEmitter(r.Store, r.journalDir(), ri.TraceID, r.Book.BookID, r.Log) + if err != nil { + // A journal that cannot even be OPENED is reported and not fatal, by the same policy emit() is: + // the run is paid for, the money is protected by the hold and the ceiling, and the reader's + // fallback channel is the `status --json` resync. Nothing here returns an error, on purpose — an + // error return would be a way for observability to stop a run, and there must not be one. + r.Log.ErrorContext(ctx, "could not open the run-event journal; the platform's live stream will be silent for this run (the run continues; resync channel: `tmctl status --json`)", + "dir", r.journalDir(), "err", err) + return + } + r.events = e +} + +// beginRunEvents seeds the live per-phase counters from what the store already holds. It reads the +// stored rows once — the same read `status` makes — so the baseline is the BOOK's state and not this +// process's: a resumed run walks every finished unit again at $0, and counters that started at zero +// would walk a reader's progress bar backwards on every resume. +// It degrades rather than aborting, by the same policy emit() follows: a read taken for a progress +// indicator must not be what kills a paid run. Without the baseline the counters are simply not +// published — every other event still is. +func (r *Runner) beginRunEvents(ctx context.Context, chunks []chunk.Chunk) { + if r.events == nil { + return + } + statuses, err := r.Store.ChunkStatusesForBook(r.Book.BookID) + if err != nil { + r.Log.ErrorContext(ctx, "could not read the stored dispositions for the run-event counters; this run publishes no progress (the run continues; resync channel: `tmctl status --json`)", "err", err) + return + } + byChunk := map[chunkKey][]store.ChunkStatus{} + for _, cs := range statuses { + byChunk[chunkKey{cs.Chapter, cs.ChunkIdx}] = append(byChunk[chunkKey{cs.Chapter, cs.ChunkIdx}], cs) + } + r.events.beginWaves(r.outputUnits(chunks), r.waveShape(), byChunk) +} + +// draftUnitTracker answers "was that the LAST member of its unit?" for the draft wave, which fans out +// over chunks while the seam counts output units. +type draftUnitTracker struct { + units []editUnit + of map[chunkKey]int // member chunk → its unit's index + at map[chunkKey]int // member chunk → its index in the wave's result slice + left []atomic.Int32 +} + +func newDraftUnitTracker(units []editUnit, chunks []chunk.Chunk) *draftUnitTracker { + t := &draftUnitTracker{ + units: units, + of: make(map[chunkKey]int, len(chunks)), + at: make(map[chunkKey]int, len(chunks)), + left: make([]atomic.Int32, len(units)), + } + for i, ch := range chunks { + t.at[chunkKey{ch.Chapter, ch.ChunkIdx}] = i + } + for i, u := range units { + t.left[i].Store(int32(len(u.Members))) + for _, m := range u.Members { + t.of[chunkKey{m.Chapter, m.ChunkIdx}] = i + } + } + return t +} + +// memberDone records one member's completion and reports the unit when it was the last one. The atomic +// is also the synchronisation point for the results slice the caller then reads: each worker writes its +// own slot BEFORE decrementing, so the worker that sees zero sees every sibling's write. +func (t *draftUnitTracker) memberDone(ch chunk.Chunk) (editUnit, bool) { + i, ok := t.of[chunkKey{ch.Chapter, ch.ChunkIdx}] + if !ok { + return editUnit{}, false + } + if t.left[i].Add(-1) != 0 { + return editUnit{}, false + } + return t.units[i], true +} + +// outcome folds a unit's member drafts into the pair the stream carries. The member→result index is the +// tracker's own and is built ONCE: rebuilding it per completed unit is quadratic in the book. SHIPPED means the wave +// left something the next one can work on (or, in a draft-only pipeline, something that exports); +// FLAGGED means at least one member needs a human, which is the c-lite rule the read models already use +// — a unit can legally be both. +func (t *draftUnitTracker) outcome(u editUnit, results []stageSeqResult) (shipped, flagged bool, reason string) { + for _, m := range u.Members { + i, ok := t.at[chunkKey{m.Chapter, m.ChunkIdx}] + if !ok { + continue + } + d := results[i] + if d.flagged { + if !flagged { + flagged, reason = true, string(d.flagReason) + } + shipped = shipped || d.recovered != "" // a cosmetic strip still exports its cleaned remainder + continue + } + shipped = shipped || d.finalText != "" + } + return shipped, flagged, reason +} + +// journalDir is where this book's journal lives: the directory of book.yaml — the BOOK's directory +// (D39.106 §2), which is also the working directory the platform spawns the run in and tails. It is +// deliberately NOT the project DB's directory: `project_db` may point anywhere, and the seam is anchored +// to the config the caller passed. +func (r *Runner) journalDir() string { + if r.Book.Dir != "" { + return r.Book.Dir + } + return filepath.Dir(r.Book.ProjectDB) +} + +// ingestSource reads and normalizes the book's source, classifying a failure as the refusal it is: this +// is the one place where "the text we were handed is unusable" is distinguishable from "the operator's +// config or host is broken", and an automated intake acts on the user's upload from that distinction. +func (r *Runner) ingestSource() (*chunk.Document, error) { + doc, err := chunk.IngestEncoded(r.Book.SourceFile, r.Book.Encoding, r.Book.SourceLang) + if err != nil { + return nil, refuseSource(err) + } + return doc, nil +} diff --git a/backend/internal/pipeline/manifest.go b/backend/internal/pipeline/manifest.go index d704c357..2befea37 100644 --- a/backend/internal/pipeline/manifest.go +++ b/backend/internal/pipeline/manifest.go @@ -391,15 +391,15 @@ func (r *Runner) BuildAndPersistManifest() (*BookManifest, error) { // same bytes. Here a fingerprint failure IS an error: producing the artifact is the command's job. before, err := sourceSHA256(r.Book.SourceFile) if err != nil { - return nil, fmt.Errorf("pipeline: hash source %s for the manifest: %w", r.Book.SourceFile, err) + return nil, refuseSource(fmt.Errorf("pipeline: hash source %s for the manifest: %w", r.Book.SourceFile, err)) } - doc, err := chunk.IngestEncoded(r.Book.SourceFile, r.Book.Encoding, r.Book.SourceLang) + doc, err := r.ingestSource() if err != nil { return nil, err } chunks, chapterTexts := chunk.SplitChunksWithChapters(doc.Chapters, r.segBudget(), r.headingRule(), r.sentenceAbbrevs()) if len(chunks) == 0 { - return nil, fmt.Errorf("pipeline: source file %s produced no chunks after normalization", r.Book.SourceFile) + return nil, sourceHasNoContent(fmt.Errorf("pipeline: source file %s produced no chunks after normalization", r.Book.SourceFile)) } return r.writeManifest(before, chapterTexts, chunks) } diff --git a/backend/internal/pipeline/refusal.go b/backend/internal/pipeline/refusal.go new file mode 100644 index 00000000..16e7da62 --- /dev/null +++ b/backend/internal/pipeline/refusal.go @@ -0,0 +1,83 @@ +package pipeline + +// refusal.go: the shell contract's REFUSAL classes (row 165 / PD-196 of the platform). +// +// The defect this closes was not cosmetic. `tmctl` mapped every failure it did not recognise onto exit +// 1, so "this source is unreadable", "this config is broken" and "another process holds the project" +// arrived at an automated caller as one number — and the platform's intake, which retries a book five +// times and then rejects it as `source_unreadable`, came within one step of deleting a user's upload +// because an operator mistyped a key in a hand-written book.yaml. +// +// The form is a CLASS carried by a typed error, mapped to an exit code by cmd/tmctl. It is a class and +// not a code here on purpose: the engine owns the vocabulary, the shell contract owns the numbers, and a +// class this build of a reader has never heard of still lands inside the reserved band and reads as +// "refused" rather than as "failed" — which is the difference between waiting and destroying data. + +// RefusalClass names WHY an invocation was turned down. Values are stable strings: a new class is a new +// value here and a new number in cmd/tmctl's table, never a new branch in a consumer. +type RefusalClass string + +const ( + // RefusalBadConfig is a configuration this engine will not run: unreadable, unparseable, or invalid. + // The operator's file is the thing to fix; the book's source is untouched and blameless. + RefusalBadConfig RefusalClass = "config_invalid" + // RefusalSourceUnreadable is a book whose SOURCE cannot be read or decoded. This is the one class + // that says something about the user's text rather than about the operator's config. + RefusalSourceUnreadable RefusalClass = "source_unreadable" + // RefusalProjectLocked is another tmctl process owning the project. Nothing is wrong with anything — + // the answer is to come back later. + RefusalProjectLocked RefusalClass = "project_locked" +) + +// Refusal is an invocation the engine turned down before doing any work of its own: nothing reached a +// provider, nothing was spent, and nothing this process would have written was written. It says nothing +// about whether the BOOK is untouched — a resumed run refused at ingest has been paid for before — only +// that THIS process changed nothing. +type Refusal struct { + Class RefusalClass + err error +} + +func (e *Refusal) Error() string { return e.err.Error() } +func (e *Refusal) Unwrap() error { return e.err } + +// refuse wraps err as a refusal of class c. A nil err is nil: the wrapper never invents a failure. +func refuse(c RefusalClass, err error) error { + if err == nil { + return nil + } + return &Refusal{Class: c, err: err} +} + +// RefuseConfig classifies a config-load failure for a caller OUTSIDE this package. The pre-flight backup +// guard is one: it loads book.yaml before the runner exists, so it — not openRunner — is what a broken +// config meets first on the `translate` path, and an unclassified error there would put every refusal +// back on exit 1 no matter how carefully the runner classifies its own. +func RefuseConfig(err error) error { + return refuse(RefusalBadConfig, err) +} + +// refuseSource classifies a failure to obtain the book's text, and it classifies almost all of them as a +// CONFIG fault. That is deliberate, and it is the most consequential decision in this file. +// +// RefusalSourceUnreadable is the verdict an automated intake acts on by DELETING the user's upload. So +// it may only be returned for something no configuration knob can explain — and a read failure is not +// that: a path that is not there, a permission, an I/O error, a vanished mount all say something about +// the deployment (a template naming a filename the upload route did not use, a chown bug) and nothing +// about the text. Neither is a DECODE failure, which was the first answer here and is wrong for the same +// reason: decoding is driven by the book's declared `encoding` and `source_lang`, so "these bytes are +// not text" and "you told me the wrong way to read them" are the same error. Two independent reviews +// arrived at that case from opposite directions. +// +// What is left, and the only thing the engine can assert about the TEXT with no config in the way, is +// sourceHasNoContent below: the bytes were read and cut, and there is no book in them. +func refuseSource(err error) error { + return refuse(RefusalBadConfig, err) +} + +// sourceHasNoContent is the one refusal that IS about the user's text: reading and cutting the source +// succeeded and produced nothing to translate. No `encoding`, `source_lang` or path setting explains an +// empty result from a successful read, which is what makes it safe to act on. +func sourceHasNoContent(err error) error { + return refuse(RefusalSourceUnreadable, err) +} diff --git a/backend/internal/pipeline/repair.go b/backend/internal/pipeline/repair.go index 189860b6..2b3e55fc 100644 --- a/backend/internal/pipeline/repair.go +++ b/backend/internal/pipeline/repair.go @@ -245,18 +245,22 @@ func (r *Runner) maybeRepair(ctx context.Context, st config.Stage, snapID string // (its own doc says so) while repair is common-path, and a lock spanning the provider call (which is what // makes the escalation bound exact) would put every worker behind one slow transport retry. // - // The cap is applied PER CANDIDATE and only to a FRESH call (see the loop below): an ALREADY-PAID repair - // must replay from its checkpoint regardless of the remaining budget, or a crash between the paid call - // and the chunk_status write would make the resumed run ship DIFFERENT bytes than the run that paid — - // exactly the idempotency escalation.go:99-114 exists to protect. - budgetExhausted := false - if spent, err := r.Store.RepairSpentUSD(r.Book.BookID); err != nil { + // It is checked PER CALL and against what the call would COST (row 135). It used to be ONE decision per + // UNIT, taken here before the loop: a unit that found the budget merely "not yet exhausted" could then + // buy up to gates.repair.max_calls_per_unit fresh calls on the strength of it, so the configured number + // was not the bound it looked like. Pricing the call is the same shape the terminology pass has always + // had (runBankRoleBatches) and refuses on the conservative side — the estimate is the reservation's own + // upper bound. + // + // An ALREADY-PAID repair replays regardless of the remaining budget, and an unaffordable candidate is + // SKIPPED rather than ending the loop, so a paid later candidate still replays: a crash between the paid + // call and the chunk_status write would otherwise make the resumed run ship DIFFERENT bytes than the run + // that paid — exactly the idempotency escalation.go exists to protect. + spent, err := r.Store.RepairSpentUSD(r.Book.BookID) + if err != nil { return finalText, res, err - } else if spent >= gate.BudgetUSD { - budgetExhausted = true - r.Log.InfoContext(ctx, "repair budget exhausted; only already-paid repairs will replay", - "chapter", ch.Chapter, "chunk", ch.ChunkIdx, "spent_usd", fmt.Sprintf("%.6f", spent), "budget_usd", gate.BudgetUSD) } + saidBudget := false type accepted struct { span [2]int @@ -283,8 +287,17 @@ func (r *Runner) maybeRepair(ctx context.Context, st config.Stage, snapID string if perr != nil { return finalText, res, perr } - if budgetExhausted && !paid { - continue + if !paid { + model, maxTokens := r.repairCallBudget(msgs) + if want := r.callEstimateUSD(r.repairStage(st, model), model, msgs, maxTokens); spent+want > gate.BudgetUSD { + if !saidBudget { + saidBudget = true + r.Log.InfoContext(ctx, "repair budget would be exceeded by the next call; the remaining defects stay flagged (already-paid repairs still replay)", + "chapter", ch.Chapter, "chunk", ch.ChunkIdx, "spent_usd", fmt.Sprintf("%.6f", spent), + "next_call_usd", fmt.Sprintf("%.6f", want), "budget_usd", gate.BudgetUSD) + } + continue + } } att, err := r.runRepairAttempt(ctx, st, snapID, ch, job, i, msgs) if err != nil { @@ -302,6 +315,7 @@ func (r *Runner) maybeRepair(ctx context.Context, st config.Stage, snapID string res.CostUSD += att.runCost res.CumUSD += att.cumCost res.Fresh = res.Fresh || att.freshCall + spent += att.runCost // a replay costs 0, so only fresh calls consume the budget reply, verdict := repairReplyVerdict(att, dstSpan, c.Class, cfg.Checkers) switch verdict { case repairDeclined: diff --git a/backend/internal/pipeline/repair_budget_test.go b/backend/internal/pipeline/repair_budget_test.go new file mode 100644 index 00000000..c98e8efe --- /dev/null +++ b/backend/internal/pipeline/repair_budget_test.go @@ -0,0 +1,118 @@ +package pipeline + +import ( + "context" + "strings" + "testing" +) + +// repair_budget_test.go: backlog row 135 — "the ceiling gate on EVERY paid call, not on a unit of work". +// +// The ceilings themselves (book and day) were already per call: every fresh attempt reserves, and Reserve +// compares the book's cumulative committed+reserved against them (store/ledger.go, from stagerun.go). The +// gate that genuinely sat at a UNIT boundary was the repair sub-budget. It asked ONE question before the +// candidate loop — "is `spent` already at or over the budget?" — and never priced the calls it then +// authorised, so a unit that found the budget merely not-yet-exhausted could buy up to +// gates.repair.max_calls_per_unit fresh calls on the strength of that single answer, and every parallel +// worker could do the same. The number in the config was not the bound it looked like. + +func TestABudgetSmallerThanOneRepairCallBuysNone(t *testing.T) { + // The clean statement of the old defect: with nothing spent yet, `spent >= budget` is false for ANY + // positive budget, so the loop admitted a call it could not afford and overshot the configured bound + // by that call's entire cost. Pricing the call is what makes the config number the bound. + rec := &reqRec{} + srv := newJSONProvider(rec, func(body string) (string, string) { + switch { + case isRepairBody(body): + return "Он прождал час и вошёл внутрь.", "stop" + case isEditBody(body): + return "Он прождал полчаса и вошёл внутрь.", "stop" + } + return "ЧЕРНОВИК ПЕРЕВОДА.", "stop" + }) + defer srv.Close() + bookPath := setupRepairProject(t, srv.URL) + + // What one repair call would cost, measured from the code under test rather than from a constant that + // drifts with the price table. + price := repairCallEstimate(t, bookPath) + r := newRepairRunner(t, bookPath) + defer r.Close() + r.Pipeline.Gates.Repair.BudgetUSD = price / 2 // positive, and smaller than one call + + res, err := r.TranslateBook(context.Background()) + if err != nil { + t.Fatal(err) + } + t.Logf("one repair call reserves $%.6f; budget $%.6f — before row 135 the unit bought the call anyway (%.1f× the budget), now it buys none", + price, r.Pipeline.Gates.Repair.BudgetUSD, price/r.Pipeline.Gates.Repair.BudgetUSD) + for _, body := range rec.all() { + if isRepairBody(body) { + t.Fatalf("a repair call was bought under a budget of $%.6f that a $%.6f call cannot fit", r.Pipeline.Gates.Repair.BudgetUSD, price) + } + } + // The defect stays in the shipped text, flagged for a human — the sub-step is optional, and refusing + // it is not a failure. + if !strings.Contains(res.Chunks[0].FinalText, "полчаса") { + t.Fatalf("with the repair refused the unit must ship the editor's own bytes, got %q", res.Chunks[0].FinalText) + } +} + +func TestABudgetThatFitsTheCallStillBuysIt(t *testing.T) { + // The other side of the same gate: pricing the call must not turn the sub-step off. Without this the + // test above passes for the wrong reason. + rec := &reqRec{} + srv := newJSONProvider(rec, func(body string) (string, string) { + switch { + case isRepairBody(body): + return "Он прождал час и вошёл внутрь.", "stop" + case isEditBody(body): + return "Он прождал полчаса и вошёл внутрь.", "stop" + } + return "ЧЕРНОВИК ПЕРЕВОДА.", "stop" + }) + defer srv.Close() + bookPath := setupRepairProject(t, srv.URL) + + price := repairCallEstimate(t, bookPath) + r := newRepairRunner(t, bookPath) + defer r.Close() + r.Pipeline.Gates.Repair.BudgetUSD = price * 1.5 + + res, err := r.TranslateBook(context.Background()) + if err != nil { + t.Fatal(err) + } + repairs := 0 + for _, body := range rec.all() { + if isRepairBody(body) { + repairs++ + } + } + if repairs != 1 { + t.Fatalf("a budget of $%.6f must buy the one $%.6f call, got %d", r.Pipeline.Gates.Repair.BudgetUSD, price, repairs) + } + if strings.Contains(res.Chunks[0].FinalText, "полчаса") { + t.Fatalf("the affordable repair must have applied, shipped %q", res.Chunks[0].FinalText) + } +} + +// repairCallEstimate is what one repair call on this fixture would reserve — the same figure the gate +// now weighs, taken through the same helper the attempt uses. +func repairCallEstimate(t *testing.T, bookPath string) float64 { + t.Helper() + r := newRepairRunner(t, bookPath) + defer r.Close() + st := r.Pipeline.Stages[len(r.Pipeline.Stages)-1] + msgs, err := Messages(r.repairTemplates["dc1_fractional"], + RenderVars{Book: r.Book, Text: "他等了半个时辰。", Draft: "Он прождал полчаса и вошёл внутрь."}) + if err != nil { + t.Fatal(err) + } + model, maxTokens := r.repairCallBudget(msgs) + price := r.callEstimateUSD(r.repairStage(st, model), model, msgs, maxTokens) + if price <= 0 { + t.Fatalf("a repair call must have a positive estimate, got %v", price) + } + return price +} diff --git a/backend/internal/pipeline/runevents_crash_test.go b/backend/internal/pipeline/runevents_crash_test.go new file mode 100644 index 00000000..4931c7a0 --- /dev/null +++ b/backend/internal/pipeline/runevents_crash_test.go @@ -0,0 +1,279 @@ +package pipeline + +import ( + "bytes" + "fmt" + "os" + "os/exec" + "path/filepath" + "syscall" + "testing" + "time" + + "textmachine/backend/internal/chunk/chunktest" + "textmachine/backend/internal/obs" + "textmachine/backend/internal/runevents" +) + +// runevents_crash_test.go — the acceptance core of the outbox (row 103): a real SIGKILL in the middle of +// a wave must leave a journal a reader can still consume, and a journal that says nothing the engine's +// SQLite does not hold. It is the same helper-process shape as store/kill9_test.go, and for the same +// reason: an emulated crash proves the emulation. + +const ( + crashBookEnv = "TM_EVENTS_CRASH_BOOK" + crashModeEnv = "TM_EVENTS_CRASH_MODE" +) + +// TestHelperEventsRun is the child process. It runs the book against the PARENT's provider (an +// httptest server on 127.0.0.1, which a subprocess can dial) and, in `exit` mode, leaves through +// os.Exit — which skips every defer, including Runner.Close. +func TestHelperEventsRun(t *testing.T) { + bookPath := os.Getenv(crashBookEnv) + if bookPath == "" { + t.Skip("helper process only") + } + r, err := NewRunner(bookPath, obs.NewLogger()) + if err != nil { + fmt.Fprintln(os.Stderr, "helper runner:", err) + os.Exit(1) + } + if _, err := r.TranslateBook(tracedCtx()); err != nil { + fmt.Fprintln(os.Stderr, "helper translate:", err) + os.Exit(1) + } + if os.Getenv(crashModeEnv) == "exit" { + // PD-61(а): os.Exit skips defers, so anything the emitter had been holding would be lost here — + // which is why it holds nothing. Runner.Close is deliberately NOT called. + os.Exit(0) + } + r.Close() +} + +// crashFixture writes a book big enough that a kill lands mid-wave, with a provider slow enough to make +// the window wide. Returns the book path. +func crashFixture(t *testing.T, chapters int) string { + t.Helper() + rec := &reqRec{} + srv := newJSONProvider(rec, func(body string) (string, string) { + time.Sleep(4 * time.Millisecond) // widen the window the SIGKILL has to land in + return draftEdit(body) + }) + t.Cleanup(srv.Close) + + var eps []chunktest.Chapter + var spine []string + for i := 1; i <= chapters; i++ { + id := fmt.Sprintf("c%d", i) + eps = append(eps, chunktest.Chapter{ID: id, Href: id + ".xhtml", Body: fmt.Sprintf("

静かな図書館の朝%d。

", i)}) + spine = append(spine, id) + } + return setupProjectOpts(t, srv.URL, projectOpts{epub: eps, spine: spine, waveWorkers: 4}) +} + +// waitForJournalLines blocks until the book's journal holds at least n COMPLETE lines. +func waitForJournalLines(t *testing.T, bookPath string, n int) { + t.Helper() + path := filepath.Join(filepath.Dir(bookPath), runevents.JournalFile) + deadline := time.Now().Add(30 * time.Second) + for { + if body, err := os.ReadFile(path); err == nil && bytes.Count(body, []byte("\n")) >= n { + return + } + if time.Now().After(deadline) { + t.Fatalf("the child wrote fewer than %d journal lines in 30s", n) + } + time.Sleep(2 * time.Millisecond) + } +} + +func runHelper(t *testing.T, bookPath, mode string) *exec.Cmd { + t.Helper() + exe, err := os.Executable() + if err != nil { + t.Fatal(err) + } + cmd := exec.Command(exe, "-test.run", "^TestHelperEventsRun$") + cmd.Env = append(os.Environ(), crashBookEnv+"="+bookPath, crashModeEnv+"="+mode) + cmd.Stderr = os.Stderr + return cmd +} + +func TestASigkillMidWaveLeavesAReadableJournalThatMatchesTheDatabase(t *testing.T) { + if testing.Short() { + t.Skip("subprocess test") + } + bookPath := crashFixture(t, 40) + + cmd := runHelper(t, bookPath, "kill") + if err := cmd.Start(); err != nil { + t.Fatal(err) + } + // Kill on the journal's OWN progress rather than on a stopwatch: a sleep long enough to be safe on a + // loaded machine is long enough to let the child finish on an idle one, and then the test proves + // nothing. Waiting for lines means the signal always lands mid-wave. + waitForJournalLines(t, bookPath, 8) + if err := cmd.Process.Signal(syscall.SIGKILL); err != nil { + t.Fatal(err) + } + _ = cmd.Wait() + + envs, raw := readJournal(t, bookPath) // also asserts the file does not end mid-line + assertOneStream(t, envs) + units := 0 + for _, ev := range envs { + if ev.Type == runevents.TypeUnitDone { + units++ + } + } + if units == 0 { + t.Fatal("the killed process made no announced progress — the window missed the wave entirely") + } + // The kill has to land MID-wave for this test to be about anything: a stream that reached its own + // terminal line finished before the signal, and then nothing here was exercised. + if envs[len(envs)-1].Type == runevents.TypeFinished { + t.Fatal("the child finished before the SIGKILL — widen the book or the provider delay") + } + + // Everything the file claims, the database holds — in the outbox byte for byte, and as the + // dispositions the announcements describe. This is the direction that matters: a journal running + // AHEAD of the ledger is what would show a user work that was never done. + r := newRunner(t, bookPath) + runID := payload[runevents.Hello](t, envs[0]).EngineRunID + stored, err := r.Store.PendingEvents(runID, 0, 1_000_000) + if err != nil { + t.Fatal(err) + } + if len(stored) < len(raw) { + t.Fatalf("the file carries %d lines the outbox does not have (outbox %d)", len(raw)-len(stored), len(stored)) + } + for i := range raw { + if string(stored[i].Line) != string(raw[i]) { + t.Fatalf("line %d is not the stored row:\n file %s\noutbox %s", i+1, raw[i], stored[i].Line) + } + } + rowsAt := map[chunkKey]map[string]bool{} + for _, cs := range storedRows(t, r) { + k := chunkKey{cs.Chapter, cs.ChunkIdx} + if rowsAt[k] == nil { + rowsAt[k] = map[string]bool{} + } + rowsAt[k][cs.Stage] = true + } + for _, ev := range envs { + if ev.Type != runevents.TypeUnitDone { + continue + } + u := payload[runevents.UnitDone](t, ev) + stage := "draft" + if u.Wave == runevents.WaveEdit { + stage = "edit" + } + if !rowsAt[chunkKey{u.Chapter, u.Unit}][stage] { + t.Fatalf("the journal announced ch%d unit%d (%s) but the database has no such row", u.Chapter, u.Unit, u.Wave) + } + } + + // …and the run catches up honestly: a second process opens its OWN stream in the same file, finishes + // the book, and announces only the units IT resolved. + if _, err := r.TranslateBook(tracedCtx()); err != nil { + t.Fatal(err) + } + r.Close() + + envs2, _ := readJournal(t, bookPath) + rs := regions(envs2) + if len(rs) != 2 { + t.Fatalf("want the killed stream plus the resumed one, got %d regions", len(rs)) + } + for _, region := range rs { + assertOneStream(t, region) + assertProgressSane(t, region) + } + resumedUnits := 0 + for _, ev := range rs[1] { + if ev.Type == runevents.TypeUnitDone { + resumedUnits++ + } + } + if resumedUnits == 0 { + t.Fatal("the resumed process announced nothing — the crash left no work to catch up on") + } + // COVERAGE is the guarantee, and it is the one the crash used to break: every unit×wave of the book is + // announced at least once across the processes it took. Losing one is not a cosmetic miss — a reader + // folds these into a chapter's counters, and a chapter one short of its own total never reads finished, + // which is a book that can never complete and a chapter the platform keeps offering to translate. + // + // DUPLICATION across processes is legal and deliberate. Between a line landing on the file and the + // ledger row that records the delivery there is no transaction — nothing can put a file write and a + // database commit in one — so a process killed in that window makes the next one announce that unit + // again. Delivery is ratified as at-least-once (D39.119 п.3) exactly because this boundary exists; the + // engine therefore errs to the side that loses nothing, and a duplicate is the consumer's to absorb. + // Within ONE process there is no such window and no such duplicate, which is asserted separately. + counted := map[string]int{} + for _, ev := range envs2 { + if ev.Type != runevents.TypeUnitDone { + continue + } + u := payload[runevents.UnitDone](t, ev) + counted[fmt.Sprintf("%s/%d/%d", u.Wave, u.Chapter, u.Unit)]++ + } + for _, region := range rs { + perRegion := map[string]int{} + for _, ev := range region { + if ev.Type != runevents.TypeUnitDone { + continue + } + u := payload[runevents.UnitDone](t, ev) + key := fmt.Sprintf("%s/%d/%d", u.Wave, u.Chapter, u.Unit) + if perRegion[key]++; perRegion[key] > 1 { + t.Fatalf("one process announced unit %s twice — within a stream this is a plain bug", key) + } + } + } + last := envs2[len(envs2)-1] + if last.Type != runevents.TypeFinished { + t.Fatalf("the resumed run must terminate its stream, got %s", last.Type) + } + var final runevents.Progress + for _, ev := range envs2 { + if ev.Type == runevents.TypeProgress { + final = payload[runevents.Progress](t, ev) + } + } + if final.Draft.Done != final.Draft.Total || final.Edit.Done != final.Edit.Total || final.Draft.Total == 0 { + t.Fatalf("the caught-up counters are %+v — a finished book must reach its own denominator", final) + } + if len(counted) != final.Draft.Total+final.Edit.Total { + t.Fatalf("%d unit-waves announced, the book has %d+%d: the crash lost an announcement for good", + len(counted), final.Draft.Total, final.Edit.Total) + } +} + +func TestTheTerminalEventSurvivesAnExitThatSkipsEveryDefer(t *testing.T) { + // PD-61(а), the property this pack had to build rather than promise: `os.Exit` and `log.Fatal` skip + // defers, so a buffered writer around the journal would lose exactly the lines that say the run + // ended. Nothing is buffered — a line and its newline go to the kernel in one write — so there is + // nothing left to flush. Wrapping the journal in a bufio.Writer fails this test. + if testing.Short() { + t.Skip("subprocess test") + } + bookPath := crashFixture(t, 3) + + cmd := runHelper(t, bookPath, "exit") + if err := cmd.Run(); err != nil { + t.Fatalf("helper: %v", err) + } + envs, _ := readJournal(t, bookPath) + assertOneStream(t, envs) + last := envs[len(envs)-1] + if last.Type != runevents.TypeFinished { + t.Fatalf("the last line after an os.Exit is %s — the terminal event was lost", last.Type) + } + if got := payload[runevents.Finished](t, last).Outcome; got != runevents.OutcomeClean { + t.Fatalf("outcome %q, want %q", got, runevents.OutcomeClean) + } + if _, err := os.Stat(filepath.Join(filepath.Dir(bookPath), runevents.JournalFile)); err != nil { + t.Fatal(err) + } +} diff --git a/backend/internal/pipeline/runevents_test.go b/backend/internal/pipeline/runevents_test.go new file mode 100644 index 00000000..e5d83ae4 --- /dev/null +++ b/backend/internal/pipeline/runevents_test.go @@ -0,0 +1,673 @@ +package pipeline + +import ( + "context" + "encoding/json" + "errors" + "fmt" + "os" + "path/filepath" + "strings" + "testing" + + "textmachine/backend/internal/chunk/chunktest" + "textmachine/backend/internal/obs" + "textmachine/backend/internal/runevents" + "textmachine/backend/internal/store" +) + +// runevents_test.go: the driver's half of the run-event seam (row 103) — the stream a real run leaves +// behind, read back exactly as the platform's tailer reads it. + +// readJournal returns the journal beside a book config, as decoded envelopes and as raw lines. +func readJournal(t *testing.T, bookPath string) ([]runevents.Envelope, [][]byte) { + t.Helper() + body, err := os.ReadFile(filepath.Join(filepath.Dir(bookPath), runevents.JournalFile)) + if err != nil { + t.Fatalf("read journal: %v", err) + } + if len(body) > 0 && body[len(body)-1] != '\n' { + t.Fatalf("the journal ends mid-line — a line and its newline leave in one write: %q", tail(body)) + } + var envs []runevents.Envelope + var raw [][]byte + for _, line := range strings.Split(strings.TrimSuffix(string(body), "\n"), "\n") { + if line == "" { + continue + } + var ev runevents.Envelope + if err := json.Unmarshal([]byte(line), &ev); err != nil { + t.Fatalf("malformed journal line %q: %v", line, err) + } + envs = append(envs, ev) + raw = append(raw, []byte(line)) + } + return envs, raw +} + +func tail(b []byte) string { + if len(b) > 120 { + return string(b[len(b)-120:]) + } + return string(b) +} + +// payload decodes one event's data. +func payload[T any](t *testing.T, ev runevents.Envelope) T { + t.Helper() + var v T + if err := json.Unmarshal(ev.Data, &v); err != nil { + t.Fatalf("decode %s payload: %v", ev.Type, err) + } + return v +} + +// assertOneStream checks the invariants the reader enforces over ONE process's region: it opens with a +// hello at seq 1 and every following number is exactly one more than the last. +func assertOneStream(t *testing.T, envs []runevents.Envelope) { + t.Helper() + if len(envs) == 0 { + t.Fatal("empty stream") + } + if envs[0].Type != runevents.TypeHello || envs[0].Seq != 1 { + t.Fatalf("a stream must open with hello at seq 1, got %s at seq %d", envs[0].Type, envs[0].Seq) + } + for i, ev := range envs { + if ev.Seq != int64(i+1) { + t.Fatalf("seq %d at position %d — the numbering must be dense, a gap is fatal to the reader", ev.Seq, i) + } + } +} + +// assertProgressSane checks what a progress bar is allowed to do: never pass its own denominator, and +// never go backwards. A reader ASSIGNS these counters, so both would be visible to a user. +func assertProgressSane(t *testing.T, envs []runevents.Envelope) { + t.Helper() + var prev runevents.Progress + for _, ev := range envs { + if ev.Type != runevents.TypeProgress { + continue + } + p := payload[runevents.Progress](t, ev) + if p.Draft.Done > p.Draft.Total || p.Edit.Done > p.Edit.Total { + t.Fatalf("progress %+v passes its own denominator at seq %d", p, ev.Seq) + } + if p.Draft.Done < prev.Draft.Done || p.Edit.Done < prev.Edit.Done { + t.Fatalf("progress went backwards at seq %d: %+v after %+v", ev.Seq, p, prev) + } + prev = p + } +} + +// regions splits a journal into its per-PROCESS streams: a resumed run appends a second hello to the +// same file, which is exactly what the tailer keys on. +func regions(envs []runevents.Envelope) [][]runevents.Envelope { + var out [][]runevents.Envelope + for _, ev := range envs { + if ev.Type == runevents.TypeHello { + out = append(out, nil) + } + if len(out) == 0 { + continue + } + out[len(out)-1] = append(out[len(out)-1], ev) + } + return out +} + +func tracedCtx() context.Context { + return obs.WithReqInfo(context.Background(), obs.ReqInfo{TraceID: obs.NewTraceID()}) +} + +func TestARunLeavesAStreamThatOpensWithItsHandshake(t *testing.T) { + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + bookPath := setupProject(t, srv.URL) + + r := newRunner(t, bookPath) + if _, err := r.TranslateBook(tracedCtx()); err != nil { + t.Fatal(err) + } + r.Close() + + envs, _ := readJournal(t, bookPath) + assertOneStream(t, envs) + assertProgressSane(t, envs) + + h := payload[runevents.Hello](t, envs[0]) + if h.StreamVersion != runevents.StreamVersion || h.BookID != "test-book" || h.EngineRunID == "" { + t.Fatalf("handshake does not identify the stream: %+v", h) + } + if h.ChunkerVersion != chunkerVersion { + t.Fatalf("hello must carry the chunker version the manifest was cut by: %q", h.ChunkerVersion) + } + + seen := map[runevents.Type]int{} + for _, ev := range envs { + seen[ev.Type]++ + } + for _, want := range []runevents.Type{runevents.TypeProgress, runevents.TypeUnitDone, runevents.TypeSpend, runevents.TypeFinished} { + if seen[want] == 0 { + t.Errorf("a clean run must announce %s", want) + } + } + last := envs[len(envs)-1] + if last.Type != runevents.TypeFinished { + t.Fatalf("the last line of a finished run must be `finished`, got %s", last.Type) + } + if got := payload[runevents.Finished](t, last).Outcome; got != runevents.OutcomeClean { + t.Fatalf("outcome %q, want %q", got, runevents.OutcomeClean) + } + + // The counters are in OUTPUT UNITS and both waves finish the one unit this fixture has. + var lastProgress runevents.Progress + for _, ev := range envs { + if ev.Type == runevents.TypeProgress { + lastProgress = payload[runevents.Progress](t, ev) + } + } + if lastProgress.Draft != (runevents.Counter{Done: 1, Total: 1}) || lastProgress.Edit != (runevents.Counter{Done: 1, Total: 1}) { + t.Fatalf("final counters %+v, want 1/1 in both waves", lastProgress) + } +} + +func TestEveryLineOnTheFileIsTheOutboxRowVerbatim(t *testing.T) { + // The projection is a COPY, never a re-render: the reader compares a re-read line against the sha256 + // it stored, so a line rebuilt with a fresher timestamp reads as corruption and quarantines the run's + // projection. This is the property that makes retrying a failed journal write safe. + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + bookPath := setupProject(t, srv.URL) + + r := newRunner(t, bookPath) + if _, err := r.TranslateBook(tracedCtx()); err != nil { + t.Fatal(err) + } + envs, raw := readJournal(t, bookPath) + runID := payload[runevents.Hello](t, envs[0]).EngineRunID + stored, err := r.Store.PendingEvents(runID, 0, 1_000_000) + if err != nil { + t.Fatal(err) + } + r.Close() + + if len(stored) != len(raw) { + t.Fatalf("the outbox holds %d lines, the file %d", len(stored), len(raw)) + } + for i := range raw { + if stored[i].Seq != int64(i+1) || string(stored[i].Line) != string(raw[i]) { + t.Fatalf("line %d diverged:\n file %s\noutbox %s", i+1, raw[i], stored[i].Line) + } + } +} + +func TestAResumedRunOpensItsOwnStreamAndDoesNotRecountFinishedUnits(t *testing.T) { + // A resumed run walks every finished unit again at $0. `unit_done` is the vocabulary's only COUNTING + // event, so re-announcing those units would add a whole book to a reader's chapter counters on every + // resume — and `progress`, which a reader ASSIGNS, must not walk its bar backwards either. + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + bookPath := setupProject(t, srv.URL) + + r1 := newRunner(t, bookPath) + if _, err := r1.TranslateBook(tracedCtx()); err != nil { + t.Fatal(err) + } + r1.Close() + + r2 := newRunner(t, bookPath) + if _, err := r2.TranslateBook(tracedCtx()); err != nil { + t.Fatal(err) + } + r2.Close() + + envs, _ := readJournal(t, bookPath) + rs := regions(envs) + if len(rs) != 2 { + t.Fatalf("want two process regions in one book journal, got %d", len(rs)) + } + first, second := rs[0], rs[1] + for _, region := range rs { + assertOneStream(t, region) + assertProgressSane(t, region) + } + idA := payload[runevents.Hello](t, first[0]).EngineRunID + idB := payload[runevents.Hello](t, second[0]).EngineRunID + if idA == idB { + t.Fatal("each process must name itself: the idempotency key is (engine_run_id, seq)") + } + for _, ev := range second { + if ev.Type == runevents.TypeUnitDone { + t.Fatalf("the resumed run re-announced a unit it only replayed at $0: %s", ev.Data) + } + } + // Its first progress line carries the BOOK's state, not this process's work. + for _, ev := range second { + if ev.Type == runevents.TypeProgress { + p := payload[runevents.Progress](t, ev) + if p.Draft.Done != 1 || p.Edit.Done != 1 { + t.Fatalf("a resumed run's first counters %+v — a bar that starts at zero walks backwards", p) + } + break + } + } +} + +func TestACeilingHaltAnnouncesItselfAndNamesWhichCeiling(t *testing.T) { + // PD-113: the stop is resumable, so it is not a failure — and the platform's contract forbids calling + // it `failed`. Before this event, a ceiling stop reached the platform only as exit 1. + for _, c := range []struct { + name string + bookUSD float64 + dayUSD float64 + wantScope string + }{ + {"the book ceiling", 0.0000001, 2.0, runevents.ScopeBook}, + {"the day ceiling", 1.0, 0.0000001, runevents.ScopeDay}, + } { + t.Run(c.name, func(t *testing.T) { + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + bookPath := setupCeilingProject(t, srv.URL, c.bookUSD, c.dayUSD) + + r := newRunner(t, bookPath) + _, err := r.TranslateBook(tracedCtx()) + r.Close() + + var halt *CeilingHalt + if !errors.As(err, &halt) { + t.Fatalf("want a typed ceiling halt, got %v", err) + } + if halt.Scope != c.wantScope { + t.Fatalf("scope %q, want %q", halt.Scope, c.wantScope) + } + if !errors.Is(err, errReserveCeiling) { + t.Fatal("the typed halt must keep matching the sentinel every degrade path uses") + } + + envs, _ := readJournal(t, bookPath) + assertOneStream(t, envs) + if len(envs) < 2 { + t.Fatalf("want the ceiling and the terminal line, got %d events", len(envs)) + } + ceiling, finished := envs[len(envs)-2], envs[len(envs)-1] + if ceiling.Type != runevents.TypeCeiling { + t.Fatalf("want a ceiling event before the terminal line, got %s", ceiling.Type) + } + c2 := payload[runevents.Ceiling](t, ceiling) + if !c2.Halted || c2.Scope != c.wantScope { + t.Fatalf("ceiling event %+v, want halted with scope %q", c2, c.wantScope) + } + if got := payload[runevents.Finished](t, finished).Outcome; got != runevents.OutcomeCeiling { + t.Fatalf("terminal outcome %q, want %q — `failed` is what the contract forbids here", got, runevents.OutcomeCeiling) + } + // Money never leaves the engine except inside `spend`: the halt says THAT, never how much. + if body := string(ceiling.Data); strings.Contains(body, "$") || strings.Contains(body, "usd") { + t.Fatalf("the ceiling event must carry the fact and no figures: %s", body) + } + }) + } +} + +func TestAReadOnlyProjectionWritesNoStream(t *testing.T) { + // `status`/`report` describe a run; they do not run one. Appending to a stream that says "a process + // is working on this book" from a read-only command would be a lie a reader acts on. + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + bookPath := setupProject(t, srv.URL) + + r := newRunner(t, bookPath) + if _, err := r.TranslateBook(tracedCtx()); err != nil { + t.Fatal(err) + } + r.Close() + before, err := os.ReadFile(filepath.Join(filepath.Dir(bookPath), runevents.JournalFile)) + if err != nil { + t.Fatal(err) + } + + ro, err := NewReadOnlyRunner(bookPath, obs.NewLogger()) + if err != nil { + t.Fatal(err) + } + if _, err := ro.Status(tracedCtx()); err != nil { + t.Fatal(err) + } + ro.Close() + + after, err := os.ReadFile(filepath.Join(filepath.Dir(bookPath), runevents.JournalFile)) + if err != nil { + t.Fatal(err) + } + if string(before) != string(after) { + t.Fatal("a read-only projection appended to the run stream") + } +} + +func TestTheStreamCountsUnitsAcrossAMultiChapterBook(t *testing.T) { + // The draft wave fans out over CHUNKS, the seam counts OUTPUT UNITS: one announcement per unit per + // wave, no more and no fewer, so a reader's per-chapter counters land on the manifest's own totals. + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + bookPath := setupProjectOpts(t, srv.URL, projectOpts{ + waveWorkers: 3, + epub: []chunktest.Chapter{ + {ID: "c1", Href: "ch1.xhtml", Body: `

静かな図書館の朝。

`}, + {ID: "c2", Href: "ch2.xhtml", Body: `

静かな図書館の昼。

`}, + {ID: "c3", Href: "ch3.xhtml", Body: `

静かな図書館の夜。

`}, + }, + spine: []string{"c1", "c2", "c3"}, + }) + + r := newRunner(t, bookPath) + res, err := r.TranslateBook(tracedCtx()) + if err != nil { + t.Fatal(err) + } + r.Close() + + envs, _ := readJournal(t, bookPath) + assertOneStream(t, envs) + assertProgressSane(t, envs) + perWave := map[string]map[int]int{runevents.WaveDraft: {}, runevents.WaveEdit: {}} + for _, ev := range envs { + if ev.Type != runevents.TypeUnitDone { + continue + } + u := payload[runevents.UnitDone](t, ev) + perWave[u.Wave][u.Chapter*1000+u.Unit]++ + } + for wave, units := range perWave { + if len(units) != len(res.Chunks) { + t.Fatalf("%s wave announced %d units, the run produced %d", wave, len(units), len(res.Chunks)) + } + for key, n := range units { + if n != 1 { + t.Fatalf("%s wave announced unit %d %d times — the reader folds this by increment", wave, key, n) + } + } + } +} + +// setupCeilingProject is setupProject with an explicit day ceiling, so the two ceiling scopes can be +// exercised apart. (setupProjectOpts pins day_usd at 2.0.) +func setupCeilingProject(t *testing.T, providerURL string, bookUSD, dayUSD float64) string { + t.Helper() + base := setupProjectOpts(t, providerURL, projectOpts{bookUSD: 1.0}) + body, err := os.ReadFile(base) + if err != nil { + t.Fatal(err) + } + patched := strings.Replace(string(body), "ceilings: { book_usd: 1, day_usd: 2.0 }", + fmt.Sprintf("ceilings: { book_usd: %g, day_usd: %g }", bookUSD, dayUSD), 1) + if patched == string(body) { + t.Fatalf("the ceilings line moved; fixture needs updating:\n%s", body) + } + writeFile(t, base, patched) + return base +} + +// storedRows is the book's dispositions, for the crash test's cross-check. +func storedRows(t *testing.T, r *Runner) []store.ChunkStatus { + t.Helper() + rows, err := r.Store.ChunkStatusesForBook(r.Book.BookID) + if err != nil { + t.Fatal(err) + } + return rows +} + +func TestAReusedRunIdDoesNotReopenTheEarlierStream(t *testing.T) { + // Since row 102 the CALLER supplies the run id (TM_TRACE_ID), and a caller that exports it in a + // wrapper reuses it. The seam's identity is per PROCESS, so a reused id used to make the second run + // continue the first one's numbering: its projection cursor starts at zero, so it re-appended the + // whole earlier stream and then wrote its handshake at a seq far past 1. A reader re-applies every + // counting event it already applied and finally refuses the handshake (hello must carry seq 1). + // Measured on the real binary before the guard: 33 lines, 15 byte-identical duplicates, hello at 16. + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + bookPath := setupProject(t, srv.URL) + reused := obs.WithReqInfo(context.Background(), obs.ReqInfo{TraceID: "a-caller-that-reuses-its-id"}) + + for i := 0; i < 2; i++ { + r := newRunner(t, bookPath) + if _, err := r.TranslateBook(reused); err != nil { + t.Fatal(err) + } + r.Close() + } + + envs, raw := readJournal(t, bookPath) + seen := map[string]int{} + for _, line := range raw { + seen[string(line)]++ + } + for line, n := range seen { + if n > 1 { + t.Fatalf("line appears %d times — the second run re-projected the first one's stream: %s", n, line) + } + } + rs := regions(envs) + if len(rs) != 2 { + t.Fatalf("want one region per process, got %d", len(rs)) + } + for _, region := range rs { + assertOneStream(t, region) // each opens with hello at seq 1 and is dense + } + ids := map[string]bool{} + for _, region := range rs { + ids[payload[runevents.Hello](t, region[0]).EngineRunID] = true + } + if len(ids) != 2 { + t.Fatalf("the two streams must not share an identity: %v", ids) + } +} + +func TestAJournalThatCannotBeOpenedDoesNotStopThePaidRun(t *testing.T) { + // The PD-60 policy this pack argues for at length — degrade loudly, never let the journal stop the + // run — was exercised by nothing. A paid book must not die because a freshness side-channel is + // unavailable: the money protection is the platform's hold and the engine's own ceiling, neither of + // which depends on this file. + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + bookPath := setupProject(t, srv.URL) + // A directory where the journal should be: every open of it fails, for the whole run. + if err := os.Mkdir(filepath.Join(filepath.Dir(bookPath), runevents.JournalFile), 0o755); err != nil { + t.Fatal(err) + } + + r := newRunner(t, bookPath) + res, err := r.TranslateBook(tracedCtx()) + r.Close() + if err != nil { + t.Fatalf("an unusable journal must not fail the run: %v", err) + } + if len(res.Chunks) != 1 || res.Flagged != 0 { + t.Fatalf("the run must have completed normally, got %+v", res) + } + if rec.count() == 0 { + t.Fatal("the run made no provider calls — it did not actually run") + } +} + +func TestWhatTheUnitDidTravelsWithIt(t *testing.T) { + // shipped/flagged/reason are the payload a reader derives unit state from — shipped→translated, + // flagged without text→withheld. Nothing asserted them, so dropping `reason` or collapsing shipped + // into !flagged passed the whole battery. + rec := &reqRec{} + srv := newJSONProvider(rec, func(body string) (string, string) { + if isEditBody(body) { + return "", "stop" // the edit produces nothing usable → the unit is flagged and ships nothing + } + return "ЧЕРНОВИК ПЕРЕВОДА", "stop" + }) + defer srv.Close() + bookPath := setupProject(t, srv.URL) + + r := newRunner(t, bookPath) + if _, err := r.TranslateBook(tracedCtx()); err != nil { + t.Fatal(err) + } + r.Close() + + envs, _ := readJournal(t, bookPath) + var draft, edit *runevents.UnitDone + for _, ev := range envs { + if ev.Type != runevents.TypeUnitDone { + continue + } + u := payload[runevents.UnitDone](t, ev) + switch u.Wave { + case runevents.WaveDraft: + draft = &u + case runevents.WaveEdit: + edit = &u + } + } + if draft == nil || edit == nil { + t.Fatalf("both waves must announce their unit, got draft=%v edit=%v", draft, edit) + } + if !draft.Shipped || draft.Flagged || draft.Reason != "" { + t.Fatalf("the draft resolved cleanly and must say so: %+v", *draft) + } + if edit.Shipped || !edit.Flagged || edit.Reason == "" { + t.Fatalf("a flagged unit that ships nothing must carry flagged + a reason and shipped=false: %+v", *edit) + } +} + +func TestTheJournalFollowsTheBookNotTheProjectDatabase(t *testing.T) { + // The whole reason config.Book.Dir exists. The platform tails `events.jsonl` in the directory it + // spawned the run in — the one holding book.yaml — while `project_db` may point anywhere; pointing + // the journal at the database's directory instead passed every other test. + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + bookPath := setupProject(t, srv.URL) + dir := filepath.Dir(bookPath) + if err := os.Mkdir(filepath.Join(dir, "state"), 0o755); err != nil { + t.Fatal(err) + } + body, err := os.ReadFile(bookPath) + if err != nil { + t.Fatal(err) + } + writeFile(t, bookPath, string(body)+"\nproject_db: state/test-book.db\n") + + r := newRunner(t, bookPath) + if _, err := r.TranslateBook(tracedCtx()); err != nil { + t.Fatal(err) + } + r.Close() + + if _, err := os.Stat(filepath.Join(dir, runevents.JournalFile)); err != nil { + t.Fatalf("the journal must sit beside book.yaml: %v", err) + } + if _, err := os.Stat(filepath.Join(dir, "state", runevents.JournalFile)); err == nil { + t.Fatal("the journal followed the project database instead of the book") + } +} + +func TestTheStreamCarriesAnEstimateOnceItHasMeasuredOne(t *testing.T) { + // Omitting the field is not leaving it alone: the consumer's progress handler ASSIGNS the column + // (`eta_seconds = $6` with etaOrNil), so an absent field decodes to 0 and NULLs on every line the + // estimate the `status --json` resync had just written. The first line carries none — nothing has + // been measured yet — and every line after a resolved unit must. + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + bookPath := setupProjectOpts(t, srv.URL, projectOpts{ + epub: []chunktest.Chapter{ + {ID: "c1", Href: "ch1.xhtml", Body: `

静かな図書館の朝。

`}, + {ID: "c2", Href: "ch2.xhtml", Body: `

静かな図書館の昼。

`}, + {ID: "c3", Href: "ch3.xhtml", Body: `

静かな図書館の夜。

`}, + }, + spine: []string{"c1", "c2", "c3"}, + }) + + r := newRunner(t, bookPath) + if _, err := r.TranslateBook(tracedCtx()); err != nil { + t.Fatal(err) + } + r.Close() + + envs, _ := readJournal(t, bookPath) + withETA, withWorkLeft := 0, 0 + for _, ev := range envs { + if ev.Type != runevents.TypeProgress { + continue + } + p := payload[runevents.Progress](t, ev) + left := (p.Draft.Total - p.Draft.Done) + (p.Edit.Total - p.Edit.Done) + if left == 0 { + continue // a finished book has nothing to estimate + } + withWorkLeft++ + if p.ETASeconds > 0 { + withETA++ + } + } + if withWorkLeft == 0 { + t.Fatal("no progress line reported work remaining — the fixture cannot exercise this") + } + if withETA == 0 { + t.Fatalf("%d progress lines reported work remaining and none carried an estimate — each of them NULLs the reader's column", withWorkLeft) + } +} + +func TestTwoBooksSharingOneProjectDatabaseBothGetAnnounced(t *testing.T) { + // The announce-once ledger lives in the project database, and `project_db` is a path a config may + // share. Without the book in the key, the second book's units collide with the first book's and are + // announced never — its chapters would sit at zero forever with no repair channel. + rec := &reqRec{} + srv := newJSONProvider(rec, draftEdit) + defer srv.Close() + first := setupProject(t, srv.URL) + dir := filepath.Dir(first) + + body, err := os.ReadFile(first) + if err != nil { + t.Fatal(err) + } + writeFile(t, filepath.Join(dir, "source2.txt"), "静かな図書館の夜。") + second := filepath.Join(dir, "book2.yaml") + writeFile(t, second, strings.NewReplacer( + "book_id: test-book", "book_id: other-book", + "source_file: source.txt", "source_file: source2.txt", + ).Replace(string(body))+"\nproject_db: test-book.db\n") + + for _, path := range []string{first, second} { + r := newRunner(t, path) + if _, err := r.TranslateBook(tracedCtx()); err != nil { + t.Fatal(err) + } + r.Close() + } + + envs, _ := readJournal(t, bookPathOf(dir)) + perBook := map[string]int{} + book := "" + for _, ev := range envs { + if ev.Type == runevents.TypeHello { + book = payload[runevents.Hello](t, ev).BookID + } + if ev.Type == runevents.TypeUnitDone { + perBook[book]++ + } + } + for _, id := range []string{"test-book", "other-book"} { + if perBook[id] == 0 { + t.Fatalf("book %q announced no unit; the ledger key collided across books: %v", id, perBook) + } + } +} + +// bookPathOf names the journal's directory for readJournal, which takes a config path. +func bookPathOf(dir string) string { return filepath.Join(dir, "book.yaml") } diff --git a/backend/internal/pipeline/runner.go b/backend/internal/pipeline/runner.go index 746294d8..fc0bf246 100644 --- a/backend/internal/pipeline/runner.go +++ b/backend/internal/pipeline/runner.go @@ -168,6 +168,11 @@ type Runner struct { // store would be read once per chunk for an answer that cannot differ. repinMu sync.Mutex repinCache map[string]bool + + // events is the run-event seam (row 103): the journal the platform tails. It exists only on the WRITE + // path — a read-only projection must not append to a stream that describes runs — and a nil one is a + // no-op at every call site, which is what keeps every $0 test and the golden byte-identical. + events *emitter } // NewRunner loads all three configs rooted at book.yaml and opens the project @@ -197,23 +202,29 @@ func NewReadOnlyRunner(bookPath string, logger *slog.Logger) (*Runner, error) { // openRunner loads the config stack and opens the store. forWrite selects the call // path: translate/redrive (provider keys required, store owned — // flock+migrations+recovery) versus status/report (no keys, store read-only). +// Every failure BEFORE the store opens is a REFUSAL, not a failure: nothing reached a provider, nothing +// was spent, nothing was written. They are classified rather than collapsed onto exit 1 because an +// automated caller acts on the difference — the platform's intake retries a book five times and then +// rejects it as `source_unreadable`, and it came within one step of deleting a user's upload over an +// operator's typo in a hand-written book.yaml (PD-196). "The text is unusable" and "the config is +// broken" have opposite repairs and opposite consequences for the file. func openRunner(bookPath string, logger *slog.Logger, forWrite bool) (*Runner, error) { book, err := config.LoadBook(bookPath) if err != nil { - return nil, err + return nil, RefuseConfig(err) } models, err := config.LoadModels(book.ModelsFile) if err != nil { - return nil, err + return nil, refuse(RefusalBadConfig, err) } pipe, err := config.LoadPipeline(book.Pipeline, models, book.LangPair(), book.ContentLabels) if err != nil { - return nil, err + return nil, refuse(RefusalBadConfig, err) } // Fail-fast BEFORE opening the store (taking the flock and side-effects): whether // the config mechanics are executable and the keys of the used models are set. if err := pipe.CheckRunnable(); err != nil { - return nil, err + return nil, refuse(RefusalBadConfig, err) } // Content-routing REFUSALS are for the paths that spend money or reach a provider; the routing // itself was RESOLVED for every path inside LoadPipeline (the read models re-render the snapshot, so @@ -225,17 +236,17 @@ func openRunner(bookPath string, logger *slog.Logger, forWrite bool) (*Runner, e // catches a broken config even on a read). if forWrite { if err := pipe.ContentRoutingError(); err != nil { - return nil, err + return nil, refuse(RefusalBadConfig, err) } if err := models.CheckKeys(pipe); err != nil { - return nil, err + return nil, refuse(RefusalBadConfig, err) } } else if err := pipe.ContentRoutingError(); err != nil { logger.Warn("content routing is not runnable for this book; read-only projections continue (translate/redrive would refuse)", "err", err) } pricer, err := models.Prices() if err != nil { - return nil, err + return nil, refuse(RefusalBadConfig, err) } var st *store.Store if forWrite { @@ -251,6 +262,9 @@ func openRunner(bookPath string, logger *slog.Logger, forWrite bool) (*Runner, e } } if err != nil { + if errors.Is(err, store.ErrLocked) { + return nil, refuse(RefusalProjectLocked, err) + } return nil, err } r := &Runner{ @@ -343,7 +357,12 @@ func (r *Runner) packVersion() string { return "" } -func (r *Runner) Close() error { return r.Store.Close() } +func (r *Runner) Close() error { + // The journal first: it holds no buffer (runevents.Journal writes each line straight through), so this + // only returns the descriptor — nothing that could still be lost is waiting in it. + _ = r.events.close() + return r.Store.Close() +} // bookCeilingUSD is the ONE definition of "the book ceiling in force for this process" (row 145): the // run-scoped override when the invocation named one, the book's own `ceilings.book_usd` otherwise. Every diff --git a/backend/internal/pipeline/stagerun.go b/backend/internal/pipeline/stagerun.go index 624f9a5f..eed0de4b 100644 --- a/backend/internal/pipeline/stagerun.go +++ b/backend/internal/pipeline/stagerun.go @@ -13,6 +13,7 @@ import ( "textmachine/backend/internal/llm" "textmachine/backend/internal/membank" "textmachine/backend/internal/obs" + "textmachine/backend/internal/runevents" "textmachine/backend/internal/store" "time" ) @@ -411,6 +412,26 @@ func (r *Runner) attemptRequest(st config.Stage, model, snapID string, ch chunk. } } +// callEstimateUSD is the ONE definition of what a paid call would cost at most — the reservation's own +// upper bound (prompt estimate + the whole output budget + D13.6's additive reasoning buffer, priced by +// the model that will be CALLED, which for an escalation hop is not the stage's model). +// +// It exists for the same reason attemptRequest does, one layer up: every gate that admits a paid call now +// prices it here (row 135), so a sub-budget can never admit a call the reservation books at a different +// figure — and a gate that priced its own call by hand would drift from the ledger the day a new axis +// (a reasoning buffer, a floor) entered the estimate. +func (r *Runner) callEstimateUSD(st config.Stage, model string, msgs []llm.Message, maxTokens int) float64 { + promptEst := 0 + for _, m := range msgs { + promptEst += EstimateTokens(m.Content) + } + // The additive reasoning buffer is reserved for the ACTUAL model being called (the escalate_to + // fallback may differ from st.Model and have its own provider). 0 for subset providers / reasoning-off + // — the ceiling then sees only completion, as before. + return ledger.EstimateUSD(r.Pricer.PriceFor(model), promptEst, maxTokens, + r.Models.AdditiveReasoningTokens(model, st.Reasoning, st.ReasoningMaxTokens)) +} + // runAttempt executes exactly one attempt on the request-hash axis: a checkpoint // hit is classified for free (self-heal, incl. legacy Phase-0 empty/decode // checkpoints — no re-billing), otherwise a fresh reserve → call → settle+ @@ -465,16 +486,7 @@ func (r *Runner) runAttempt(ctx context.Context, st config.Stage, model, snapID r.setJobStatus(ctx, job.ID, "failed") return att, err } - price := r.Pricer.PriceFor(model) - promptEst := 0 - for _, m := range msgs { - promptEst += EstimateTokens(m.Content) - } - // D13.6: reserve the additive reasoning buffer for the ACTUAL model being called (the - // escalate_to fallback may differ from st.Model and have its own provider). 0 for - // subset providers / reasoning-off — the ceiling then sees only completion, as before. - reasoningBudget := r.Models.AdditiveReasoningTokens(model, st.Reasoning, st.ReasoningMaxTokens) - estimate := ledger.EstimateUSD(price, promptEst, maxTokens, reasoningBudget) + estimate := r.callEstimateUSD(st, model, msgs, maxTokens) resv, verdict, err := r.Store.Reserve(r.Book.BookID, estimate, store.Ceilings{ BookUSD: r.bookCeilingUSD(), DayUSD: r.Book.Ceilings.DayUSD, @@ -508,9 +520,9 @@ func (r *Runner) runAttempt(ctx context.Context, st config.Stage, model, snapID if r.CeilingUSD > 0 { raise = fmt.Sprintf("this run's --ceiling-usd=%g overrides the book's ceilings.book_usd=%g — re-run with a higher --ceiling-usd", r.CeilingUSD, r.Book.Ceilings.BookUSD) } - return att, fmt.Errorf("pipeline: book USD ceiling reached ($%g)%s — %s or stop: %w", r.bookCeilingUSD(), money, raise, errReserveCeiling) + return att, &CeilingHalt{Scope: runevents.ScopeBook, err: fmt.Errorf("pipeline: book USD ceiling reached ($%g)%s — %s or stop: %w", r.bookCeilingUSD(), money, raise, errReserveCeiling)} } - return att, fmt.Errorf("pipeline: daily USD ceiling reached ($%g)%s: %w", r.Book.Ceilings.DayUSD, money, errReserveCeiling) + return att, &CeilingHalt{Scope: runevents.ScopeDay, err: fmt.Errorf("pipeline: daily USD ceiling reached ($%g)%s: %w", r.Book.Ceilings.DayUSD, money, errReserveCeiling)} } if err := r.Store.SetJobStatus(job.ID, "running"); err != nil { @@ -559,9 +571,10 @@ func (r *Runner) runAttempt(ctx context.Context, st config.Stage, model, snapID Stage: st.Name, Role: st.Role, ModelRequested: model, ModelActual: model, ResponseText: "", UsageJSON: "{}", CostUSD: estimate, FinishReason: decodeErrorFinish, Escalation: escalation, - }); serr != nil { + }, r.events.spendLine()); serr != nil { return att, fmt.Errorf("pipeline: settle after billed decode failure: %w", serr) } + r.events.flush() att.finish = decodeErrorFinish att.cumCost, att.runCost = estimate, estimate att.cls = classification{FlagDecodeError, "billed 2xx with an unreadable body: " + err.Error()} @@ -597,7 +610,7 @@ func (r *Runner) runAttempt(ctx context.Context, st config.Stage, model, snapID // Price by the model that actually answered, with a fallback to the REQUESTED // one (not to a cheap global anchor) if the provider returned a canonicalized slug. - price = r.Pricer.PriceForResponse(model, modelActual) + price := r.Pricer.PriceForResponse(model, modelActual) cost := ledger.CostUSD(price, resp.Usage) // A paid model (InputPerM>0) returned 2xx with zero usage — $0 would blind the // ceiling: take a conservative estimate. For local ($0 price) zero usage is @@ -624,11 +637,14 @@ func (r *Runner) runAttempt(ctx context.Context, st config.Stage, model, snapID ModelRequested: model, ModelActual: modelActual, ResponseText: resp.Text, UsageJSON: string(usageJSON), CostUSD: cost, FinishReason: resp.FinishReason, ProviderRequestID: resp.ProviderRequestID, Escalation: escalation, - }); err != nil { + }, r.events.spendLine()); err != nil { // The provider HAS billed this 2xx; failing to persist means the money // state is behind reality — fail loud, never continue on top. return att, fmt.Errorf("pipeline: settle stage %s: %w", st.Name, err) } + // The money event was enqueued INSIDE that transaction; put it on the file now rather than at the end + // of the unit, so the freshness the event exists for is not a unit behind the ledger. + r.events.flush() // Classify AFTER the money is durably settled+checkpointed. F4 lives here: a // non-empty truncated length draft is now classified (flagged/retried), never diff --git a/backend/internal/pipeline/status.go b/backend/internal/pipeline/status.go index cde09131..d42b0bab 100644 --- a/backend/internal/pipeline/status.go +++ b/backend/internal/pipeline/status.go @@ -71,6 +71,42 @@ type PhaseProgress struct { Edit WaveCounter `json:"edit"` } +// waveShape is the row arithmetic behind "this wave is done with this unit": which stage names belong to +// each wave and how many rows each owes a unit. A row exists only once the wave DECIDED (ok, flagged or +// skipped alike — see PhaseProgress), and chunk_status is keyed (book, chapter, chunk, stage), so +// counting the rows a wave wrote IS the resolution test. +// +// It is one definition because two readers need it: this projection, over stored rows, and the live event +// emitter (events.go), which counts the same units as it resolves them. A second copy of the arithmetic +// would put the event stream and the `status --json` resync on two different numbers, and the platform +// folds both into one column. +type waveShape struct { + draftNames map[string]bool + editNames map[string]bool + nDraft int + nEdit int +} + +func (r *Runner) waveShape() waveShape { + d, e := r.waveStagesIndexed(waveDraft), r.waveStagesIndexed(waveEdit) + return waveShape{draftNames: stageNameSet(d), editNames: stageNameSet(e), nDraft: len(d), nEdit: len(e)} +} + +// resolved reports, for one unit's stored rows, whether each wave has written every row it owes it. A +// wave the pipeline does not have answers false — its denominator is 0, not a total it can never reach. +func (w waveShape) resolved(u editUnit, rows []store.ChunkStatus) (draft, edit bool) { + draftRows, editRows := 0, 0 + for _, cs := range rows { + switch { + case w.draftNames[cs.Stage]: + draftRows++ + case w.editNames[cs.Stage]: + editRows++ + } + } + return w.nDraft > 0 && draftRows >= len(u.Members)*w.nDraft, w.nEdit > 0 && editRows >= w.nEdit +} + // ChapterPassport is the per-chapter quality passport (D12): unit counts, the worst flag // reason, a pass|attention|fail verdict (exp07 chapter rule) and the chapter's spend. type ChapterPassport struct { @@ -235,7 +271,7 @@ func flagReasonSeverity(reason string) int { // because the resume fast-path already re-checks content_hash on the NEXT translate — which is // where such an edit surfaces (as a re-bill of exactly the touched chunks), just not in status. func (r *Runner) bookChunks() ([]chunk.Chunk, error) { - doc, err := chunk.IngestEncoded(r.Book.SourceFile, r.Book.Encoding, r.Book.SourceLang) + doc, err := r.ingestSource() if err != nil { return nil, err } @@ -384,6 +420,7 @@ func (r *Runner) Status(ctx context.Context) (*StatusReport, error) { draftStages := r.waveStagesIndexed(waveDraft) editStages := r.waveStagesIndexed(waveEdit) draftStageNames, editStageNames := stageNameSet(draftStages), stageNameSet(editStages) + shape := r.waveShape() units := r.outputUnits(chunks) // The post-check GATE (opt-in) flags a unit at the CHUNK level AFTER the stage loop, so it is NEVER @@ -434,24 +471,14 @@ func (r *Runner) Status(ctx context.Context) (*StatusReport, error) { rows := unitRows(u, byChunk) res := resolveChunkState(rows, expected) state, reason := res.State, res.Reason - // Per-wave resolution (row 99), off the SAME rows the unit state is folded from. A wave owes a unit - // a fixed number of rows — |members|·|draft stages| in the draft wave, |edit stages| at the leader in - // the edit one — and chunk_status is keyed (book, chapter, chunk, stage), so counting the rows that - // wave wrote IS the resolution test: a row exists only once the wave decided (ok/flagged/skipped). - draftRows, editRows := 0, 0 - for _, cs := range rows { - switch { - case draftStageNames[cs.Stage]: - draftRows++ - case editStageNames[cs.Stage]: - editRows++ - } - } - if len(draftStages) > 0 && draftRows >= len(u.Members)*len(draftStages) { + // Per-wave resolution (row 99), off the SAME rows the unit state is folded from — through the one + // definition the live emitter also counts by (waveShape). + draftDone, editDone := shape.resolved(u, rows) + if draftDone { rep.Progress.Draft.Done++ p.Progress.Draft.Done++ } - if len(editStages) > 0 && editRows >= len(editStages) { + if editDone { rep.Progress.Edit.Done++ p.Progress.Edit.Done++ } diff --git a/backend/internal/pipeline/synthetic_stage_seam_test.go b/backend/internal/pipeline/synthetic_stage_seam_test.go index fe15cde3..49220700 100644 --- a/backend/internal/pipeline/synthetic_stage_seam_test.go +++ b/backend/internal/pipeline/synthetic_stage_seam_test.go @@ -75,7 +75,7 @@ func TestBankProbeAndAttemptAddressOneCheckpoint(t *testing.T) { RequestHash: hash, JobID: job.ID, ChunkIdx: ch.ChunkIdx, Stage: terminologyStageName, Role: roleTerminologist, ModelRequested: stage.Model, ModelActual: stage.Model, ResponseText: "reply", UsageJSON: "{}", CostUSD: 0.001, FinishReason: "stop", - }); err != nil { + }, nil); err != nil { t.Fatal(err) } paid, err = r.bankCheckpointExists(stage, snapID, ch, msgs) diff --git a/backend/internal/pipeline/terminologist.go b/backend/internal/pipeline/terminologist.go index 9022e51f..54c91d27 100644 --- a/backend/internal/pipeline/terminologist.go +++ b/backend/internal/pipeline/terminologist.go @@ -10,7 +10,6 @@ import ( "textmachine/backend/internal/chunk" "textmachine/backend/internal/config" "textmachine/backend/internal/lang" - "textmachine/backend/internal/ledger" "textmachine/backend/internal/llm" "textmachine/backend/internal/miner" "textmachine/backend/internal/obs" @@ -589,17 +588,12 @@ const terminologyReplyFloor = 256 // so the pre-call number and the reserved number are the same number. func (r *Runner) bankCallEstimateUSD(st config.Stage, msgs []llm.Message) float64 { _, maxTokens := r.bankCallBudget(st.Model, msgs) - promptEst := 0 - for _, m := range msgs { - promptEst += EstimateTokens(m.Content) - } // The buffer is read off the SAME stage the call will use rather than passed as a literal, so this line // cannot drift from the attempt's. ⚠ It is structurally 0 on every path today and that is NOT because of // the effort: AdditiveReasoningTokens ignores its effort argument entirely (D39.26 добор B) and returns 0 // whenever the declared buffer is 0, which InternalCall pins. The gate's additive-provider refusal // (config.LoadPipeline) is what makes that safe rather than blind. - return ledger.EstimateUSD(r.Pricer.PriceFor(st.Model), promptEst, maxTokens, - r.Models.AdditiveReasoningTokens(st.Model, st.Reasoning, st.ReasoningMaxTokens)) + return r.callEstimateUSD(st, st.Model, msgs, maxTokens) } // bankCheckpointExists reports whether THIS batch was already paid for in an earlier run, on the role's own diff --git a/backend/internal/pipeline/waverun.go b/backend/internal/pipeline/waverun.go index 7d2dde6e..7888e4b7 100644 --- a/backend/internal/pipeline/waverun.go +++ b/backend/internal/pipeline/waverun.go @@ -12,6 +12,7 @@ import ( "textmachine/backend/internal/config" "textmachine/backend/internal/lang" "textmachine/backend/internal/membank" + "textmachine/backend/internal/runevents" "textmachine/backend/internal/store" ) @@ -108,6 +109,11 @@ func (r *Runner) translateBookWaves(ctx context.Context, chunks []chunk.Chunk, s workers := r.Pipeline.Waves.Workers editWave := len(editStages) > 0 // a real editor wave exists; else the draft IS the shipping output (draft-only) + // The run-event counters (row 103), seeded from what the store already holds: the same output units + // and the same per-wave arithmetic `status` projects, so the stream and the resync channel can never + // quote two different numbers. + r.beginRunEvents(ctx, chunks) + // --- the draft wave: draft stage(s) ∥ over draft chunks under draft-wave snapshot (base-bank version) --- draftSnapshot, draftPayload, err := r.snapshotIDForWave(waveDraft) if err != nil { @@ -119,12 +125,19 @@ func (r *Runner) translateBookWaves(ctx context.Context, chunks []chunk.Chunk, s r.Log.InfoContext(ctx, "draft wave started", "snapshot", draftSnapshot[:12], "chunks", len(chunks), "workers", workers, "draft_stages", len(draftStages)) draftResults := make([]stageSeqResult, len(chunks)) + draftUnits := newDraftUnitTracker(r.outputUnits(chunks), chunks) if err := r.runWave(ctx, workers, len(chunks), func(ctx context.Context, i int) error { d, err := r.runDraftChunk(ctx, draftSnapshot, chunks[i], stickySel[i], draftStages, !editWave) if err != nil { return err } draftResults[i] = d + // The wave fans out over CHUNKS but the seam counts OUTPUT UNITS (the manifest's granularity, and + // therefore the reader's): a unit is announced by whichever member finishes last. + if u, done := draftUnits.memberDone(chunks[i]); done { + shipped, flagged, reason := draftUnits.outcome(u, draftResults) + r.events.unitResolved(runevents.WaveDraft, u.Chapter, u.FirstChunkIdx, shipped, flagged, reason) + } return nil }); err != nil { return nil, err @@ -136,6 +149,9 @@ func (r *Runner) translateBookWaves(ctx context.Context, chunks []chunk.Chunk, s if stopped, err := r.runBankMiningStop(ctx, chunks, draftSnapshot, editWave); err != nil { return nil, err } else if stopped { + // The COUNT travels; the table does not (row 101 ships it as an artifact — a thousand rows are + // not an event). + r.events.emit(runevents.TypeBankStop, runevents.BankStop{TermsProposed: r.lastMinedCount}) return nil, &WaveSignatureStop{ Terms: r.lastMinedCount, SignaturePath: r.signatureMapPath(), TablePath: r.bankStopTablePath(), TableJSONPath: r.bankStopTableJSONPath(), Rows: r.lastBankStopRows, @@ -185,6 +201,8 @@ func (r *Runner) translateBookWaves(ctx context.Context, chunks []chunk.Chunk, s return err } unitOutcomes[i] = oc + r.events.unitResolved(runevents.WaveEdit, oc.Chapter, oc.ChunkIdx, + oc.FinalText != "", oc.Disposition == DispFlagged, string(oc.FlagReason)) return nil }); err != nil { return nil, err diff --git a/backend/internal/runevents/journal.go b/backend/internal/runevents/journal.go new file mode 100644 index 00000000..ae0c3a49 --- /dev/null +++ b/backend/internal/runevents/journal.go @@ -0,0 +1,187 @@ +package runevents + +import ( + "bytes" + "errors" + "fmt" + "io" + "os" + "path/filepath" +) + +// JournalFile is the name of the event journal in the BOOK's directory. It is the platform's constant +// too (`platform/internal/ingest/tail.go`) and is ratified by D39.106 §2 — one journal per BOOK, one +// stream per PROCESS, appended to it. +const JournalFile = "events.jsonl" + +// maxPartialTail bounds the repair scan below. It is the reader's own line cap: a tail longer than that +// with no newline in it is not a torn line of ours, it is a file that is not what we think it is. +const maxPartialTail = 1 << 20 + +// Journal is the append-only event journal of one book. +// +// FORMAT (the fork row 103 left open — single JSONL vs per-file events vs CRC framing): a single +// `events.jsonl`, appended with one write(2) per line. The reader is already built for exactly this +// (tail.go), so any other shape is a coordinated change of BOTH zones, not an engine decision — and the +// objection recorded against it (research/25: JSONL is blind to a torn record that happens to end in a +// valid newline) does not survive contact with the reader's own contract: +// +// - a torn record CANNOT acquire a newline while this process lives — the line and its newline are one +// write(2), so the only torn tail is the one a dead process left behind; +// - the reader deliberately leaves a trailing line WITHOUT a newline alone ("still being written"), so +// it never MATERIALIZES one. +// +// So the torn tail is repaired at open, before this process's own hello. The repair PADS it into a blank +// line — it does NOT truncate, and that distinction is load-bearing rather than stylistic. An earlier +// version cut back to the last newline, reasoning that a reader's cursor can never stand past an +// unterminated line. That reasoning covers only a cursor EARNED BY READING. The ratified consumer also +// seeds one from `stat`: a new attempt starts at `journalSize(workdir)` — the raw size, torn fragment +// included (platform/internal/runs/spawn.go, runs.go, reconcile.go). Truncating below it makes the very +// next drain report "journal shrank … it is not append-only" (platform/internal/ingest/tail.go) and +// quarantine the attempt's projection — on a healthy resumed run. Padding keeps the file monotone in +// length, and a run of spaces plus a newline is exactly what that reader skips as a blank line. +// +// DURABILITY (the fsync fork): a line is handed to the kernel immediately and is NOT fsynced. The journal +// is a projection of SQLite commits taken at synchronous=NORMAL — "survives kill -9; power loss is +// outside the MVP threat model" (store/store.go) — and a projection cannot be more durable than the truth +// it projects, so an fsync per event would buy nothing and cost one on every unit of a 4000-unit book. +// What IS synced is the directory, exactly once, when the journal is created: the file's NAME is the one +// thing no later write re-creates. +// +// There is no user-space buffer, and that is the answer to PD-61(а) rather than a discipline about it: +// `os.Exit`, `log.Fatal` and a panic all skip defers, so a buffered writer would lose precisely the last +// events — `finished` and `ceiling`, the two that say why the run ended. Nothing is retained, so nothing +// can be lost by not flushing. Events are per unit and per stop, not per token, so the syscall is free. +type Journal struct { + f *os.File + // w is where lines go — f itself, except in tests that need a writer which stops part-way. A short + // write is the failure this type's retry logic exists for, and it cannot be provoked on a real file + // without filling a disk. + w io.Writer + // pending is the tail of a line whose write stopped part-way (a full disk is the realistic cause). + // Those bytes are ALREADY on the file, so the retry must send only the remainder: re-sending the + // whole line would concatenate a prefix and a copy, and that is a malformed line no repair can + // recognise later — the reader would refuse the journal from there on, permanently. + pending []byte + // pendingOf is the full buffer `pending` belongs to, so a caller that moves on to a DIFFERENT line + // while a remainder is outstanding is detected instead of silently splicing two lines together. + pendingOf []byte +} + +// OpenJournal opens (creating if needed) the journal in dir and repairs a torn tail left by a previous +// process. dir is the BOOK's directory — where book.yaml lives and where the platform tails. +func OpenJournal(dir string) (*Journal, error) { + path := filepath.Join(dir, JournalFile) + created := false + if _, err := os.Stat(path); os.IsNotExist(err) { + created = true + } else if err != nil { + return nil, fmt.Errorf("runevents: stat %s: %w", path, err) + } + // The repair READS the tail and OVERWRITES it in place, so it needs a descriptor without O_APPEND — + // with O_APPEND the kernel forces every write to the end, WriteAt included. The appending descriptor + // is opened afterwards, once the file is sound. + if !created { + rw, err := os.OpenFile(path, os.O_RDWR, 0o644) + if err != nil { + return nil, fmt.Errorf("runevents: open %s: %w", path, err) + } + err = padTornTail(rw) + rw.Close() + if err != nil { + return nil, err + } + } + f, err := os.OpenFile(path, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o644) + if err != nil { + return nil, fmt.Errorf("runevents: open %s: %w", path, err) + } + if created { + // Only on creation: an append changes no directory entry, so this is once per book, ever. + if d, derr := os.Open(dir); derr == nil { + _ = d.Sync() + d.Close() + } + } + return &Journal{f: f, w: f}, nil +} + +// padTornTail turns an unterminated trailing line into a blank one, in place. A file that ends in a +// newline (or is empty) is left untouched, which is every ordinary case. +// +// It never shortens the file — see the type comment: a consumer may hold an offset taken from the SIZE, +// and shrinking below it reads to that consumer as a journal that is not append-only. +func padTornTail(f *os.File) error { + st, err := f.Stat() + if err != nil { + return fmt.Errorf("runevents: stat journal: %w", err) + } + size := st.Size() + if size == 0 { + return nil + } + window := int64(maxPartialTail) + if size < window { + window = size + } + buf := make([]byte, window) + if _, err := f.ReadAt(buf, size-window); err != nil && !errors.Is(err, io.EOF) { + return fmt.Errorf("runevents: read journal tail: %w", err) + } + if buf[len(buf)-1] == '\n' { + return nil + } + i := bytes.LastIndexByte(buf, '\n') + if i < 0 && window < size { + return fmt.Errorf("runevents: journal ends with a partial line longer than %d bytes — refusing to repair a file this cannot have written", maxPartialTail) + } + from := size - window + int64(i) + 1 // i == -1 (the whole file is one partial line) ⇒ from 0 + blank := bytes.Repeat([]byte{' '}, int(size-from)) + if _, err := f.WriteAt(blank, from); err != nil { + return fmt.Errorf("runevents: blank the torn journal tail: %w", err) + } + if _, err := f.WriteAt([]byte{'\n'}, size); err != nil { + return fmt.Errorf("runevents: terminate the torn journal tail: %w", err) + } + return nil +} + +// Append writes one line and its newline. The whole buffer goes in ONE write(2) — that syscall is what +// makes a torn line impossible while the process lives, and O_APPEND is what makes the position atomic +// without a seek. +// +// A write that stops part-way (ENOSPC is the realistic cause) leaves those bytes on the file, so the +// remainder is remembered and the retry sends only that. The caller retries by re-offering the SAME +// line, because a failed append leaves the projection cursor where it was. +func (j *Journal) Append(line []byte) error { + buf := make([]byte, 0, len(line)+1) + buf = append(buf, line...) + buf = append(buf, '\n') + + out := buf + if len(j.pending) > 0 { + if !bytes.Equal(j.pendingOf, buf) { + // Appending a DIFFERENT line after a half-written one splices two records into a malformed + // third, and no later repair can tell where the seam was. It cannot happen through the + // projection — a failed append leaves the cursor where it was, so the retry always re-offers + // the same line — so this is an assertion, not a recovery path. The half-written line stays + // unterminated, which the reader treats as "still being written", and the next open blanks it. + return fmt.Errorf("runevents: refusing to append a new line while %d bytes of another are half-written", len(j.pending)) + } + out = j.pending // continue the line whose write stopped part-way + } + n, err := j.w.Write(out) + if n > 0 && n < len(out) { + j.pending, j.pendingOf = out[n:], buf + } + if err != nil { + return fmt.Errorf("runevents: append to journal: %w", err) + } + if n != len(out) { + return fmt.Errorf("runevents: short append to journal: wrote %d of %d bytes", n, len(out)) + } + j.pending, j.pendingOf = nil, nil + return nil +} + +func (j *Journal) Close() error { return j.f.Close() } diff --git a/backend/internal/runevents/runevents.go b/backend/internal/runevents/runevents.go new file mode 100644 index 00000000..dc6b75ac --- /dev/null +++ b/backend/internal/runevents/runevents.go @@ -0,0 +1,230 @@ +// Package runevents is the ENGINE side of the run-event seam (row 103): the vocabulary of the +// NDJSON stream the platform tails, and the append-only journal it is written to. +// +// The transport is ratified and not open (D39.106 §2, research/25 §Форма): the engine is a transient +// systemd unit per run, the platform is NOT its parent, and the stream is `events.jsonl` in the BOOK's +// directory — an outbox projection of rows the engine has already committed to its SQLite. Delivery is +// at-least-once; a re-read line is normal (D39.119 п.3 / PD-105). What this package owns is only the +// FORM: the envelope, the payloads and the file discipline. WHEN an event happens is the driver's +// (internal/pipeline), and the durable sequencing is the store's (internal/store, events_outbox). +// +// The payload shapes mirror the platform's reader (`platform/internal/ingest/events.go`), which is the +// platform's PROPOSAL written as code, "so the engine zone can answer it with a diff". Where this file +// differs from that one, the difference is DELIBERATE and named in the doc comment of the type: +// `Ceiling` adds `scope` and `Finished` widens its outcome vocabulary. (`Progress` was going to omit +// `eta_seconds`; measurement showed omission NULLs the consumer's column, so it is carried — see there.) +// +// Nothing here is language-, pair- or book-specific, and nothing may become so: an event carries +// counters, ordinals and engine-side enums only (общность §0.1 — a pair that is not in the repository +// must stream identically without a line of Go changing). +package runevents + +import ( + "encoding/json" + "fmt" + "math" + "time" +) + +// StreamVersion is the version of the stream this build writes. The rule is terraform's, ratified by +// D39.85: a MINOR bump adds fields and event types — a reader ignores the ones it does not know; a +// MAJOR bump is refused by the reader outright. So: adding a field or an event type bumps the minor, +// changing what an existing field MEANS bumps the major. +// +// 1.1, and the bump is the point rather than a formality. This build adds a field (`Ceiling.Scope`) and +// two outcome values, so by the rule above it is not 1.0 — and a version is a fact about the BYTES on +// the wire, not about whether the vocabulary diff has been accepted yet. Leaving it at 1.0 would make +// two streams that differ in content claim the same version, which is the one thing a version exists to +// prevent; the reader compares only the major, so the bump costs nothing and is safe in both directions +// (if `scope` is later declined, removing it is another minor — that is what minors are for). +const StreamVersion = "1.1" + +// Type is the event name. +type Type string + +const ( + // TypeHello is always the first line a process writes: the version handshake. + TypeHello Type = "hello" + // TypeProgress carries the per-phase counters. Per phase because a unit is done only once its edit + // resolved, so one end-to-end counter reads zero for the whole draft wave (row 99 / D39.122 п.2б). + TypeProgress Type = "progress" + // TypeUnitDone is one resolved output unit. + TypeUnitDone Type = "unit_done" + // TypeBankStop is the book-wide signing stop before the edit wave. + TypeBankStop Type = "bank_stop" + // TypeCeiling is the resumable halt on a spend ceiling: the fact only, no figures. + TypeCeiling Type = "ceiling" + // TypeSpend is the cumulative spend counter. + TypeSpend Type = "spend" + // TypeFinished is the terminal line of a run that ended on purpose. + TypeFinished Type = "finished" +) + +// Envelope is one line of the stream. Seq is per PROCESS and starts at 1: a resumed run is a NEW +// process that appends a second hello to the same file and numbers from 1 again, which is why the +// ratified idempotency key is (engine_run_id, seq) and not the platform's run id. +type Envelope struct { + Seq int64 `json:"seq"` + Type Type `json:"type"` + Time time.Time `json:"time"` + Data json.RawMessage `json:"data"` +} + +// Hello is the handshake payload. +type Hello struct { + StreamVersion string `json:"stream_version"` + // EngineRunID is this PROCESS's identity — the trace id, which since row 102 the caller may supply + // (TM_TRACE_ID). It must be non-empty: it is half of the idempotency key, and an empty one would + // collapse every run's events into one namespace instead of failing. + EngineRunID string `json:"engine_run_id"` + BookID string `json:"book_id"` + // ChunkerVersion lets a reader notice that the chapter manifest it persisted was produced by a + // different chunker — the case that silently re-numbers chapters. + ChunkerVersion string `json:"chunker_version"` +} + +// Counter is one phase's done/total pair, in OUTPUT UNITS — the granularity every engine read model +// counts in (status.go, the manifest). Counting the draft wave in CHUNKS instead would put the stream +// and the `status --json` resync on two different scales, and the platform folds both into one column. +type Counter struct { + Done int `json:"done"` + Total int `json:"total"` +} + +// Progress is the run's per-wave counters. Total is 0 for a wave this pipeline does not have, which is +// how a reader tells "no such phase" from "none of it is done yet". +// +// ETASeconds is carried, and the reason is worth recording because the first version of this pack +// omitted it on an argument that MEASUREMENT destroyed. The argument was: the engine has one ETA +// definition already (pipeline/status.go, a book-lifetime mean over stored latencies), computing it here +// would cost a store aggregate per unit, and the field is optional to the reader anyway. The last clause +// is false. The consumer's progress handler ASSIGNS the column unconditionally — +// `update runs set … eta_seconds = $6` with `etaOrNil(p.ETASeconds)` (platform/internal/pgstore/sink.go) +// — so an absent field decodes to 0 and NULLS the estimate on every single progress line, erasing what +// the `status --json` resync had just written. Omitting a field is not leaving it alone. +// +// So it is emitted, computed from THIS RUN's own throughput (see pipeline/events.go). That deliberately +// differs from status.go's book-lifetime mean: this one is what the run is achieving now, it costs no +// query, and the alternative on the table was not "a second opinion" but "no estimate at all". +type Progress struct { + Draft Counter `json:"draft"` + Edit Counter `json:"edit"` + ETASeconds int `json:"eta_seconds,omitempty"` +} + +// UnitDone is one resolved output unit. Chapter is the engine's dense 1-based ordinal and Unit is the +// unit's LEADER chunk index — together the join key the manifest publishes as `first_chunk_idx`, which +// is how a reader maps this onto its own opaque ids. +// +// Shipped and Flagged are BOTH carried and neither implies the other: a flagged unit legally ships text +// (a cosmetic sanitizer strip, a c-lite member drop), and the pair is exactly the contract's derivation +// of unit state. +// +// It is emitted ONLY for a unit THIS process resolved — a unit already resolved when the process started +// is walked again at $0 on every resume and re-announcing it would make a counting reader count it twice +// (see pipeline/events.go, `resolvedAtStart`). +type UnitDone struct { + Chapter int `json:"chapter"` + Unit int `json:"unit"` + Wave string `json:"wave"` // draft | edit + Shipped bool `json:"shipped"` + Flagged bool `json:"flagged"` + // Reason is the ENGINE's flag reason (glossary_miss, sanitizer_stripped, …) — stored by a reader, + // never projected verbatim, so a reason it has never heard of still gets a neutral phrase. + Reason string `json:"reason,omitempty"` +} + +// BankStop is the signing stop. The full table travels as an artifact (row 101), not through the +// stream: a thousand rows are not an event. +type BankStop struct { + TermsProposed int `json:"terms_proposed"` +} + +// Ceiling is the ceiling halt. It carries the FACT and nothing else: money never reaches the platform's +// wire or its INFO logs (D39.84), and the stop is resumable, so it is NOT a failure — which is the whole +// of PD-113. +// +// ⚠ DIFF against the platform's proposal: `scope` is added. It is not money — it names WHICH ceiling +// stopped the run, book or day — and it closes the diagnosis half of PD-157: a book whose `day_usd` the +// platform never chose stops the run on a limit the platform cannot even see, and today it cannot tell +// that from the ceiling it set itself. +type Ceiling struct { + Halted bool `json:"halted"` + Scope string `json:"scope"` // book | day +} + +// Spend is the freshness channel for money and ONLY that: the balance is protected by the platform's +// hold and by the per-book ceiling the engine enforces itself, so a lost tail costs an indicator its +// accuracy and never costs an account its correctness. Building enforcement on this event is forbidden — +// the stream is at-least-once and a crash truncates it (D39.106 §2: холд+потолок = защита, события = +// свежесть). +// +// CUMULATIVE, not a delta, so a re-delivered line is harmless to a reader that keeps the maximum. It is +// the book's LIFETIME committed spend — the same figure `status --json` reports as `committed_usd`, so +// the two channels can never quote different numbers. Integer micro-USD: money never travels as a float +// (PD-79), and the engine's ledger is a lower bound, so the conversion rounds UP. +type Spend struct { + CommittedMicroUSD int64 `json:"committed_micro_usd"` +} + +// Finished is the terminal line of a run that ended on purpose. Its absence is meaningful: a stream +// without it ended without finishing a book run — a crash, or a command that never started one. +// +// ⚠ DIFF against the platform's proposal: the outcome vocabulary gains `ceiling` and `stopped`. The +// proposal has clean|flagged|bank_stop|failed, and a ceiling halt fits none of them — `failed` is exactly +// what the contract forbids for a resumable stop (PD-113), and leaving the stream unterminated would make +// "stopped on purpose" indistinguishable from "truncated by a crash", which is the same confusion one +// level down. `stopped` is its sibling for a caught SIGTERM (PD-152). +type Finished struct { + Outcome string `json:"outcome"` +} + +// The outcomes this engine writes. They mirror the shell contract of cmd/tmctl (0/2/3/4/5/1) so a reader +// never has to do exit-code archaeology over a stream that ended cleanly. +const ( + OutcomeClean = "clean" + OutcomeFlagged = "flagged" + OutcomeBankStop = "bank_stop" + OutcomeCeiling = "ceiling" + OutcomeStopped = "stopped" + OutcomeFailed = "failed" +) + +// The waves a unit can be resolved by. +const ( + WaveDraft = "draft" + WaveEdit = "edit" +) + +// The ceiling scopes. +const ( + ScopeBook = "book" + ScopeDay = "day" +) + +// Line renders one journal line — the envelope, WITHOUT its newline. The bytes it returns are the line: +// they are stored verbatim and re-projected verbatim, because a reader compares a re-read line against +// the sha256 it recorded and a re-render with a fresher timestamp would read as a payload conflict +// (tail.go: ErrPayloadConflict) and quarantine the projection. +func Line(seq int64, t Type, at time.Time, data any) ([]byte, error) { + payload, err := json.Marshal(data) + if err != nil { + return nil, fmt.Errorf("runevents: marshal %s payload: %w", t, err) + } + line, err := json.Marshal(Envelope{Seq: seq, Type: t, Time: at.UTC(), Data: payload}) + if err != nil { + return nil, fmt.Errorf("runevents: marshal %s envelope: %w", t, err) + } + return line, nil +} + +// MicroUSD converts a ledger figure to the integer micro-USD the seam carries, rounding UP: the ledger +// is a lower bound on what a provider billed (a 2xx whose body did not decode is settled at its +// estimate), so the seam must never round the shortfall away. A negative figure cannot exist in the +// ledger and is clamped rather than sign-extended into a nonsense counter. +func MicroUSD(usd float64) int64 { + if !(usd > 0) { // also catches NaN + return 0 + } + return int64(math.Ceil(usd*1e6 - 1e-6)) +} diff --git a/backend/internal/runevents/runevents_test.go b/backend/internal/runevents/runevents_test.go new file mode 100644 index 00000000..2d212967 --- /dev/null +++ b/backend/internal/runevents/runevents_test.go @@ -0,0 +1,271 @@ +package runevents + +import ( + "encoding/json" + "errors" + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +func TestMoneyCrossesTheSeamAsWholeMicroUSDRoundedUp(t *testing.T) { + // The ledger is a LOWER bound on what a provider billed, so a fraction of a micro-dollar must round + // AWAY from zero: rounding it down would let the seam report less than the engine already knows it + // owes. The float-noise cases are the ones that matter in practice — 0.114378 is not representable. + for _, c := range []struct { + usd float64 + want int64 + }{ + {0, 0}, + {-1, 0}, + {0.114378, 114378}, + {0.0000001, 1}, // a tenth of a micro-dollar still costs a whole one + {0.000001, 1}, // exactly one, and float noise must not turn it into two + {2.0, 2_000_000}, // + } { + if got := MicroUSD(c.usd); got != c.want { + t.Errorf("MicroUSD(%v) = %d, want %d", c.usd, got, c.want) + } + } +} + +func TestALineIsTheSameBytesEveryTimeItIsRendered(t *testing.T) { + // The reader compares a re-read line against the sha256 it recorded, so two renders of one event must + // be byte-identical or the projection is quarantined (ErrPayloadConflict). This is why the OUTBOX + // keeps the bytes instead of the event. + at := time.Date(2026, 8, 14, 10, 0, 0, 0, time.UTC) + a, err := Line(7, TypeSpend, at, Spend{CommittedMicroUSD: 5}) + if err != nil { + t.Fatal(err) + } + b, err := Line(7, TypeSpend, at, Spend{CommittedMicroUSD: 5}) + if err != nil { + t.Fatal(err) + } + if string(a) != string(b) { + t.Fatalf("two renders of one event differ:\n%s\n%s", a, b) + } + var env Envelope + if err := json.Unmarshal(a, &env); err != nil { + t.Fatalf("a line must be one JSON object: %v", err) + } + if env.Seq != 7 || env.Type != TypeSpend || !env.Time.Equal(at) { + t.Fatalf("envelope lost a field: %+v", env) + } + if strings.Contains(string(a), "\n") { + t.Fatalf("a line must not carry a newline of its own: %q", a) + } +} + +func TestATornTailIsBlankedAndTheFileNeverShrinks(t *testing.T) { + // The only way a journal can end mid-line is a process that died while writing one: a line and its + // newline leave in ONE write(2). + // + // The repair PADS the fragment into a blank line instead of truncating it, and the file's LENGTH is + // the reason. A consumer of this journal seeds an attempt's starting offset from the file's SIZE + // (platform/internal/runs/spawn.go journalSize), torn fragment included; a repair that shortened the + // file below that offset would make its very next read report "journal shrank … it is not + // append-only" and quarantine a healthy resumed run. A run of spaces plus a newline is what that + // same reader skips as a blank line. + dir := t.TempDir() + path := filepath.Join(dir, JournalFile) + torn := `{"seq":1}` + "\n" + `{"seq":2}` + "\n" + `{"seq":3,"ty` + if err := os.WriteFile(path, []byte(torn), 0o644); err != nil { + t.Fatal(err) + } + before := int64(len(torn)) + + j, err := OpenJournal(dir) + if err != nil { + t.Fatal(err) + } + if err := j.Append([]byte(`{"seq":1,"again":true}`)); err != nil { + t.Fatal(err) + } + j.Close() + + got, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if int64(len(got)) < before { + t.Fatalf("the journal shrank from %d to %d bytes — a reader holding a size-seeded offset reads that as corruption", before, len(got)) + } + lines := strings.Split(strings.TrimSuffix(string(got), "\n"), "\n") + if len(lines) != 4 { + t.Fatalf("want the two complete lines, the blanked fragment and the new line, got %d: %q", len(lines), got) + } + if lines[0] != `{"seq":1}` || lines[1] != `{"seq":2}` { + t.Fatalf("the complete lines were damaged: %q", got) + } + if strings.TrimSpace(lines[2]) != "" { + t.Fatalf("the torn fragment must become a line the reader skips, got %q", lines[2]) + } + if lines[3] != `{"seq":1,"again":true}` { + t.Fatalf("the new line is wrong: %q", lines[3]) + } +} + +func TestACompleteJournalIsNotTouchedOnOpen(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, JournalFile) + body := `{"seq":1}` + "\n" + `{"seq":2}` + "\n" + if err := os.WriteFile(path, []byte(body), 0o644); err != nil { + t.Fatal(err) + } + j, err := OpenJournal(dir) + if err != nil { + t.Fatal(err) + } + j.Close() + got, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if string(got) != body { + t.Fatalf("a journal that ends in a newline must be left alone: %q", got) + } +} + +func TestAFileThatIsOneTornLineBecomesOneBlankLine(t *testing.T) { + // The degenerate torn tail: the process died on its very first line. Still padded, not emptied — the + // length must not go backwards (see the test above). + dir := t.TempDir() + path := filepath.Join(dir, JournalFile) + if err := os.WriteFile(path, []byte(`{"seq":1,"ty`), 0o644); err != nil { + t.Fatal(err) + } + j, err := OpenJournal(dir) + if err != nil { + t.Fatal(err) + } + j.Close() + got, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if len(got) < len(`{"seq":1,"ty`) { + t.Fatalf("the journal shrank: %q", got) + } + if strings.TrimSpace(string(got)) != "" || !strings.HasSuffix(string(got), "\n") { + t.Fatalf("want one blank, terminated line, got %q", got) + } +} + +func TestAPartialLineTooLongToBeOursIsRefusedRatherThanCut(t *testing.T) { + // Events carry counters and ids, never text. A megabyte with no newline in it is not a line this + // engine wrote, and truncating a file we do not recognise is how data is destroyed. + dir := t.TempDir() + path := filepath.Join(dir, JournalFile) + if err := os.WriteFile(path, []byte(strings.Repeat("x", maxPartialTail+16)), 0o644); err != nil { + t.Fatal(err) + } + if _, err := OpenJournal(dir); err == nil { + t.Fatal("want a refusal on a partial line longer than the reader's own cap") + } + st, err := os.Stat(path) + if err != nil { + t.Fatal(err) + } + if st.Size() != int64(maxPartialTail+16) { + t.Fatalf("the refused file must be intact, size is now %d", st.Size()) + } +} + +func TestTheJournalIsCreatedInTheBooksDirectoryUnderTheRatifiedName(t *testing.T) { + // The name is the platform's constant too (ingest.JournalFile): a rename here is a coordinated change + // of both zones, not an engine decision. + dir := t.TempDir() + j, err := OpenJournal(dir) + if err != nil { + t.Fatal(err) + } + j.Close() + if _, err := os.Stat(filepath.Join(dir, "events.jsonl")); err != nil { + t.Fatalf("want %s in the book's directory: %v", JournalFile, err) + } +} + +// shortWriter accepts `limit` bytes and then refuses, the way a filesystem behaves when it runs out of +// room mid-line. It is the only way to reach this path without filling a real disk. +type shortWriter struct { + to *os.File + limit int + fail error +} + +func (w *shortWriter) Write(p []byte) (int, error) { + if w.fail == nil { + return w.to.Write(p) + } + n := len(p) + if n > w.limit { + n = w.limit + } + written, err := w.to.Write(p[:n]) + if err != nil { + return written, err + } + return written, w.fail +} + +func TestAWriteThatStoppedPartWayIsResumed(t *testing.T) { + // The defect this pins: a failed append leaves a PREFIX of the line on the file, and the projection + // retries by re-offering the SAME line. Re-sending it whole concatenates a prefix and a copy — a + // malformed record that no later repair can recognise, sitting behind every future cursor. The retry + // must therefore send only the remainder. + dir := t.TempDir() + path := filepath.Join(dir, JournalFile) + f, err := os.OpenFile(path, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o644) + if err != nil { + t.Fatal(err) + } + w := &shortWriter{to: f, limit: 7, fail: errors.New("no space left on device")} + j := &Journal{f: f, w: w} + + line := []byte(`{"seq":2,"type":"unit_done"}`) + if err := j.Append(line); err == nil { + t.Fatal("the failing write must be reported") + } + // The disk frees up; the projection retries the same line. + w.fail = nil + if err := j.Append(line); err != nil { + t.Fatal(err) + } + j.Close() + + got, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if string(got) != string(line)+"\n" { + t.Fatalf("the retry did not resume the interrupted line:\n got %q\n want %q", got, string(line)+"\n") + } + var env Envelope + if err := json.Unmarshal([]byte(strings.TrimSuffix(string(got), "\n")), &env); err != nil { + t.Fatalf("the repaired line is not a readable event: %v (%q)", err, got) + } +} + +func TestANewLineIsRefusedWhileAnotherIsHalfWritten(t *testing.T) { + // Appending a different line after a half-written one splices two records into a malformed third. + // The projection cannot do it (a failed append leaves its cursor where it was), so this is an + // assertion rather than a recovery path — but an unasserted invariant is the kind that rots. + dir := t.TempDir() + f, err := os.OpenFile(filepath.Join(dir, JournalFile), os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o644) + if err != nil { + t.Fatal(err) + } + w := &shortWriter{to: f, limit: 5, fail: errors.New("no space left on device")} + j := &Journal{f: f, w: w} + if err := j.Append([]byte(`{"seq":2}`)); err == nil { + t.Fatal("the failing write must be reported") + } + w.fail = nil + if err := j.Append([]byte(`{"seq":3}`)); err == nil { + t.Fatal("a different line must be refused while a remainder is outstanding") + } + j.Close() +} diff --git a/backend/internal/store/kill9_test.go b/backend/internal/store/kill9_test.go index 02509570..3090d99c 100644 --- a/backend/internal/store/kill9_test.go +++ b/backend/internal/store/kill9_test.go @@ -53,7 +53,7 @@ func TestHelperKillLoop(t *testing.T) { ModelRequested: "m", ModelActual: "m", ResponseText: "ответ", UsageJSON: "{}", CostUSD: 0.001, } - if err := s.SettleWithCheckpoint(res, 0.001, cp); err != nil { + if err := s.SettleWithCheckpoint(res, 0.001, cp, nil); err != nil { os.Exit(1) } } diff --git a/backend/internal/store/ledger.go b/backend/internal/store/ledger.go index 8e2fbc40..f6b44aa3 100644 --- a/backend/internal/store/ledger.go +++ b/backend/internal/store/ledger.go @@ -168,7 +168,14 @@ type Checkpoint struct { // // Idempotent per request_hash: a duplicate settle for the same hash books // nothing and keeps the original checkpoint. -func (s *Store) SettleWithCheckpoint(res Reservation, cost float64, cp Checkpoint) error { +// +// `spend` is the run-event seam (row 103) joining this transaction: it renders the cumulative-spend +// journal line from the sequence number the outbox assigns here and the book's new committed total, read +// after the debit and INSIDE this transaction. That is the ratified formula — the event is an outbox +// projection of a committed row, not a second write — and this is the one place it is load-bearing: a +// journal line claiming money the ledger never booked is a divergence about money, not about a progress +// bar. nil disables it (every read-only path and every $0 test). +func (s *Store) SettleWithCheckpoint(res Reservation, cost float64, cp Checkpoint, spend *SpendLine) error { ctx, cancel := opContext() defer cancel() @@ -211,9 +218,30 @@ func (s *Store) SettleWithCheckpoint(res Reservation, cost float64, cp Checkpoin res.BookID, res.Date, cost, res.Estimate); err != nil { return fmt.Errorf("store: settle spend: %w", err) } + if spend != nil { + var committed float64 + if err := tx.QueryRowContext(ctx, + `SELECT COALESCE(SUM(committed_usd), 0) FROM spend WHERE book_id = ?`, res.BookID).Scan(&committed); err != nil { + return fmt.Errorf("store: read committed for the spend event: %w", err) + } + if _, err := enqueueEvent(ctx, tx, spend.RunID, func(seq int64) ([]byte, error) { + return spend.Line(seq, committed) + }); err != nil { + return err + } + } return tx.Commit() } +// SpendLine is how the driver puts its cumulative-spend event into the settle transaction: RunID names +// the outbox stream (the process's engine run id) and Line renders the journal line from the sequence +// number the outbox assigned and the book's new committed total. The store stays dumb storage — it +// never learns what an event means, exactly as it never learns what a `disposition` string means. +type SpendLine struct { + RunID string + Line func(seq int64, committedUSD float64) ([]byte, error) +} + // PutDerivedCheckpoint persists a $0 DERIVED checkpoint — a deterministic post-processing // artifact, NOT a billed provider response (D38 infra-pack): the output-sanitizer's cosmetic // strip commits the cleaned final text here so the standard final_hash→checkpoint.response_text diff --git a/backend/internal/store/migrate.go b/backend/internal/store/migrate.go index c2f64650..d8f6d8d6 100644 --- a/backend/internal/store/migrate.go +++ b/backend/internal/store/migrate.go @@ -413,6 +413,29 @@ var migrations = []string{ ALTER TABLE retrieval_state ADD COLUMN n_spoiler_leaks INTEGER NOT NULL DEFAULT 0; ALTER TABLE retrieval_state ADD COLUMN spoiler_leak_detail TEXT NOT NULL DEFAULT ''; `, + // v15 (row 103): the run-event OUTBOX. A line of `events.jsonl` is a projection of a row committed + // here — that is the ratified form of the seam (D39.106 §2), and it is what lets the money event ride + // the very transaction that settled the money. The number is assigned inside that transaction, so a + // rollback leaves no hole in a stream whose reader treats a hole as fatal; the exact bytes are kept, + // so a retry after a failed journal write re-projects the identical line rather than a fresher one. + // + // It is a BUFFER, not an archive: outbox.go drops every other run's rows at open, so a book that has + // been resumed a hundred times carries one run's worth of them. + ` + CREATE TABLE IF NOT EXISTS events_outbox ( + engine_run_id TEXT NOT NULL, -- the PROCESS's id (trace id); seq restarts at 1 per process + seq INTEGER NOT NULL, + -- Non-empty for an event that must be announced ONCE for the life of the book however many + -- processes it takes (today: one per unit per wave). Those rows OUTLIVE their run — they are the + -- emission ledger, not a buffer — which is what makes a crash between a unit's disposition and + -- its announcement recoverable instead of a count lost for good. + once_key TEXT NOT NULL DEFAULT '', + line TEXT NOT NULL, -- the NDJSON line, verbatim, without its newline + created_at TEXT NOT NULL DEFAULT (datetime('now')), + PRIMARY KEY (engine_run_id, seq) + ); + CREATE UNIQUE INDEX IF NOT EXISTS events_outbox_once ON events_outbox (once_key) WHERE once_key <> ''; + `, } // DESIGN NOTE (D21.10 → BUILT by pack-19 / D39.55; kept as the record of what each type is FOR). diff --git a/backend/internal/store/outbox.go b/backend/internal/store/outbox.go new file mode 100644 index 00000000..d1f6f540 --- /dev/null +++ b/backend/internal/store/outbox.go @@ -0,0 +1,216 @@ +package store + +import ( + "context" + "database/sql" + "errors" + "fmt" +) + +// outbox.go: the durable half of the run-event seam (row 103). The ratified form is an OUTBOX, not a +// second write (D39.106 §2, research/25): a line of the event journal is a projection of a row this +// database has already committed, so the file can never claim something the ledger does not have. +// +// What lives here is the SEQUENCING and the STORAGE, and nothing about what an event means: the store +// takes an opaque line, exactly as it takes an opaque `disposition` string on chunk_status. Two +// properties are the whole point of putting it in SQLite rather than in a variable: +// +// - a number is assigned INSIDE the transaction, so a transaction that rolls back consumes no +// sequence number and the stream has no hole — and the reader treats a hole as fatal (ErrStreamGap); +// - the exact BYTES are kept, so a write to the journal that failed can be retried later and produce +// the identical line. A re-render with a fresher timestamp would read to the platform as the same +// seq with a different payload, which quarantines the projection (ErrPayloadConflict). + +// onceKeyLookup asks whether a unit has already been announced. The trailing `once_key <> ”` is not +// redundant with the equality: the uniqueness index is PARTIAL on exactly that predicate, and SQLite +// uses a partial index only when the query implies its WHERE clause SYNTACTICALLY — with a bind +// parameter it cannot prove ?1 <> ” while planning, so the bare equality plans as a full SCAN. That is +// O(rows) per announced unit, i.e. quadratic over a book, on the wave's own path. It is a constant so +// the plan can be asserted against the SHIPPING query rather than a copy of it +// (TestTheAnnounceLedgerLookupUsesItsIndex). +const onceKeyLookup = `SELECT 1 FROM events_outbox WHERE once_key = ? AND once_key <> ''` + +// EventLine is one stored journal line: its sequence number and the exact bytes, without a newline. +type EventLine struct { + Seq int64 + Line []byte +} + +// EventBuilder renders the line for the sequence number the outbox has just assigned. It runs INSIDE the +// transaction, so a render failure rolls the number back with everything else. +type EventBuilder func(seq int64) ([]byte, error) + +// EnqueueEvent assigns runID's next sequence number, renders the line and stores it — one transaction. +func (s *Store) EnqueueEvent(runID string, build EventBuilder) error { + ctx, cancel := opContext() + defer cancel() + tx, err := s.w.BeginTx(ctx, nil) + if err != nil { + return err + } + defer tx.Rollback() + if _, err := enqueueEvent(ctx, tx, runID, build); err != nil { + return err + } + return tx.Commit() +} + +// EnqueueOnce is EnqueueEvent for an event that must be announced ONCE for the life of the book, +// whatever crashes and resumes happen in between. It reports whether THIS call is the one announcing it +// (false = a ledger row already says a reader has been told) and the sequence number it took, which the +// caller passes back to MarkAnnounced once the line is actually ON THE FILE. +// +// It exists for the vocabulary's only COUNTING event. A reader folds `unit_done` by increment, so the +// engine has to decide once per unit — and "has this unit been announced" cannot be answered from the +// dispositions alone: a process that resolved a unit and died before the line reached the file leaves a +// book whose SQLite says done and whose reader was never told, and the next process, seeing the unit +// already resolved, would stay silent forever. +// +// The ledger is written AFTER the file, never with the enqueue, and the order is the whole design: what +// it records is not "this line exists" but "a reader has seen it". An unprojected row of a dead run +// carries no key, ForgetEvents drops it, and its unit is announced again by the next process — the +// at-least-once side of a boundary that has no transaction across it (D39.119 п.3), because the other +// side loses counts permanently. +func (s *Store) EnqueueOnce(runID, onceKey string, build EventBuilder) (announcing bool, seq int64, err error) { + if onceKey == "" { + return false, 0, fmt.Errorf("store: an announce-once event needs a key") + } + ctx, cancel := opContext() + defer cancel() + tx, err := s.w.BeginTx(ctx, nil) + if err != nil { + return false, 0, err + } + defer tx.Rollback() + var exists int + // See onceKeyLookup: `AND once_key <> ''` is not redundant: the uniqueness index is PARTIAL (same predicate), and SQLite + // will only use a partial index when the query implies its WHERE clause SYNTACTICALLY. With a bind + // parameter it cannot prove ?1 <> '' at planning time, so the bare equality plans as SCAN — O(rows) + // per announced unit, i.e. quadratic over a book, on the wave's own path. Spelling the predicate out + // restores SEARCH ... USING COVERING INDEX; pinned by TestTheAnnounceLedgerLookupUsesItsIndex. + switch err := tx.QueryRowContext(ctx, onceKeyLookup, onceKey).Scan(&exists); { + case errors.Is(err, sql.ErrNoRows): + case err != nil: + return false, 0, fmt.Errorf("store: read the announce-once ledger: %w", err) + default: + return false, 0, nil // already announced, by this process or by one that ran before it + } + seq, err = enqueueEvent(ctx, tx, runID, build) + if err != nil { + return false, 0, err + } + if err := tx.Commit(); err != nil { + return false, 0, err + } + return seq > 0, seq, nil +} + +// MarkAnnounced records that these lines have reached the journal, keyed so a later process knows not +// to announce them again. One transaction for the batch a projection just wrote. +func (s *Store) MarkAnnounced(runID string, keyBySeq map[int64]string) error { + if len(keyBySeq) == 0 { + return nil + } + ctx, cancel := opContext() + defer cancel() + tx, err := s.w.BeginTx(ctx, nil) + if err != nil { + return err + } + defer tx.Rollback() + for seq, key := range keyBySeq { + if _, err := tx.ExecContext(ctx, + `UPDATE events_outbox SET once_key = ? WHERE engine_run_id = ? AND seq = ?`, key, runID, seq); err != nil { + return fmt.Errorf("store: mark event %d announced: %w", seq, err) + } + } + return tx.Commit() +} + +// enqueueEvent is the shared body, inside a caller's transaction — which is also how the spend event +// joins the settle that produced it (SettleWithCheckpoint): the formula "the event line is written in +// the SAME transaction as the checkpoint", at the one place where a divergence would be about money. +// It returns the number it assigned, or 0 when the builder declined to produce a line. +func enqueueEvent(ctx context.Context, tx *sql.Tx, runID string, build EventBuilder) (int64, error) { + var next int64 + if err := tx.QueryRowContext(ctx, + `SELECT COALESCE(MAX(seq), 0) + 1 FROM events_outbox WHERE engine_run_id = ?`, runID).Scan(&next); err != nil { + return 0, fmt.Errorf("store: next event seq: %w", err) + } + line, err := build(next) + if err != nil { + return 0, err + } + if line == nil { + return 0, nil + } + if _, err := tx.ExecContext(ctx, + `INSERT INTO events_outbox (engine_run_id, seq, line) VALUES (?, ?, ?)`, + runID, next, string(line)); err != nil { + return 0, fmt.Errorf("store: enqueue event: %w", err) + } + return next, nil +} + +// PendingEvents returns at most `limit` of runID's stored lines with seq > after, in sequence order — +// the next batch the journal has not been told about. +// +// The order is dense and complete by construction, not by hope: every number is assigned by the query +// above under the single-connection write pool, so a transaction can only see MAX(seq)=N once the +// transaction that took N has committed. A caller that projects strictly in this order therefore never +// writes seq N+1 above seq N, which is the one interleaving the reader cannot survive. +// +// The LIMIT is what keeps a DEGRADED journal from becoming quadratic. While the file refuses writes the +// caller's cursor cannot advance, so the unprojected prefix grows with every event and an unbounded read +// would materialize all of it again on each one — under the emitter's mutex, on the failure path, where +// the run is least able to afford it. Bounded, each attempt costs a fixed batch and the caller drains +// the rest by looping. +func (s *Store) PendingEvents(runID string, after int64, limit int) ([]EventLine, error) { + return queryAll(s.r, `SELECT seq, line FROM events_outbox WHERE engine_run_id = ? AND seq > ? ORDER BY seq LIMIT ?`, + func(rows *sql.Rows) (EventLine, error) { + var e EventLine + var line string + err := rows.Scan(&e.Seq, &line) + e.Line = []byte(line) + return e, err + }, runID, after, limit) +} + +// EventsUsed reports whether runID has ever written a row for this book — buffered or ledgered. +// +// It answers one question the seam cannot get wrong: is this process's stream identity FRESH. The +// identity is per PROCESS by contract (the reader's key is (engine_run_id, seq), and its handshake must +// carry seq 1), but since row 102 the identity can be supplied by the caller — and a caller that reuses +// one, e.g. by exporting TM_TRACE_ID in a wrapper, would otherwise have this run continue the previous +// one's numbering and re-project its whole stream. +func (s *Store) EventsUsed(runID string) (bool, error) { + ctx, cancel := opContext() + defer cancel() + var one int + switch err := s.r.QueryRowContext(ctx, + `SELECT 1 FROM events_outbox WHERE engine_run_id = ? LIMIT 1`, runID).Scan(&one); { + case errors.Is(err, sql.ErrNoRows): + return false, nil + case err != nil: + return false, fmt.Errorf("store: check the run's event identity: %w", err) + } + return true, nil +} + +// ForgetEvents drops the BUFFERED rows of every run except runID. For those the outbox is a projection +// buffer, not an archive — the authoritative state is chunk_status/checkpoints/spend — so it is bounded +// to one run instead of growing with the number of times a book has been resumed. Called once, at open, +// before the process writes its own handshake. +// +// Announce-once rows are kept: they are the ledger that says what a reader has already been told, and +// deleting them would make every resume re-announce the whole book. They are bounded by the BOOK's size +// (one per unit per wave), not by the number of runs. +func (s *Store) ForgetEvents(runID string) error { + ctx, cancel := opContext() + defer cancel() + if _, err := s.w.ExecContext(ctx, + `DELETE FROM events_outbox WHERE engine_run_id <> ? AND once_key = ''`, runID); err != nil { + return fmt.Errorf("store: forget the previous runs' events: %w", err) + } + return nil +} diff --git a/backend/internal/store/outbox_test.go b/backend/internal/store/outbox_test.go new file mode 100644 index 00000000..ff914ff2 --- /dev/null +++ b/backend/internal/store/outbox_test.go @@ -0,0 +1,316 @@ +package store + +import ( + "errors" + "fmt" + "strings" + "testing" +) + +// outbox_test.go pins the two properties that put the run-event outbox in SQLite instead of in a +// variable: a sequence number that a rollback gives back (the reader treats a hole as fatal), and bytes +// that survive to be re-projected identically (the reader treats a changed payload at a known seq as +// corruption). + +func line(seq int64) []byte { return []byte(fmt.Sprintf(`{"seq":%d}`, seq)) } + +func enqueue(t *testing.T, s *Store, runID string, want int64) { + t.Helper() + if err := s.EnqueueEvent(runID, func(seq int64) ([]byte, error) { + if seq != want { + t.Errorf("next seq for %s = %d, want %d", runID, seq, want) + } + return line(seq), nil + }); err != nil { + t.Fatal(err) + } +} + +func TestSequenceNumbersAreDenseAndPerRun(t *testing.T) { + s, _ := openTemp(t) + enqueue(t, s, "run-a", 1) + enqueue(t, s, "run-a", 2) + // A second process numbers from 1 again in the SAME book: the ratified idempotency key is + // (engine_run_id, seq), so a resumed run is a new stream, not a continuation of the old numbers. + enqueue(t, s, "run-b", 1) + enqueue(t, s, "run-a", 3) + + got, err := s.PendingEvents("run-a", 0, 100) + if err != nil { + t.Fatal(err) + } + if len(got) != 3 { + t.Fatalf("want run-a's three lines, got %d", len(got)) + } + for i, e := range got { + if e.Seq != int64(i+1) { + t.Fatalf("run-a seq %d at position %d — the stream must be dense and ordered", e.Seq, i) + } + } +} + +func TestARolledBackEventConsumesNoSequenceNumber(t *testing.T) { + // The hole is what makes this worth a transaction: the reader's ErrStreamGap is fatal, so a number + // handed out to a render that then failed must go back. + s, _ := openTemp(t) + enqueue(t, s, "run", 1) + + boom := errors.New("render failed") + if err := s.EnqueueEvent("run", func(int64) ([]byte, error) { return nil, boom }); !errors.Is(err, boom) { + t.Fatalf("want the render error back, got %v", err) + } + enqueue(t, s, "run", 2) // NOT 3 +} + +func TestAStoredLineIsHandedBackByteForByte(t *testing.T) { + // Re-projection after a failed journal write must produce the identical line: the reader compares a + // re-read line against the sha256 it stored, and a fresher render at the same seq is a payload + // conflict, which quarantines the projection. + s, _ := openTemp(t) + original := []byte(`{"seq":1,"type":"spend","time":"2026-08-14T10:00:00Z","data":{"committed_micro_usd":7}}`) + if err := s.EnqueueEvent("run", func(int64) ([]byte, error) { return original, nil }); err != nil { + t.Fatal(err) + } + for i := 0; i < 2; i++ { + got, err := s.PendingEvents("run", 0, 100) + if err != nil { + t.Fatal(err) + } + if len(got) != 1 || string(got[0].Line) != string(original) { + t.Fatalf("read %d: %+v, want %q", i, got, original) + } + } +} + +func TestTheAnnounceLedgerRecordsDeliveryAndNotIntent(t *testing.T) { + // The order is the design: an event is ledgered only once its line is ON THE FILE. A row that was + // enqueued and never delivered leaves no ledger entry, so the next process announces it again — + // at-least-once, which is what the ratified contract asks for at a boundary no transaction spans. + s, _ := openTemp(t) + announcing, seq, err := s.EnqueueOnce("run", "unit:draft:1:0", func(seq int64) ([]byte, error) { return line(seq), nil }) + if err != nil || !announcing || seq != 1 { + t.Fatalf("first announcement: announcing=%v seq=%d err=%v", announcing, seq, err) + } + // Not yet delivered ⇒ not yet ledgered. + if err := s.MarkAnnounced("run", map[int64]string{seq: "unit:draft:1:0"}); err != nil { + t.Fatal(err) + } + announcing, _, err = s.EnqueueOnce("run", "unit:draft:1:0", func(seq int64) ([]byte, error) { return line(seq), nil }) + if err != nil { + t.Fatal(err) + } + if announcing { + t.Fatal("a delivered announcement must not be made twice — a reader increments on it") + } + // A DIFFERENT unit is unaffected, and numbering continues where it left off. + announcing, seq, err = s.EnqueueOnce("run", "unit:edit:1:0", func(seq int64) ([]byte, error) { return line(seq), nil }) + if err != nil || !announcing || seq != 2 { + t.Fatalf("second unit: announcing=%v seq=%d err=%v", announcing, seq, err) + } +} + +func TestAnUndeliveredAnnouncementIsRetriedByTheNextRunAndADeliveredOneIsNot(t *testing.T) { + // The crash case, at the storage layer: one unit's line reached the file, another's did not. After the + // next process clears the buffer, the delivered one is still ledgered and the undelivered one is free + // to be announced again. + s, _ := openTemp(t) + _, delivered, err := s.EnqueueOnce("dead-run", "unit:draft:1:0", func(seq int64) ([]byte, error) { return line(seq), nil }) + if err != nil { + t.Fatal(err) + } + if _, _, err := s.EnqueueOnce("dead-run", "unit:draft:2:0", func(seq int64) ([]byte, error) { return line(seq), nil }); err != nil { + t.Fatal(err) + } + if err := s.MarkAnnounced("dead-run", map[int64]string{delivered: "unit:draft:1:0"}); err != nil { + t.Fatal(err) + } + + if err := s.ForgetEvents("live-run"); err != nil { + t.Fatal(err) + } + if announcing, _, err := s.EnqueueOnce("live-run", "unit:draft:1:0", func(seq int64) ([]byte, error) { return line(seq), nil }); err != nil || announcing { + t.Fatalf("the delivered unit must stay silent: announcing=%v err=%v", announcing, err) + } + if announcing, _, err := s.EnqueueOnce("live-run", "unit:draft:2:0", func(seq int64) ([]byte, error) { return line(seq), nil }); err != nil || !announcing { + t.Fatalf("the unit whose line never landed must be announced again: announcing=%v err=%v", announcing, err) + } +} + +func TestPendingEventsStartAfterTheCursor(t *testing.T) { + s, _ := openTemp(t) + for i := int64(1); i <= 4; i++ { + enqueue(t, s, "run", i) + } + got, err := s.PendingEvents("run", 2, 100) + if err != nil { + t.Fatal(err) + } + if len(got) != 2 || got[0].Seq != 3 || got[1].Seq != 4 { + t.Fatalf("want seq 3,4 after the cursor at 2, got %+v", got) + } +} + +func TestForgetEventsKeepsOnlyTheCurrentRun(t *testing.T) { + // The outbox is a projection buffer, not an archive — otherwise a book resumed a hundred times keeps + // a hundred runs' worth of lines nothing will ever read. + s, _ := openTemp(t) + enqueue(t, s, "old", 1) + enqueue(t, s, "new", 1) + if err := s.ForgetEvents("new"); err != nil { + t.Fatal(err) + } + if got, err := s.PendingEvents("old", 0, 100); err != nil || len(got) != 0 { + t.Fatalf("the previous run's lines must be gone, got %+v (%v)", got, err) + } + if got, err := s.PendingEvents("new", 0, 100); err != nil || len(got) != 1 { + t.Fatalf("this run's lines must survive, got %+v (%v)", got, err) + } +} + +func TestTheSpendEventIsCommittedByTheSettleThatEarnedIt(t *testing.T) { + s, _ := openTemp(t) + job := mustSnapshotAndJob(t, s) + caps := Ceilings{BookUSD: 1.0, DayUSD: 2.0} + res, verdict, err := s.Reserve("book", 0.10, caps) + if err != nil || verdict != ReserveOK { + t.Fatalf("reserve: %v %v", verdict, err) + } + cp := Checkpoint{RequestHash: "h1", JobID: job.ID, Stage: "draft", Role: "translator", + ModelRequested: "m", ModelActual: "m", ResponseText: "текст", UsageJSON: "{}", CostUSD: 0.04} + + var sawCommitted float64 + spend := &SpendLine{RunID: "run", Line: func(seq int64, committedUSD float64) ([]byte, error) { + sawCommitted = committedUSD + return line(seq), nil + }} + if err := s.SettleWithCheckpoint(res, 0.04, cp, spend); err != nil { + t.Fatal(err) + } + // The figure is read INSIDE the transaction, AFTER the debit: an event that reported the pre-settle + // total would under-report the book's spend by exactly the call it is announcing. + if sawCommitted != 0.04 { + t.Fatalf("the event saw committed=%v, want the post-settle 0.04", sawCommitted) + } + if got, err := s.PendingEvents("run", 0, 100); err != nil || len(got) != 1 { + t.Fatalf("the settle must have booked its event, got %+v (%v)", got, err) + } +} + +func TestASettleThatRollsBackLeavesNeitherCheckpointNorEvent(t *testing.T) { + // This is the whole claim of "the event line is written in the SAME transaction as the checkpoint": + // the two cannot disagree, in either direction. (The driver never lets a render failure reach here — + // losing a paid checkpoint to protect an indicator would be the wrong way round — but the storage + // layer's guarantee is what that policy rests on.) + s, _ := openTemp(t) + job := mustSnapshotAndJob(t, s) + res, _, err := s.Reserve("book", 0.10, Ceilings{BookUSD: 1.0}) + if err != nil { + t.Fatal(err) + } + cp := Checkpoint{RequestHash: "h-doomed", JobID: job.ID, Stage: "draft", Role: "translator", + ModelRequested: "m", ModelActual: "m", ResponseText: "текст", UsageJSON: "{}", CostUSD: 0.04} + + boom := errors.New("render failed") + spend := &SpendLine{RunID: "run", Line: func(int64, float64) ([]byte, error) { return nil, boom }} + if err := s.SettleWithCheckpoint(res, 0.04, cp, spend); !errors.Is(err, boom) { + t.Fatalf("want the render error, got %v", err) + } + got, err := s.GetCheckpoint("h-doomed") + if err != nil { + t.Fatal(err) + } + if got != nil { + t.Fatal("the checkpoint must have rolled back with the event") + } + committed, _, err := s.SpentUSD("book") + if err != nil { + t.Fatal(err) + } + if committed != 0 { + t.Fatalf("the debit must have rolled back too, committed=%v", committed) + } + if lines, err := s.PendingEvents("run", 0, 100); err != nil || len(lines) != 0 { + t.Fatalf("no event may survive the transaction that failed, got %+v (%v)", lines, err) + } +} + +func TestADuplicateSettleBooksNoSecondSpendEvent(t *testing.T) { + // A duplicate settle books no money, so it must announce none: the counter is cumulative and a second + // line at the same total is noise the reader would still have to hash and store. + s, _ := openTemp(t) + job := mustSnapshotAndJob(t, s) + cp := Checkpoint{RequestHash: "h1", JobID: job.ID, Stage: "draft", Role: "translator", + ModelRequested: "m", ModelActual: "m", ResponseText: "текст", UsageJSON: "{}", CostUSD: 0.04} + spend := &SpendLine{RunID: "run", Line: func(seq int64, _ float64) ([]byte, error) { return line(seq), nil }} + for i := 0; i < 2; i++ { + res, _, err := s.Reserve("book", 0.10, Ceilings{BookUSD: 1.0}) + if err != nil { + t.Fatal(err) + } + if err := s.SettleWithCheckpoint(res, 0.04, cp, spend); err != nil { + t.Fatal(err) + } + } + lines, err := s.PendingEvents("run", 0, 100) + if err != nil { + t.Fatal(err) + } + if len(lines) != 1 { + t.Fatalf("want one spend event for one billed call, got %d", len(lines)) + } +} + +func TestTheAnnounceLedgerLookupUsesItsIndex(t *testing.T) { + // The uniqueness index on once_key is PARTIAL, and SQLite uses a partial index only when the query + // implies its predicate SYNTACTICALLY — with a bind parameter it cannot prove ?1 <> '' while planning. + // The bare equality therefore plans as a full SCAN, once per announced unit: quadratic over a book, on + // the wave's own path. Reproduced on modernc.org/sqlite before the fix; this is the pin. + s, _ := openTemp(t) + rows, err := s.r.Query("EXPLAIN QUERY PLAN "+onceKeyLookup, "unit:x:1:0") + if err != nil { + t.Fatal(err) + } + defer rows.Close() + plan := "" + for rows.Next() { + var a, b, c int + var detail string + if err := rows.Scan(&a, &b, &c, &detail); err != nil { + t.Fatal(err) + } + plan += detail + "\n" + } + if err := rows.Err(); err != nil { + t.Fatal(err) + } + if !strings.Contains(plan, "USING COVERING INDEX events_outbox_once") { + t.Fatalf("the announce-ledger lookup does not use its index:\n%s", plan) + } + if strings.Contains(plan, "SCAN events_outbox") { + t.Fatalf("the announce-ledger lookup scans the table:\n%s", plan) + } +} + +func TestPendingEventsReturnsAtMostOneBatch(t *testing.T) { + // The bound is what keeps a DEGRADED journal from being quadratic: the caller's cursor cannot advance + // while the file refuses writes, so an unbounded read would re-materialize the whole growing prefix on + // every event, under the emitter's mutex. + s, _ := openTemp(t) + for i := int64(1); i <= 10; i++ { + enqueue(t, s, "run", i) + } + got, err := s.PendingEvents("run", 0, 4) + if err != nil { + t.Fatal(err) + } + if len(got) != 4 || got[0].Seq != 1 || got[3].Seq != 4 { + t.Fatalf("want the first four, got %d rows starting at %d", len(got), got[0].Seq) + } + rest, err := s.PendingEvents("run", got[3].Seq, 100) + if err != nil { + t.Fatal(err) + } + if len(rest) != 6 || rest[0].Seq != 5 { + t.Fatalf("the next read must continue at 5 and drain, got %d rows", len(rest)) + } +} diff --git a/backend/internal/store/store.go b/backend/internal/store/store.go index 885c5542..2357c52b 100644 --- a/backend/internal/store/store.go +++ b/backend/internal/store/store.go @@ -16,6 +16,7 @@ package store import ( "context" "database/sql" + "errors" "fmt" "net/url" "os" @@ -158,6 +159,12 @@ func (s *Store) Close() error { return err2 } +// ErrLocked is "another process owns this project right now". It is a distinct sentinel because it is +// the one open failure that is neither the caller's fault nor a broken project: the right answer is to +// come back later, and an automated caller that cannot tell it from "this book is corrupt" acts on the +// book instead of on the clock (PD-196). +var ErrLocked = errors.New("store: project database is in use by another tmctl process") + // acquireLock takes a non-blocking exclusive flock. Kernel releases it on // process death (kill -9 included), so a crashed run never wedges the // project. @@ -168,7 +175,7 @@ func acquireLock(path string) (*os.File, error) { } if err := syscall.Flock(int(f.Fd()), syscall.LOCK_EX|syscall.LOCK_NB); err != nil { f.Close() - return nil, fmt.Errorf("store: project database is in use by another tmctl process (lock %s): %w", path, err) + return nil, fmt.Errorf("%w (lock %s): %w", ErrLocked, path, err) } return f, nil } diff --git a/backend/internal/store/store_test.go b/backend/internal/store/store_test.go index f64b1d13..ebe2aaff 100644 --- a/backend/internal/store/store_test.go +++ b/backend/internal/store/store_test.go @@ -45,7 +45,7 @@ func TestReserveSettleLifecycle(t *testing.T) { cp := Checkpoint{RequestHash: "h1", JobID: job.ID, Stage: "draft", Role: "translator", ModelRequested: "m", ModelActual: "m", ResponseText: "текст", UsageJSON: "{}", CostUSD: 0.04} - if err := s.SettleWithCheckpoint(res, 0.04, cp); err != nil { + if err := s.SettleWithCheckpoint(res, 0.04, cp, nil); err != nil { t.Fatal(err) } committed, reserved, _ = s.SpentUSD("book") @@ -64,7 +64,7 @@ func TestReserveSettleLifecycle(t *testing.T) { if err != nil || verdict != ReserveOK { t.Fatalf("reserve2: %v %v", verdict, err) } - if err := s.SettleWithCheckpoint(res2, 0.04, cp); err != nil { + if err := s.SettleWithCheckpoint(res2, 0.04, cp, nil); err != nil { t.Fatal(err) } committed, reserved, _ = s.SpentUSD("book")