textmachine/platform/internal/runs/reconcile.go

package runs

import (
	"context"
	"errors"
	"fmt"
	"path/filepath"
	"time"

	"textmachine/platform/internal/ingest"
	"textmachine/platform/internal/money"
	"textmachine/platform/internal/pgstore"
	"textmachine/platform/internal/runner"
)

// spawnGrace is how long after an attempt was admitted the reconciler still believes systemd simply
// has not got to it. Under it, "no unit and no marker" means "not started yet"; over it, the same
// two facts mean the unit died without being able to say so — which is what a reboot looks like,
// since a transient unit does not survive one and its ExecStopPost never runs.
const spawnGrace = 60 * time.Second

// Sweep reconciles every run the database believes is live, then settles the money of every run
// that finished without it.
//
// It runs on a ticker AND at boot, and the boot pass is not a special case: the same reading of the
// same three sources — Postgres, the book's journal, the exit marker — restarts what a reboot
// interrupted (unified backlog row 138). systemd is asked only "is this unit still there", and its
// answer is evidence rather than truth (research/25 §Опс).
//
// One run's failure never stops the sweep: these are independent runs belonging to independent
// accounts, and a book whose directory an operator moved must not freeze everyone else's progress.
func (s *Service) Sweep(ctx context.Context) error {
	live, err := s.Store.ListLiveRuns(ctx)
	if err != nil {
		return err
	}
	for _, l := range live {
		if err := ctx.Err(); err != nil {
			return err
		}
		if err := s.reconcile(ctx, l); err != nil {
			s.log().ErrorContext(ctx, "run could not be reconciled", "run", l.RunID, "err", err)
		}
	}
	unsettled, err := s.Store.UnsettledRuns(ctx)
	if err != nil {
		return err
	}
	for _, u := range unsettled {
		if err := ctx.Err(); err != nil {
			return err
		}
		if err := s.settle(ctx, u); err != nil {
			s.log().ErrorContext(ctx, "run could not be settled", "run", u.RunID, "err", err)
		}
	}
	return nil
}

func (s *Service) reconcile(ctx context.Context, l pgstore.LiveRun) error {
	// The cursor this call MOVED, not the one the sweep's snapshot was taken with. Everything below
	// that asks "has the stream said anything" has to ask about now: the snapshot is read before the
	// journal is drained, so a run whose first events arrive during this very sweep still looks
	// silent in it — and the repair channel would then be woken for a run that had just spoken.
	// Measured end to end, not reasoned about: a live run showed "edit 10/10" from a status report
	// seconds after its journal said "edit 0/10".
	// ⚠ A journal that cannot be read stops the PROJECTION and nothing else. It used to abort the
	// whole reconcile before the exit marker was even looked at, so one malformed line left a run
	// "translating" forever with its hold reserved — the engine long gone, the marker on disk, and
	// every sweep failing at the same byte. The lifecycle is decided from the marker and from
	// systemd; the journal only decides how fresh the numbers are.
	seq, drainErr := s.drainJournal(ctx, l)
	l.Position.LastSeq = max(l.Position.LastSeq, seq)
	if drainErr != nil {
		s.log().ErrorContext(ctx, "journal could not be materialized; the run's lifecycle continues without it",
			"run", l.RunID, "err", drainErr)
	}
	marker, err := runner.ReadMarker(s.markerPath(l.RunID, l.AttemptNo))
	switch {
	case err == nil:
		return s.finish(ctx, l, marker)
	case !errors.Is(err, runner.ErrNoMarker):
		return err
	}
	if l.UnitName == "" {
		// Admitted and never spawned: the platform stopped between the transaction and the unit, or
		// the queue entry was lost. The reconciler is the backstop for both.
		return s.spawnAttempt(ctx, l)
	}
	alive, err := s.Runner.Alive(ctx, l.UnitName)
	if err != nil {
		// The bus did not answer. "I could not ask" must never be read as "the run is gone": that
		// mistake restarts a live engine against its own project lock.
		return err
	}
	if alive {
		return s.maybeResync(ctx, l)
	}
	if s.now().Sub(l.AttemptStartedAt) < spawnGrace {
		return nil // systemd has not started it yet
	}
	return s.restart(ctx, l)
}

// drainJournal applies whatever the engine has written since the cursor, and returns where the
// cursor now stands.
func (s *Service) drainJournal(ctx context.Context, l pgstore.LiveRun) (int64, error) {
	if l.Quarantined {
		return l.Position.LastSeq, nil
	}
	path := filepath.Join(l.Workdir, ingest.JournalFile)
	sink := s.Store.NewRunSink(l.AttemptID, l.RunID, l.BookID)
	from := ingest.Position{Offset: l.Position.Offset, LastSeq: l.Position.LastSeq, LastHash: l.Position.LastHash}
	pos, _, err := ingest.Tail(ctx, path, l.EngineRunID, from, sink)
	switch {
	case errors.Is(err, ingest.ErrNoJournal):
		// The emitter is unified backlog row 103 and does not exist yet, so this is the ordinary case
		// today. The tailer is built against the vocabulary and waits.
		return l.Position.LastSeq, nil
	case err != nil && !quarantines(err):
		// A moment we could not read it, not a stream we cannot read. Returned so the sweep logs it and
		// meets the same bytes again next pass.
		return l.Position.LastSeq, err
	case err != nil:
		// The RUN is left alone: it is spending money the account reserved, and our inability to read
		// its journal is not a reason to throw that away. Freshness falls back to the resync channel.
		s.log().ErrorContext(ctx, "journal cannot be materialized; falling back to resync",
			"run", l.RunID, "err", err)
		return l.Position.LastSeq, s.Store.Quarantine(ctx, l.AttemptID, err.Error())
	}
	if pos.Offset > l.Position.Offset {
		// Lines that were read and NOT applied — duplicates the cursor already covers — still move
		// the byte hint. Without this they are re-read on every sweep, forever.
		return pos.LastSeq, s.Store.SaveCursor(ctx, l.AttemptID, pgstore.Position{Offset: pos.Offset})
	}
	return pos.LastSeq, nil
}

// quarantines decides what a failure to materialize the journal MEANS: a stream this platform cannot
// read, or a moment in which it could not read one.
//
// That distinction is the whole decision, and getting it wrong is expensive in both directions. A
// gap, a changed payload, a malformed line, a line past the buffer: none is repaired by reading the
// same bytes again, and retrying them forever is what wedged a run — so those stop the projection.
// Our own shutdown and a lock Postgres broke are the opposite: the very next sweep reads exactly the
// same bytes successfully, and stopping the projection over one blinds a live, paying run for good.
func quarantines(err error) bool {
	switch {
	case err == nil:
		return false
	case errors.Is(err, context.Canceled), errors.Is(err, context.DeadlineExceeded):
		return false
	case pgstore.IsTransient(err):
		return false
	default:
		return true
	}
}

// maybeResync refreshes a live run from `tmctl status --json`, at most once every ResyncEvery.
//
// ⚠ What it produces is HONESTLY STALE, and by an amount the interval names: the run moves
// continuously and this reads it every few minutes. It exists because the event emitter does not
// (row 103); when it does, this becomes what it was designed to be — a repair path, not the only
// source of progress.
func (s *Service) maybeResync(ctx context.Context, l pgstore.LiveRun) error {
	// The stream, when there is one, is the FRESHER source and the free one. A status call costs
	// seconds of CPU on the engine's side, every time, and can only report what the journal has
	// already said — so the repair channel runs where there is nothing to repair from: an attempt
	// whose cursor has never moved, or one whose materialization was quarantined and for which this
	// is now the only source.
	//
	// ⚠ This gate used to carry a second job that it no longer has to: before the engine reported the
	// per-wave split (row 99, landed D39.122) a resync could only fold ONE aggregate over the two
	// counters the stream keeps apart, which is how a live run showed "edit 10/10" seconds after its
	// journal said "edit 0/10". ApplyStatus now materializes the same four counters as the stream.
	if l.Position.LastSeq > 0 && !l.Quarantined {
		return nil
	}
	if !s.dueForResync(l.RunID) {
		return nil
	}
	now := s.now()
	rep, err := s.Engine.Status(ctx, s.engineBinary(l), l.Workdir)
	if err != nil {
		// A status call that fails is not a run that failed. It is logged and retried on the next
		// interval; the read model keeps the last figures it had.
		s.log().WarnContext(ctx, "resync failed", "run", l.RunID, "err", err)
		return nil
	}
	return s.Store.ApplyStatus(ctx, l.RunID, l.BookID, rep, now)
}

// dueForResync is the rate limit, and it is the whole of what makes the resync affordable: the
// sweep runs every few seconds and each status call costs seconds of CPU. It records the decision as
// it makes it, so two sweeps cannot both conclude "due".
//
// In memory on purpose: this is a rate limit, not a fact — losing it on restart costs one extra
// status call, whereas persisting it would put a row write on a path that exists to avoid work.
func (s *Service) dueForResync(runID string) bool {
	if s.Cfg.ResyncEvery <= 0 || s.Engine == nil {
		return false
	}
	now := s.now()
	if s.resynced == nil {
		s.resynced = map[string]time.Time{}
	}
	if last, ok := s.resynced[runID]; ok && now.Sub(last) < s.Cfg.ResyncEvery {
		return false
	}
	s.resynced[runID] = now
	return true
}

// finish closes a run whose unit has ended.
func (s *Service) finish(ctx context.Context, l pgstore.LiveRun, m runner.Marker) error {
	delete(s.resynced, l.RunID) // a finished run keeps no rate-limit entry: the map is per process
	status, exit := outcome(l, m)
	if err := s.Store.FinishRun(ctx, l.RunID, l.AttemptID, status, m.Result, exit, s.now()); err != nil {
		return err
	}
	s.log().InfoContext(ctx, "run finished", "run", l.RunID, "status", status, "result", m.Result)
	// Settling immediately rather than waiting for the next sweep: the hold is the account's money
	// and every second it stays reserved is a second the user cannot start another book.
	return s.settle(ctx, l)
}

// outcome maps what systemd saw onto the product status of the run.
//
// The engine's exit contract is the input for a process that exited on its own (0 clean · 2
// completed with flagged units · 3 the deliberate bank-signing stop · 1 everything else); a process
// that did NOT exit on its own has no exit code to map, and $SERVICE_RESULT is what tells a stop we
// asked for from a kill we did not.
//
// ⚠ Named limit, not an oversight: a CEILING stop is exit 1 today, indistinguishable from an infra
// failure, because the engine reports it as an error and the ceiling EVENT does not exist yet
// (unified backlog row 103 — verified in the engine's own code, stagerun.go, where the ceiling
// verdict returns errReserveCeiling). The contract requires a ceiling stop to be `paused` and never
// `failed`, so until the emitter lands the only ceiling stop this platform can report correctly is
// one it heard about on the stream — which is exactly the branch below that reads paused_reason.
func outcome(l pgstore.LiveRun, m runner.Marker) (status string, exitCode *int) {
	if l.PausedReason != "" {
		return "paused", nil
	}
	code, exited := m.Exited()
	if !exited {
		if m.Result == "success" {
			return "stopped", nil // asked to stop, and it did
		}
		return "failed", nil
	}
	switch code {
	case 0, 2:
		// 2 is "completed with flagged units": a finished translation whose notes carry the flags.
		return "ready", &code
	case 3:
		// The bank-signing stop. The ATTEMPT is over — the engine exits — and so is this run row;
		// the work is resumable and resuming it starts a new run, because the contract's resume
		// handle is not part of this pack.
		return "awaiting_bank", &code
	default:
		return "failed", &code
	}
}

// settle resolves the money of an attempt whose process is gone.
//
// The figure is the engine's OWN committed spend, read through `tmctl status --json` — the ratified
// repair channel — after the process has exited, so there is no lock to contend with and no
// inference from a stream that may have been truncated. If it cannot be read the reservation stays
// OPEN and the next sweep tries again: a hold that is still reserved is visible and recoverable,
// whereas a settlement against a guessed number is neither.
//
// ⚠ What this deliberately does NOT do is the escrow half of research/25 — write-ahead intent, the
// `uncertain` state, `closing` until the terminal seq. That is unified backlog row 136 and its own
// prompt; building half of it here would put a second, weaker answer next to the one being designed.
func (s *Service) settle(ctx context.Context, l pgstore.LiveRun) error {
	if s.Engine == nil {
		return nil
	}
	key := pgstore.ReservationKey(l.RunID, l.AttemptNo)
	rep, err := s.Engine.Status(ctx, s.engineBinary(l), l.Workdir)
	if err != nil {
		s.log().WarnContext(ctx, "settlement deferred: the engine's committed spend could not be read",
			"run", l.RunID, "err", err)
		return nil
	}
	if rep.Spend == nil {
		// Absent is not zero (PD-40): a settlement computed from a missing figure would release the
		// whole hold and charge nothing.
		s.log().WarnContext(ctx, "settlement deferred: the status report carries no committed spend",
			"run", l.RunID)
		return nil
	}
	// What the book's counter says NOW, bounded by what it said when a later attempt of the same book
	// started. Settlement is allowed to defer and a deferred one can be overtaken: the run is finished,
	// so nothing stops the account from starting another on the same book, and the counter this reads
	// is the BOOK's lifetime total. Without the bound the deferred settlement of the first run pays for
	// the second one's work as well, and the second then pays for it again.
	bound, err := s.Store.SpendBound(ctx, l.BookID, l.AttemptID)
	if err != nil {
		return err
	}
	committed := *rep.Spend
	if bound != nil && *bound < committed {
		committed = *bound
	}
	if l.SpendBaseline != nil && committed < *l.SpendBaseline {
		// The book's meter went BACKWARDS across this attempt, which no run produces: it is a project
		// database that was replaced or restored. attemptSpend clamps to zero rather than paying an
		// account for it, and this says so out loud — a settlement of nothing is not something to
		// discover from a balance. WARN and not INFO because the subject is money; the figures
		// themselves stay out of the line (D39.84).
		s.log().WarnContext(ctx, "the book's meter reads below this attempt's own baseline; it is settled at nothing",
			"run", l.RunID, "attempt", l.AttemptNo)
	}
	spent, err := attemptSpend(l, committed)
	if err != nil {
		if l.UnitName == "" {
			// No baseline because there was no spawn: the attempt was admitted and never started, so it
			// cost nothing and its hold comes back WHOLE. Without this the money of a run that never ran
			// is reserved forever.
			//
			// "Never started" is re-checked against the ROW, not against this snapshot: the sweep read
			// its list before working through it, and a run can be spawned, spend and exit inside that
			// window. Measured: the hold of an attempt that spent $0.50 came back in full.
			switch err := s.Store.ReleaseUnspawned(ctx, key, l.AttemptID, s.now()); {
			case errors.Is(err, pgstore.ErrAttemptSpawned):
				s.log().InfoContext(ctx, "settlement deferred: the attempt was spawned after this sweep read it",
					"run", l.RunID, "attempt", l.AttemptNo)
				return nil // the next sweep sees the unit and settles against its baseline
			case err != nil && !errors.Is(err, pgstore.ErrNoReservation):
				return err
			}
			return s.Store.MarkSettled(ctx, l.RunID, s.now())
		}
		// Spawned, but with no baseline — an attempt from before this column existed. Charging the
		// book's lifetime total would bill every earlier run again and charging zero would give this
		// one away, so it is left open and said out loud.
		s.log().ErrorContext(ctx, "settlement withheld: this attempt ran without a spend baseline",
			"run", l.RunID, "attempt", l.AttemptNo)
		return nil
	}
	if err := s.Store.Settle(ctx, key, spent, s.now()); err != nil {
		if errors.Is(err, pgstore.ErrNoReservation) {
			// Already closed by an earlier pass. Settling is idempotent by refusal, not by repetition.
			return s.Store.MarkSettled(ctx, l.RunID, s.now())
		}
		return err
	}
	return s.Store.MarkSettled(ctx, l.RunID, s.now())
}

// restart brings back a run whose unit vanished without a word — the case a reboot produces, since
// transient units do not survive one (research/25 §Форма, unified backlog row 138).
//
// The money is closed on the old attempt and reopened on the new one rather than carried over: the
// old hold was taken for a process that is gone, and what the account still owes for it is the
// engine's committed figure, not the ceiling. What remains of the run's budget is what the new
// attempt gets, so a restart cannot spend the run's ceiling twice.
//
// The LIMIT the resumed process is given is not that remainder: spawnAttempt reads the engine's
// meter again and hands it committed + the remainder, because the flag caps the book's cumulative
// spend and the interrupted attempt moved it (D39.122, and meter.bookCap for why the reserved figure
// is deliberately not in that sum).
func (s *Service) restart(ctx context.Context, l pgstore.LiveRun) error {
	if err := s.settle(ctx, l); err != nil {
		return err
	}
	// Settling is allowed to DEFER — the engine's figure may not be readable — and a deferral must not
	// become a second reservation. Asked rather than assumed: proceeding on an unsettled attempt holds
	// the ceiling twice and strands the first hold where no later sweep looks for it.
	open, err := s.Store.AttemptReservationOpen(ctx, l.RunID, l.AttemptNo)
	if err != nil {
		return err
	}
	if open {
		s.log().WarnContext(ctx, "restart deferred: the interrupted attempt is not settled yet",
			"run", l.RunID, "attempt", l.AttemptNo)
		return nil
	}
	budget := s.Pricing.Ceiling(l.CeilingChapters)
	spent, err := s.Store.RunSpent(ctx, l.RunID)
	if err != nil {
		return err
	}
	remaining := budget - spent
	if remaining <= 0 {
		// `paused` WITH its reason: the contract describes PausedReason as the reason a run is paused,
		// and a paused run with a null reason gives the screen nothing to say. PauseRun is the path
		// that sets it; FinishRun does not.
		s.log().InfoContext(ctx, "interrupted run has no budget left", "run", l.RunID)
		return s.Store.PauseRun(ctx, l.RunID, l.AttemptID, pgstore.PausedCreditExhausted, s.now())
	}
	offset, err := journalSize(l.Workdir)
	if err != nil {
		return err
	}
	// Nil = inherit the pinned build. A different one only when an operator asked for it (row 139).
	var version *string
	if s.Cfg.AllowEngineVersionChange && s.Cfg.EngineBinary != "" {
		version = &s.Cfg.EngineBinary
	}
	next, err := s.Store.RestartRun(ctx, pgstore.RestartInput{
		RunID:        l.RunID,
		AttemptID:    l.AttemptID,
		UserID:       l.UserID,
		BookID:       l.BookID,
		Ceiling:      remaining,
		Offset:       offset,
		EngineBinary: version,
		Now:          s.now(),
	})
	if errors.Is(err, pgstore.ErrInsufficientCredit) {
		// The balance went elsewhere while this run was down. Honest state, not a failure: the run is
		// paused for the reason the contract has a word for.
		s.log().InfoContext(ctx, "interrupted run cannot be resumed on the current balance", "run", l.RunID)
		return s.Store.PauseRun(ctx, l.RunID, l.AttemptID, pgstore.PausedCreditExhausted, s.now())
	}
	if err != nil {
		return err
	}
	s.log().InfoContext(ctx, "interrupted run restarted", "run", l.RunID, "attempt", next.AttemptNo)
	return s.spawnAttempt(ctx, next)
}

// Stop asks a live run to shut down. The engine stops gracefully on SIGTERM and finishes the chunk
// it has already paid for; the reconciler turns the exit into a status.
func (s *Service) Stop(ctx context.Context, l pgstore.LiveRun) error {
	if l.UnitName == "" {
		return fmt.Errorf("runs: run %s has no unit to stop", l.RunID)
	}
	return s.Runner.Stop(ctx, l.UnitName)
}

// attemptSpend turns the engine's figure into what THIS attempt cost.
//
// ⚠ The engine's `committed_usd` is a lifetime total for the BOOK — literally
// `SELECT COALESCE(SUM(committed_usd),0) FROM spend WHERE book_id = ?`
// (backend/internal/store/ledger.go at HEAD, reached through pipeline/status.go) — across every run
// and every day. Settling with it verbatim charges an account for all of the book's earlier runs
// again, every time; the overcharge is bounded by the hold, and the ledger then reads "capped at the
// hold", which looks like an engine overspend rather than the platform's own arithmetic. So each
// attempt records where the meter stood when it started and owes the DIFFERENCE.
//
// Clamped at zero: a total that went DOWN is not a refund, it is a book whose project database was
// replaced, and paying an account for that is not something this code may decide.
func attemptSpend(l pgstore.LiveRun, committed money.MicroUSD) (money.MicroUSD, error) {
	if l.SpendBaseline == nil {
		return 0, errors.New("runs: the attempt has no spend baseline")
	}
	if committed < *l.SpendBaseline {
		return 0, nil
	}
	return committed - *l.SpendBaseline, nil
}