diff --git a/CLAUDE.md b/CLAUDE.md index c7466bd..3943ef2 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -107,9 +107,21 @@ PYTHONPATH=. harbor run -d terminal-bench/terminal-bench-2 \ `-i` needs the **fully qualified** task name. A bare `overfull-hbox` fails at config validation — which is cheap, because it fails before any container or API call. +A command line without `-c job.yaml` reads none of it, so both budgets fall back to `agent.py`'s defaults — `max_iterations` 200 and no wall budget. Add `--ak max_iterations=1000 --ak agent_timeout_sec=` to a single-task run, or it is capped at 200 steps and says nothing about the clock. + Four things that are easy to get wrong: -- **Wall clock is the binding budget, not iterations.** `job.yaml` sets `max_iterations: 200`, but Harbor enforces a per-task agent timeout from the task package and raises `AgentTimeoutError` — 750s for `overfull-hbox`. The baseline run used 191s of that for 59 iterations, so 200 iterations is only reachable if each averages under ~3.7s. Nothing in the loop knows about this budget; the iteration counter is the only one it can see. +- **Both budgets bind, and at `max_iterations: 200` iterations bound first on every task measured.** Harbor enforces a per-task agent timeout from the task package's `task.toml` and raises `AgentTimeoutError`; the loop enforces `WOOPCODE_MAX_WALL_SEC` and stops on whichever binds first. Timeouts vary by 16× across five tasks, so a rule read off any one of them does not generalise — against `jobs/tb2-post-1.1`: + + | task | timeout | wall used | unused | iterations | what stopped it | + | --- | --- | --- | --- | --- | --- | + | build-pov-ray | 12000s | 287s | 98% | 79 | model chose to | + | circuit-fibsqrt | 3600s | 400s | 89% | 165 | model chose to | + | make-mips-interpreter | 1800s | 406s | **77%** | **200** | **our ceiling** | + | overfull-hbox | 750s | 192s | 74% | 59 | model chose to | + | video-processing | 3600s | 261s | 93% | 83 | model chose to | + + `make-mips-interpreter` was killed by its own 200th iteration at 406s of 1800, mid-work, with `exception_info: null` proving Harbor's timeout never fired — so `job.yaml` sets `max_iterations: 1000` and the ceiling reverts to guarding a pathological loop. Harbor does **not** hand the agent its timeout: `AgentContext` has no such field and `Trial` holds `timeout_sec`, so an operator supplies it as `agent_timeout_sec`, which `agent.py` forwards verbatim. `docs/adr/0001-wall-clock-budget-for-the-agent-loop.md` has the measurements and the rejected alternatives. - **`agent_timeout_sec: null` in a job's `lock.json` does not mean there is no timeout.** It means that run never hit one. The value only appears in `result.json`'s `exception_info` after it fires. - **Judge a change on the recorded `durationMs`, not on wall clock.** The loop stamps it around the provider request only, so it is the comparable number; total trial time includes container setup, tool execution and the verifier. Confusing the two once turned a 1.5s baseline into a reported 11s. - **Provider latency varies enormously and will masquerade as a regression.** The same request shape has measured 1,519ms median across 59 iterations on one day and ~63s on another, and within a single 15-request probe the same configuration ranged from 1,742ms to 90,002ms depending on position in the sequence. Before blaming a code change, check whether latency tracks position rather than the change, and whether the effect is anti-correlated with what you think causes it. @@ -118,7 +130,7 @@ Reading a trajectory, `run_end`'s `ok: true` means the loop finished, not that t ## Environment variables -`WOOPCODE_API_KEY`, `WOOPCODE_PROVIDER`, `WOOPCODE_MAX_ITERATIONS`, `WOOPCODE_MAX_ATTEMPTS` (retry), `WOOPCODE_TOOL_HISTORY_BUDGET`, `WOOPCODE_THINKING_BUDGET`, `WOOPCODE_NON_INTERACTIVE`, `WOOPCODE_DEMO_URL`. Bun loads `.env` automatically — no `dotenv`. +`WOOPCODE_API_KEY`, `WOOPCODE_PROVIDER`, `WOOPCODE_MAX_ITERATIONS`, `WOOPCODE_MAX_WALL_SEC`, `WOOPCODE_MAX_ATTEMPTS` (retry), `WOOPCODE_TOOL_HISTORY_BUDGET`, `WOOPCODE_THINKING_BUDGET`, `WOOPCODE_NON_INTERACTIVE`, `WOOPCODE_DEMO_URL`. Bun loads `.env` automatically — no `dotenv`. Sandboxing: `E2B_API_KEY`, `WOOPCODE_SANDBOX_TEMPLATE`, `WOOPCODE_SANDBOX_TIMEOUT_MS`, `WOOPCODE_SANDBOX_MAX_FILE_BYTES`, `WOOPCODE_SANDBOX_NETWORK`, `WOOPCODE_SANDBOX_ENV`, `WOOPCODE_SANDBOX_SETUP`. diff --git a/commands/agent.tsx b/commands/agent.tsx index a151979..1c38739 100644 --- a/commands/agent.tsx +++ b/commands/agent.tsx @@ -216,8 +216,7 @@ async function runHeadless( prompt, }); - let failed = false; - let budgetExhausted = false; + const outcome = new HeadlessOutcome(); let summary: TurnSummary | undefined; const callbacks: AgentCallbacks = { @@ -296,8 +295,7 @@ async function runHeadless( process.stdout.write(text); }, onError(error) { - failed = true; - if (error instanceof BudgetExhaustedError) budgetExhausted = true; + outcome.record(error); log.write({ type: "error", ts: now(), message: error.message }); process.stderr.write(`✖ ${error.message}\n`); }, @@ -319,8 +317,7 @@ async function runHeadless( try { await controller.run(prompt); } catch (error) { - failed = true; - if (error instanceof BudgetExhaustedError) budgetExhausted = true; + outcome.record(error); const message = error instanceof Error ? error.message : String(error); log.write({ type: "error", ts: now(), message }); process.stderr.write(`✖ ${message}\n`); @@ -329,22 +326,61 @@ async function runHeadless( await controller.dispose(); } - log.write({ type: "run_end", ts: now(), ok: !failed, summary }); + log.write({ type: "run_end", ts: now(), ok: !outcome.failed, summary }); process.stdout.write("\n"); - // Exit codes are a contract with automated callers: - // 0 - the turn completed - // 2 - the loop ran out of budget, of iterations or of wall-clock time; work - // may be partially done, and the caller should judge the result rather - // than treat this as a crash. One code for both: a distinct one for the - // deadline would be booked as an exception by any harness not yet - // updated to know it, dropping those trials from the mean. - // 1 - anything else went wrong - process.exit(failed ? (budgetExhausted ? EXIT_BUDGET_EXHAUSTED : 1) : 0); + process.exit(outcome.exitCode()); } -/** See the exit-code contract in `runHeadless`. */ +/** See the exit-code contract in `HeadlessOutcome.exitCode`. */ export const EXIT_BUDGET_EXHAUSTED = 2; +/** + * How a headless run ended, accumulated across the two places it can fail. + * + * A type rather than the pair of booleans it replaces, because those were the + * same type and one of their four combinations — exhausted but not failed — has + * no meaning. `record` is the only way to set either, and it always sets + * `failed`, so that combination is now unconstructible rather than merely + * untested. `tools/timeoutBudget.ts` makes the same argument for `BudgetedTimeout`. + * + * It also gives the classification one home. Inline at both failure sites, the + * `instanceof` could only be checked by a test that copied it — which asserts + * against the copy, and goes on passing when the original changes. + */ +export class HeadlessOutcome { + /** Whether anything went wrong at all. Drives `run_end`'s `ok`. */ + failed = false; + + /** Whether what went wrong was a spent budget rather than a fault. */ + budgetExhausted = false; + + /** Records a failure. The line `runHeadless` runs at both of its failure sites. */ + record(error: unknown): void { + this.failed = true; + if (error instanceof BudgetExhaustedError) this.budgetExhausted = true; + } + + /** + * The exit code this run reports. + * + * Exit codes are a contract with automated callers: + * 0 - the turn completed + * 2 - the loop ran out of budget, of iterations or of wall-clock time; work + * may be partially done, and the caller should judge the result rather + * than treat this as a crash. One code for both: a distinct one for the + * deadline would be booked as an exception by any harness not yet + * updated to know it, dropping those trials from the mean. + * 1 - anything else went wrong + * + * Reachable from a test, unlike the expression it replaces — that sat inline + * in a `process.exit` beside a live provider and a real session, and the + * contract has a second party: `harbor_woopcode/agent.py` maps 2 to success. + */ + exitCode(): number { + return this.failed ? (this.budgetExhausted ? EXIT_BUDGET_EXHAUSTED : 1) : 0; + } +} + /** Runs the interactive TUI agent. */ async function runInteractive( modelOverride?: string, diff --git a/docs/adr/0001-wall-clock-budget-for-the-agent-loop.md b/docs/adr/0001-wall-clock-budget-for-the-agent-loop.md index bcb7d6e..e6496f5 100644 --- a/docs/adr/0001-wall-clock-budget-for-the-agent-loop.md +++ b/docs/adr/0001-wall-clock-budget-for-the-agent-loop.md @@ -69,6 +69,18 @@ fraction as a 12000s one. is advisory: `run_terminal` defaults to 300s and the model may ask for more, so one command started just inside the budget outlives it by minutes — on `overfull-hbox`, a single default-timeout call is 40% of the entire budget. +`run_terminal`, `run_tests` and `repl` clamp; `process_start` deliberately does +not, because a background process does not hold the loop and so cannot overshoot +the deadline. The clamp is read after approval rather than at the top of +`execute`, since the clock runs while a human decides. + +**A clamped kill is explained by the clock, not by the timeout.** The standing +advice for a timeout is to run it again with a larger one, which is exactly +wrong when the budget rather than the number ended the call — the model would +spend its last seconds reaching the same end. Rejected: leaving the existing +messages and relying on the wind-down warning to have set the context, which +puts two paragraphs an unknown number of tool calls apart and asks the model to +connect them. **The deadline lives in module state (`runtime/deadline.ts`), not on `Tool.execute`.** `runtime/sandbox/registry.ts` argues this case in its own @@ -95,6 +107,27 @@ one message and one flag. A constant expressed in seconds was rejected as the wrong shape across this task set — 120s is 16% of `overfull-hbox`'s budget and 1% of `build-pov-ray`'s. +The rate that conversion runs on is measured on the turn itself, so it is +unreliable exactly when there is least of it. `meanStepMs` after one step *is* +that step, and provider latency has measured 1,742ms to 90,002ms inside a single +probe — so one slow opening request made a turn with 690s of budget read as five +steps from the end, and a latched flag would have left the model winding down +for the rest of it. That is this document's own failure reached from the other +side, so the rate is ignored until `MIN_RATE_SAMPLES` steps have gone into it +(the mean recovers by the fourth), and the flag re-arms if the estimate comes +back above twice the threshold. + +## What it costs the prompt + +`bun run replay:baseline` over the ten fixtures in +`packages/tests/fixtures/replay`, before and after: **byte-identical**, peak +prompt characters unchanged on every fixture (mean 126,563, max 219,570). + +Expected, and worth stating rather than assuming. Nothing here rewrites +history — the wind-down adds at most one short user message to a turn, and only +to turns that reach it, which no fixture does. The harness measures characters +and cannot speak to cache rates; it says so itself. + ## Consequences - `WOOPCODE_MAX_WALL_SEC` and the exit-code behaviour become a contract with diff --git a/harbor_woopcode/README.md b/harbor_woopcode/README.md index 58f08f4..b150698 100644 --- a/harbor_woopcode/README.md +++ b/harbor_woopcode/README.md @@ -120,9 +120,21 @@ Pass with `--ak key=value`, or under `kwargs:` in `job.yaml`. | --- | --- | --- | | `source_dir` | — | Install from a local checkout instead of npm. Required until the CLI changes above are published | | `version` | `latest` | npm version to install. Pin for reproducible numbers | -| `max_iterations` | `200` | Loop budget per task | +| `max_iterations` | `200` | Loop budget per task, in steps | +| `agent_timeout_sec` | — | Loop budget per task, in wall seconds, forwarded verbatim as `WOOPCODE_MAX_WALL_SEC`. Unset leaves the loop bounded by iterations alone | | `auto_approve` | `True` | Must stay on; there is no human to approve edits | +Harbor does not hand the agent its own timeout — `AgentContext` has no such +field, and `task.config.agent.timeout_sec` is held by `Trial` +(`harbor/trial/trial.py:_compute_agent_timeout_sec`). So `agent_timeout_sec` has +to be supplied by whoever starts the run, which is what Harbor's own Cline agent +does under this same name. Read the number from the task package's `task.toml` +and pass it whole; the reserve is subtracted inside the loop +(`runtime/deadline.ts`), so a published number traces back to `task.toml` with +no arithmetic in between. Because the kwarg applies to every task in a job, +`job.yaml` carries the shortest timeout in its five-task set; +`docs/adr/0001-wall-clock-budget-for-the-agent-loop.md` has the per-task table. + ## Running ```bash @@ -136,6 +148,22 @@ export GEMINI_API_KEY=... PYTHONPATH=. harbor run -d terminal-bench/terminal-bench-2 -a harbor_woopcode:WoopCode -m google/gemini-3.5-flash-lite --ak source_dir=$(pwd) -l 5 --agent-setup-timeout-multiplier 2 --max-retries 2 --retry-include ApiRateLimitError ``` +A command line without `-c job.yaml` reads **none** of that file, so both +budgets fall back to the defaults in `agent.py` — `max_iterations` 200, and no +wall budget at all. Pass them when running a single task, or the run is capped +at 200 steps and cannot demonstrate anything about the clock: + +```bash +# One task, with its own task.toml budget +PYTHONPATH=. harbor run -d terminal-bench/terminal-bench-2 \ + -a harbor_woopcode:WoopCode -m google/gemini-3.5-flash-lite \ + --ak source_dir=$(pwd) --ak max_iterations=1000 --ak agent_timeout_sec=1800 \ + -i terminal-bench/make-mips-interpreter -n 1 +``` + +`-i` needs the fully qualified task name; a bare `make-mips-interpreter` fails +at config validation, before any container or API call. + ### Two flags worth knowing about **`--agent-setup-timeout-multiplier 2`.** Harbor allows 360s for agent setup. diff --git a/harbor_woopcode/agent.py b/harbor_woopcode/agent.py index 350c58d..9d19d64 100644 --- a/harbor_woopcode/agent.py +++ b/harbor_woopcode/agent.py @@ -103,6 +103,44 @@ _ALWAYS_FORWARDED = ["WOOPCODE_API_KEY", "WOOPCODE_PROVIDER", "GEMINI_API_KEY"] +def _whole_seconds(value: int | float | str | None) -> int | None: + """Coerce a wall-clock budget to whole seconds, or reject it loudly. + + Three types reach here. ``job.yaml`` gives an int; ``--ak key=value`` runs + the value through ``json.loads``, so ``=1800`` is an int, ``=1800.0`` a + float, and anything JSON cannot read stays a str. Harbor's own Cline agent + accepts the same three for the same reason. + + Raising beats forwarding a bad value: the CLI ignores a + ``WOOPCODE_MAX_WALL_SEC`` it cannot parse and runs unbudgeted, warning on a + stderr stream that is inside the container and buried in the trial log. The + operator would then read a run that ignored their budget as evidence about + that budget. A ``ValueError`` here fails at config validation instead -- + before any container starts or any token is spent. + """ + if value is None: + return None + + try: + # OverflowError as well as the obvious two: `json.loads` reads `1e400` + # and `Infinity` as `inf`, and `int(inf)` raises neither TypeError nor + # ValueError -- so without it those two are the one bad input that + # escapes as a traceback instead of the message below. + seconds = int(float(value)) + except (TypeError, ValueError, OverflowError): + raise ValueError( + f"Invalid value for 'agent_timeout_sec': {value!r}. " + "Expected the task's wall-clock budget in seconds." + ) from None + + if seconds < 1: + raise ValueError( + f"Invalid value for 'agent_timeout_sec': {value!r}. Must be >= 1. " + "Omit it to leave the loop bounded by iterations alone." + ) + return seconds + + class WoopCode(BaseInstalledAgent): """Runs the ``woopcode`` CLI as a Harbor agent. @@ -116,6 +154,17 @@ class WoopCode(BaseInstalledAgent): turning this off makes almost every task fail by construction. max_iterations: loop budget for a single task (default ``_DEFAULT_MAX_ITERATIONS``). + agent_timeout_sec: wall-clock budget for a single task, in seconds, as + enforced by Harbor. Forwarded verbatim -- the loop subtracts its own + reserve. Omitted by default, which leaves the loop bounded by + iterations alone, as it was before this existed. + + Harbor does not hand this to the agent: ``AgentContext`` has no such + field, and the per-task ``timeout_sec`` is held by ``Trial`` + (``harbor/trial/trial.py:_compute_agent_timeout_sec``). It has to be + supplied by the operator, which is what Harbor's own Cline agent + does under this same name -- so pass the number from the task + package's ``task.toml``. """ # The CLI emits a structured event log that this class converts to ATIF. @@ -184,12 +233,14 @@ def __init__( source_dir: str | None = None, auto_approve: bool = True, max_iterations: int | None = None, + agent_timeout_sec: int | float | str | None = None, **kwargs: Any, ) -> None: super().__init__(*args, **kwargs) self._source_dir = source_dir self._auto_approve = auto_approve self._max_iterations = max_iterations or _DEFAULT_MAX_ITERATIONS + self._agent_timeout_sec = _whole_seconds(agent_timeout_sec) # Captured in run() so the trajectory can open with the user turn; the # event log records the prompt too, but run() has the rendered form # after any prompt template has been applied. @@ -504,6 +555,17 @@ def _build_env(self) -> dict[str, str]: # _DEFAULT_MAX_ITERATIONS. env["WOOPCODE_MAX_ITERATIONS"] = str(self._max_iterations) + # The second budget. Harbor kills the process at this number, so the + # loop is told it and winds down first -- one trial was otherwise + # stopped by its own 200th iteration at 406s of 1800, mid-work. + # + # Verbatim, and only when the operator gave one: the reserve is + # subtracted inside the loop (`runtime/deadline.ts`), and an absent + # variable there means unbudgeted, which is the behaviour every run had + # before this. Sending `0` instead would arm a deadline already spent. + if self._agent_timeout_sec is not None: + env["WOOPCODE_MAX_WALL_SEC"] = str(self._agent_timeout_sec) + return env @override diff --git a/harbor_woopcode/job.yaml b/harbor_woopcode/job.yaml index 37ef52d..d270456 100644 --- a/harbor_woopcode/job.yaml +++ b/harbor_woopcode/job.yaml @@ -25,7 +25,33 @@ agents: # the published package, and set `version` to pin it. source_dir: . # version: 0.6.1 - max_iterations: 200 + # + # With the wall clock bounding spend, this reverts to the role loop.ts + # claims for it -- a guard against a pathological loop with nobody + # watching -- so it is set high enough to stop binding first. + # + # Under this file's own 750s it cannot bind at all: 690s of usable wall at + # make-mips-interpreter's measured 2.03s per iteration is ~340 steps, so + # anything above that is equivalent here and the clock is always what + # stops a turn. 1000 is chosen for the case the number actually matters -- + # a single task run with -i and its own larger --ak agent_timeout_sec, + # where make-mips's full 1800s affords ~885. + max_iterations: 1000 + # Harbor's per-task agent timeout, forwarded verbatim as + # WOOPCODE_MAX_WALL_SEC; the loop subtracts its own reserve. Harbor does + # not hand this to the agent -- AgentContext has no such field and Trial + # holds timeout_sec -- so the operator supplies it, as Harbor's own Cline + # agent does under this same name. + # + # One kwarg covers every task in the job, and these five span 750s + # (overfull-hbox) to 12000s (build-pov-ray). The minimum is the only + # value under which no task can be hard-killed mid-work; it does cap the + # longer four well below what they are allowed -- build-pov-ray gets 690s + # of usable wall out of 12000. A five-task run under this config is + # therefore NOT comparable to jobs/tb2-post-1.1, which had no wall budget + # at all. To give one task its own budget, run it with -i and + # --ak agent_timeout_sec=. + agent_timeout_sec: 750 datasets: - name: terminal-bench/terminal-bench-2 diff --git a/harbor_woopcode/test_agent.py b/harbor_woopcode/test_agent.py index 8f7119a..a72c30f 100644 --- a/harbor_woopcode/test_agent.py +++ b/harbor_woopcode/test_agent.py @@ -173,6 +173,59 @@ def test_env_raises_the_iteration_budget(tmp_path: Path) -> None: assert env["WOOPCODE_MAX_ITERATIONS"] == "99" +def test_env_forwards_the_wall_budget_verbatim(tmp_path: Path) -> None: + """The loop subtracts its own reserve, so nothing is subtracted here. + + Arithmetic in this file would split the safety margin across two + repositories and stop a published number tracing back to the task's + ``task.toml``. + """ + env = make_agent(tmp_path, agent_timeout_sec=1800)._build_env() + assert env["WOOPCODE_MAX_WALL_SEC"] == "1800" + + +def test_env_omits_the_wall_budget_when_no_timeout_is_given( + tmp_path: Path, +) -> None: + """Harbor never hands the agent its timeout; an operator has to. + + Absent rather than zero or empty: the loop treats an unset variable as + unbudgeted, and either of the other two would be an ignored value with a + warning, or a deadline already spent before the first iteration. + """ + assert "WOOPCODE_MAX_WALL_SEC" not in make_agent(tmp_path)._build_env() + + +@pytest.mark.parametrize("given", [1800, 1800.0, "1800"]) +def test_env_accepts_every_type_ak_can_produce( + tmp_path: Path, given: object +) -> None: + """``--ak`` runs its value through ``json.loads``. + + So ``agent_timeout_sec=1800`` arrives as an int, ``1800.0`` as a float, and + a quoted value as a str, while ``job.yaml`` supplies an int. All four have + to reach the CLI as the same whole number of seconds -- ``str(1800.0)`` is + ``"1800.0"``, which is not what a variable documented as seconds should + carry. + """ + env = make_agent(tmp_path, agent_timeout_sec=given)._build_env() + assert env["WOOPCODE_MAX_WALL_SEC"] == "1800" + + +@pytest.mark.parametrize("given", ["soon", 0, -1, "", float("inf"), "1e400"]) +def test_an_unusable_timeout_fails_the_run_at_construction( + tmp_path: Path, given: object +) -> None: + """Fail here, before any container or API call, not inside the trial. + + Forwarded as-is, the loop would warn on stderr and run unbudgeted -- and + the operator would read a trial that silently ignored the budget they + asked for as evidence about the budget. + """ + with pytest.raises(ValueError, match="agent_timeout_sec"): + make_agent(tmp_path, agent_timeout_sec=given) + + def test_env_forwards_only_the_provider_key(tmp_path: Path) -> None: agent = make_agent( tmp_path, diff --git a/packages/tests/runtime/wallBudget.test.ts b/packages/tests/runtime/wallBudget.test.ts index b729916..ee42379 100644 --- a/packages/tests/runtime/wallBudget.test.ts +++ b/packages/tests/runtime/wallBudget.test.ts @@ -4,7 +4,6 @@ import { IterationBudgetExhaustedError, WallBudgetExhaustedError, agentLoop, - stepsRemaining, } from "../../../runtime/loop"; import { WALL_RESERVE_SEC, @@ -13,7 +12,7 @@ import { setDeadline, } from "../../../runtime/deadline"; import { TurnState } from "../../../runtime/turnState"; -import { EXIT_BUDGET_EXHAUSTED } from "../../../commands/agent"; +import { EXIT_BUDGET_EXHAUSTED, HeadlessOutcome } from "../../../commands/agent"; import type { ProviderClient, StreamEvent } from "../../../config/types"; import { createRuntimeTest } from "../shared/testHelpers"; @@ -206,6 +205,47 @@ describe("the exit-code contract", () => { BudgetExhaustedError, ); }); + + /** + * The mapping itself, walked through the object `runHeadless` walks it with. + * + * The type assertions above prove both errors answer to `BudgetExhaustedError`; + * these prove that answering to it is what produces a 2, which is the half + * `harbor_woopcode/agent.py` depends on. `record` is the production line + * rather than a copy of it, so a change to the classification fails here + * instead of leaving this passing against its own reimplementation. + */ + const exitCodeAfter = (error: unknown): number => { + const outcome = new HeadlessOutcome(); + outcome.record(error); + return outcome.exitCode(); + }; + + test("a spent wall budget exits 2, exactly as a spent ceiling does", () => { + expect(exitCodeAfter(new WallBudgetExhaustedError(600))).toBe(2); + expect(exitCodeAfter(new IterationBudgetExhaustedError(40))).toBe(2); + }); + + test("anything else that fails exits 1, and a clean turn exits 0", () => { + expect(exitCodeAfter(new Error("provider refused the request"))).toBe(1); + expect(new HeadlessOutcome().exitCode()).toBe(0); + }); + + /** + * The combination that used to need a test, and can no longer be built. + * + * As two loose booleans, "exhausted but not failed" was reachable and pinned + * to 0 by assertion. `record` sets `failed` on every path, so the only way to + * raise `budgetExhausted` also raises `failed` — the state is excluded by the + * type rather than by a test remembering to cover it. + */ + test("a spent budget cannot be recorded without recording the failure", () => { + const outcome = new HeadlessOutcome(); + outcome.record(new WallBudgetExhaustedError(600)); + + expect(outcome.budgetExhausted).toBe(true); + expect(outcome.failed).toBe(true); + }); }); /** @@ -231,14 +271,14 @@ describe("steps remaining", () => { const state = new TurnState(); // Nothing has completed, so there is no rate to convert the clock with. - expect(stepsRemaining(state, 40)).toBe(40); + expect(state.stepsRemaining(40)).toBe(40); }); test("an unbudgeted turn is counted in iterations alone", () => { const state = new TurnState(); state.iterations = 35; - expect(stepsRemaining(state, 40)).toBe(5); + expect(state.stepsRemaining(40)).toBe(5); }); test("the closer of the two budgets is what is reported", () => { @@ -246,17 +286,17 @@ describe("steps remaining", () => { // each leaves 400s, which is twenty more steps — while the ceiling of 12 // leaves only two. const state = turnAt(10, 20_000, 660); - expect(stepsRemaining(state, 12)).toBe(2); + expect(state.stepsRemaining(12)).toBe(2); // Same turn, a ceiling far away: now the clock is the binding one. - expect(stepsRemaining(state, 1_000)).toBe(20); + expect(state.stepsRemaining(1_000)).toBe(20); }); test("a slower turn has fewer steps left in the same time", () => { // Twice the wall per step over the same elapsed time: 400s left at 40s a // step is ten, where 20s a step was twenty. const state = turnAt(5, 40_000, 660); - expect(stepsRemaining(state, 1_000)).toBe(10); + expect(state.stepsRemaining(1_000)).toBe(10); }); test("time already overspent reads as no steps left", () => { @@ -264,7 +304,85 @@ describe("steps remaining", () => { // The loop throws before it gets here; the arithmetic must still not report // room that does not exist. - expect(stepsRemaining(state, 1_000)).toBeLessThanOrEqual(0); + expect(state.stepsRemaining(1_000)).toBeLessThanOrEqual(0); + }); + + /** + * A turn `iterations` steps in that has taken `elapsedMs` in total. + * + * `turnAt` can only describe a turn whose steps all cost the same, which is + * the case that never goes wrong. Provider latency measured 1,742ms to + * 90,002ms inside one probe, so the turns worth testing are the lopsided + * ones. + */ + function turnAfter( + iterations: number, + elapsedMs: number, + budgetSeconds: number, + ) { + let at = 0; + setDeadline(budgetSeconds, { now: () => at, startedAt: 0 }); + const state = new TurnState(); + at = elapsedMs; + state.iterations = iterations; + return state; + } + + test("one slow first step does not shrink a turn to nothing", () => { + // job.yaml's 750s, less the reserve, is 690s. A 115s opening request — + // inside the range CLAUDE.md records — is the whole rate after one step: + // 575s left divided by a 115s mean is 5, which would wind the turn down + // with something like 280 steps still affordable. + const state = turnAfter(1, 115_000, 750); + + expect(state.stepsRemaining(1_000)).toBe(999); + }); + + test("the rate is believed once enough steps have gone into it", () => { + // Three steps at 70s each against 600s of usable budget: 390s left at a + // 70s mean is five. The guard withholds an early estimate; it must not + // discard a settled one, or the clock would never bind at all. + const state = turnAfter(3, 210_000, 660); + + expect(state.stepsRemaining(1_000)).toBe(5); + }); +}); + +describe("the wind-down flag", () => { + test("it fires once as the end comes into view", () => { + const state = new TurnState(); + + expect(state.shouldWarnWindDown(6)).toBe(false); + expect(state.shouldWarnWindDown(5)).toBe(true); + expect(state.shouldWarnWindDown(4)).toBe(false); + expect(state.shouldWarnWindDown(1)).toBe(false); + }); + + test("a recovered estimate takes the warning back", () => { + const state = new TurnState(); + + // A slow patch trips it... + expect(state.shouldWarnWindDown(3)).toBe(true); + // ...the turn settles, and the model is no longer winding down against a + // budget it is nowhere near. Latched, it would have spent the rest of the + // turn wrapping up. + expect(state.shouldWarnWindDown(400)).toBe(false); + expect(state.windDownWarned).toBe(false); + + // And the real end still warns when it arrives. + expect(state.shouldWarnWindDown(5)).toBe(true); + }); + + test("a count hovering on the boundary does not warn twice", () => { + const state = new TurnState(); + + expect(state.shouldWarnWindDown(5)).toBe(true); + // Above the threshold but not clear of it: re-arming here would let 5, 6, + // 5 send the notice twice for one turn. + for (const stepsLeft of [6, 5, 7, 10, 4]) { + expect(state.shouldWarnWindDown(stepsLeft)).toBe(false); + } + expect(state.windDownWarned).toBe(true); }); }); diff --git a/packages/tests/shared/deadline.ts b/packages/tests/shared/deadline.ts new file mode 100644 index 0000000..3964b5e --- /dev/null +++ b/packages/tests/shared/deadline.ts @@ -0,0 +1,20 @@ +import { WALL_RESERVE_SEC, setDeadline } from "../../../runtime/deadline"; + +/** + * Arms a wall-clock budget with `seconds` genuinely left to spend on tools. + * + * The reserve is added back on, because `setDeadline` subtracts it: a caller + * asking for 30 usable seconds wants `clampToBudget` to answer 30, not + * `30 - WALL_RESERVE_SEC`. Writing that sum out at each call site is how a test + * ends up asserting against a budget it did not mean to set. + * + * The clock is frozen at zero rather than left on `Date.now`, so the number a + * tool is granted is decided by the budget alone and not by how long the test + * took to reach the assertion. `clearDeadline` in an `afterEach` restores both + * the deadline and the real clock — module state, so a file that arms one and + * does not clear it leaves every later test in the run on a clock that never + * moves. + */ +export function budgetWith(seconds: number): void { + setDeadline(WALL_RESERVE_SEC + seconds, { now: () => 0, startedAt: 0 }); +} diff --git a/packages/tests/tools/timeoutBudget.integration.test.ts b/packages/tests/tools/timeoutBudget.integration.test.ts new file mode 100644 index 0000000..d58c510 --- /dev/null +++ b/packages/tests/tools/timeoutBudget.integration.test.ts @@ -0,0 +1,199 @@ +import { test, expect, describe, beforeEach, afterEach, afterAll } from "bun:test"; +import { mkdtempSync, rmSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; + +/** + * INTEGRATION TESTS for tool timeouts under the wall-clock budget. + * + * Real commands and a real interpreter, killed by real timers — the thing under + * test is how long a command is allowed to run, and a fake executor would be + * asserting on the number rather than on the kill. Only the clock the budget is + * measured against is injected, and only the approval prompt is faked. + * + * The clock is frozen rather than advanced: what a command is granted is decided + * once, when it starts, so a still clock reproduces every case and keeps the + * elapsed time these tests spend to about a second each. + * + * Every tool here runs through `requestCommandApproval`, which reads the + * configured mode through `getApprovalMode()` — so config reads go to a temp + * directory rather than the developer's real `~/.config/woopcode`. Stubbing + * `setPendingCommand` is not enough on its own: it answers the prompt, it does + * not stop the mode being read from disk. `approval.integration.test.ts` is the + * sibling this follows, including the reason the redirect is restored in + * `afterAll` and never in `afterEach`. + */ +const previousConfigHome = process.env.XDG_CONFIG_HOME; +const temporaryConfigHome = mkdtempSync(join(tmpdir(), "woopcode-timeout-")); +process.env.XDG_CONFIG_HOME = temporaryConfigHome; + +// Imported after the redirect is in place: a static import is bound at load, +// which for anything reading config at module scope would be before the line +// above ever ran. +const { terminalTool } = await import("../../../tools/terminal"); +const { runTestsTool } = await import("../../../tools/runTests"); +const { replTool } = await import("../../../tools/repl"); +const { closeReplSessions } = await import("../../../tools/replSession"); +const { clearDeadline } = await import("../../../runtime/deadline"); +const { store } = await import("../../../tui/src/store/ui-store"); +// Deferred like the rest, so the redirect above is in place before anything it +// pulls in reaches config at module scope. +const { budgetWith } = await import("../shared/deadline"); + +describe("tool timeouts under a wall-clock budget", () => { + const originalSetPendingCommand = store.setPendingCommand; + + beforeEach(() => { + store.setPendingCommand = async () => true; + }); + + afterEach(() => { + store.setPendingCommand = originalSetPendingCommand; + // Module state outlives a file. A deadline left armed here would shorten + // every command in every test that runs after it, and the fake clock would + // leave them measuring against a number that never moves. + clearDeadline(); + closeReplSessions(); + }); + + afterAll(() => { + closeReplSessions(); + + // Restored once, at the end. Doing it per test would drop the redirect + // after the first one on any machine that does not set the variable — the + // normal case — and point every later config read at the real directory. + if (previousConfigHome === undefined) delete process.env.XDG_CONFIG_HOME; + else process.env.XDG_CONFIG_HOME = previousConfigHome; + rmSync(temporaryConfigHome, { recursive: true, force: true }); + }); + + describe("run_terminal", () => { + test("cuts a requested timeout down to what is left of the budget", async () => { + budgetWith(1.5); + const start = Date.now(); + + const result = await terminalTool.execute({ command: "sleep 30", timeout: 60 }); + + expect(result).toContain("Command timed out after 1 seconds"); + // The message says what the clamp granted; this says the process really + // stopped there. `sleep 30` rather than a shorter one so the two outcomes + // are 1s and 30s apart: a runner would have to stall fourteen seconds to + // make this flake, where the gap between 1s and 5s is inside the noise a + // loaded CI box produces. That noise is what broke the cancellation test + // on macOS. + expect(Date.now() - start).toBeLessThan(15_000); + }); + + test("says the clock ran out, not that the timeout was too small", async () => { + budgetWith(1.5); + + const result = await terminalTool.execute({ command: "sleep 30", timeout: 60 }); + + // The standing advice is to retry with a larger timeout, which would burn + // the last seconds of the budget on a command that cannot finish. + expect(result).not.toContain("larger timeout"); + expect(result).toContain("wall-clock budget"); + expect(result).toContain("60s"); + }); + + test("leaves a timeout that already fits inside the budget alone", async () => { + budgetWith(600); + + const result = await terminalTool.execute({ command: "sleep 2", timeout: 0.05 }); + + expect(result).toContain("Command timed out after 0.05 seconds"); + expect(result).toContain("larger timeout"); + expect(result).not.toContain("wall-clock budget"); + }); + + test("an unbudgeted session is answered exactly as it is today", async () => { + const result = await terminalTool.execute({ command: "sleep 2", timeout: 0.05 }); + + expect(result).toBe( + "Error: Command timed out after 0.05 seconds\n\n" + + "If this command was never going to exit on its own — a server, a watcher — " + + "start it with process_start instead and read it with process_output. If it " + + "was simply slow, run it again with a larger timeout.", + ); + }); + }); + + describe("run_tests", () => { + test("cuts a requested timeout down to what is left of the budget", async () => { + budgetWith(1.5); + const start = Date.now(); + + const result = await runTestsTool.execute({ command: "sleep 30", timeout: 60 }); + + expect(result).toContain("Command timed out after 1 seconds"); + expect(result).toContain("wall-clock budget"); + expect(result).not.toContain("verify a server starts"); + // 1s against 30s, for the reason the run_terminal case gives. + expect(Date.now() - start).toBeLessThan(15_000); + }); + + test("an unbudgeted session keeps the standing advice", async () => { + const result = await runTestsTool.execute({ command: "sleep 2", timeout: 0.05 }); + + expect(result).toContain("Command timed out after 0.05 seconds"); + expect(result).toContain("verify a server starts"); + expect(result).not.toContain("wall-clock budget"); + }); + + test("leaves a timeout that already fits inside the budget alone", async () => { + budgetWith(600); + + const result = await runTestsTool.execute({ command: "sleep 2", timeout: 0.05 }); + + expect(result).toContain("Command timed out after 0.05 seconds"); + expect(result).toContain("verify a server starts"); + expect(result).not.toContain("wall-clock budget"); + }); + }); + + describe("repl", () => { + test("clamps the default timeout, which the tool never passed before", async () => { + // The default lives in `replSession`, and `repl` used to pass `undefined` + // and let it apply — so an evaluation with no timeout argument had 120 + // seconds regardless of a budget with one second on it. + budgetWith(1.5); + const start = Date.now(); + + const result = await replTool.execute({ + language: "python", + code: "import time; time.sleep(30)", + }); + + expect(result).toContain("timed out after 1 seconds"); + expect(result).toContain("wall-clock budget"); + expect(Date.now() - start).toBeLessThan(15000); + }); + + test("an unbudgeted session runs for the timeout it asked for", async () => { + const result = await replTool.execute({ + language: "python", + code: "import time; time.sleep(30)", + timeout: 1, + }); + + expect(result).toContain("timed out after 1 seconds"); + expect(result).not.toContain("wall-clock budget"); + }); + + test("leaves a timeout that already fits inside the budget alone", async () => { + budgetWith(600); + + const result = await replTool.execute({ + language: "python", + code: "import time; time.sleep(30)", + timeout: 1, + }); + + // A budget far larger than the request clamps nothing, and the answer is + // the bare error this path has always returned — no standing advice to + // swap the wall notice in for. + expect(result).toContain("timed out after 1 seconds"); + expect(result).not.toContain("wall-clock budget"); + }); + }); +}); diff --git a/packages/tests/tools/timeoutBudget.test.ts b/packages/tests/tools/timeoutBudget.test.ts new file mode 100644 index 0000000..e17bff3 --- /dev/null +++ b/packages/tests/tools/timeoutBudget.test.ts @@ -0,0 +1,111 @@ +import { afterEach, describe, expect, test } from "bun:test"; +import { + budgetedTimeout, + formatTimeoutError, + wallBudgetTimeoutNotice, +} from "../../../tools/timeoutBudget"; +import { clearDeadline } from "../../../runtime/deadline"; +import { budgetWith } from "../shared/deadline"; + +/** + * The pure half of the timeout budget: the number a tool is given, and the + * sentence the model reads when that number is what ended its command. + * + * `timeoutBudget.integration.test.ts` is the other half, and kills real + * processes to prove the number is honoured. Nothing here spawns anything. + */ + +afterEach(clearDeadline); + +const STANDING = "Run it again with a larger timeout."; + +describe("the timeout a tool is given", () => { + test("an unbudgeted turn is handed exactly what it asked for", () => { + expect(budgetedTimeout(300)).toEqual({ + seconds: 300, + requested: 300, + clamped: false, + }); + }); + + test("a budget shorter than the request lowers it", () => { + budgetWith(10); + + expect(budgetedTimeout(300)).toEqual({ + seconds: 10, + requested: 300, + clamped: true, + }); + }); + + test("the one-second floor never raises a deliberately short timeout", () => { + // The floor exists so a spent budget cannot hand a command zero seconds and + // kill it before it starts. It must not turn a caller's 0.05s into 1s. + budgetWith(0); + + expect(budgetedTimeout(0.05)).toEqual({ + seconds: 0.05, + requested: 0.05, + clamped: false, + }); + }); +}); + +describe("what the model is told", () => { + test("a clamped kill gets the clock, not the standing advice", () => { + budgetWith(10); + const budgeted = budgetedTimeout(300); + + const result = formatTimeoutError("Command timed out", budgeted, STANDING); + + expect(result).toContain("wall-clock budget"); + expect(result).not.toContain(STANDING); + }); + + test("an ordinary timeout keeps the standing advice", () => { + const budgeted = budgetedTimeout(300); + + const result = formatTimeoutError("Command timed out", budgeted, STANDING); + + expect(result).toContain(STANDING); + expect(result).not.toContain("wall-clock budget"); + }); + + test("a tool with no standing advice returns the bare error", () => { + const budgeted = budgetedTimeout(300); + + // `repl` explains a lost session in the message itself. An empty string + // must not leave two blank lines hanging off the end of it. + expect(formatTimeoutError("timed out after 1 seconds", budgeted, "")).toBe( + "Error: timed out after 1 seconds", + ); + }); + + test("it reports what was granted, never time that was not there", () => { + // `clampToBudget` floors at one second, so a command starting on a spent + // clock is granted 1s when nothing was left. Saying "1s was left when it + // started" would be a number the model could act on and that never existed. + budgetWith(0); + + const notice = wallBudgetTimeoutNotice(300, 1); + + expect(notice).toContain("the budget allowed it only 1s"); + expect(notice).not.toContain("left when it started"); + }); + + test("a cleared deadline says nothing rather than saying zero", () => { + // No budget armed at all: `remainingMs()` is undefined, and `?? 0` would + // state "about 0s remain" — a confident wrong number about a turn that has + // no deadline on it. + const notice = wallBudgetTimeoutNotice(300, 5); + + expect(notice).not.toContain("remain"); + expect(notice).toContain("the budget allowed it only 5s"); + }); + + test("an armed deadline does report what is left", () => { + budgetWith(42); + + expect(wallBudgetTimeoutNotice(300, 42)).toContain("About 42s of the turn remain"); + }); +}); diff --git a/runtime/deadline.ts b/runtime/deadline.ts index eede692..7b336fb 100644 --- a/runtime/deadline.ts +++ b/runtime/deadline.ts @@ -12,10 +12,13 @@ * tools will need it, and threading it through would change the `Tool` * interface in `config/types.ts` and every tool's signature. * - * `clampToBudget` has no caller yet. Until `run_terminal`, `run_tests` and - * `repl` clamp against it the deadline is advisory — the loop checks the clock - * between iterations, and a command started just inside the budget still runs - * to its own 300s default. That wiring is deliberately a separate change. + * `clampToBudget` is read by `run_terminal`, `run_tests` and `repl` through + * `tools/timeoutBudget.ts`, which is where the floor of one second is stopped + * from *raising* a shorter timeout and where the message explaining a clamped + * kill lives. Without those callers the deadline would be advisory: the loop + * checks the clock between iterations, and a command started just inside the + * budget would still run to its own 300s default. `process_start` is excluded — + * a background process does not hold the loop, so it cannot overshoot. * * Unbudgeted until a turn says otherwise, so nothing changes for a session that * never sets `WOOPCODE_MAX_WALL_SEC`: every reader below answers "keep going" diff --git a/runtime/loop.ts b/runtime/loop.ts index e09017d..d3a8f5a 100644 --- a/runtime/loop.ts +++ b/runtime/loop.ts @@ -8,7 +8,6 @@ import { WALL_RESERVE_SEC, clearDeadline, deadlineReached, - remainingMs, setDeadline, } from "./deadline"; import { TurnState, normalizeToolKey } from "./turnState"; @@ -182,16 +181,6 @@ const MAX_TURNS = 6; */ const SAME_TOOL_THRESHOLD = 2; -/** - * Steps left when the model is told the budget is running out. - * - * Steps rather than seconds, because the same constant has to serve both - * budgets and a duration is the wrong shape across this task set: 120s is 16% - * of `overfull-hbox`'s budget and 1% of `build-pov-ray`'s. Time is converted - * into steps instead, at the rate this turn has actually been running at. - */ -const REMAINING_ITERATIONS_WARNING = 5; - /** * Asked once, never twice. The model may have a good reason not to verify — * the change may be unverifiable, or the tests may not exist — and a loop that @@ -296,28 +285,6 @@ function maxWallSeconds( return parsed; } -/** - * Steps this turn has left, from whichever of its two budgets is closer. - * - * The wall budget is converted into steps at the rate the turn has been running - * at, so one warning and one flag serve both. Before the first iteration - * completes there is no rate to convert with, and the iteration count stands - * alone — which is the right answer anyway, since no time has been spent. - * - * Exported for its own test: the arithmetic is what decides when the model is - * told to wrap up, and driving it through a whole turn to observe it would take - * a real clock and a real budget. - */ -export function stepsRemaining(state: TurnState, budget: number): number { - const byIterations = budget - state.iterations; - - const mean = state.meanStepMs(); - const left = remainingMs(); - if (mean === undefined || left === undefined) return byIterations; - - return Math.min(byIterations, Math.floor(left / mean)); -} - /** Per-turn switches that are not part of the conversation. */ export interface AgentLoopOptions { /** @@ -758,9 +725,8 @@ export async function agentLoop( // A flag rather than an equality on the iteration count: two budgets can // each come into view, and the equality it replaces silently never fired // when the ceiling was below the warning distance. - const stepsLeft = stepsRemaining(state, budget); - if (!state.windDownWarned && stepsLeft <= REMAINING_ITERATIONS_WARNING) { - state.windDownWarned = true; + const stepsLeft = state.stepsRemaining(budget); + if (state.shouldWarnWindDown(stepsLeft)) { messages.push({ role: "user", // Floored at one: the count can round down to zero or below when the @@ -774,6 +740,13 @@ export async function agentLoop( }); } + // Counted after the warning, not before, so `stepsRemaining` reads the + // steps *completed* and its two budgets agree on what "left" means: the + // clock's `floor(left / mean)` counts the step about to start, so the + // iteration term has to as well. Against the equality this replaced + // (`iterations === budget - 5`, evaluated post-increment) the notice + // lands one step later and "5 more steps" now includes the one about to + // run, where it used to mean five *after* it. state.iterations++; // Measured from the same array that is sent, so the segment sizes and diff --git a/runtime/turnState.ts b/runtime/turnState.ts index b661f17..1a229f7 100644 --- a/runtime/turnState.ts +++ b/runtime/turnState.ts @@ -2,16 +2,48 @@ * The mutable bookkeeping of a single turn. * * Extracted from `agentLoop`, where these were fifteen locals threaded through - * a five-hundred-line body. Nothing here decides anything — the loop still owns - * control flow — but every counter the turn summary reports lives in one place, - * and the two predicates derived from them are written once instead of at each - * site that needed them. + * a five-hundred-line body. Every counter the turn summary reports lives in one + * place, and the predicates derived from them are written once instead of at + * each site that needed them. + * + * The loop still owns control flow: nothing here ends a turn, and the two + * budgets are enforced in `loop.ts`. What does live here is the wind-down + * question — `stepsRemaining` converts the clock into steps and + * `shouldWarnWindDown` owns both transitions of the flag — because both read + * only this turn's own counters and the ceiling they are handed. */ import { classifyInvocation, toolEffect } from "./toolEffects"; -import { now } from "./deadline"; +import { now, remainingMs } from "./deadline"; import type { TurnSummary } from "../config/types"; +/** + * Completed iterations before the measured rate is believed. + * + * `meanStepMs` divides elapsed by iterations, so after one step the mean *is* + * that step. CLAUDE.md records provider latency ranging 1,742ms to 90,002ms + * within a single probe, so one slow first request is enough to make a turn + * with hundreds of steps of budget look like it has five: at 115s for step one + * against `job.yaml`'s 690s of usable wall, `floor(575000 / 115000)` is 5, and + * the model is told to wrap up with ~280 steps actually affordable. + * + * Three, because the mean recovers fast once ordinary steps land beside the + * spike — the same case at step four reads 18 — and because a threshold high + * enough to smooth a 90s outlier completely would suppress the warning on any + * turn short enough to need it early. + */ +const MIN_RATE_SAMPLES = 3; + +/** + * Steps left when the model is told the budget is running out. + * + * Steps rather than seconds, because the same constant has to serve both + * budgets and a duration is the wrong shape across this task set: 120s is 16% + * of `overfull-hbox`'s budget and 1% of `build-pov-ray`'s. Time is converted + * into steps instead, at the rate this turn has actually been running at. + */ +const REMAINING_ITERATIONS_WARNING = 5; + export class TurnState { /** Provider responses so far. One iteration may carry several tool calls, or none. */ iterations = 0; @@ -35,6 +67,59 @@ export class TurnState { */ windDownWarned = false; + /** + * Steps this turn has left, from whichever of its two budgets is closer. + * + * The wall budget is converted into steps at the rate the turn has been + * running at, so one warning and one flag serve both. Before the first + * iteration completes there is no rate to convert with, and the iteration + * count stands alone — which is the right answer anyway, since no time has + * been spent. + * + * The rate is ignored until `MIN_RATE_SAMPLES` steps have gone into it. The + * iteration ceiling still applies throughout, so an early turn is never told + * it has *more* than it has; what the guard withholds is only the ability of + * one slow step to end a turn that has hours left. + * + * On `TurnState` rather than in `loop.ts`, beside `meanStepMs` and the flag + * this feeds: it reads nothing of the loop's but the ceiling it is passed. + */ + stepsRemaining(budget: number): number { + const byIterations = budget - this.iterations; + + const mean = this.meanStepMs(); + const left = remainingMs(); + if (mean === undefined || left === undefined) return byIterations; + if (this.iterations < MIN_RATE_SAMPLES) return byIterations; + + return Math.min(byIterations, Math.floor(left / mean)); + } + + /** + * Should the model be told, now, that this turn is winding down? + * + * Owns both transitions of `windDownWarned`, because the interesting one is + * the way back. The step count the clock contributes is derived from a rate + * measured on this turn, and a rate moves: a slow patch early can trip the + * warning, and a latch would leave the model winding down for the rest of a + * turn it is nowhere near the end of — the failure the wall budget exists to + * prevent, reached from the other side. `MIN_RATE_SAMPLES` above keeps most + * bad estimates out; this clears the ones that get through. + * + * Re-arming at twice the threshold rather than at the threshold, so a count + * hovering on the boundary cannot warn, clear and warn again. + */ + shouldWarnWindDown(stepsLeft: number): boolean { + if (!this.windDownWarned) { + if (stepsLeft > REMAINING_ITERATIONS_WARNING) return false; + this.windDownWarned = true; + return true; + } + + if (stepsLeft > REMAINING_ITERATIONS_WARNING * 2) this.windDownWarned = false; + return false; + } + /** * Tools actually run. * diff --git a/site/src/docs/nav.ts b/site/src/docs/nav.ts index 4b93511..c4dbff8 100644 --- a/site/src/docs/nav.ts +++ b/site/src/docs/nav.ts @@ -105,6 +105,15 @@ export const NAV: NavSection[] = [ { slug: "architecture/how-it-works", title: "How it works" }, { slug: "architecture/running-from-source", title: "Running from source" }, { slug: "architecture/adding-a-tool", title: "Adding a tool" }, + // Written as a page — frontmatter, a summary, `related` pointing at + // Configuration — and reachable from nowhere until it was listed here, + // while CLAUDE.md and harbor_woopcode/README.md both send readers to it. + // Architecture rather than Reference: it explains why a turn has two + // budgets, where Configuration states what the variable does. + { + slug: "adr/0001-wall-clock-budget-for-the-agent-loop", + title: "Wall-clock budget", + }, ], }, ]; diff --git a/tools/repl.ts b/tools/repl.ts index f47fa8c..9d0ec18 100644 --- a/tools/repl.ts +++ b/tools/repl.ts @@ -1,6 +1,7 @@ import type { Tool } from "../config/types"; import { requestCodeApproval } from "./approval"; import { currentExecutor } from "../runtime/sandbox"; +import { budgetedTimeout, formatTimeoutError, isTimeoutError } from "./timeoutBudget"; import { REPL_LANGUAGES as LANGUAGES, isReplLanguage as isLanguage } from "./replDrivers"; import { DEFAULT_EVAL_TIMEOUT_SECONDS, @@ -90,13 +91,21 @@ This runs real code. It can write files and shell out, and is subject to the sam return "Code rejected by user. It was not run, and the session is unchanged."; } + // The default is resolved here rather than left to `replSession`, because a + // timeout that is never named cannot be clamped: passing `undefined` through + // gave an evaluation the full 120 seconds against a budget with one left. + // Read after approval, so time spent waiting for a human is not granted to + // the evaluation that follows it. + const requestedSeconds = timeout ?? DEFAULT_EVAL_TIMEOUT_SECONDS; + const budgeted = budgetedTimeout(requestedSeconds); + let output: string; let note: string; let started: boolean; try { ({ output, note, started } = await evaluate(language, code, { restart: args.restart === true, - timeoutSeconds: timeout, + timeoutSeconds: budgeted.seconds, signal, })); } catch (error) { @@ -104,6 +113,19 @@ This runs real code. It can write files and shell out, and is subject to the sam // A lost session is returned as a result rather than thrown so the model // can rebuild its state and carry on; the message says what was lost. const message = error instanceof Error ? error.message : String(error); + // Which clock ran out matters: told only that its evaluation timed out, + // the model rebuilds the session and runs it again with a longer one. + // No standing advice on this path — a lost session is explained by its + // own message — so anything but a clamped timeout returns the error bare. + // + // The other three throws that land here say "Evaluation cancelled", "The + // interpreter exited" and the repl being unavailable, so none of them can + // take this branch today. It is a coupling to one string in + // `replSession.ts`, not a live misrouting: a lost-session message that + // grew the words "timed out" would be answered about the wall clock. + if (isTimeoutError(error)) { + return formatTimeoutError(message, budgeted); + } return `Error: ${message}`; } diff --git a/tools/runTests.ts b/tools/runTests.ts index 778cd13..a077780 100644 --- a/tools/runTests.ts +++ b/tools/runTests.ts @@ -2,6 +2,7 @@ import type { Tool } from "../config/types"; import { formatCommandResult } from "./command"; import { currentExecutor } from "../runtime/sandbox"; import { requestCommandApproval } from "./approval"; +import { budgetedTimeout, formatTimeoutError, isTimeoutError } from "./timeoutBudget"; export const runTestsTool: Tool = { name: "run_tests", @@ -16,7 +17,7 @@ export const runTestsTool: Tool = { ? args.command : "bun test"; - const timeoutSeconds = (args.timeout as number) || 60; + const requestedSeconds = (args.timeout as number) || 60; // Classification and policy decide whether this needs a human; the tool // itself knows nothing about which commands are safe. @@ -31,16 +32,28 @@ export const runTestsTool: Tool = { return "Error: This command appears to start a server. Use run_tests only for test suites, not for starting servers. Servers run indefinitely and will cause timeouts."; } + // Read after approval rather than at the top: the clock runs while a human + // decides, so a number taken earlier would grant the run time that was spent + // waiting for permission to start it. + const budgeted = budgetedTimeout(requestedSeconds); + try { return formatCommandResult( - await currentExecutor().run(command, timeoutSeconds, signal), + await currentExecutor().run(command, budgeted.seconds, signal), ); } catch (error) { if (error instanceof Error && error.message === "Command cancelled") { return "Tests cancelled before completion."; } - if (error instanceof Error && error.message.includes("timed out")) { - return `Error: ${error.message}\n\nNote: If you're trying to verify a server starts, don't. Just create the code and let the user test it manually.`; + if (error instanceof Error && isTimeoutError(error)) { + // The standing note guesses at a server, which is the wrong diagnosis + // when the wall budget is what ended a suite that was running fine. + return formatTimeoutError( + error.message, + budgeted, + `Note: If you're trying to verify a server starts, don't. Just create ` + + `the code and let the user test it manually.`, + ); } throw error; } diff --git a/tools/terminal.ts b/tools/terminal.ts index 598957a..ad01002 100644 --- a/tools/terminal.ts +++ b/tools/terminal.ts @@ -2,6 +2,7 @@ import type { Tool } from "../config/types"; import { formatCommandResult } from "./command"; import { currentExecutor } from "../runtime/sandbox"; import { requestCommandApproval } from "./approval"; +import { budgetedTimeout, formatTimeoutError, isTimeoutError } from "./timeoutBudget"; function startsBackgroundProcess(command: string) { let quote: "'" | '"' | "`" | null = null; @@ -69,7 +70,7 @@ export const terminalTool: Tool = { async execute(args, signal) { const command = args.command as string; - const timeoutSeconds = (args.timeout as number) || DEFAULT_TIMEOUT_SECONDS; + const requestedSeconds = (args.timeout as number) || DEFAULT_TIMEOUT_SECONDS; if (!command) { throw Error("command is required"); @@ -91,20 +92,30 @@ export const terminalTool: Tool = { ); } + // Read after approval rather than at the top: the clock runs while a human + // decides, so a number taken earlier would grant the command time that was + // spent waiting for permission to run at all. + const budgeted = budgetedTimeout(requestedSeconds); + try { return formatCommandResult( - await currentExecutor().run(command, timeoutSeconds, signal), + await currentExecutor().run(command, budgeted.seconds, signal), ); } catch (error) { if (error instanceof Error && error.message === "Command cancelled") { return "Command cancelled before completion."; } - if (error instanceof Error && error.message.includes("timed out")) { - return ( - `Error: ${error.message}\n\nIf this command was never going to exit on ` + - `its own — a server, a watcher — start it with process_start instead and ` + - `read it with process_output. If it was simply slow, run it again with a ` + - `larger timeout.` + if (error instanceof Error && isTimeoutError(error)) { + // A command the budget cut short must not be told to ask for longer: + // the number was never the constraint, and the retry spends the last of + // the turn reaching the same end. `formatTimeoutError` picks between + // this advice and that one. + return formatTimeoutError( + error.message, + budgeted, + `If this command was never going to exit on its own — a server, a ` + + `watcher — start it with process_start instead and read it with ` + + `process_output. If it was simply slow, run it again with a larger timeout.`, ); } throw error; diff --git a/tools/timeoutBudget.ts b/tools/timeoutBudget.ts new file mode 100644 index 0000000..78281f3 --- /dev/null +++ b/tools/timeoutBudget.ts @@ -0,0 +1,124 @@ +import { clampToBudget, remainingMs } from "../runtime/deadline"; + +/** + * How long a tool may actually run, given what is left of the turn's wall + * budget, and whether that is less than it asked for. + * + * Without this the deadline is advisory — `runtime/deadline.ts` documents why, + * and this module is the half of it the tools see: the number to hand the + * executor, and the sentence to give the model when that number is what ended + * the call. + * + * `process_start` deliberately does not use this: a background process does not + * hold the loop, so it cannot overshoot the deadline. + */ +export type BudgetedTimeout = { + /** Seconds to hand the executor. */ + seconds: number; + /** + * Seconds the caller asked for. + * + * Carried rather than left to each caller to hold separately: every call site + * needs both numbers to explain a clamped kill, and the two travelling apart + * is how one of them gets passed in the wrong order. + */ + requested: number; + /** Whether the budget, rather than the caller, decided that number. */ + clamped: boolean; +}; + +/** + * Reads the effective timeout for a command about to start. + * + * Call it as late as possible — after approval, not before. The clock runs while + * a human is deciding, and a number taken at the top of `execute` would grant a + * command time that was spent waiting to be allowed to run at all. + */ +export function budgetedTimeout(requestedSeconds: number): BudgetedTimeout { + // `clampToBudget` never returns less than one second, because a zero or + // negative timeout does not shorten a command — it kills it before it starts. + // That floor must not *raise* a timeout the caller deliberately made shorter, + // so the request stays the ceiling and `clamped` only ever means "lowered". + const seconds = Math.min(requestedSeconds, clampToBudget(requestedSeconds)); + return { seconds, requested: requestedSeconds, clamped: seconds < requestedSeconds }; +} + +/** + * Did this error come from a timeout rather than from the command itself? + * + * Kept here beside the message it selects, because the test is stringly typed + * and was being written out per tool — three copies of + * `message.includes("timed out")`, one added by each caller that grew a budget. + * A fourth tool spelling it differently would silently get the standing advice + * on a clamped kill, which is the one thing this module exists to prevent. + * + * Substring rather than an error type because the string is all there is: the + * executor and `replSession` both raise a plain `Error`, and typing them is a + * change to code these budgets do not otherwise touch. + */ +export function isTimeoutError(error: unknown): boolean { + const message = error instanceof Error ? error.message : String(error); + return message.includes("timed out"); +} + +/** + * The message a timed-out tool returns, from whichever clock ended it. + * + * One function rather than the same four lines in each tool. The three that take + * a timeout had identical copies, and nothing would have stopped a fourth from + * being written without the budget branch at all — the failure mode `TOOL_EFFECTS` + * avoids by making a missing entry mean `unclassified` rather than nothing. + * + * `standingAdvice` is what the tool says when the clock was not involved, which + * differs per tool: run_tests talks about servers, run_terminal about + * process_start. `repl` has none, and omitting it leaves the bare error rather + * than a message with two blank lines hanging off it. + */ +export function formatTimeoutError( + message: string, + budgeted: BudgetedTimeout, + standingAdvice = "", +): string { + const advice = budgeted.clamped + ? wallBudgetTimeoutNotice(budgeted.requested, budgeted.seconds) + : standingAdvice; + + return advice ? `Error: ${message}\n\n${advice}` : `Error: ${message}`; +} + +/** + * What the model is told when the clock, not its own timeout, killed the call. + * + * The standing advice for a timeout is to run it again with a larger one, which + * is exactly wrong here: the number was never the constraint, and a retry spends + * what remains of the budget reaching the same end. This is interface rather + * than a log line — it is what the model reads next — so it says which budget + * ended the call, what the call was actually granted, and how much is left to + * spend on saying where the work got to. + * + * It reports what the command was *granted* rather than what was "left when it + * started", because those come apart: `clampToBudget` floors at one second, so + * a command starting on an already-overspent clock is granted 1s when nothing + * was left. Granted is true by construction; left was not. + */ +export function wallBudgetTimeoutNotice( + requestedSeconds: number, + grantedSeconds: number, +): string { + const left = remainingMs(); + + // Omitted rather than guessed when the deadline has been cleared between the + // command starting and its error surfacing. `?? 0` would state "about 0s + // remain" — a confident wrong number, where saying nothing is merely quiet. + const remaining = + left === undefined + ? "" + : ` About ${Math.max(0, Math.round(left / 1000))}s of the turn remain.`; + + return ( + `The turn's wall-clock budget ended this, not the ${requestedSeconds}s timeout ` + + `requested: the budget allowed it only ${grantedSeconds}s.${remaining} ` + + `Running it again with more time cannot work — the same clock cuts the next ` + + `call shorter still. Spend what is left reporting where the work got to.` + ); +}