From 68d7ea65a2496571da9f1af094b7c4a6fd6b77af Mon Sep 17 00:00:00 2001 From: bchanot Date: Sun, 11 Oct 2026 18:56:14 +0200 Subject: [PATCH] =?UTF-8?q?feat(model-router):=20wave=204-A=20=E2=80=94=20?= =?UTF-8?q?transition-only=20logs,=20residual=20hardening?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit verbose now logs one line per real change, built from the decision itself: main 'fable/high → fable/xhigh (plan: skill /ship-feature)' once per turn per transition, a hand-off line per agent dispatch deduped per (type, target) 'main fable/high → agent verifier sonnet/xhigh (row verify, row)', a later agent effort move, and an answered-by anomaly for agents. The four stream lines (step, answered by, spawn, route JSON, skill path) are gone; the host prefixes the plugin name, so the new lines carry none. Lines are built inside safely before next (a log failure never unroutes a step); names are cleaned (≤ 40 code points). Residuals: failure texts go to the log with a generic answer (forget, ask), file fragments cleaned at render, floorFile name allowlisted, __proto__ refused in restoreOf, the changed scan limited to rows, dialog Change offers only shipped phases, a post-answer write failure keeps the key asked. Kit suite 284 → 358. Contract .claude/tasks/contracts/2026-10-11-model-router-w4a-logs-residuals-1637.md, plan r3: 3 lenses (BLOCKER: agent model moves are decided at spawn) + 1 confirmation, feater + 4 rounds, GATE 0 MET, verifier at the cap on coverage (user-accepted), security PASS + 2 MEDIUM fixed. --- CHANGELOG.md | 2 + README.md | 6 +- USAGE.md | 2 +- mods/model-router/hooks/register.test.ts | 863 ++++++++++++++++++++++- mods/model-router/hooks/register.ts | 445 +++++++++--- 5 files changed, 1219 insertions(+), 99 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f9b619d..74a59b1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ Format follows [Keep a Changelog](https://keepachangelog.com/) and this project - **Manual-push mode**: `git config gitflow.autopush false` (human-set) now stops every push the gitflow lib makes, not only the post-commit / post-merge hooks. `gitflow start` and `finish` branch, commit and merge locally and push nothing; `gitflow delete` leaves the `origin/` copy in place and prints `git push origin --delete
` for the user to run. `hooks/unpushed-guard.sh` stays silent at turn end in this mode and opens each session with one `ℹ manual push mode:` line counting the commits no remote holds across every local branch; an unparseable or unreadable `gitflow.autopush` value is treated as manual push mode too, and that line names it. `hooks/push-guard.sh` (PreToolUse, `Bash|Monitor`) refuses any `git push` Claude types while `gitflow.autopush` reads false in the session cwd or in a literal `-C`/`cd` directory the command names (global config counts outside a repo); the refusal tells the user to run it with `! git push`. It reads the mode through the same lib verb as every other reader and fails closed: an unparseable or unreadable value reads as manual, and an internal error, a missing `lib/gitflow.sh`, more than 20 distinct directory tokens in one command (capped before any token is classified), a `cd`/`-C` directory token mixing quoted and unquoted parts, or a payload jq cannot parse whose raw text looks like a push refuse the push (these pathological cases fire in auto mode too). Directory tokens are read as whole shell words, adjacent quoted segments and backslash escapes included. In manual mode it over-blocks any command where a `push` word follows a `git` token; the misses listed in its header fall to a new `autoMode.soft_deny` rule that no request in the turn clears. The session banner adds `🔒 push : manual (autopush=false) — ! git push` when the key reads false, and `🔒 push : manual (autopush bad) — ! git push` when the value is invalid. Skills read the mode through a new lib verb, `bash ~/.claude/lib/gitflow.sh push-mode`: it prints `auto`, `manual` or `invalid` (rc 0) and names an invalid value on stderr (printable characters only, 64 at most). It is the one reader a skill may call, since the `git config` read of the key is denied to Claude. Skills push nothing on their own, except the `/release-candidate` tag in auto-push mode on an explicit go. Every "on origin" or "not pushed" line they print comes from `git rev-list --count origin/
..
` read after the fact, with the complete `! git …` command when something is left for the user to push. An invalid value (anything but unset, true or false, or a read that fails) is manual push mode for every reader and is named where it is read (see Fixed). Tests: `lib/gitflow-test.sh` T11b (push-mode verb), T18m and T18q blocks, `lib/tests/unpushed-guard.test.sh` T10-T16, `lib/tests/push-guard.test.sh` (98 checks). ### Changed +- model-router `verbose: true` logs transitions only: one line when main changes model or effort (`model-router: main: fable/high → fable/xhigh (plan: route tool)`), one hand-off line per dispatch and one per later effort move of an agent, each with its cause; the per-step, "answered by", spawn, route-tool and skill-path lines are gone. An agent answering on a model other than the planned one is said once. A non-boolean `verbose` falls back to `false`, said once. - `security-auditor` runs on the `judge` row (opus/xhigh) by a first-use decision; its frontmatter floor is aligned (`model: opus`). - `lib/model-gate.md` calls the model-router `route` tool and takes its answer as the witness; with the mod off the gate stops and names `/route on`. The `model:` / `effort:` frontmatter of agents and skills is now the off-state floor, census-locked equal to the rows (`lib/tests/effort-routing.test.sh`; a row changed through the first-use dialog passes with a `WARN floor drift` line while its frontmatter still holds the shipped value). `analyzer` effort goes from high to xhigh. Built-in judgment dispatches carry an explicit `effort=`. - `settings.json` denies every write form of the human-only `gitflow.*` keys (18 entries): any `git … config` spelling, section remove/rename, `git -c`, the git config env overrides, and Edit/Write of `.git/config`, `.gitconfig` and `~/.config/git/config`. Side effect: Claude can no longer read `gitflow.autopush` through `git config` either; hooks and `lib/gitflow.sh` still read it. The `hard_deny` rule on routing around a guardrail now names PreToolUse hook refusals. @@ -25,6 +26,7 @@ Format follows [Keep a Changelog](https://keepachangelog.com/) and this project - The five `effort-low` … `effort-max` skills, `lib/effort-pins.txt`, `lib/effort-pins.sh` and `lib/model-check.sh`, with their tests and the effort-pin re-apply steps of `install-plugins.sh` and `update-all.sh`. The model-router rows replace them. A typed `/effort-` no longer exists: use `ultrathink` or `/route effort=max`. Breaking: the next release is 3.0.0. ### Fixed +- model-router residuals of the confirmation waves: a failed `/route forget` or `/route ask` write logs its cause and answers a generic text; forget answers clean every file-sourced name, phase and key; a restore names a frontmatter file only for a valid skill name and refuses a `__proto__` row; `/route forget` never restores `changed.phases`; the dialog's Change offers and writes shipped phases only (a machine-only phase never reaches routing.json, and an alias no shipped phase uses says so); a failure after the user answered keeps the key asked instead of asking again at every use. - `gitflow delete` (and `finish`) land on the base that contains the branch and drop the branch's upstream before `git branch -d`, so a branch whose upstream lags (manual-push mode) is deleted instead of refused by git (T18k). - An invalid `gitflow.autopush` value (not a boolean, or a config read that fails) no longer pushes. The post-commit / post-merge hooks and every push site of `lib/gitflow.sh` (`start`, `finish`, the `origin/` cleanup of `delete`) read it as auto and pushed; they now push nothing and say why. Each hook run prints `gitflow post-commit: gitflow.autopush unreadable (git rc ) — NOT pushed, treated as manual push mode; fix the value by hand` (post-merge likewise), and the lib passes through the `push-mode` verb's line, `gitflow.sh push-mode: gitflow.autopush='' is not a boolean (git rc )`. A repo with its own committed `.githooks/` (onboarded projects) keeps running its old hooks, which still push on an invalid value, until a session start runs `reconcile-hooks` and rewrites them; commit that refresh so other clones get it. Tests: `lib/gitflow-test.sh` T18q block. diff --git a/README.md b/README.md index 421ea41..24b0cbb 100644 --- a/README.md +++ b/README.md @@ -135,12 +135,12 @@ effort, never version. Transcript audit `python3 lib/effort-audit.py`. - Main loop: every request gets the route in force. A typed skill with a row routes the main loop to it; a best-tier row (`plan`, `reflect`, `orchestrate`, `escalate`) holds across turns in a run slot until `/route clear`, `/route off`, a user `/model` or a typed skill on a non-best row. A skill without a row leaves the route as it is. - Sub-agents: a routed agent gets its row's model at spawn, within its tier and only upward from its frontmatter model, and the row's effort on every step. Explicit `model` / `effort` params on the Agent call win; a project-defined agent of the same name keeps its own definition. Built-ins: Explore runs on sonnet/medium, Plan on opus/xhigh. - Levers inside a run: `ultrathink` in a prompt sets the turn's minimum effort; `/route effort=max` holds until `/route clear`. The built-in `/effort` is not a lever inside a run, rows and routes outrank it. -- `/route` (user command) shows or sets the route: `show`, `clear`, `off`, `on`, `reload`, `pending` (rows and phases not confirmed yet), `ask on|off` (first-use dialog on or off), `forget ` (takes decisions back: a changed row returns to its shipped phase; `all` and `projects` ask first), a phase name, `model= effort=`, `switch on|off`, `verbose on|off`. `/route show` names the run slot when one holds (`main: run `). The model sets routes through a `route` tool. +- `/route` (user command) shows or sets the route: `show`, `clear`, `off`, `on`, `reload`, `pending` (rows and phases not confirmed yet), `ask on|off` (first-use dialog on or off), `forget ` (takes decisions back: a changed row returns to its shipped phase; `all` and `projects` ask first), a phase name, `model= effort=`, `switch on|off`, `verbose on|off` (logs transitions only: each change of model or effort, with a few words of cause). `/route show` names the run slot when one holds (`main: run `). The model sets routes through a `route` tool. - First use: the first time a rowed skill is typed, a rowed agent is spawned or a phase is declared on the main loop through the `route` tool, the mod asks once whether the route is right. The question gives context: the skill's description (first sentence of its `SKILL.md` frontmatter) or the agent's, the phase with its `about` line, and the model id and effort the next step really runs on; a declared phase also says what uses it (rows, prompt rules). A row offers Later, Keep or Change; a declared phase offers Later or Keep. Change asks the model (fable, opus, sonnet, haiku, each shown with the tier it heads), then the effort among those the phases on that model use (shipped table: fable medium, high, xhigh or max; sonnet low, medium, high or xhigh; opus and haiku have one level each, so no question), then Everywhere or This project only. Rows stay phase names, so the pair maps to an existing phase: the row's current phase wins a tie and the same phase counts as Keep; a pair no phase offers needs a new phase added by hand in routing.json. Everywhere moves the row and records the shipped phase under `changed`; This project only stores an exception under `projects`, keyed by the origin remote reduced to `host/path` (no credentials, no local paths; a remote that cannot be read that way offers no project choice). Keep lands under `confirmed`; Later, a dismissed dialog or a free-text answer asks again next session. After a skill row changes, a toast names the model and effort that skill now runs on, plus the `/route switch on` hint when the main loop holds back a downgrade. One dialog at a time, never in a headless (`-p`) run, never inside a sub-agent. - Only a dialog answer, `/route ask on|off` or `/route forget` writes `routing.json`, never the model. Writes are serialized, capped at 64 KiB, and refused when the file is missing (it is never created). Each write leaves the config repo dirty; a toast reminds you to commit it from there. - The spinner suffix and the status line under the prompt show the route in force. -Config layers: `mods/model-router/routing.json` (tracked: phases with their tier, effort and `about` line, rows, decisions, `ask`), then the optional per-machine `~/.claude/model-router.json`, which wins. A `.claude/model-router.json` inside a project is never read. Machine keys: `models` (alias → full id), `windows` (context window per full id), `tiers` (ordered alias lists per tier: `best` fable>opus>sonnet, `big` opus>fable>sonnet, `work` sonnet>opus, `cheap` haiku>sonnet; the first alias not down is used), `fallback` (the rank order of the aliases, best first, used by the breaker), `cooldownMinutes` (how long a model stays marked down after an availability error, 15 by default, doubling per episode up to 300), `mainUpgrade` (default `true`: the main loop may move up to a phase's tier), `upgradeMaxTokens` (default 200000: no main-loop upgrade above this context size, since an upgrade re-reads the whole context cold), `phases`, `agents`, `skills`, `prompt` (rules), `mainModelSwitch` (default `false`), `verbose` (default `false`), `spinner` (default `true`), `enabled` (default `true`; `false` turns the mod off on that machine), `ask` (overrides routing.json's `ask` on that machine). A `null` value in `agents` or `skills` drops a row. Edit phases and rows by hand in routing.json (a phase's `about`, 120 characters at most, is read from there only and shown in the dialog; a model and effort pair no phase offers needs a new phase there); without it the mod runs the code's default phases, with no rows and no dialog. `/route reload` re-reads both files. +Config layers: `mods/model-router/routing.json` (tracked: phases with their tier, effort and `about` line, rows, decisions, `ask`), then the optional per-machine `~/.claude/model-router.json`, which wins. A `.claude/model-router.json` inside a project is never read. Machine keys: `models` (alias → full id), `windows` (context window per full id), `tiers` (ordered alias lists per tier: `best` fable>opus>sonnet, `big` opus>fable>sonnet, `work` sonnet>opus, `cheap` haiku>sonnet; the first alias not down is used), `fallback` (the rank order of the aliases, best first, used by the breaker), `cooldownMinutes` (how long a model stays marked down after an availability error, 15 by default, doubling per episode up to 300), `mainUpgrade` (default `true`: the main loop may move up to a phase's tier), `upgradeMaxTokens` (default 200000: no main-loop upgrade above this context size, since an upgrade re-reads the whole context cold), `phases`, `agents`, `skills`, `prompt` (rules), `mainModelSwitch` (default `false`), `verbose` (default `false`; `true` logs transitions only, a non-boolean value falls back to `false`), `spinner` (default `true`), `enabled` (default `true`; `false` turns the mod off on that machine), `ask` (overrides routing.json's `ask` on that machine). A `null` value in `agents` or `skills` drops a row. Edit phases and rows by hand in routing.json (a phase's `about`, 120 characters at most, is read from there only and shown in the dialog; a model and effort pair no phase offers needs a new phase there); without it the mod runs the code's default phases, with no rows and no dialog. `/route reload` re-reads both files. Limits: the main loop changes model only with `mainModelSwitch` on, and each switch into another model costs one cold-cache step. The hooks send full model ids, so the `models` table has to follow new model versions. @@ -234,7 +234,7 @@ a different package, ships its own conflicting `graphify` bin) — see | `/profile` | Activate a skill profile (web / seo / web-full / full / max / backend / design / dev / qa / audit / minimal) (default: full) | | `/tour` | Grouped all-axes sweep — cleanup + security + reconcile + doc, fix and loop until clean | | `/site-motion` | Site-level motion: scroll engine choice, page transitions, pin/scrub sequencing across a page or Astro route (design stack) | -| `/route` | model-router mod: show or set the main-loop route (show, clear, off, on, reload, pending, ask on\|off, , model=… effort=…, switch on\|off, verbose on\|off) | +| `/route` | model-router mod: show or set the main-loop route (show, clear, off, on, reload, pending, ask on\|off, , model=… effort=…, switch on\|off, verbose on\|off: transitions only) | > This table lists personal skills. Gstack skills (investigate, review, retro, > office-hours, cso…) and marketplace plugins add many more — run diff --git a/USAGE.md b/USAGE.md index b4d37f2..21c05cc 100644 --- a/USAGE.md +++ b/USAGE.md @@ -163,7 +163,7 @@ Tu veux... | `/pdf-translate` | Traduire un PDF vers une autre langue | Sortie HTML fidèle (images, layout, style préservés) | | `/impeccable` | Audit/polish design + détecteur anti-slop déterministe | 23 verbes ; `npx impeccable detect` (exit 0/2) | | `/tour` | Sweep groupé sur un ou plusieurs projets | Sécu + nettoyage + reconcile + doc, boucle jusqu'à un pass propre | -| `/route` | Voir ou fixer la route du mod model-router | show / clear / off / on / reload / pending / ask on\|off / / model=… effort=… / switch on\|off / verbose on\|off | +| `/route` | Voir ou fixer la route du mod model-router | show / clear / off / on / reload / pending / ask on\|off / / model=… effort=… / switch on\|off / verbose on\|off (transitions seules) | | `/profile` | Changer le profil de skills | web / seo / web-full / full / max / backend / design / dev / qa / audit / minimal | > Cette table couvre les skills personnels principaux. Les plugins (gstack, diff --git a/mods/model-router/hooks/register.test.ts b/mods/model-router/hooks/register.test.ts index 55824c0..96d61cd 100644 --- a/mods/model-router/hooks/register.test.ts +++ b/mods/model-router/hooks/register.test.ts @@ -2039,7 +2039,7 @@ test('T3: routing.json unreadable at the dialog asks nothing', async ( expect(w.asked).toEqual([]) }) -test('T1: a failed write applies the default, key left unasked', async ( +test('T1: a failed write applies the default, key stays asked', async ( $, on) => { const logs = recordLogs(on) const w = asks(['Keep', 'Later']) @@ -2050,24 +2050,39 @@ test('T1: a failed write applies the default, key left unasked', async ( expect(logs.join('\n')).toContain('first-use dialog failed') w.failWrite = false await typeFeat($) + expect(w.asked).toHaveLength(1) +}) + +test('T1: after a failed write the next session asks again', async ( + $, on) => { + on('session.end', ($, e) => ({ sessionId: e.sessionId })) + const w = asks(['Keep', 'Later']) + await bootRun($, on, FABLE, w) + w.failWrite = true + await typeFeat($) + w.failWrite = false + await clearOf($) + await typeFeat($) expect(w.asked).toHaveLength(2) }) const failures = (logs: string[]): string[] => logs.filter(l => l.includes('first-use dialog failed')) -test('T1: two failed writes log the failure once', async ($, on) => { +test('T1: two rows failing to write log the failure once', async ( + $, on) => { const logs = recordLogs(on) const w = asks(['Keep', 'Keep']) await bootRun($, on, FABLE, w) w.failWrite = true await typeFeat($) - await typeFeat($) + await typed($, '/status') + await skillPrompt($, 'status') expect(w.asked).toHaveLength(2) expect(failures(logs)).toHaveLength(1) }) -test('T1: a rebuild failing after the write leaves the key unasked', async ( +test('T1: a rebuild failing after the write keeps the key asked', async ( $, on) => { const logs = recordLogs(on) const w = asks([...TO_IMPLEMENT, 'Everywhere']) @@ -2077,7 +2092,7 @@ test('T1: a rebuild failing after the write leaves the key unasked', async ( expect((routingOf(w).skills as Rec).feat).toBe('implement') expect(await mainNow($)).toContain('skill reflect') const pending = (await route($, 'pending')).split('\n') - expect(pending[1]).toBe('asked this session: none') + expect(pending[1]).toBe('asked this session: skills:feat') expect(failures(logs)).toHaveLength(1) expect(failures(logs)[0]).toContain('rebuild failed after the write') }) @@ -2827,15 +2842,21 @@ for (const [label, phase] of [ }) } -test('change: an alias no phase uses is a Later and says so', async ( +/** The shipped mechanical phase moved off haiku: no shipped phase uses it. */ +const lowMechanical = (f: Rec): void => { + (f.phases as Rec).mechanical = { tier: 'work', effort: 'low' } +} + +test('change: an alias no shipped phase uses is a Later and says so', async ( $, on) => { const toasts = recordToasts(on) const w = asks(['Change', 'haiku (cheap)'], { - home: { phases: { mechanical: { tier: 'work', effort: 'low' } } }, + edit: lowMechanical, }) await bootRun($, on, FABLE, w) await typeFeat($) - expect(toasts).toContain('no phase uses haiku') + expect(toasts).toContain( + 'no shipped phase uses haiku: add one to routing.json') expect(w.asked).toHaveLength(2) expect(w.written).toEqual([]) }) @@ -3530,3 +3551,829 @@ test('forget: a non-composer origin is refused, nothing written', async ( expect(out.text).toContain('user-only') expect(w.written).toEqual([]) }) + +// ---- wave 4-A: transition logs -------------------------------------------- + +type LoggedOpts = { + model?: string + answeredBy?: (planned: string) => string // the model a step answers on + world?: World + verbose?: boolean // default true + stepMark?: string // the bottom step pushes this into `logs` +} + +const usageFor = (model: string) => ({ + model, + input_tokens: 0, + output_tokens: 0, + cache_read_input_tokens: 0, + cache_creation_input_tokens: 0, +}) + +type Logged = { logs: string[]; seen: Seen[] } + +/** A run with every bottom hook a logged scenario needs, verbose on. */ +async function bootLogged( + $: Engine, + on: On, + o: LoggedOpts = {}, +): Promise { + const logs = recordLogs(on) + const seen: Seen[] = [] + let spawned = 0 + on('turn.step', async function* ($, e) { + seen.push({ model: e.model, effort: e.effort }) + if (o.stepMark !== undefined) logs.push(o.stepMark) + return { + turnId: e.turnId, + index: e.index, + answer: '', + toolUses: [], + stopReason: 'end_turn' as const, + usage: o.answeredBy ? usageFor(o.answeredBy(e.model)) : null, + } + }) + on('prompt.submit', ($, e) => ({ text: e.text })) + on('turn.complete', () => ({ text: '' })) + on('session.end', ($, e) => ({ sessionId: e.sessionId })) + on('tool.call', { tool: 'Skill' }, () => ({ + result: { success: true, commandName: 'bottom' }, + })) + on('tool.call', { tool: 'Agent' }, () => ({ + result: { + status: 'async_launched' as const, + agentId: 'a1', + description: 'd', + prompt: 'p', + outputFile: '/tmp/o', + }, + })) + on('agent.spawn', ($, e) => ({ + model: e.model ?? e.parentModel, + agentId: `a${++spawned}`, + })) + await boot($, on, o.model ?? FABLE, 1000, o.world ?? newWorld()) + if (o.verbose !== false) await route($, 'verbose on') + logs.splice(0) + return { logs, seen } +} + +const mainWord = (from: string, to: string, why: string): string => + `main: ${from} → ${to} (${why})` + +test('logs: a main that never changes logs nothing', async ($, on) => { + const { logs } = await bootLogged($, on) + for (let i = 0; i < 3; i++) await runStep($, highStep()) + expect(logs).toEqual([]) +}) + +test('logs: a route-tool plan logs one line, not one per step', async ( + $, on) => { + const { logs } = await bootLogged($, on) + await planRoute($) + await runStep($, highStep()) + await runStep($, highStep()) + expect(logs).toEqual([ + mainWord('fable/high', 'fable/xhigh', 'plan: route tool'), + ]) +}) + +test('logs: a typed skill names itself as the cause', async ($, on) => { + const { logs } = await bootLogged($, on) + await typeFeat($) + await runStep($, stepInput()) + expect(logs).toEqual([ + mainWord('fable/low', 'fable/high', 'reflect: skill /feat'), + ]) +}) + +test('logs: an upgrade rides on the same line', async ($, on) => { + const { logs } = await bootLogged($, on, { model: SONNET }) + await typeFeat($) + await runStep($, { ...highStep(), model: SONNET }) + expect(logs).toEqual([ + mainWord('sonnet/high', 'fable/high', 'reflect: skill /feat, upgrade'), + ]) +}) + +test('logs: a downgrade is a switch', async ($, on) => { + const { logs } = await bootLogged($, on) + await route($, 'switch on') + await route($, 'mechanical') + await runStep($, highStep()) + expect(logs).toEqual([ + mainWord('fable/high', 'haiku/-', 'mechanical: sticky /route, switch'), + ]) +}) + +test('logs: a model down names the alias it left', async ($, on) => { + const { logs } = await bootLogged($, on) + await runStep($, highStep()) + await failWith($, 'rate_limit') + logs.splice(0) + await runStep($, highStep()) + expect(logs).toEqual([ + mainWord('fable/high', 'opus/high', 'session, fallback: fable down'), + ]) +}) + +test('logs: derived orchestrate logs once per turn', async ($, on) => { + const { logs } = await bootLogged($, on) + await runStep($, highStep()) + await dispatch($) + await runStep($, highStep()) + await agentEnds($) + await runStep($, highStep()) + await dispatch($) + await runStep($, highStep()) + const waves = logs.filter(l => l.includes('orchestrate: dispatch')) + expect(waves).toEqual([ + mainWord('fable/high', 'fable/medium', 'orchestrate: dispatch'), + ]) +}) + +test('logs: an ultrathink floor names the prompt floor', async ($, on) => { + const { logs } = await bootLogged($, on) + await ultrathink($) + await runStep($, highStep()) + expect(logs).toEqual([ + mainWord('fable/high', 'fable/max', 'escalate: prompt floor'), + ]) +}) + +test('logs: a sticky /route names itself', async ($, on) => { + const { logs } = await bootLogged($, on) + await route($, 'xhigh') + await runStep($, highStep()) + expect(logs).toEqual([ + mainWord('fable/high', 'fable/xhigh', 'custom: sticky /route'), + ]) +}) + +test('logs: a default prompt rule says prompt rule', async ($, on) => { + const { logs } = await bootLogged($, on) + await typed($, 'explain why it fails') + await runStep($, stepInput()) + expect(logs).toEqual([ + mainWord('fable/low', 'fable/high', 'reflect: prompt rule'), + ]) +}) + +test('logs: after /clear the first step compares to the engine', async ( + $, on) => { + const { logs } = await bootLogged($, on) + await route($, 'xhigh') + await runStep($, highStep()) + logs.splice(0) + await clearOf($) + await runStep($, highStep()) + expect(logs).toEqual([]) +}) + +test('logs: /route on after off compares to the engine', async ($, on) => { + const { logs } = await bootLogged($, on) + await route($, 'xhigh') + await runStep($, highStep()) + await endTurn($) + await route($, 'off') + await route($, 'on') + await runStep($, highStep()) + expect(logs.filter(l => l.includes('sticky'))).toHaveLength(2) +}) + +test('logs: a failing log never unroutes the step', async ($, on) => { + const { logs, seen } = await bootLogged($, on) + await route($, 'xhigh') + const poison = { toString: 1 } // String(poison) throws + await runStep($, { ...highStep(), effort: poison as never }) + expect(seen[seen.length - 1]?.effort).toBe('xhigh') + expect(logs.join('\n')).toContain('turn.step log failed') +}) + +test('logs: verbose off logs no transition', async ($, on) => { + const { logs } = await bootLogged($, on, { verbose: false }) + await planRoute($) + await runStep($, highStep()) + await typeFeat($) + await $.agent.spawn(spawnOf('feater')) + expect(logs).toEqual([]) +}) + +test('logs: the transition line precedes the step below it', async ( + $, on) => { + const { logs } = await bootLogged($, on, { stepMark: 'STEP' }) + await planRoute($) + await runStep($, highStep()) + expect(logs).toEqual([ + mainWord('fable/high', 'fable/xhigh', 'plan: route tool'), + 'STEP', + ]) +}) + +test('logs: switch warnings keep their exact texts', async ($, on) => { + const logs = recordLogs(on) + const home = { verbose: 'ON', enabled: 'no' } + await bootRun($, on, FABLE, newWorld({ home })) + expect(logs).toContain('config "verbose" is not a boolean; ignored') + expect(logs).toContain( + 'model-router: config "enabled" is not a boolean; ignored') +}) + +for (const bad of ['ON', 1, null]) { + test(`logs: verbose ${JSON.stringify(bad)} falls back to off`, async ( + $, on) => { + const logs = recordLogs(on) + await bootRun($, on, FABLE, newWorld({ home: { verbose: bad } })) + expect(logs.filter(l => l.includes('"verbose" is not a boolean'))) + .toHaveLength(1) + expect(await route($, 'show')).toContain('verbose: off') + }) +} + +test('logs: verbose true in the override turns the lines on', async ( + $, on) => { + await bootRun($, on, FABLE, newWorld({ home: { verbose: true } })) + expect(await route($, 'show')).toContain('verbose: on') +}) + +/** What each of the old firehose lines would have been triggered by. */ +const LEGACY: [string, string, ($: Engine) => Promise][] = [ + ['step', 'step ', $ => runStep($, highStep())], + ['answered by', 'answered by', $ => runStep($, highStep())], + ['skill path', 'skill ', $ => typeFeat($)], + ['route json', 'route main', $ => planRoute($)], + ['spawn', 'spawn ', $ => $.agent.spawn(spawnOf('feater'))], +] + +for (const [name, text, act] of LEGACY) { + test(`logs: the old ${name} line is gone at true`, async ($, on) => { + const { logs } = await bootLogged($, on) + await act($) + await runStep($, highStep()) + expect(logs.filter(l => l.includes(text))).toEqual([]) + }) +} + +// ---- wave 4-A: agent lines ---------------------------------------------- + +const handoffs = (logs: string[]): string[] => + logs.filter(l => l.includes(' → agent ')) + +/** A main step first, so the hand-off starts from fable/high. */ +async function afterMainStep($: Engine, on: On, o: LoggedOpts = {}) { + const run = await bootLogged($, on, o) + await runStep($, highStep()) + return run +} + +test('logs: a rowed spawn is one hand-off line, then silence', async ( + $, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('feater')) + const line = 'main fable/high → agent feater sonnet/medium ' + + '(row implement, row)' + expect(logs).toEqual([line]) + await runStep($, { ...highStep('a1'), model: SONNET }) + await runStep($, { ...highStep('a1'), model: SONNET }) + expect(logs).toEqual([line]) +}) + +test('logs: an explicit model is its own cause', async ($, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('feater', { model: 'opus' })) + expect(logs).toEqual([ + 'main fable/high → agent feater opus/medium ' + + '(explicit, row)', + ]) +}) + +test('logs: an explicit effort is one line, then silence', async ($, on) => { + const { logs } = await afterMainStep($, on) + await $.tool.call({ + tool: 'Agent', description: 'd', prompt: 'p', effort: 'low', + tool_use_id: 't1', + }) + await $.agent.spawn(spawnOf('feater')) + const line = 'main fable/high → agent feater sonnet/low ' + + '(row implement, explicit)' + expect(logs).toEqual([line]) + await runStep($, { ...stepInput('a1'), model: SONNET }) + expect(logs).toEqual([line]) +}) + +test('logs: a haiku spawn shows no effort, then silence', async ($, on) => { + const world = newWorld({ + edit: f => { (f.agents as Rec).feater = 'mechanical' }, + }) + const { logs } = await afterMainStep($, on, { world }) + await $.agent.spawn(spawnOf('feater')) + const line = 'main fable/high → agent feater haiku/- ' + + '(row mechanical, row)' + expect(logs).toEqual([line]) + await runStep($, { ...highStep('a1'), model: HAIKU }) + expect(logs).toEqual([line]) +}) + +test('logs: three parallel challengers are one hand-off line', async ( + $, on) => { + const { logs } = await afterMainStep($, on) + await Promise.all([1, 2, 3].map(() => + $.agent.spawn(spawnOf('plan-challenger')))) + expect(handoffs(logs)).toHaveLength(1) +}) + +test('logs: two agent types to one model are two hand-offs', async ( + $, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('feater')) + await $.agent.spawn(spawnOf('Explore')) + expect(handoffs(logs)).toHaveLength(2) +}) + +test('logs: one agent type to two models is two hand-offs', async ( + $, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('feater')) + await $.agent.spawn(spawnOf('feater', { model: 'opus' })) + expect(handoffs(logs)).toHaveLength(2) +}) + +test('logs: a tier moved up in-tier names the alias that was down', async ( + $, on) => { + const { logs } = await bootLogged($, on) + await switchTo($, OPUS, SONNET, 'auto') + await $.agent.spawn(spawnOf('plan-challenger')) + expect(handoffs(logs)).toEqual([ + 'main fable/- → agent plan-challenger fable/xhigh ' + + '(fallback: opus down, row)', + ]) +}) + +test('logs: a tier down keeps the frontmatter, said as such', async ( + $, on) => { + const { logs } = await bootLogged($, on) + await switchTo($, OPUS, SONNET, 'auto') + await switchTo($, FABLE, SONNET, 'auto') + await $.agent.spawn(spawnOf('plan-challenger')) + expect(handoffs(logs)[0]).toContain('(frontmatter, row)') +}) + +test('logs: an in-agent route tool move is one line', async ($, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('feater')) + logs.splice(0) + await $.tool.call({ tool: ROUTE_TOOL, phase: 'judge', agentId: 'a1' }) + await runStep($, { ...highStep('a1'), model: SONNET }) + await runStep($, { ...highStep('a1'), model: SONNET }) + expect(logs).toEqual([ + 'agent feater: sonnet/medium → sonnet/xhigh (route tool)', + ]) +}) + +test('logs: an agent moving twice logs both moves', async ($, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('feater')) + logs.splice(0) + await $.tool.call({ tool: ROUTE_TOOL, phase: 'judge', agentId: 'a1' }) + await runStep($, { ...highStep('a1'), model: SONNET }) + await $.tool.call({ tool: ROUTE_TOOL, phase: 'implement', agentId: 'a1' }) + await runStep($, { ...highStep('a1'), model: SONNET }) + expect(logs).toHaveLength(2) + expect(logs[1]).toContain('sonnet/xhigh → sonnet/medium (route tool)') +}) + +test('logs: an in-agent skill move names the skill', async ($, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('feater')) + logs.splice(0) + await loadSkill($, 'status', 'a1') + await runStep($, { ...highStep('a1'), model: SONNET }) + expect(logs).toEqual([ + 'agent feater: sonnet/medium → sonnet/low (skill status)', + ]) +}) + +const answers = (logs: string[]): string[] => + logs.filter(l => l.includes('answered by')) + +/** One agent step on the planned model, the engine answering on `by`. */ +async function agentAnswer($: Engine, on: On, by: string, planned = SONNET) { + const run = await afterMainStep($, on, { answeredBy: () => by }) + await $.agent.spawn(spawnOf('feater')) + await runStep($, { ...highStep('a1'), model: planned }) + await runStep($, { ...highStep('a1'), model: planned }) + return run +} + +test('logs: an agent answered by another model is said once', async ( + $, on) => { + const { logs } = await agentAnswer($, on, OPUS) + expect(answers(logs)).toEqual([ + 'agent feater answered by opus instead of sonnet', + ]) +}) + +test('logs: a [1m] suffix alone is not an answer anomaly', async ($, on) => { + const { logs } = await agentAnswer($, on, SONNET, `${SONNET}[1m]`) + expect(answers(logs)).toEqual([]) +}) + +test('logs: a [1m] usage against a bare plan is no anomaly', async ( + $, on) => { + const { logs } = await agentAnswer($, on, `${SONNET}[1m]`) + expect(answers(logs)).toEqual([]) +}) + +test('logs: a second agent answering off-plan logs its own line', async ( + $, on) => { + const { logs } = await afterMainStep($, on, { answeredBy: () => OPUS }) + await $.agent.spawn(spawnOf('feater')) + await $.agent.spawn(spawnOf('Explore')) + for (const id of ['a1', 'a2']) { + await runStep($, { ...highStep(id), model: SONNET }) + await runStep($, { ...highStep(id), model: SONNET }) + } + expect(answers(logs)).toHaveLength(2) +}) + +test('logs: one agent answering two off-plan models logs twice', async ( + $, on) => { + let n = 0 + const { logs } = await afterMainStep($, on, { + answeredBy: () => (++n % 2 ? OPUS : FABLE) }) + await $.agent.spawn(spawnOf('feater')) + for (let i = 0; i < 4; i++) { + await runStep($, { ...highStep('a1'), model: SONNET }) + } + expect(answers(logs)).toHaveLength(2) +}) + +test('logs: an unanswered usage says nothing', async ($, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('feater')) + await runStep($, { ...highStep('a1'), model: SONNET }) + expect(answers(logs)).toEqual([]) +}) + +test('logs: main answered by another model says nothing here', async ( + $, on) => { + const { logs } = await bootLogged($, on, { answeredBy: () => OPUS }) + await runStep($, highStep()) + expect(answers(logs)).toEqual([]) + expect(logs).toEqual([]) // no bookkeeping warning either +}) + +test('logs: verbose off says no answer anomaly either', async ($, on) => { + const { logs } = await bootLogged($, on, { + answeredBy: () => OPUS, verbose: false }) + await $.agent.spawn(spawnOf('feater')) + await runStep($, { ...highStep('a1'), model: SONNET }) + expect(answers(logs)).toEqual([]) +}) + +// ---- wave 4-A: log guards ------------------------------------------------ + +const CTRL = '\u0007' // a control char inside a name +const LONG = `${'a'.repeat(30)}${CTRL}${'b'.repeat(30)}` +const CUT = `${'a'.repeat(30)}${'b'.repeat(9)}…` // 40 clean code points +const hasCtrl = (text: string): boolean => /[\p{Cc}\p{Cf}]/u.test(text) + +/** A phase named LONG (with a bidi mark), as a routing.json may hold it. */ +const hostilePhase = `${'a'.repeat(30)}\u202e${'b'.repeat(30)}` +const withPhase = (f: Rec): void => { + (f.phases as Rec)[hostilePhase] = { tier: 'best', effort: 'xhigh' } +} + +test('logs: two dispatches in one turn are one hand-off, main moved between', + async ($, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('feater')) + await route($, 'xhigh') + await runStep($, highStep()) + await $.agent.spawn(spawnOf('feater')) + expect(handoffs(logs)).toHaveLength(1) + }) + +test('logs: an agent type is cleaned in the hand-off line', async ( + $, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf(LONG, { model: 'opus' })) + expect(handoffs(logs)).toHaveLength(1) + expect(handoffs(logs)[0]).toContain(`agent ${CUT} `) + expect(hasCtrl(logs.join('\n'))).toBe(false) +}) + +test('logs: a model id is cleaned in the hand-off line', async ($, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('feater', { model: `m${LONG}` })) + expect(handoffs(logs)).toHaveLength(1) + expect(handoffs(logs)[0]).toContain( + `feater m${'a'.repeat(30)}${'b'.repeat(8)}…/`) + expect(hasCtrl(logs.join('\n'))).toBe(false) +}) + +test('logs: an agent type is cleaned in a later move line', async ( + $, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf(LONG, { model: 'opus' })) + logs.splice(0) + await $.tool.call({ tool: ROUTE_TOOL, phase: 'judge', agentId: 'a1' }) + await runStep($, { ...highStep('a1'), model: OPUS }) + expect(logs).toHaveLength(1) + expect(logs[0]).toContain(`agent ${CUT}: `) + expect(hasCtrl(logs[0] ?? '')).toBe(false) +}) + +test('logs: an unchanged sticky /route logs once across turns', async ( + $, on) => { + const { logs } = await bootLogged($, on) + await route($, 'xhigh') + for (let i = 0; i < 3; i++) { + await runStep($, highStep()) + await endTurn($) + } + expect(logs.filter(l => l.includes('sticky /route'))).toHaveLength(1) +}) + +test('logs: an engine-picked effort is named in the hand-off', async ( + $, on) => { + const { logs } = await afterMainStep($, on) + await $.agent.spawn(spawnOf('stranger', { model: 'opus' })) + expect(handoffs(logs)).toHaveLength(1) + expect(handoffs(logs)[0]).toContain('(explicit, engine)') +}) + +// ---- wave 4-A: residuals of waves 3-A, 3-B, 3-C --------------------------- + +test('residual a: a failing forget write answers without the cause', async ( + $, on) => { + const w = forgetWorld(confirmedFeat) + await bootRun($, on, FABLE, w) + w.failWrite = true + const out = await route($, 'forget feat') + expect(out).toBe('forget not applied, see the log') +}) + +test('residual a: a failing forget write logs the cause', async ($, on) => { + const logs = recordLogs(on) + const w = forgetWorld(confirmedFeat) + await bootRun($, on, FABLE, w) + w.failWrite = true + await route($, 'forget feat') + expect(logs.some(l => l.startsWith('forget failed: '))) + .toBe(true) +}) + +test('residual a: a failing ask write answers without the cause', async ( + $, on) => { + const logs = recordLogs(on) + const w = newWorld() + await bootRun($, on, FABLE, w) + w.failWrite = true + expect(await route($, 'ask off')).toBe('ask not applied, see the log') + expect(logs.some(l => l.startsWith('ask failed: '))) + .toBe(true) +}) + +test('residual a: an ask saved but not rebuilt says so', async ($, on) => { + const w = newWorld() + await bootRun($, on, FABLE, w) + w.onWrite = () => { w.files.set(HOME_FILE, '{nope') } + expect(await route($, 'ask off')).toBe( + 'ask saved, config not rebuilt: /route reload') + expect(routingOf(w).ask).toBe(false) +}) + +const ODD = 'x‮y' // a bidi override inside a name + +const bidi = '‮' + +test('residual b: a restored row name is cleaned in the answer', async ( + $, on) => { + const w = newWorld({ edit: f => { + (f.skills as Rec)[ODD] = 'plan' + f.changed = { skills: { [ODD]: { from: 'reflect', to: 'plan' } } } + } }) + await bootRun($, on, FABLE, w) + const out = await route($, `forget ${ODD}`) + expect(out).toContain('(skills.xy → reflect:') +}) + +test('residual b: a restored row\'s old phase is cleaned too', async ( + $, on) => { + const w = newWorld({ edit: f => { + (f.skills as Rec).feat = `pl${bidi}an` + f.changed = { skills: { feat: { from: 'reflect', to: `pl${bidi}an` } } } + } }) + await bootRun($, on, FABLE, w) + const out = await route($, 'forget feat') + expect(out).toContain('was aligned to plan,') + expect(out).not.toContain(bidi) +}) + +test('residual b: a refused restore\'s phase is cleaned', async ($, on) => { + const w = newWorld({ edit: brokenRestore( + { from: `no${bidi}such`, to: 'judge' }) }) + await bootRun($, on, FABLE, w) + const out = await route($, 'forget feater') + expect(out).toContain('nosuch is not a known phase') + expect(out).not.toContain(bidi) +}) + +test('residual b: a refused restore\'s row name is cleaned', async ( + $, on) => { + const w = newWorld({ edit: f => { + f.changed = { skills: { [ODD]: { from: 5, to: 'plan' } } } + } }) + await bootRun($, on, FABLE, w) + const out = await route($, `forget ${ODD}`) + expect(out).toContain('skills.xy: no phase recorded') +}) + +test('residual b: a long row name is cut in the answer only', async ( + $, on) => { + const name = 'a'.repeat(45) + const w = newWorld({ edit: f => { + (f.skills as Rec)[name] = 'plan' + f.changed = { skills: { [name]: { from: 'reflect', to: 'plan' } } } + } }) + await bootRun($, on, FABLE, w) + const out = await route($, `forget ${name}`) + expect(out).toContain(`(skills.${'a'.repeat(39)}… → reflect:`) + expect((routingOf(w).skills as Rec)[name]).toBe('reflect') +}) + +test('residual c: a name outside the skill charset names no file', async ( + $, on) => { + const w = newWorld({ edit: f => { + (f.agents as Rec)['../x'] = 'judge' + f.changed = { agents: { '../x': { from: 'implement', to: 'judge' } } } + } }) + await bootRun($, on, FABLE, w) + const out = await route($, 'forget ../x') + expect(out).toContain('1 row(s) restored') + expect(out).not.toContain('was aligned to') +}) + +/** A file whose `kind` table holds `__proto__` as an OWN key. */ +const protoRow = (kind: string, entry: unknown) => (f: Rec): void => { + const rows = (f[kind] ?? {}) as Rec + Object.defineProperty(rows, '__proto__', { + value: entry, enumerable: true, configurable: true, writable: true, + }) + f[kind] = rows +} + +test('residual d: a __proto__ restore is refused, plan and apply agree', async ( + $, on) => { + const w = newWorld({ edit: f => { + protoRow('skills', 'plan')(f) + const changed: Rec = {} + protoRow('changed', changed)(f) + const skills: Rec = {} + Object.defineProperty(skills, '__proto__', { + value: { from: 'reflect', to: 'plan' }, + enumerable: true, configurable: true, writable: true, + }) + f.changed = { skills } + } }) + await bootRun($, on, FABLE, w) + const out = await route($, 'forget __proto__') + expect(out).toContain('skills.__proto__: reserved name') + expect(w.written).toEqual([]) +}) + +test('residual e: a changed.phases entry is never restored', async ($, on) => { + const w = newWorld({ edit: f => { + (f.phases as Rec).plan = 'reflect' + f.changed = { phases: { plan: { from: 'reflect', to: 'reflect' } } } + } }) + await bootRun($, on, FABLE, w) + expect(await route($, 'forget plan')).toBe('nothing to forget for plan') + expect(w.written).toEqual([]) +}) + +/** The efforts the Change chain offers for fable, from the second question. */ +async function fableEfforts($: Engine, on: On, fx: Fixture) { + const w = asks(['Change', 'fable (best)', 'Later'], fx) + await bootRun($, on, FABLE, w) + await typeFeat($) + return w.asked[2]?.options +} + +const FABLE_EFFORTS = ['medium', 'high', 'xhigh', 'max'] + +test('residual f: a null phase in the file is ignored, no crash', async ( + $, on) => { + const edit = (f: Rec): void => { (f.phases as Rec).plan = null } + expect(await fableEfforts($, on, { edit })).toEqual(FABLE_EFFORTS) +}) + +test('residual f: a file without phases offers the code defaults', async ( + $, on) => { + const edit = (f: Rec): void => { delete f.phases } + expect(await fableEfforts($, on, { edit })).toEqual(FABLE_EFFORTS) +}) + +const CUSTOM_CHEAP = { phases: { custom: { tier: 'cheap', effort: 'high' } } } + +test('residual f: an override-only phase is not offered', async ($, on) => { + const w = asks(['Change', 'haiku (cheap)', 'Later'], { home: CUSTOM_CHEAP }) + await bootRun($, on, FABLE, w) + await typeFeat($) + expect(w.asked[2]?.text).toContain('Use mechanical for feat') +}) + +test('residual f: an override-only phase is never written', async ($, on) => { + const w = asks(['Change', 'haiku (cheap)', 'high', 'Everywhere'], + { home: CUSTOM_CHEAP }) + await bootRun($, on, FABLE, w) + await typeFeat($) + expect((routingOf(w).skills as Rec).feat).toBe('reflect') + expect(w.written).toEqual([]) +}) + +test('residual f: the target is a shipped phase the override redefines', async ( + $, on) => { + const w = asks(['Change', 'haiku (cheap)', 'Everywhere'], { + home: { phases: { mechanical: { tier: 'work', effort: 'medium' } } }, + }) + await bootRun($, on, FABLE, w) + await typeFeat($) + expect((routingOf(w).skills as Rec).feat).toBe('mechanical') +}) + +test('residual f: an alias only an override phase uses toasts, Later', async ( + $, on) => { + const toasts = recordToasts(on) + const w = asks(['Change', 'haiku (cheap)'], { + edit: lowMechanical, + home: { phases: { custom: { tier: 'cheap', effort: 'low' } } }, + }) + await bootRun($, on, FABLE, w) + await typeFeat($) + expect(toasts).toContain( + 'no shipped phase uses haiku: add one to routing.json') + expect(w.written).toEqual([]) +}) + +test('residual b: a hostile restored phase is cleaned in the clause', async ( + $, on) => { + const w = newWorld({ edit: f => { + withPhase(f) + ;(f.skills as Rec).feat = 'plan' + f.changed = { skills: { feat: { from: hostilePhase, to: 'plan' } } } + } }) + await bootRun($, on, FABLE, w) + const out = await route($, 'forget feat') + expect(out).toContain(`skills.feat → ${CUT}:`) + expect(hasCtrl(out)).toBe(false) +}) + +// ---- wave 4-A: hostile skill name ---------------------------------------- + +const HOSTILE_SKILL = `${'a'.repeat(30)}‮${CTRL}${'b'.repeat(30)}` +const skillWorld = (): World => newWorld({ edit: f => { + (f.skills as Rec)[HOSTILE_SKILL] = 'plan' +} }) + +/** The name a line shows after `marker`, up to the closing char. */ +const nameAfter = (line: string, marker: string, end: string): string => + line.slice(line.indexOf(marker) + marker.length).split(end)[0] + +test('logs: a hostile skill name is cleaned in the main line', async ( + $, on) => { + const { logs } = await bootLogged($, on, { world: skillWorld() }) + await runStep($, highStep()) + logs.splice(0) + await loadSkill($, HOSTILE_SKILL) + await runStep($, { ...highStep(), effort: 'low' as const }) + const line = logs.find(l => l.includes('skill /')) ?? '' + const name = nameAfter(line, 'skill /', ')') + expect(name).not.toBe('') + expect(hasCtrl(line)).toBe(false) + expect([...name].length).toBeLessThanOrEqual(40) +}) + +test('logs: a hostile skill name is cleaned in the agent cause', async ( + $, on) => { + const { logs } = await afterMainStep($, on, { world: skillWorld() }) + await $.agent.spawn(spawnOf('feater')) + logs.splice(0) + await loadSkill($, HOSTILE_SKILL, 'a1') + await runStep($, { ...highStep('a1'), model: SONNET }) + const line = logs.find(l => l.includes('(skill ')) ?? '' + const name = nameAfter(line, '(skill ', ')') + expect(name).not.toBe('') + expect(hasCtrl(line)).toBe(false) + expect([...name].length).toBeLessThanOrEqual(40) +}) + +test('logs: an ended agent forgets its answer marks (reused id)', async ( + $, on) => { + const { logs } = await agentAnswer($, on, OPUS) + await agentEnds($) + await $.agent.spawn(spawnOf('feater')) + await runStep($, { ...highStep('a1'), model: SONNET }) + expect(answers(logs)).toHaveLength(2) +}) diff --git a/mods/model-router/hooks/register.ts b/mods/model-router/hooks/register.ts index a73739f..11ba8f9 100644 --- a/mods/model-router/hooks/register.ts +++ b/mods/model-router/hooks/register.ts @@ -37,12 +37,20 @@ type Config = { } type Rule = { re: RegExp; phase: string; mode: PromptMode } type Source = 'user' | 'model' | 'skill' | 'prompt' | 'run' | 'derived' -type Routed = { phase: string; route: Route; source: Source } +type Routed = { + phase: string + route: Route + source: Source + label?: string // the skill a skill route came from, for the logs +} type Hold = { until: number; reason: string } // until: ms, Infinity = reload type Pushed = { prev: Routed | null; spawnIds: Set } type Loop = { effort?: Level // an agent's model is fixed at spawn: effort is its only axis explicitEffort: boolean // Agent call gave an effort: axis frozen + type?: string // subagentType, for the log lines + last?: Plan // the plan this loop last ran, once it was told + cause?: string // who set the effort in force, for the log lines } type State = { cfg: Config @@ -113,6 +121,7 @@ type Memory = { base: Record // the file's rows, before any project layer confirmed: Record // name -> the phase a Keep endorsed about: Table // phase -> its one-line meaning, shown in the dialog only + filePhases: Record // the shipped phases: defaults + the file local: Record> // rows of projects[key] or the override key: string | undefined // normalized repo key; undefined = no project layer } @@ -414,10 +423,15 @@ function mergePrompt( const pickBool = (v: unknown, fallback: boolean): boolean => typeof v === 'boolean' ? v : fallback -/** The kill switch: a non-boolean value is dropped, and said so. */ -function pickEnabled(v: unknown, fallback: boolean, log: Log): boolean { +/** A switch key: a non-boolean is dropped, and `warning` is logged. */ +function pickSwitch( + warning: string, + v: unknown, + fallback: boolean, + log: Log, +): boolean { if (v !== undefined && typeof v !== 'boolean') { - log('model-router: config "enabled" is not a boolean; ignored') + log(warning) } return pickBool(v, fallback) } @@ -496,9 +510,12 @@ function mergeConfig( skills: mergeRows(base.skills, user.skills, 'skills', ref, log), prompt: mergePrompt(base.prompt, user.prompt, phases, log), mainModelSwitch: pickBool(user.mainModelSwitch, base.mainModelSwitch), - verbose: pickBool(user.verbose, base.verbose), + verbose: pickSwitch( + 'config "verbose" is not a boolean; ignored', user.verbose, base.verbose, log), spinner: pickBool(user.spinner, base.spinner), - enabled: pickEnabled(user.enabled, base.enabled, log), + enabled: pickSwitch( + 'model-router: config "enabled" is not a boolean; ignored', + user.enabled, base.enabled, log), } } @@ -584,6 +601,7 @@ function emptyMemory(): Memory { base: { skills: {}, agents: {} }, confirmed: { skills: {}, agents: {}, phases: {} }, about: {}, + filePhases: {}, local: { skills: new Set(), agents: new Set() }, key: undefined, } @@ -630,6 +648,7 @@ function buildMemory( phases: strTable(sure.phases), }, about: aboutOf(file.phases, log), + filePhases: mergeConfig({ phases: file.phases }, () => undefined).phases, local: { skills: local('skills'), agents: local('agents') }, key, } @@ -1231,8 +1250,10 @@ function loopOf(st: State, agentId: string): Loop { } /** Writes a route on an agent loop, never on an axis given explicitly. */ -function writeLoop(loop: Loop, route: Route): void { - if (!loop.explicitEffort) loop.effort = route.effort +function writeLoop(loop: Loop, route: Route, cause: string): void { + if (loop.explicitEffort) return + loop.effort = route.effort + loop.cause = cause } function clearRoutes(st: State): void { @@ -1368,6 +1389,7 @@ function statusLine(st: State): string { const refresh = ($: Api, st: State): void => $.ui.status(statusLine(st)) +/** The one gate of the verbose lines, which say transitions only. */ function vlog($: Api, st: State, text: string): void { if (st.cfg.verbose) $.ui.log(text) } @@ -1497,6 +1519,7 @@ async function handleCommand($: Api, st: State, args: string): Promise { case 'off': st.off = head === 'off' st.offConfig = false + st.lastPlan = null // the next step compares to the engine's input if (st.off) st.runMain = null refresh($, st) return show($, st) @@ -1746,29 +1769,36 @@ async function askModel($: Api, st: State, req: RowReq) { return label === undefined ? undefined : CHOICE_ALIASES[labels.indexOf(label)] } -/** The efforts of the phases headed by `alias`, ascending, four at most. */ -function effortsOf(cfg: Config, alias: string): Level[] { - const found = Object.values(cfg.phases) +/** + * The efforts of the shipped phases headed by `alias`, ascending, four at + * most. A phase only the machine override defines is never offered: the + * answer is written into the tracked file. + */ +function effortsOf(cfg: Config, shipped: Record, alias: string) { + const found = Object.values(shipped) .filter(r => headAlias(cfg, r) === alias).map(r => r.effort) return LEVELS.filter(level => found.includes(level)).slice(0, 4) } /** One effort is no question; none is a Later, said. */ async function askEffort($: Api, st: State, alias: string) { - const efforts = effortsOf(st.cfg, alias) - if (efforts.length === 0) $.ui.toast(`no phase uses ${alias}`) + const efforts = effortsOf(st.cfg, st.mem.filePhases, alias) + if (efforts.length === 0) { + $.ui.toast(`no shipped phase uses ${alias}: add one to ${ROUTING}`) + } if (efforts.length < 2) return efforts[0] const label = await askStep($, `Which effort on ${alias}?`, efforts) return efforts.find(effort => effort === label) } -/** The row's current phase when it matches, else the first that does. */ -function targetPhase(cfg: Config, now: string, alias: string, effort: Level) { +/** The row's phase when it matches, else the first shipped one that does. */ +function targetPhase(st: State, now: string, alias: string, effort: Level) { + const shipped = st.mem.filePhases const fits = (name: string): boolean => { - const route = phaseRoute(cfg, name) - return route?.effort === effort && headAlias(cfg, route) === alias + const route = hasKey(shipped, name) ? shipped[name] : undefined + return route?.effort === effort && headAlias(st.cfg, route) === alias } - return fits(now) ? now : Object.keys(cfg.phases).find(fits) + return fits(now) ? now : Object.keys(shipped).find(fits) } /** Change: model, then effort, mapped to a phase of the table. */ @@ -1776,7 +1806,7 @@ async function changeRoute($: Api, st: State, req: RowReq): Promise { const alias = await askModel($, st, req) const effort = alias === undefined ? undefined : await askEffort($, st, alias) if (alias === undefined || effort === undefined) return { act: 'later' } - const phase = targetPhase(st.cfg, req.phase, alias, effort) + const phase = targetPhase(st, req.phase, alias, effort) if (phase === undefined) return { act: 'later' } return phase === req.phase ? { act: 'keep' } : { act: 'change', phase } } @@ -1890,6 +1920,12 @@ function writeRouting($: Api, st: State, patch: Patch): Promise { return run } +/** A write that failed: the cause goes to the log, never to the answer. */ +function failedWrite($: Api, cmd: string, err: unknown): string { + $.ui.log(`${cmd} failed: ${String(err)}`) + return `${cmd} not applied, see the log` +} + async function saveAnswer($: Api, st: State, req: Req, ans: Answer) { if (ans.act === 'keep') return writeRouting($, st, keepPatch(req)) if (ans.act !== 'change' || !isRowReq(req)) return false @@ -1899,10 +1935,21 @@ async function saveAnswer($: Api, st: State, req: Req, ans: Answer) { return writeRouting($, st, patch) } -/** The dialog and what follows; true when routing.json was rewritten. */ +/** + * The dialog and what follows; true when routing.json was rewritten. A + * failure before the user answered leaves the key unasked (the next use + * asks again); one after it keeps the key asked, the answer being given. + */ async function runDialog($: Api, st: State, req: Req, text: string) { st.asked.add(keyOf(req)) - return saveAnswer($, st, req, await decide($, st, req, text)) + let answer: Answer + try { + answer = await decide($, st, req, text) + } catch (err) { + st.asked.delete(keyOf(req)) + throw err + } + return saveAnswer($, st, req, answer) } function failOnce($: Api, st: State, err: unknown): void { @@ -1932,7 +1979,6 @@ async function confirmFirst( if (!(await refreshMemory($, st)) || !wantsAsk(st, req)) return false return await runDialog($, st, req, await say()) } catch (err) { - st.asked.delete(keyOf(req)) failOnce($, st, err) return false } finally { @@ -1990,7 +2036,7 @@ async function confirmSkill($: Api, st: State, skill: string, row: Picked) { if (!(await confirmFirst($, st, req, say))) return const after = skillRow(st, skill) if (after === undefined) return - routeMainBySkill(st, after, true) + routeMainBySkill(st, skill, after, true) refresh($, st) if (after.phase !== row.phase) await toastChange($, st, skill) } @@ -2049,7 +2095,9 @@ async function askCommand($: Api, st: State, arg: string | undefined) { return `${ROUTING} missing or unreadable: ask unchanged` } } catch (err) { - return `ask not applied (${String(err)})` + return err instanceof RebuildFailed + ? 'ask saved, config not rebuilt: /route reload' + : failedWrite($, 'ask', err) } const local = st.mem.askLocal const note = local === undefined ? '' : `; ~/${OVERRIDE} sets ask ${ @@ -2065,10 +2113,11 @@ async function askCommand($: Api, st: State, arg: string | undefined) { type Target = { label: string; name?: string; only?: 'projects' } type Restore = { kind: Kind; name: string; from: string; to: string } +type Kept = { kind: Kind; name: string; reason: string } type ForgetPlan = { confirmed: [Kind, string][] restores: Restore[] - kept: string[] // refused restores, with the reason + kept: Kept[] // refused restores, with the reason projects: [string, Kind, string][] // repo key, kind, name } @@ -2084,15 +2133,27 @@ function targetOf(arg: string): Target { } /** The [kind, name, value] entries of a kind-keyed table the target picks. */ -function decided(tables: unknown, t: Target): [Kind, string, unknown][] { +function decided( + tables: unknown, + t: Target, + kinds: readonly Kind[] = KINDS, +): [Kind, string, unknown][] { if (!isRecord(tables)) return [] - return Object.entries(tables).filter(([kind]) => isKind(kind)) + return Object.entries(tables).filter(([kind]) => isKind(kind) && + kinds.includes(kind)) .flatMap(([kind, rows]) => isRecord(rows) ? Object.keys(rows) .filter(name => t.name === undefined || name === t.name) .map(name => [kind as Kind, name, rows[name]] as [Kind, string, unknown]) : []) } +/** A fragment read from the file, as it may enter an answer. */ +const shown = (text: string): string => clean(text, NAME_CAP) + +const keptText = (k: Kept): string => `${k.kind}.${shown(k.name)}: ${k.reason}` +const keptList = (plan: ForgetPlan): string => + plan.kept.map(keptText).join('; ') + /** The restore a `changed` entry allows, or why it is refused. */ function restoreOf( file: Rec, @@ -2101,6 +2162,7 @@ function restoreOf( entry: unknown, ): Restore | string { const { from, to } = isRecord(entry) ? entry : ({} as Rec) + if (name === '__proto__') return 'reserved name, edit routing.json' if (typeof from !== 'string') return 'no phase recorded to return to' const rows = subRec(file, kind) if (typeof to !== 'string' || !hasKey(rows, name) || rows[name] !== to) { @@ -2108,7 +2170,7 @@ function restoreOf( } if (!hasKey(subRec(file, 'phases'), from) && !hasKey(DEFAULT_CONFIG.phases, from)) { - return `${from} is not a known phase` + return `${shown(from)} is not a known phase` } return { kind, name, from, to } } @@ -2122,9 +2184,9 @@ function forgetPlan(file: Rec, t: Target): ForgetPlan { for (const [kind, name] of decided(file.confirmed, t)) { plan.confirmed.push([kind, name]) } - for (const [kind, name, entry] of decided(file.changed, t)) { + for (const [kind, name, entry] of decided(file.changed, t, ROWS)) { const done = restoreOf(file, kind, name, entry) - if (typeof done === 'string') plan.kept.push(`${kind}.${name}: ${done}`) + if (typeof done === 'string') plan.kept.push({ kind, name, reason: done }) else plan.restores.push(done) } } @@ -2191,7 +2253,7 @@ function idleAnswer( ): string | undefined { if (removals(plan) > 0) return undefined if (plan.kept.length > 0) { - return `nothing restored for ${t.label}: ${plan.kept.join('; ')}` + return `nothing restored for ${t.label}: ${keptList(plan)}` } const keys = askedKeys(st, t) if (keys.length === 0) { @@ -2214,6 +2276,7 @@ async function confirmForget($: Api, plan: ForgetPlan): Promise { /** Where a restored row's frontmatter lives; none for a built-in agent. */ function floorFile(r: Restore): string | undefined { + if (!SKILL_NAME.test(r.name)) return undefined if (r.kind === 'skills') return `skills/${r.name}/SKILL.md` return r.kind === 'agents' && !BUILTIN_AGENTS.has(r.name) ? `agents/${r.name}.md` @@ -2225,10 +2288,12 @@ function restoreClause(st: State, r: Restore): string { const alias = (route && headAlias(DEFAULT_CONFIG, route)) ?? 'its own model' const values = `${alias} at ${route?.effort ?? 'its own effort'}` const file = floorFile(r) + const effort = route?.effort ?? '-' const realign = file === undefined ? '' : `; if ${file} was aligned to ${ - r.to}, set model: ${alias}, effort: ${route?.effort ?? '-'} and its ` + - 'lock in lib/tests/model-routing.test.sh, then `make test`' - return ` (${r.kind}.${r.name} → ${r.from}: ${values}${realign})` + shown(r.to)}, set model: ${alias}, effort: ${effort} and its lock in ` + + 'lib/tests/model-routing.test.sh, then `make test`' + const row = `${r.kind}.${shown(r.name)} → ${shown(r.from)}` + return ` (${row}: ${values}${realign})` } /** Restored skill rows whose old phase the current run still holds. */ @@ -2238,13 +2303,13 @@ function runKeeps(st: State, plan: ForgetPlan): string { const kept = plan.restores.find(r => r.kind === 'skills' && live.some(slot => slot?.phase === r.to)) return kept === undefined ? '' : - `; current run may keep ${kept.to}: /route clear to apply` + `; current run may keep ${shown(kept.to)}: /route clear to apply` } /** The one answer of every form, from the counts really applied. */ function forgetAnswer(st: State, t: Target, plan: ForgetPlan): string { const kept = plan.kept.length === 0 ? '' : - `, ${plan.kept.length} restore(s) kept: ${plan.kept.join('; ')}` + `, ${plan.kept.length} restore(s) kept: ${keptList(plan)}` const name = t.name const wins = name !== undefined && ROWS.some(kind => st.mem.local[kind].has(name)) @@ -2269,7 +2334,7 @@ async function forgetWrite($: Api, st: State, t: Target, seen: ForgetPlan) { } catch (err) { return err instanceof RebuildFailed ? 'saved, config not rebuilt: /route reload' - : `forget not applied (${String(err)})` + : failedWrite($, 'forget', err) } askedKeys(st, t).forEach(key => st.asked.delete(key)) return forgetAnswer(st, t, out.plan ?? seen) @@ -2378,7 +2443,7 @@ function applyRoute(st: State, agentId: string | undefined, p: Picked): void { if (agentId === undefined) { st.turnMain = { phase: p.phase, route: p.route, source: 'model' } } else { - writeLoop(loopOf(st, agentId), p.route) + writeLoop(loopOf(st, agentId), p.route, 'route tool') } } @@ -2395,7 +2460,7 @@ function clearLoop(st: State, agentId: string | undefined): string { return 'route cleared for main' + held + run } const loop = st.loops.get(agentId) - if (loop) writeLoop(loop, {}) + if (loop) writeLoop(loop, {}, 'route tool') return 'route cleared for this agent' } @@ -2457,9 +2522,14 @@ function skillRow(st: State, skill: string): Picked | undefined { * run slot. A typed non-best row drops the run; one the model loads (a * helper skill inside a run) leaves it. */ -function routeMainBySkill(st: State, row: Picked, typed: boolean): void { +function routeMainBySkill( + st: State, + skill: string, + row: Picked, + typed: boolean, +): void { const turn: Routed = { phase: row.phase, route: { ...row.route }, - source: 'skill' } + source: 'skill', label: clean(skill, NAME_CAP) } st.turnMain = turn if (row.route.tier === BEST) st.runMain = { ...turn, source: 'run' } else if (typed) st.runMain = null @@ -2469,10 +2539,10 @@ function routeMainBySkill(st: State, row: Picked, typed: boolean): void { function onSkillLoad(st: State, skill: string, agentId: string | undefined) { const row = skillRow(st, skill) if (agentId === undefined) { - if (row) routeMainBySkill(st, row, false) + if (row) routeMainBySkill(st, skill, row, false) return } - if (row) writeLoop(loopOf(st, agentId), row.route) + if (row) writeLoop(loopOf(st, agentId), row.route, `skill ${clean(skill, NAME_CAP)}`) } type TypedPath = 'typed-marker' | 'typed-fallback' @@ -2496,9 +2566,8 @@ function armTypedSkill($: Api, st: State, skill: string) { const row = skillRow(st, skill) const path = typedPath(st, skill) if (row === undefined || path === undefined) return undefined - routeMainBySkill(st, row, true) + routeMainBySkill(st, skill, row, true) refresh($, st) - vlog($, st, `skill ${skill}: ${path} → ${row.phase}`) return row } @@ -2519,6 +2588,7 @@ type SpawnIn = { subagentType: string model?: string parentAgentId?: string // set when the spawn happens inside an agent + parentModel?: string // the model the spawning loop runs on fork: boolean workflow?: unknown } @@ -2574,16 +2644,34 @@ function spawnTarget($: Api, st: State, e: SpawnIn, route: Route | undefined) { return inTier($, st, e.subagentType, route.tier) } -function trackLoop(st: State, e: SpawnIn, started: { - agentId?: string -}, route: Route | undefined): void { - const given = st.explicitEffort.get(e.tool_use_id) - st.explicitEffort.delete(e.tool_use_id) - if (started.agentId === undefined) return - st.loops.set(started.agentId, { +/** Spawn facts the bookkeeping after the engine started the agent needs. */ +type Spawned = { + e: SpawnIn + started: { agentId?: unknown; model: string } + route: Route | undefined // the row's route in force, if any + wanted: string | undefined // the model the hook asked for, if it did +} + +/** Who set a new agent's effort: the Agent call, its row, or the engine. */ +function spawnEffortCause(given: Level | undefined, route: Route | undefined) { + if (given !== undefined) return 'explicit' + return route?.effort === undefined ? 'engine' : 'row' +} + +function trackLoop( + st: State, + sp: Spawned, + agentId: string, + given: Level | undefined, +): Loop { + const loop: Loop = { explicitEffort: given !== undefined, - effort: given ? undefined : route?.effort, - }) + effort: given ? undefined : sp.route?.effort, + type: sp.e.subagentType, + cause: spawnEffortCause(given, sp.route), + } + st.loops.set(agentId, loop) + return loop } /** The breaker's target for an agent's failure; oldest entries dropped. */ @@ -2638,10 +2726,190 @@ function afterDispatch(st: State, result: unknown): void { /** An agent's loop ended: forget it, pop when it was the last awaited. */ function endAgent(st: State, agentId: string): void { st.loops.delete(agentId) + for (const key of st.logged) { + if (key.startsWith(`answered:${agentId}:`)) st.logged.delete(key) + } const awaited = st.pushed?.spawnIds if (awaited?.delete(agentId) && awaited.size === 0) popOrchestrate(st) } +// ---- transition logs ----------------------------------------------------- +// `verbose` says WHEN a loop changes model or effort, with a few words of +// cause; a step that changes nothing logs nothing. + +const NAME_CAP = 40 // code points of any name read from outside, in a line + +const isHaiku = (cfg: Config, id: string): boolean => + canonical(cfg, id).startsWith(HAIKU) + +/** The table alias of a model id (a `[1m]` marker kept), else the id. */ +function nameOf(cfg: Config, id: string): string { + const bare = canonical(cfg, id) + const marker = ONE_M.test(id) ? '[1m]' : '' + return clean((aliasOf(cfg, bare) ?? bare) + marker, NAME_CAP) +} + +/** "alias/effort": a plan in a log line. */ +const planWord = (cfg: Config, plan: Plan): string => + `${nameOf(cfg, plan.model)}/${String(plan.effort ?? '-')}` + +/** Logged at `true` only, and once per turn per `key` (default: text). */ +function turnLine($: Api, st: State, text: string, key = text): void { + if (!st.cfg.verbose || st.turnLogged.has(key)) return + st.turnLogged.add(key) + vlog($, st, text) +} + +const agentLabel = (st: State, agentId: string): string => + `agent ${clean(st.loops.get(agentId)?.type ?? agentId.slice(0, 8), NAME_CAP)}` + +/** The route slot a main effort came from, in words. */ +function slotWord(slot: Routed | null): string { + const label = slot?.label === undefined ? '' : ` /${slot.label}` + switch (slot?.source) { + case 'model': return 'route tool' + case 'prompt': return 'prompt rule' + case 'derived': return 'dispatch' + case 'skill': + case 'run': return 'skill' + label + default: return 'session' + } +} + +type Cause = { phase?: string; word: string } + +/** Who supplied main's effort: the phase of that slot, and a few words. */ +function effortCause(st: State, by: EffortBy): Cause { + if (by === 'floor') { + return { phase: st.turnFloor?.phase, word: 'prompt floor' } + } + if (by === 'sticky') { + return { phase: st.userMain?.phase, word: 'sticky /route' } + } + if (by === 'engine') return { phase: mainRoute(st)?.phase, word: 'session' } + const named = st.turnMain?.route.effort === undefined + ? st.runMain + : st.turnMain + return { phase: named?.phase, word: slotWord(named) } +} + +/** Why the model moved, when it did. */ +function modelCause(st: State, why: Why): string | undefined { + const { call, cur } = why + if (!call.moved) return undefined + if (call.why === 'upgrade') return 'upgrade' + if (call.why === 'downgrade') return 'switch' + return `fallback: ${nameOf(st.cfg, cur)} down` +} + +/** "main: a → b (phase: cause[, model cause])", or none when unchanged. */ +function mainMove( + st: State, + from: Plan, + step: Step, +): string | undefined { + const [was, now] = [planWord(st.cfg, from), planWord(st.cfg, step.plan)] + if (step.why === undefined || was === now) return undefined + const { phase, word } = effortCause(st, step.why.by) + const causes = [word, modelCause(st, step.why)].filter(c => c !== undefined) + const lead = phase === undefined ? '' : `${clean(phase, NAME_CAP)}: ` + return `main: ${was} → ${now} (${lead}${causes.join(', ')})` +} + +/** "agent x: a → b (cause)": a later move; the loop remembers `plan`. */ +function agentMove(st: State, e: StepIn, plan: Plan): string | undefined { + const id = e.agentId + const loop = id === undefined ? undefined : st.loops.get(id) + if (id === undefined) return undefined + const from = loop?.last ?? { model: e.model, effort: e.effort } + if (loop) loop.last = plan + const [was, now] = [planWord(st.cfg, from), planWord(st.cfg, plan)] + return was === now + ? undefined + : `${agentLabel(st, id)}: ${was} → ${now} (${ + loop?.cause ?? 'engine'})` +} + +/** The step's transition line; `prev` is main's plan before this step. */ +function logMove( + $: Api, + st: State, + e: StepIn, + prev: Plan | null, + step: Step, +): void { + const line = e.agentId === undefined + ? mainMove(st, prev ?? { model: e.model, effort: e.effort }, step) + : agentMove(st, e, step.plan) + if (line !== undefined) turnLine($, st, line) +} + +/** An agent answered on a model other than the planned one: said once. */ +function logAnswer( + $: Api, + st: State, + agentId: string | undefined, + plan: Plan, + usage: { model: string } | null | undefined, +): void { + if (agentId === undefined || !st.cfg.verbose || !usage) return + const got = canonical(st.cfg, usage.model) + const key = `answered:${agentId}:${got}` + if (got === canonical(st.cfg, plan.model) || st.logged.has(key)) return + st.logged.add(key) + vlog($, st, `${agentLabel(st, agentId)} answered by ${ + nameOf(st.cfg, got)} instead of ${nameOf(st.cfg, plan.model)}`) +} + +type Handoff = { to: Plan; modelCause: string; effortCause: string } + +/** Why an agent runs on the model it was sent to. */ +function spawnModelCause(st: State, sp: Spawned): string { + const { e, route, wanted } = sp + if (e.model !== undefined) return 'explicit' + if (route === undefined || wanted === undefined) return 'frontmatter' + const head = headAlias(st.cfg, route) + const lead = head === undefined ? undefined : st.cfg.models[head] + const phase = clean(st.cfg.agents[e.subagentType] ?? '', NAME_CAP) + return route.tier !== undefined && lead !== wanted + ? `fallback: ${nameOf(st.cfg, head ?? '')} down` + : `row ${phase}` +} + +/** What a dispatch hands the agent, or undefined when nothing was given. */ +function handoffOf( + st: State, + sp: Spawned, + given: Level | undefined, +): Handoff | undefined { + const { e, route, started } = sp + if (route === undefined && e.model === undefined && given === undefined) { + return undefined + } + const effort = isHaiku(st.cfg, started.model) + ? undefined + : given ?? route?.effort + return { + to: { model: started.model, effort }, + modelCause: spawnModelCause(st, sp), + effortCause: spawnEffortCause(given, route), + } +} + +/** "main a → agent x b (model cause, effort cause)": the dispatch itself. */ +function handoffLine(st: State, e: SpawnIn, hand: Handoff): string { + const parent = e.parentAgentId + const lead = parent === undefined ? 'main' : agentLabel(st, parent) + const known = parent === undefined + ? st.lastPlan + : st.loops.get(parent)?.last + const from = known ?? { model: e.parentModel ?? st.sessionModel, + effort: undefined } + return `${lead} ${planWord(st.cfg, from)} → agent ${ + clean(e.subagentType, NAME_CAP)} ${planWord(st.cfg, hand.to)} (${ + hand.modelCause}, ${hand.effortCause})` +} + // ---- turn steps ------------------------------------------------------ function agentPlan(st: State, e: StepIn): Plan { @@ -2649,27 +2917,33 @@ function agentPlan(st: State, e: StepIn): Plan { return { model: e.model, effort: loop?.effort ?? e.effort } } +/** What a main plan was decided from: the log words are built from it. */ +type Why = { by: EffortBy; call: Call; cur: string } +type Step = { plan: Plan; why?: Why } + /** * The main loop's plan: effort from the floor/sticky/turn decision, model * from `decideMain`. `cur` is the model the router moved this turn, else * the engine's own (verbatim: an engine fallback is respected). */ -async function mainPlan($: Api, st: State, e: StepIn): Promise { - const { effort } = mainEffort(st, e.effort) +async function mainPlan($: Api, st: State, e: StepIn): Promise { + const { effort, by } = mainEffort(st, e.effort) await prune($, st) const cur = st.turnModel ?? e.model const { call } = await decideFor($, st, cur) logCall($, st, call) if (call.moved) st.turnModel = call.model - return { model: call.model, effort } + return { plan: { model: call.model, effort }, why: { by, call, cur } } } -async function planStep($: Api, st: State, e: StepIn): Promise { - const plan = e.agentId === undefined +async function planStep($: Api, st: State, e: StepIn): Promise { + const step: Step = e.agentId === undefined ? await mainPlan($, st, e) - : agentPlan(st, e) + : { plan: agentPlan(st, e) } // Haiku takes no effort: omit it rather than send a hook-set value. - return plan.model.startsWith(HAIKU) ? { ...plan, effort: undefined } : plan + return step.plan.model.startsWith(HAIKU) + ? { ...step, plan: { ...step.plan, effort: undefined } } + : step } function withPlan(e: StepIn, plan: Plan): StepIn { @@ -2678,13 +2952,6 @@ function withPlan(e: StepIn, plan: Plan): StepIn { return plan.effort === undefined ? base : { ...base, effort: plan.effort } } -function stepLog(e: StepIn, plan: Plan): string { - const id = e.agentId - const loop = id === undefined ? 'main' : `agent ${id.slice(0, 8)}` - return `step ${e.index} ${loop}: ${e.model}/${String(e.effort)} → ` + - `${plan.model}/${String(plan.effort)}` -} - function noteMain($: Api, st: State, plan: Plan): void { st.lastPlan = plan st.spinner = `${plan.model.replace(/^claude-/, '')}/${plan.effort ?? '-'}` @@ -2846,7 +3113,6 @@ function registerRouteTool(on: On, st: State): void { await ensureConfig($, st) const out = await handleRouteTool($, st, e) refresh($, st) - vlog($, st, `route ${e.agentId ?? 'main'}: ${JSON.stringify(out)}`) return out }).catch(($, e, next) => { warnOnce(st, $, 'route tool', next.error.kind) @@ -2900,20 +3166,23 @@ function registerAgents(on: On, st: State): void { } /** Bookkeeping once the agent started: its loop, its model, a log line. */ -function afterSpawn( - $: Api, - st: State, - e: SpawnIn, - started: { agentId?: unknown; model: string }, - route: Route | undefined, -): void { - if (typeof started.agentId !== 'string') return - const agentId = started.agentId +function afterSpawn($: Api, st: State, sp: Spawned): void { + if (typeof sp.started.agentId !== 'string') return + const agentId = sp.started.agentId safely(st, $, 'agent.spawn', () => { - trackLoop(st, e, { agentId }, route) - rememberAgent(st, agentId, started.model) - vlog($, st, - `spawn ${e.subagentType}: ${e.model ?? '-'} → ${started.model}`) + const given = st.explicitEffort.get(sp.e.tool_use_id) + st.explicitEffort.delete(sp.e.tool_use_id) + const loop = trackLoop(st, sp, agentId, given) + rememberAgent(st, agentId, sp.started.model) + const hand = handoffOf(st, sp, given) + if (hand === undefined) return + // an effort the engine picks is unknown here: the first step tells it + if (hand.effortCause !== 'engine' || isHaiku(st.cfg, hand.to.model)) { + loop.last = hand.to + } + if (!st.cfg.verbose) return + const key = `handoff:${sp.e.subagentType}:${planWord(st.cfg, hand.to)}` + turnLine($, st, handoffLine(st, sp.e, hand), key) }) } @@ -2936,7 +3205,7 @@ function registerSpawn(on: On, st: State): void { const started = await next(wanted === undefined ? e : { ...e, model: wanted }) - afterSpawn($, st, e, started, route) + afterSpawn($, st, { e, started, route, wanted }) return started } finally { st.spawning = Math.max(0, st.spawning - 1) @@ -2950,13 +3219,15 @@ function registerSpawn(on: On, st: State): void { function registerTurns(on: On, st: State): void { on('turn.step', async function* ($, e, next) { if (st.off) return yield* next(e) - const plan = await planStep($, st, e) + const step = await planStep($, st, e) + const plan = step.plan const changed = plan.model !== e.model || plan.effort !== e.effort + const prev = st.lastPlan // main's last plan, before noteMain replaces it if (e.agentId === undefined) noteMain($, st, plan) - vlog($, st, stepLog(e, plan)) + safely(st, $, 'turn.step log', () => logMove($, st, e, prev, step)) const result = yield* next(changed ? withPlan(e, plan) : e) - safely(st, $, 'turn.step', () => vlog($, st, - `step ${e.index} answered by ${result.usage?.model ?? '?'}`)) + safely(st, $, 'turn.step', () => + logAnswer($, st, e.agentId, plan, result.usage)) return result }).catch(async function* ($, e, next) { warnOnce(st, $, 'turn.step', next.error.kind)