package books import ( "bytes" "context" "errors" "fmt" "log/slog" "strings" "sync" "testing" "time" "textmachine/platform/internal/jobs" ) // waitUntil polls a condition and fails with what it last saw, so a test that never contended reads // as a test that never contended rather than as a passing one. func waitUntil(t *testing.T, what string, saw func() string, ok func() bool) { t.Helper() deadline := time.Now().Add(10 * time.Second) for time.Now().Before(deadline) { if ok() { return } time.Sleep(time.Millisecond) } t.Fatalf("%s did not happen within 10s; last reading: %s", what, saw()) } // upload runs one intake and reports what it answered. func (f *fixture) uploadAsync(name string) <-chan error { done := make(chan error, 1) go func() { _, err := f.svc.Accept(f.ctx, Intake{UserID: "u1", SourceLang: "zh", TargetLang: "ru", Filename: name, File: strings.NewReader("первая глава\fвторая глава")}) done <- err }() return done } // The host never runs more cuts at once than its cap allows, and this is asserted under LOAD rather // than read off the code: six uploads arrive together at a cap of two. // // ⚠ The control value is what makes the assertion mean anything. "The peak never exceeded two" is // also true of a fixture where two uploads never managed to overlap at all, so the test first waits // until FOUR cuts are provably queued for a slot — that reading comes from the cap's own counters, // which is the number an operator reads too. func TestTheHostRunsNoMoreCutsAtOnceThanItsCapAllows(t *testing.T) { const slots, uploads = 2, 6 f := newFixture(t) templated(t, f) f.svc.Cfg.MaxCuts = slots var mu sync.Mutex inFlight, peak := 0, 0 hold := make(chan struct{}) f.engine.onManifest = func(context.Context) { mu.Lock() inFlight++ if inFlight > peak { peak = inFlight } mu.Unlock() <-hold mu.Lock() inFlight-- mu.Unlock() } done := make([]<-chan error, uploads) for i := range done { done[i] = f.uploadAsync("book.txt") } waitUntil(t, "four of six uploads queued for one of two cut slots", func() string { return fmt.Sprintf("%+v", f.svc.CutCapacity()) }, func() bool { return f.svc.CutCapacity().Waiting == uploads-slots }) // Only now: with the line proven, whatever the peak turns out to be is a fact about the cap. close(hold) for _, ch := range done { if err := <-ch; err != nil { t.Errorf("an upload under the cap failed: %v", err) } } if peak != slots { t.Errorf("%d cuts ran at once at a cap of %d", peak, slots) } if c := f.svc.CutCapacity(); c.Waited < uploads-slots { t.Errorf("the cap counted %d waits for %d uploads over %d slots: an operator would not see the saturation", c.Waited, uploads, slots) } if c := f.svc.CutCapacity(); c.InFlight != 0 || c.Waiting != 0 { t.Errorf("after every upload finished the cap still reads in-flight %d waiting %d: a slot was not given back", c.InFlight, c.Waiting) } } // The same load with room for all of it reaches all of it at once. // // Without this the test above would also pass on a fixture that never got two cuts to overlap — the // vacuous shape that made a whole class of this zone's assertions invisible (D39.208 §5). Here the // cap is the ONLY thing changed between the two, so the difference in the peak is the cap's doing. func TestWithRoomForEveryCutTheHostRunsThemAllAtOnce(t *testing.T) { const uploads = 6 f := newFixture(t) templated(t, f) f.svc.Cfg.MaxCuts = uploads var mu sync.Mutex inFlight, peak := 0, 0 hold := make(chan struct{}) f.engine.onManifest = func(context.Context) { mu.Lock() inFlight++ if inFlight > peak { peak = inFlight } mu.Unlock() <-hold mu.Lock() inFlight-- mu.Unlock() } done := make([]<-chan error, uploads) for i := range done { done[i] = f.uploadAsync("book.txt") } waitUntil(t, "all six uploads cutting at once", func() string { return fmt.Sprintf("%+v", f.svc.CutCapacity()) }, func() bool { return f.svc.CutCapacity().InFlight == uploads }) close(hold) for _, ch := range done { <-ch } if peak != uploads { t.Errorf("only %d of %d cuts ran at once with a slot for each: the load never contended and the cap's test proves nothing", peak, uploads) } } // An upload that runs out of budget waiting for a slot is ACCEPTED `parsing` and finished by the // queue — never refused. A busy host must not cost a user the upload they already made. // // This is also the fixture where the cap's log line MUST sound: a message pinned only by its silence // says nothing about the case where it is wrong. func TestAnUploadThatRunsOutOfBudgetWaitingForASlotIsAcceptedRatherThanRefused(t *testing.T) { f := newFixture(t) templated(t, f) f.svc.Cfg.MaxCuts = 1 // Short enough that the second upload's whole walk expires while the first holds the only slot, // and different from every other budget in this fixture so the two cannot be confused. // THREE distinct numbers, and the third one is load-bearing rather than tidy: the reserve a cut // must leave for the writes after it is three write budgets, so a fixture that shortens only the // walk leaves no room for a cut at all and models nothing (see stepLeaving). f.svc.uploadSettle = 300 * time.Millisecond f.svc.writeBudget = 20 * time.Millisecond var buf bytes.Buffer f.svc.Log = slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo})) hold := make(chan struct{}) first := make(chan struct{}) var once sync.Once f.engine.onManifest = func(context.Context) { once.Do(func() { close(first) }) <-hold } held := f.uploadAsync("held.txt") <-first waitUntil(t, "the only slot taken", func() string { return fmt.Sprintf("%+v", f.svc.CutCapacity()) }, func() bool { return f.svc.CutCapacity().InFlight == 1 }) book, err := f.svc.Accept(f.ctx, Intake{UserID: "u1", SourceLang: "zh", TargetLang: "ru", Filename: "waited.txt", File: strings.NewReader("первая глава\fвторая глава")}) if err != nil { t.Fatalf("an upload that met a busy host was refused: %v", err) } if book.Status != "parsing" { t.Errorf("an upload that met a busy host is %q, want `parsing` with the queue to finish it", book.Status) } if c := f.svc.CutCapacity(); c.GaveUp != 1 { t.Errorf("the cap counted %d cuts that ran out of budget waiting, want 1", c.GaveUp) } if got := buf.String(); !strings.Contains(got, "the engine was not asked") || !strings.Contains(got, ReasonHostAtCapacity) { t.Errorf("nothing in the log says the engine was not asked and why (%q), so an operator sees latency and no cause; log: %s", ReasonHostAtCapacity, got) } close(hold) <-held // And the same message is SILENT on a host with room: a line that is always there is a line that // tells an operator nothing. f.engine.onManifest = nil buf.Reset() f.svc.uploadSettle = 0 if _, err := f.svc.Accept(f.ctx, Intake{UserID: "u1", SourceLang: "zh", TargetLang: "ru", Filename: "free.txt", File: strings.NewReader("первая глава\fвторая глава")}); err != nil { t.Fatalf("an upload on an idle host failed: %v", err) } if got := buf.String(); strings.Contains(got, ReasonHostAtCapacity) || strings.Contains(got, "waited for one of the host's cut slots") { t.Errorf("an idle host still logged about its cap: %s", got) } } // A queued pass that cannot cut gives the book back and spends NOTHING, and the two reasons it can // have are told apart: the host is at its cap, or what is left of the pass is shorter than a cut. // // Both matter, and the second is what makes the first safe. Waiting for a slot spends the caller's // budget, so without a reserve a pass could win a slot with seconds left, hand the engine those // seconds, and have the killed process read back as a fault of the DEPLOYMENT — which DOES spend an // attempt, and five of those delete the user's file. func TestAQueuedParseThatCannotCutSpendsNothingAndGivesTheBookBack(t *testing.T) { f := newFixture(t) f.svc.Cfg.MaxCuts = 1 // Two books that reached `parsing` without any engine call: with no template configured the // intake's own pass stops before the engine is asked, which is the state the queue picks up. held := f.accept(t, "held.txt", "первая глава\fвторая глава") waiting := f.accept(t, "waiting.txt", "первая глава\fвторая глава") f.provision(t, held) f.provision(t, waiting) hold, running := make(chan struct{}), make(chan struct{}) var once sync.Once f.engine.onManifest = func(context.Context) { once.Do(func() { close(running) }) <-hold } parsed := make(chan error, 1) go func() { parsed <- f.svc.Parse(f.ctx, held.ID) }() <-running for _, c := range []struct { what string budget time.Duration want error }{ // Enough left that a cut would be worth starting, so this pass WAITS — and the wait is bounded // by what it must leave the engine, which is why it ends in about a second rather than in the // whole budget. {"the host is at its cap", CutBudget + 1500*time.Millisecond, ErrHostAtCutCapacity}, // Less left than a cut needs, so no slot is even waited for. {"there is no time left for a cut", 300 * time.Millisecond, ErrNoTimeToCut}, } { before, _ := f.parseState(t, waiting.ID) ctx, cancel := context.WithTimeout(f.ctx, c.budget) err := f.svc.Parse(ctx, waiting.ID) cancel() if !errors.Is(err, c.want) { t.Fatalf("%s: the pass answered %v, want %v", c.what, err, c.want) } if !errors.Is(err, jobs.ErrTryAgainLater) { t.Errorf("%s: the error does not tell the queue to bring the job back, so the single attempt is spent and the book waits out the sweep's grace", c.what) } after, claimed := f.parseState(t, waiting.ID) if after != before { t.Errorf("%s: a pass that never asked the engine spent the book's budget: attempts %d → %d", c.what, before, after) } if claimed { t.Errorf("%s: a pass that established nothing kept the claim, so the next pass waits out the whole grace for it", c.what) } } close(hold) if err := <-parsed; err != nil { t.Errorf("the parse that held the slot failed: %v", err) } } // parseState reads how much of a book's attempt budget is spent and whether a claim stands on it. func (f *fixture) parseState(t *testing.T, id string) (attempts int, claimed bool) { t.Helper() var stamp *time.Time if err := f.store.Pool().QueryRow(f.ctx, `select parse_attempts, parse_started_at from books where id = $1`, id).Scan(&attempts, &stamp); err != nil { t.Fatal(err) } return attempts, stamp != nil } // The two ways an intake gets no parse claim are told apart in the log, because one of them needs a // human and the other is how the walk is meant to go. // // Both messages are asserted in a fixture where each MUST sound, and each is asserted ABSENT from the // other's: a line pinned only by its silence says nothing about the case where it is wrong, and these // two are one `if` apart — the shape that made this branch silent about a database it could not reach // for a whole claim grace. func TestTheIntakeTellsALostRaceApartFromAStoreItCouldNotAsk(t *testing.T) { f := newFixture(t) var buf bytes.Buffer f.svc.Log = slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo})) // No template, so the intake's own pass reaches no verdict: the book is left `parsing` with its // claim given back, which is the state another pass can take it in. book := f.accept(t, "蛊真人.txt", "первая глава") // (1) Somebody else holds the claim. The ordinary race, and the only other claimant an upload can // meet on this route: no job was enqueued for a book the intake cuts itself. if _, err := f.store.ClaimParse(f.ctx, book.ID, f.now, f.now.Add(-ClaimGrace)); err != nil { t.Fatal(err) } buf.Reset() f.svc.Cfg.BookTemplate = "" // still no verdict to reach; what is asserted is which line is written walk, cancel := f.svc.walk(f.ctx) defer cancel() if got := f.svc.cutNow(walk, book); got.err != nil { t.Fatalf("losing the race was answered as a verdict about the file: %v", got.err) } lost := buf.String() if !strings.Contains(lost, "did not get the parse claim") { t.Errorf("losing the race said nothing: %s", lost) } if strings.Contains(lost, "could not be taken") { t.Errorf("an ordinary race was reported as a store that could not be asked: %s", lost) } if strings.Contains(lost, `"level":"ERROR"`) { t.Errorf("an ordinary race was logged at ERROR, which is a page for an operator who has nothing to do: %s", lost) } // (2) The store could not be ASKED at all — here because the walk this cut belongs to is already // over, which is what a request whose whole tail is spent looks like from inside cutNow. buf.Reset() f.svc.uploadSettle = time.Nanosecond spent, cancelSpent := f.svc.walk(f.ctx) defer cancelSpent() <-spent.Done() if got := f.svc.cutNow(spent, book); got.err != nil { t.Fatalf("a store that could not be asked was answered as a verdict about the file: %v", got.err) } unreachable := buf.String() if !strings.Contains(unreachable, "could not be taken") { t.Errorf("a claim that could not be asked for said nothing, so the book sits `parsing` with no job and nobody knows: %s", unreachable) } if !strings.Contains(unreachable, `"level":"ERROR"`) { t.Errorf("a store that could not be asked was not logged at ERROR: %s", unreachable) } if strings.Contains(unreachable, "did not get the parse claim") { t.Errorf("a store that could not be asked was reported as an ordinary race, which needs no operator: %s", unreachable) } } // A cut that WAITS and then gets a slot says so, and a cut that never waited does not. // // The line was asserted only by its absence before, which is the vacuous half: a message pinned by // silence alone is a message nothing defends where it matters. Here the waiter actually wins its // slot — the holder lets go — so the line is one the fixture FORCES. func TestACutThatWaitedAndThenGotASlotSaysSo(t *testing.T) { f := newFixture(t) templated(t, f) f.svc.Cfg.MaxCuts = 1 var buf bytes.Buffer f.svc.Log = slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo})) hold, running := make(chan struct{}), make(chan struct{}) var once sync.Once f.engine.onManifest = func(context.Context) { once.Do(func() { close(running) }) <-hold } first := f.uploadAsync("held.txt") <-running second := f.uploadAsync("waited.txt") waitUntil(t, "the second upload queued for the only slot", func() string { return fmt.Sprintf("%+v", f.svc.CutCapacity()) }, func() bool { return f.svc.CutCapacity().Waiting == 1 }) // The holder lets go, so the waiter WINS rather than times out — the case the earlier fixture // never reached, because there the waiter always ran out of budget. close(hold) if err := <-first; err != nil { t.Fatalf("the upload that held the slot failed: %v", err) } if err := <-second; err != nil { t.Fatalf("the upload that waited for a slot failed: %v", err) } if got := buf.String(); !strings.Contains(got, "a cut waited for one of the host's cut slots") { t.Errorf("a cut that queued for a slot and got one said nothing, so an operator reading latency has no cause to read: %s", got) } // And an idle host does not say it: a line that is always there tells nobody anything. buf.Reset() f.engine.onManifest = nil if _, err := f.svc.Accept(f.ctx, Intake{UserID: "u1", SourceLang: "zh", TargetLang: "ru", Filename: "free.txt", File: strings.NewReader("первая глава\fвторая глава")}); err != nil { t.Fatalf("an upload on an idle host failed: %v", err) } if got := buf.String(); strings.Contains(got, "waited for one of the host's cut slots") { t.Errorf("an upload that never queued still reported a wait: %s", got) } } // A deployment with no engine hands the book to the queue in the row's OWN transaction, and runs no // cut. This is the false branch of cutsItsOwnUploads, which nothing exercised: with every fixture // carrying an engine, the predicate could be replaced by `true` and the whole battery stayed green. func TestADeploymentWithNoEngineQueuesTheBookWithTheRowAndCutsNothing(t *testing.T) { f := newFixture(t) templated(t, f) queue := &countingQueue{} f.svc.Queue = queue f.svc.Engine = nil var buf bytes.Buffer f.svc.Log = slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo})) book := f.accept(t, "蛊真人.txt", "первая глава\fвторая глава") if book.Status != "parsing" { t.Errorf("a deployment that cannot cut answered %q, want `parsing` for the queue to finish", book.Status) } if queue.n != 1 { t.Errorf("the queue was handed %d jobs, want the one that goes in with the row: nothing else enqueues on this path", queue.n) } // ⚠ Counting jobs CANNOT tell the two apart, and that is why the log is read instead. With the // predicate broken to «this deployment always cuts», the cut is attempted, stops at «no engine is // configured», reaches no verdict — and its release enqueues the very same one job. The observable // difference is that a cut was ATTEMPTED at all. if got := buf.String(); strings.Contains(got, "the intake's own cut was not conclusive") { t.Errorf("a deployment with no engine attempted a cut anyway: %s", got) } if _, claimed := f.parseState(t, book.ID); claimed { t.Error("a book nobody cut carries a parse claim") } // The positive control, in the same fixture: an engine that reaches no verdict DOES take the path // above and DOES say so. Without it the assertion is satisfied by a log that never says anything. buf.Reset() f.svc.Engine = f.engine f.svc.Cfg.BookTemplate = "" // no configuration to cut against: the pass reaches no verdict second := f.accept(t, "второй.txt", "первая глава\fвторая глава") if got := buf.String(); !strings.Contains(got, "the intake's own cut was not conclusive") { t.Errorf("a deployment WITH an engine did not report its inconclusive cut, so the assertion above proves nothing: %s", got) } if queue.n != 2 { t.Errorf("the second book got %d jobs in total, want one of its own", queue.n) } _ = second } // The reason an unfinished intake carries is the one an operator greps for. Its VALUE is asserted, // not just its presence: the constant could be renamed to anything and every other test stayed green. func TestAnIntakeStoppedByTheCapNamesTheReasonInWordsAnOperatorCanFind(t *testing.T) { f := newFixture(t) templated(t, f) f.svc.Cfg.MaxCuts = 1 f.svc.uploadSettle = 300 * time.Millisecond f.svc.writeBudget = 20 * time.Millisecond // the reserve follows it — see the fixture above var buf bytes.Buffer f.svc.Log = slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo})) hold, running := make(chan struct{}), make(chan struct{}) var once sync.Once f.engine.onManifest = func(context.Context) { once.Do(func() { close(running) }) <-hold } held := f.uploadAsync("held.txt") <-running if _, err := f.svc.Accept(f.ctx, Intake{UserID: "u1", SourceLang: "zh", TargetLang: "ru", Filename: "waited.txt", File: strings.NewReader("первая глава\fвторая глава")}); err != nil { t.Fatalf("an upload that met a busy host was refused: %v", err) } // The LITERAL and not the constant. Asserting `strings.Contains(log, ReasonHostAtCapacity)` renames // both sides at once and passes at any value — the tautology this assertion replaced, and the // mutation that survived it. What is being defended is a word an operator's runbook and grep can // hold still, so the word is written out here. const word = "host_at_cut_capacity" if ReasonHostAtCapacity != word { t.Errorf("the reason is %q, want the stable %q that operators and the runbook grep for", ReasonHostAtCapacity, word) } if got := buf.String(); !strings.Contains(got, word) { t.Errorf("the pass that did not cut carries no %q anywhere an operator would grep: %s", word, got) } close(hold) <-held } // An upload the host had no room to cut still leaves the book with somebody to finish it: the claim // goes back and the job goes in, in the one transaction. // // ⛔ This is what the reserve buys, and it is the assertion the first edition of these tests left out // — it checked only that the upload was ACCEPTED, which is true either way. Without the reserve the // release is the step the spent walk truncates, and then the book sits `parsing`, claimed, with no // job: nothing comes back for it until the backstop sweep's grace runs out, twenty minutes later, // and every surface says the upload went fine. func TestAnUploadTheHostCouldNotCutStillLeavesSomebodyToFinishTheBook(t *testing.T) { f := newFixture(t) templated(t, f) queue := &countingQueue{} f.svc.Queue = queue f.svc.Cfg.MaxCuts = 1 f.svc.uploadSettle = 300 * time.Millisecond f.svc.writeBudget = 20 * time.Millisecond hold, running := make(chan struct{}), make(chan struct{}) var once sync.Once f.engine.onManifest = func(context.Context) { once.Do(func() { close(running) }) <-hold } held := f.uploadAsync("held.txt") <-running book, err := f.svc.Accept(f.ctx, Intake{UserID: "u1", SourceLang: "zh", TargetLang: "ru", Filename: "waited.txt", File: strings.NewReader("первая глава\fвторая глава")}) if err != nil { t.Fatalf("an upload that met a busy host was refused: %v", err) } if book.Status != "parsing" { t.Fatalf("the upload is %q, want `parsing`", book.Status) } attempts, claimed := f.parseState(t, book.ID) if claimed { t.Error("the intake's parse claim was NOT given back: the book sits `parsing`, claimed, with nobody to finish it until the claim grace runs out") } if queue.n != 1 { t.Errorf("the queue was handed %d jobs for a book the intake could not cut, want the one that finishes it", queue.n) } if attempts != 0 { t.Errorf("a book the engine was never asked about has spent %d attempts of its budget", attempts) } close(hold) <-held } // An upload whose walk cannot hold a cut AT ALL says so in those words, and still leaves the book to // the queue. // // The branch is reachable only when what remains of the walk is shorter than the writes that must // follow a cut, which no other fixture produces — and it is the branch that used to arrive as «the // parse claim could not be taken», a diagnosis pointing at the store for a walk that had simply run // out. A message that names the wrong thing is worse than none: it sends whoever reads it to the // database. func TestAnUploadWithNoRoomLeftForACutSaysThatAndHandsTheBookOver(t *testing.T) { f := newFixture(t) templated(t, f) queue := &countingQueue{} f.svc.Queue = queue // The walk is SHORTER than the reserve three writes need, so no cut can be started at all. f.svc.writeBudget = 25 * time.Millisecond f.svc.uploadSettle = 60 * time.Millisecond var buf bytes.Buffer f.svc.Log = slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo})) book, err := f.svc.Accept(f.ctx, Intake{UserID: "u1", SourceLang: "zh", TargetLang: "ru", Filename: "late.txt", File: strings.NewReader("первая глава\fвторая глава")}) if err != nil { t.Fatalf("an upload with no room left for a cut was refused: %v", err) } if book.Status != "parsing" { t.Errorf("the upload is %q, want `parsing` for the queue to finish", book.Status) } if f.engine.called() != 0 { t.Errorf("a cut was started with no room for it (%d calls)", f.engine.called()) } got := buf.String() if !strings.Contains(got, ReasonNoTimeToCut) { t.Errorf("the pass does not say WHY it did not cut (%q): %s", ReasonNoTimeToCut, got) } if strings.Contains(got, "the parse claim could not be taken") { t.Errorf("a walk that ran out was reported as a store that could not be asked, which sends an operator to the database: %s", got) } if queue.n != 1 { t.Errorf("the queue was handed %d jobs, want the one that finishes a book nobody cut", queue.n) } if _, claimed := f.parseState(t, book.ID); claimed { t.Error("the claim was not given back, so nothing comes for the book until the grace runs out") } }