From fac545b82c92d04f2ea35988a014f5320a1966d5 Mon Sep 17 00:00:00 2001 From: Yavor Panayotov Date: Fri, 21 Aug 2026 20:11:47 +0300 Subject: [PATCH 1/4] Loop observability: a run trace and a stall alarm A long autonomous run can stop converging without anything erroring. Tests stick, weed stays dirty, obligations don't shrink, and the loop grinds tick after tick until a cap trips. Nothing surfaces it while it happens. The loop now appends a trace entry each tick to .allium-loop/.trace.jsonl, a snapshot of the tick's convergence state drawn from the phases' typed records. When a tick makes no progress on any convergence metric, the run says so out loud instead of waiting for the no-progress cap. The trace makes the run's trajectory observable, and the end report summarises how the metrics moved. The stall rule is simple counting over a short log, so the orchestrator applies it directly, with no tool to install. driving-the-loop gains section 13; the per-tick append, the stall surfacing and the trajectory report thread through sections 2, 4, 8 and 10. The 6 / 2 caps are unchanged. --- skills/allium/references/driving-the-loop.md | 27 +++++++++-- skills/allium/references/recommended-loops.md | 2 +- .../schemas/trace-entry.schema.json | 48 +++++++++++++++++++ 3 files changed, 73 insertions(+), 4 deletions(-) create mode 100644 skills/allium/references/schemas/trace-entry.schema.json diff --git a/skills/allium/references/driving-the-loop.md b/skills/allium/references/driving-the-loop.md index 2094327..3639ac0 100644 --- a/skills/allium/references/driving-the-loop.md +++ b/skills/allium/references/driving-the-loop.md @@ -32,7 +32,7 @@ Announce each phase as it begins with a one-line marker (shown in parentheses be - a test is wrong → `tend` the spec, then `propagate` again; - `weed` says the spec is wrong → `tend` the spec; - open question → classify and handle (§5). -5. **Record state** in the ledger (§8) and print a one-line summary: `tick n · tests x/y · weed clean/dirty · openQ blocking k / parked m`. +5. **Record state** in the ledger (§8), **append a trace entry** for the tick (§13), and print a one-line summary: `tick n · tests x/y · weed clean/dirty · openQ blocking k / parked m`. If the trace shows the run has stopped making progress, say so out loud this tick (§13) — don't wait for the cap. ## 3. Convergence (when to stop) @@ -50,6 +50,7 @@ The first four are the run's own reading of its state; the witness re-derives th - **Hard cap** — stop after **6** iterations. - **No-progress cap** — stop after **2** iterations with no change in tests / weed verdict / open-question count (catches thrashing against a test you can't satisfy). +- **Surface the stall early** — don't let a flattening run grind to that cap in silence. The trace (§13) shows the trajectory each tick; the moment a tick makes no progress, say so out loud. The cap is the backstop, not the first sign. - **Escalate** on a blocking open question (§5). - **Anti-cheat (non-negotiable, and witnessed)** — never weaken or edit a generated test to pass; honour `config` (no magic numbers in code the spec parameterises). This is not left to good behaviour: the witness (§11) re-derives it from ground truth — a generated test whose recorded hash changed with no intervening `propagate` fails the witness and blocks convergence. - On hitting a cap or an unrecoverable error, **stop and report** — don't spin. @@ -83,7 +84,7 @@ This is what keeps a long or large run within budget: the orchestrator's context Keep loop state in `.allium-loop/.json`: goal, mode, tick count, active inner loop, last verdicts, completed sub-goals, and parked (non-blocking) open questions. This makes the loop resumable — a fresh run reads it and continues where it left off. -The ledger is itself typed — it conforms to [ledger.schema.json](./schemas/ledger.schema.json), so a resuming run reads structured state rather than re-parsing prose. It also carries the evidence the witness (§11) re-derives convergence from, so record it as the phases produce it: `generated_test_hashes` (a content hash per generated test file, written by `propagate`) and the `reconciliation` line, the recorded `weed` verdict, and — for spec-first — the red-before-green observations per new test. The witness reads these; it does not take them on trust, but it needs them to exist. The witness writes its own artefact alongside the ledger, `.allium-loop/.witness.json` — the durable convergence record, keep it out of git the same way. +The ledger is itself typed — it conforms to [ledger.schema.json](./schemas/ledger.schema.json), so a resuming run reads structured state rather than re-parsing prose. It also carries the evidence the witness (§11) re-derives convergence from, so record it as the phases produce it: `generated_test_hashes` (a content hash per generated test file, written by `propagate`) and the `reconciliation` line, the recorded `weed` verdict, and — for spec-first — the red-before-green observations per new test. The witness reads these; it does not take them on trust, but it needs them to exist. The witness writes its own artefact alongside the ledger, `.allium-loop/.witness.json` — the durable convergence record, keep it out of git the same way. The run trace (§13) lives beside them at `.allium-loop/.trace.jsonl`; ignore it the same way. Git-ignore it: resolve the repo root (`git rev-parse --show-toplevel`; skip if not a git repo), then ensure `.allium-loop/` is ignored there — create `.gitignore` if absent, append if missing, no-op if already ignored (`git check-ignore` first). Best-effort: if it can't be written, continue and say so. Mention it once; don't prompt. @@ -93,7 +94,7 @@ The loop is only as good as its verification. Discover the project's test comman ## 10. Report -End with: what converged, per–sub-goal status, tests and weed verdict, the witness verdict and its record path, anything escalated, and all parked questions consolidated. +End with: what converged, per–sub-goal status, tests and weed verdict, the witness verdict and its record path, anything escalated, all parked questions consolidated, and the run's **trajectory** from the trace (§13) — how the metrics moved tick over tick, and any stall that was surfaced. ## 11. Witness the convergence (the gate) @@ -127,3 +128,23 @@ The schemas: [`distill`](./schemas/distill-result.schema.json), [`weed`](./schem | any record fails schema validation | reject the hand-off; the phase must re-emit — a malformed record is never treated as a result | **Convergence** is the boolean over the typed fields: `tests.failed = 0` ∧ `weed.verdict = clean` ∧ no blocking open questions ∧ `propagate.uncovered_obligations` empty ∧ (code-first) a fresh `distill` finds nothing new ∧ `witness.verdict = PASS`. When every conjunct reads from a field, "are we done" stops being a vibe and becomes an evaluation. + +## 13. Trace the run (observability) + +A long autonomous run can fail without failing. Nothing errors, but the loop stops converging — tests stick, `weed` stays dirty, obligations don't shrink — and it grinds tick after tick until a cap trips. The trace makes that visible while it is happening instead of after. + +**Append one entry per tick.** After recording state (§2 step 5), append a line to `.allium-loop/.trace.jsonl` conforming to [trace-entry.schema.json](./schemas/trace-entry.schema.json): the tick number, the phases that ran, the tick's `tests` (passed / failed), `weed` verdict, `uncovered_obligations`, and blocking / parked `open_questions`. These come straight from the phases' typed records (§12) — you already hold them, so this is bookkeeping, not new work. Carry a metric forward when its phase didn't run this tick. Timing per phase (`durations_s`) is best-effort: wrap a spawn in Bash `date` if you want it, skip it if not. + +**Watch the trajectory.** A tick makes **progress** if any convergence metric improved: fewer failing tests, `weed` went dirty → clean, fewer uncovered obligations, or fewer blocking questions. A tick with none of those, while not yet converged, is a **no-progress tick**. + +**Surface a stall out loud.** The moment a no-progress tick lands, say so in the run output — name what is stuck and for how long: + +``` +⚠ tick 4 · no progress — tests stuck at 5/10 for 2 ticks, weed still dirty, 3 uncovered +``` + +This is the whole point: the silent slow-down becomes a line you cannot miss. Keep surfacing it each further flat tick; the no-progress cap (§4) is the backstop that finally stops the run, not the first signal. The threshold for the first warning is `config.stall_warning_ticks` (default **1**, so the first flat tick warns); raise it in a `config` block if a run is legitimately slow and the early warning is noise. + +**The rule is simple on purpose.** Deciding "did any metric improve across the last N ticks" is counting over a short log, so the orchestrator applies it directly — no tool required, nothing to install. The same rule is pinned as a deterministic function in the test suite (`detectStall`) so it can't drift, and so it can later move into a script or the CLI as an accelerator, with the orchestrator as the always-present floor (§ the pattern `allium check` already uses: CLI when present, fall back otherwise). + +**Report the trajectory.** At the end (§10), summarise how the metrics moved across the run and call out any stall that was surfaced. A converged run reads as a clean descent to zero; a rescued one shows where it flattened and what unstuck it. diff --git a/skills/allium/references/recommended-loops.md b/skills/allium/references/recommended-loops.md index 0958217..8df6259 100644 --- a/skills/allium/references/recommended-loops.md +++ b/skills/allium/references/recommended-loops.md @@ -131,7 +131,7 @@ Both loops can be driven autonomously — `/distill`, `/propagate`, `/tend`, `/w - **No magic numbers in code that the spec puts in `config`.** Honour the spec's parameters. - **Fix the code, not the contract**, when code and spec disagree and the spec is right. -**State worth tracking across ticks:** tests status (pass/fail counts), `/weed` verdict, count of open questions, and — for code-first — whether the last `/distill` pass found anything new. Convergence is all four trending to zero/clean. +**State worth tracking across ticks:** tests status (pass/fail counts), `/weed` verdict, count of open questions, and — for code-first — whether the last `/distill` pass found anything new. Convergence is all four trending to zero/clean. When driving the loop autonomously, record these into a run trace each tick and surface the moment they stop trending, so a run that has quietly stalled says so instead of grinding to the cap in silence (see [driving the loop](./driving-the-loop.md) §13). ## Driving the loop with one prompt diff --git a/skills/allium/references/schemas/trace-entry.schema.json b/skills/allium/references/schemas/trace-entry.schema.json new file mode 100644 index 0000000..abdd767 --- /dev/null +++ b/skills/allium/references/schemas/trace-entry.schema.json @@ -0,0 +1,48 @@ +{ + "$schema": "http://json-schema.org/draft-07/schema#", + "$id": "allium/handoffs/trace-entry", + "title": "Run trace entry", + "description": "One tick of the loop's run trace, appended to .allium-loop/.trace.jsonl. A snapshot of the convergence state that tick, drawn from the phases' typed records. The trace makes the run's trajectory observable, so a loop that has quietly stopped converging can be seen and surfaced instead of grinding silently.", + "type": "object", + "required": ["tick", "tests", "weed", "uncovered_obligations", "open_questions"], + "additionalProperties": false, + "properties": { + "tick": { "type": "integer", "description": "the tick this entry records, from 1" }, + "phases": { + "type": "array", + "description": "which phases ran this tick", + "items": { "type": "string" } + }, + "tests": { + "type": "object", + "description": "the tick's test result; carried forward from the last run if tests did not run this tick", + "required": ["passed", "failed"], + "additionalProperties": false, + "properties": { + "passed": { "type": "integer" }, + "failed": { "type": "integer" } + } + }, + "weed": { + "enum": ["clean", "dirty"], + "description": "the tick's weed verdict, carried forward if weed did not run" + }, + "uncovered_obligations": { + "type": "integer", + "description": "count from propagate; 0 when coverage is complete" + }, + "open_questions": { + "type": "object", + "required": ["blocking", "parked"], + "additionalProperties": false, + "properties": { + "blocking": { "type": "integer" }, + "parked": { "type": "integer" } + } + }, + "durations_s": { + "type": "object", + "description": "best-effort wall-clock seconds per phase this tick, from Bash timestamps; optional" + } + } +} From b51f6449e999db35700bdf5a5dfee20547ff4fb9 Mon Sep 17 00:00:00 2001 From: Yavor Panayotov Date: Fri, 21 Aug 2026 20:11:47 +0300 Subject: [PATCH 2/4] Test the trace: entry schema and the stall rule A trace group pins the contract offline: trace entries validate against their schema, malformed ones are caught, and the stall rule (detectStall) is proven over trajectories -- a converging run stays quiet, a flat run alarms at the threshold, a recovered run does not, and the report points at where it flattened. The rule the live loop applies by hand is the rule tested here, so it cannot drift, and it is ready to move into a script or the CLI later. --- scripts/test-skills.mjs | 95 ++++++++++++++++++++++++++++++++++++++++- 1 file changed, 94 insertions(+), 1 deletion(-) diff --git a/scripts/test-skills.mjs b/scripts/test-skills.mjs index 96a33de..fa317ec 100644 --- a/scripts/test-skills.mjs +++ b/scripts/test-skills.mjs @@ -10,7 +10,7 @@ * node scripts/test-skills.mjs structure # run one group * node scripts/test-skills.mjs portability links # run multiple groups * - * Groups: structure, codex, consistency, portability, links, routing, generation, loopdocs, hooks, modes, handoffs, discovery, parking, witnessing, crosstalk + * Groups: structure, codex, consistency, portability, links, routing, generation, loopdocs, hooks, modes, handoffs, trace, discovery, parking, witnessing, crosstalk * * All groups except discovery, parking, witnessing and crosstalk are offline (free, fast); * those four require --live and make Claude API calls. @@ -247,6 +247,39 @@ function isConverged({ weed, propagate, testsFailed, blockingQuestions }) { ); } +// The stall rule, pinned deterministically (driving-the-loop §13). The live +// loop applies this by hand — it is counting over a short log, no tool needed — +// but pinning it here stops the rule drifting and lets it later move into a +// script or the CLI as an accelerator. +function traceMetricImproved(prev, cur) { + return ( + cur.tests.failed < prev.tests.failed || + (prev.weed === "dirty" && cur.weed === "clean") || + cur.uncovered_obligations < prev.uncovered_obligations || + cur.open_questions.blocking < prev.open_questions.blocking + ); +} +function traceEntryConverged(e) { + return e.tests.failed === 0 && e.weed === "clean" && + e.uncovered_obligations === 0 && e.open_questions.blocking === 0; +} +// Count the trailing run of no-progress ticks; a stall once it reaches the +// threshold (config.stall_warning_ticks, default 1). A converged tick or any +// improvement breaks the run. +function detectStall(trace, threshold = 1) { + let run = 0; + for (let i = trace.length - 1; i >= 1; i--) { + if (traceEntryConverged(trace[i])) break; + if (traceMetricImproved(trace[i - 1], trace[i])) break; + run++; + } + return { + stalled: run >= threshold, + flatTicks: run, + sinceTick: run > 0 ? trace[trace.length - run].tick : null, + }; +} + // Pull the JSON record out of a relayed agent message: prefer the marked // region, then take the outermost { ... }. Returns null if none parses. function extractJsonRecord(text) { @@ -865,6 +898,66 @@ if (shouldRun("handoffs")) { } } +// --------------------------------------------------------------------------- +// Trace — the run trace (driving-the-loop §13). Offline and deterministic: +// trace entries validate against their schema, and the stall rule is proven +// over trajectories. The live loop applies the same rule by hand; this pins it. +// --------------------------------------------------------------------------- + +if (shouldRun("trace")) { + console.log("\n── trace: run trace entries and the stall rule ──\n"); + + const traceSchema = readJson(path.join(ROOT, "skills", "allium", "references", "schemas", "trace-entry.schema.json")); + if (traceSchema) pass("schemas/trace-entry.schema.json is valid JSON"); + + const entry = (tick, failed, weed, uncovered, blocking = 0) => ({ + tick, phases: ["weed"], tests: { passed: 10 - failed, failed }, + weed, uncovered_obligations: uncovered, open_questions: { blocking, parked: 0 }, + }); + + // Schema: a valid entry validates; malformed ones are caught. + if (traceSchema) { + const good = entry(1, 5, "dirty", 3); + validateAgainstSchema(traceSchema, good).length === 0 + ? pass("trace-entry valid fixture") : fail("trace-entry valid fixture", "should validate"); + const bad = [ + ["bad weed enum", { ...good, weed: "greenish" }], + ["tests missing failed", { ...good, tests: { passed: 5 } }], + ["open_questions not object", { ...good, open_questions: 2 }], + ["unexpected property", { ...good, extra: 1 }], + ["tick not integer", { ...good, tick: "1" }], + ]; + for (const [label, rec] of bad) { + validateAgainstSchema(traceSchema, rec).length > 0 + ? pass(`trace-entry rejects: ${label}`) : fail(`trace-entry rejects: ${label}`, "malformed entry validated"); + } + } + + console.log(""); + + // The stall rule over trajectories. + const converging = [entry(1, 5, "dirty", 3), entry(2, 3, "dirty", 2), entry(3, 1, "clean", 0), entry(4, 0, "clean", 0)]; + const flat = [entry(1, 5, "dirty", 3), entry(2, 5, "dirty", 3), entry(3, 5, "dirty", 3)]; + const recovered = [entry(1, 5, "dirty", 3), entry(2, 5, "dirty", 3), entry(3, 3, "dirty", 2)]; + const converged = [entry(1, 2, "dirty", 1), entry(2, 0, "clean", 0)]; + + const cases = [ + ["converging run is not stalled", detectStall(converging, 1).stalled, false], + ["flat run stalls at threshold 1", detectStall(flat, 1).stalled, true], + ["flat run of 2 not stalled at threshold 3", detectStall(flat, 3).stalled, false], + ["recovered run is not stalled", detectStall(recovered, 1).stalled, false], + ["converged run is not stalled", detectStall(converged, 1).stalled, false], + ]; + for (const [label, got, want] of cases) { + got === want ? pass(`stall: ${label}`) : fail(`stall: ${label}`, `expected ${want}, got ${got}`); + } + // The report points at where it flattened. + const s = detectStall(flat, 1); + s.flatTicks === 2 && s.sinceTick === 2 + ? pass("stall: reports flat run length and first flat tick") + : fail("stall: report", `flatTicks=${s.flatTicks} sinceTick=${s.sinceTick}`); +} + // --------------------------------------------------------------------------- // Discovery — live Claude Code skill and agent loading // --------------------------------------------------------------------------- From 5aec7fa78598031489a8c8274d2665098d419cc2 Mon Sep 17 00:00:00 2001 From: Yavor Panayotov Date: Fri, 21 Aug 2026 20:36:35 +0300 Subject: [PATCH 3/4] Telemetry: real per-call timing via a hook, and routing in the trace MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The trace so far showed the loop's convergence trajectory, which the model can see, but not two things it can't: how long each subagent call took, and whether the calls it made were the right ones. Timing has to be captured outside the model — a subagent call isn't a Bash call to wrap in `date`, and the model can't read its own latency. A new loop-trace hook, registered on the subagent tool for PreToolUse and PostToolUse, stamps each call's start and end and appends {agent, duration_ms} to .allium-loop/timings.jsonl. It only records while a loop is active, never blocks a call, and swallows its own errors. It reuses the existing Node hook mechanism, so it adds no new dependency where hooks already run, and is a clean no-op where they don't — the trajectory and routing still stand there. Routing is the model's half and needs no hook: each trace entry now records the phases run and why each was chosen, so a phase that keeps running without moving a metric is a visible wasted call. driving-the-loop §13 covers both; the loop folds the hook's durations into the trace and report. Tests: the trace-entry schema carries the richer phases shape (name + reason); the hook's logic has its own unit tests (paired pre/post, FIFO fallback, no-op without a loop, malformed input), run in CI via the hooks group, which also checks the hook is registered on both events. A live `timinghook` probe spawns a real subagent and confirms a timing line lands — verified against Claude Code (matcher, payload fields and pre/post correlation all fire). --- hooks/hooks.json | 20 +++ hooks/loop-trace.mjs | 131 ++++++++++++++++++ hooks/loop-trace.test.mjs | 98 +++++++++++++ scripts/test-skills.mjs | 89 ++++++++++-- skills/allium/references/driving-the-loop.md | 6 +- .../schemas/trace-entry.schema.json | 12 +- 6 files changed, 340 insertions(+), 16 deletions(-) create mode 100644 hooks/loop-trace.mjs create mode 100644 hooks/loop-trace.test.mjs diff --git a/hooks/hooks.json b/hooks/hooks.json index 754294d..6cfd443 100644 --- a/hooks/hooks.json +++ b/hooks/hooks.json @@ -1,5 +1,16 @@ { "hooks": { + "PreToolUse": [ + { + "matcher": "Task|Agent", + "hooks": [ + { + "type": "command", + "command": "node \"${CLAUDE_PLUGIN_ROOT}/hooks/loop-trace.mjs\" pre" + } + ] + } + ], "PostToolUse": [ { "matcher": "Write|Edit", @@ -9,6 +20,15 @@ "command": "node \"${CLAUDE_PLUGIN_ROOT}/hooks/allium-check.mjs\"" } ] + }, + { + "matcher": "Task|Agent", + "hooks": [ + { + "type": "command", + "command": "node \"${CLAUDE_PLUGIN_ROOT}/hooks/loop-trace.mjs\" post" + } + ] } ] } diff --git a/hooks/loop-trace.mjs b/hooks/loop-trace.mjs new file mode 100644 index 0000000..f666bad --- /dev/null +++ b/hooks/loop-trace.mjs @@ -0,0 +1,131 @@ +// Records real per-subagent-call timing into the Allium loop's trace. +// +// Registered twice in hooks.json, matched to the subagent tool: +// PreToolUse → node loop-trace.mjs pre (stamp the call's start) +// PostToolUse → node loop-trace.mjs post (write duration on return) +// +// Timing has to be captured outside the model — a subagent call isn't a Bash +// call the model can wrap in `date`, and the model can't read its own latency. +// A hook fires on the tool events, so it can. It writes one line per call to +// .allium-loop/timings.jsonl; the loop folds those durations into its trace and +// report (driving-the-loop §13). The model's trajectory + routing telemetry is +// the cross-harness baseline; this hook is the deterministic timing layer where +// hooks run (Claude Code and other editors that honour them). +// +// It only records while a loop is active (a .allium-loop/ dir exists), never +// blocks a call (always exits 0), and swallows its own errors. + +import { + existsSync, + readFileSync, + writeFileSync, + appendFileSync, + realpathSync, +} from "fs"; +import path from "path"; + +process.on("uncaughtException", () => process.exit(0)); + +const event = process.argv[2]; // "pre" | "post" +if (event !== "pre" && event !== "post") process.exit(0); + +let data = ""; +for await (const chunk of process.stdin) data += chunk; + +let input; +try { + input = JSON.parse(data); +} catch { + process.exit(0); +} + +// The subagent's type is the useful label ("allium:weed"). Field placement +// varies by harness, so look in the likely spots; fall back to the tool name. +const toolInput = input.tool_input ?? input.tool_info ?? {}; +const agent = + toolInput.subagent_type ?? + toolInput.subagentType ?? + toolInput.agent ?? + input.tool_name ?? + input.tool ?? + "subagent"; + +// A correlation id pairs a pre with its post. If the harness doesn't provide +// one, fall back to FIFO, which is correct for the sequential phase calls the +// loop makes (a documented limitation under parallel calls). +const corrId = + input.tool_use_id ?? input.toolUseId ?? toolInput.id ?? null; + +// Resolve the project root the same way the allium-check hook does. +const payloadRoots = Array.isArray(input.workspace_roots) ? input.workspace_roots : []; +const roots = [process.env.CLAUDE_PROJECT_ROOT, ...payloadRoots].filter(Boolean); +if (roots.length === 0) roots.push(process.cwd()); + +let projectRoot = null; +for (const r of roots) { + try { + projectRoot = realpathSync(r); + break; + } catch { + // try the next root + } +} +if (!projectRoot) process.exit(0); + +// Only trace while a loop is running; otherwise this is an unrelated subagent. +const loopDir = path.join(projectRoot, ".allium-loop"); +if (!existsSync(loopDir)) process.exit(0); + +const pendingPath = path.join(loopDir, ".timing-pending.json"); +const timingsPath = path.join(loopDir, "timings.jsonl"); +const now = Date.now(); + +function readPending() { + try { + const p = JSON.parse(readFileSync(pendingPath, "utf-8")); + return { byId: p.byId ?? {}, fifo: Array.isArray(p.fifo) ? p.fifo : [] }; + } catch { + return { byId: {}, fifo: [] }; + } +} +function writePending(p) { + try { + writeFileSync(pendingPath, JSON.stringify(p)); + } catch { + // best-effort + } +} + +if (event === "pre") { + const p = readPending(); + if (corrId) p.byId[corrId] = { start: now, agent }; + else p.fifo.push({ start: now, agent }); + writePending(p); + process.exit(0); +} + +// event === "post" +const p = readPending(); +let rec = null; +if (corrId && p.byId[corrId]) { + rec = p.byId[corrId]; + delete p.byId[corrId]; +} else if (p.fifo.length > 0) { + rec = p.fifo.shift(); +} +writePending(p); + +if (rec) { + const line = + JSON.stringify({ + ts: new Date(now).toISOString(), + agent: rec.agent, + duration_ms: now - rec.start, + }) + "\n"; + try { + appendFileSync(timingsPath, line); + } catch { + // best-effort + } +} +process.exit(0); diff --git a/hooks/loop-trace.test.mjs b/hooks/loop-trace.test.mjs new file mode 100644 index 0000000..1828ded --- /dev/null +++ b/hooks/loop-trace.test.mjs @@ -0,0 +1,98 @@ +import { execFileSync } from "child_process"; +import { mkdtempSync, mkdirSync, readFileSync, existsSync, rmSync } from "fs"; +import path from "path"; +import { tmpdir } from "os"; + +const hook = new URL("./loop-trace.mjs", import.meta.url).pathname; +let passed = 0; +let failed = 0; + +function assert(name, cond) { + if (cond) { console.log(` pass: ${name}`); passed++; } + else { console.log(` FAIL: ${name}`); failed++; } +} + +// Run the hook once (one event) with a synthetic payload and a project root. +function runHook(event, input, projectRoot) { + try { + execFileSync("node", [hook, event], { + input: JSON.stringify(input), + encoding: "utf-8", + stdio: ["pipe", "pipe", "pipe"], + env: { ...process.env, CLAUDE_PROJECT_ROOT: projectRoot }, + }); + } catch { + // the hook always exits 0; ignore + } +} + +function newProject({ withLoopDir }) { + const dir = mkdtempSync(path.join(tmpdir(), "allium-timing-")); + if (withLoopDir) mkdirSync(path.join(dir, ".allium-loop")); + return dir; +} +function timings(dir) { + const p = path.join(dir, ".allium-loop", "timings.jsonl"); + if (!existsSync(p)) return []; + return readFileSync(p, "utf-8").trim().split("\n").filter(Boolean).map((l) => JSON.parse(l)); +} + +console.log("\n── loop-trace hook ──\n"); + +// 1. pre + post with a correlation id → one timing line, right agent, numeric duration. +{ + const dir = newProject({ withLoopDir: true }); + const payload = { tool_use_id: "abc", tool_name: "Task", tool_input: { subagent_type: "allium:weed" } }; + runHook("pre", payload, dir); + runHook("post", payload, dir); + const t = timings(dir); + assert("records one timing for a paired pre/post", t.length === 1); + assert("labels the timing with the subagent type", t[0]?.agent === "allium:weed"); + assert("duration is a non-negative number", typeof t[0]?.duration_ms === "number" && t[0].duration_ms >= 0); + rmSync(dir, { recursive: true, force: true }); +} + +// 2. No .allium-loop dir → no-op, nothing written. +{ + const dir = newProject({ withLoopDir: false }); + const payload = { tool_use_id: "x", tool_name: "Task", tool_input: { subagent_type: "allium:weed" } }; + runHook("pre", payload, dir); + runHook("post", payload, dir); + assert("does nothing when no loop is active", !existsSync(path.join(dir, ".allium-loop", "timings.jsonl"))); + rmSync(dir, { recursive: true, force: true }); +} + +// 3. FIFO fallback when there is no correlation id: two calls pair in order. +{ + const dir = newProject({ withLoopDir: true }); + runHook("pre", { tool_name: "Task", tool_input: { subagent_type: "allium:distill" } }, dir); + runHook("pre", { tool_name: "Task", tool_input: { subagent_type: "allium:propagate" } }, dir); + runHook("post", { tool_name: "Task", tool_input: {} }, dir); + runHook("post", { tool_name: "Task", tool_input: {} }, dir); + const t = timings(dir); + assert("pairs two unkeyed calls in FIFO order", t.length === 2 && t[0].agent === "allium:distill" && t[1].agent === "allium:propagate"); + rmSync(dir, { recursive: true, force: true }); +} + +// 4. A post with no matching pre writes nothing and does not crash. +{ + const dir = newProject({ withLoopDir: true }); + runHook("post", { tool_use_id: "orphan", tool_name: "Task", tool_input: { subagent_type: "allium:weed" } }, dir); + assert("ignores an unpaired post", timings(dir).length === 0); + rmSync(dir, { recursive: true, force: true }); +} + +// 5. Malformed stdin is swallowed (no crash, no output). +{ + const dir = newProject({ withLoopDir: true }); + try { + execFileSync("node", [hook, "pre"], { input: "not json", encoding: "utf-8", stdio: ["pipe", "pipe", "pipe"], env: { ...process.env, CLAUDE_PROJECT_ROOT: dir } }); + assert("survives malformed input", true); + } catch { + assert("survives malformed input", false); + } + rmSync(dir, { recursive: true, force: true }); +} + +console.log(`\n${passed} passed, ${failed} failed`); +process.exit(failed > 0 ? 1 : 0); diff --git a/scripts/test-skills.mjs b/scripts/test-skills.mjs index fa317ec..c3a4e5d 100644 --- a/scripts/test-skills.mjs +++ b/scripts/test-skills.mjs @@ -10,13 +10,13 @@ * node scripts/test-skills.mjs structure # run one group * node scripts/test-skills.mjs portability links # run multiple groups * - * Groups: structure, codex, consistency, portability, links, routing, generation, loopdocs, hooks, modes, handoffs, trace, discovery, parking, witnessing, crosstalk + * Groups: structure, codex, consistency, portability, links, routing, generation, loopdocs, hooks, modes, handoffs, trace, discovery, parking, witnessing, timinghook, crosstalk * * All groups except discovery, parking, witnessing and crosstalk are offline (free, fast); * those four require --live and make Claude API calls. */ -import { readFileSync, writeFileSync, existsSync, readdirSync, mkdtempSync, rmSync } from "fs"; +import { readFileSync, writeFileSync, existsSync, readdirSync, mkdtempSync, mkdirSync, rmSync } from "fs"; import { execFileSync, execSync } from "child_process"; import { tmpdir } from "os"; import path from "path"; @@ -696,20 +696,39 @@ if (shouldRun("hooks")) { fail("hooks PostToolUse", "missing or empty"); } else { pass("hooks PostToolUse present"); - let matchersOk = true; - let scriptsOk = true; - for (const entry of post) { + } + + // Validate every event's entries: each has a matcher, and every + // ${CLAUDE_PLUGIN_ROOT}-referenced script exists on disk. + let matchersOk = true; + let scriptsOk = true; + const commands = []; + for (const event of ["PreToolUse", "PostToolUse"]) { + for (const entry of cfg.hooks?.[event] ?? []) { if (!entry || !entry.matcher) matchersOk = false; - const cmds = Array.isArray(entry?.hooks) ? entry.hooks : []; - for (const h of cmds) { - const m = - typeof h.command === "string" && - h.command.match(/\$\{CLAUDE_PLUGIN_ROOT\}\/([^"\s]+)/); + for (const h of Array.isArray(entry?.hooks) ? entry.hooks : []) { + if (typeof h.command === "string") commands.push(h.command); + const m = typeof h.command === "string" && h.command.match(/\$\{CLAUDE_PLUGIN_ROOT\}\/([^"\s]+)/); if (m && !existsSync(path.join(ROOT, m[1]))) scriptsOk = false; } } - matchersOk ? pass("hooks have matchers") : fail("hooks matcher", "an entry is missing a matcher"); - scriptsOk ? pass("hook command scripts exist") : fail("hook command", "referenced script not found"); + } + matchersOk ? pass("hooks have matchers") : fail("hooks matcher", "an entry is missing a matcher"); + scriptsOk ? pass("hook command scripts exist") : fail("hook command", "referenced script not found"); + + // The subagent timing hook is registered on both events (loop-trace pre/post). + const hasPre = commands.some((c) => c.includes("loop-trace.mjs") && /\bpre\b/.test(c)); + const hasPost = commands.some((c) => c.includes("loop-trace.mjs") && /\bpost\b/.test(c)); + hasPre && hasPost + ? pass("loop-trace timing hook registered on pre and post") + : fail("loop-trace hook", `missing registration (pre=${hasPre}, post=${hasPost})`); + + // Run the timing hook's own unit tests, so its logic is covered in CI. + try { + execFileSync("node", [path.join(ROOT, "hooks", "loop-trace.test.mjs")], { encoding: "utf-8", stdio: "pipe" }); + pass("loop-trace hook unit tests pass"); + } catch (e) { + fail("loop-trace hook unit tests", (e.stdout || e.message || "").slice(-160)); } } } @@ -911,7 +930,8 @@ if (shouldRun("trace")) { if (traceSchema) pass("schemas/trace-entry.schema.json is valid JSON"); const entry = (tick, failed, weed, uncovered, blocking = 0) => ({ - tick, phases: ["weed"], tests: { passed: 10 - failed, failed }, + tick, phases: [{ name: "weed", reason: "spec changed this tick" }], + tests: { passed: 10 - failed, failed }, weed, uncovered_obligations: uncovered, open_questions: { blocking, parked: 0 }, }); @@ -926,6 +946,8 @@ if (shouldRun("trace")) { ["open_questions not object", { ...good, open_questions: 2 }], ["unexpected property", { ...good, extra: 1 }], ["tick not integer", { ...good, tick: "1" }], + ["phases item missing name", { ...good, phases: [{ reason: "x" }] }], + ["phases item as bare string", { ...good, phases: ["weed"] }], ]; for (const [label, rec] of bad) { validateAgainstSchema(traceSchema, rec).length > 0 @@ -1395,6 +1417,47 @@ if (shouldRun("handoffs")) { } } +// --------------------------------------------------------------------------- +// Timing hook (live) — the one thing unit tests can't settle: does the hook +// actually fire against a real Claude Code run? Spawn a real subagent inside a +// dir with .allium-loop/, then assert a timing line landed. If it didn't, the +// matcher name or the payload fields are wrong for this harness — the whole +// reason this probe exists. +// --------------------------------------------------------------------------- + +if (shouldRun("timinghook")) { + console.log("\n── timinghook (live): the hook captures a real subagent call ──\n"); + + if (!LIVE) { + skip("timing hook probe", "pass --live to enable (uses API tokens)"); + } else { + const dir = mkdtempSync(path.join(tmpdir(), "allium-timinghook-")); + try { + mkdirSync(path.join(dir, ".allium-loop")); // the hook only records while a loop is active + writeFileSync(path.join(dir, "giftcard.py"), GIFTCARD_PY); + runAgentProbe( + dir, + "Use the Agent tool to spawn the 'allium:distill' subagent with exactly this task: " + + '"Distil an Allium spec for giftcard.py into giftcard.allium." When it finishes, output only DONE.' + ); + const tp = path.join(dir, ".allium-loop", "timings.jsonl"); + if (!existsSync(tp)) { + fail("timing hook fired", "no .allium-loop/timings.jsonl — matcher/payload mismatch, or hooks not loaded via --plugin-dir"); + } else { + const lines = readFileSync(tp, "utf-8").trim().split("\n").filter(Boolean).map((l) => { try { return JSON.parse(l); } catch { return null; } }); + const hit = lines.find((l) => l && typeof l.duration_ms === "number"); + hit + ? pass(`timing hook captured a real call (agent=${hit.agent}, ${hit.duration_ms}ms)`) + : fail("timing hook entry", "timings.jsonl present but no valid {agent, duration_ms} line"); + } + } catch (e) { + fail("timing hook probe", e.message?.slice(0, 200)); + } finally { + rmSync(dir, { recursive: true, force: true }); + } + } +} + // --------------------------------------------------------------------------- // Crosstalk — skills from the plugin don't bleed into unrelated projects, // and local agents/ don't leak outside the repo diff --git a/skills/allium/references/driving-the-loop.md b/skills/allium/references/driving-the-loop.md index 3639ac0..d21d6d9 100644 --- a/skills/allium/references/driving-the-loop.md +++ b/skills/allium/references/driving-the-loop.md @@ -133,7 +133,11 @@ The schemas: [`distill`](./schemas/distill-result.schema.json), [`weed`](./schem A long autonomous run can fail without failing. Nothing errors, but the loop stops converging — tests stick, `weed` stays dirty, obligations don't shrink — and it grinds tick after tick until a cap trips. The trace makes that visible while it is happening instead of after. -**Append one entry per tick.** After recording state (§2 step 5), append a line to `.allium-loop/.trace.jsonl` conforming to [trace-entry.schema.json](./schemas/trace-entry.schema.json): the tick number, the phases that ran, the tick's `tests` (passed / failed), `weed` verdict, `uncovered_obligations`, and blocking / parked `open_questions`. These come straight from the phases' typed records (§12) — you already hold them, so this is bookkeeping, not new work. Carry a metric forward when its phase didn't run this tick. Timing per phase (`durations_s`) is best-effort: wrap a spawn in Bash `date` if you want it, skip it if not. +**Append one entry per tick.** After recording state (§2 step 5), append a line to `.allium-loop/.trace.jsonl` conforming to [trace-entry.schema.json](./schemas/trace-entry.schema.json): the tick number, the `phases` run **and why each was chosen** (the routing decision, so a wrong or repeatedly ineffective call is visible), the tick's `tests` (passed / failed), `weed` verdict, `uncovered_obligations`, and blocking / parked `open_questions`. These come straight from the phases' typed records (§12) — you already hold them, so this is bookkeeping, not new work. Carry a metric forward when its phase didn't run this tick. + +**Which calls, and were they the right ones.** Recording the phase *and its reason* each tick, next to whether that tick made progress, makes the routing auditable: a phase that keeps running and never moves a metric is a wrong or wasted call, and now it shows in the trace rather than hiding in a long run. This is the routing half of the telemetry, and the orchestrator records it directly — it knows which subagent it chose and why. + +**Real per-call timing comes from the hook, not from you.** A subagent call isn't a Bash call you can wrap in `date`, and you can't read your own latency, so precise timing is captured outside the model: the `loop-trace` hook stamps each subagent call's start and end and appends `{agent, duration_ms}` to `.allium-loop/timings.jsonl`. When that file is present, fold its durations into the trace (`durations_s`) and the end report. Where hooks don't run, there is simply no wall-clock — the trajectory and routing above still stand. Don't hand-time calls yourself; trust the hook or omit timing. **Watch the trajectory.** A tick makes **progress** if any convergence metric improved: fewer failing tests, `weed` went dirty → clean, fewer uncovered obligations, or fewer blocking questions. A tick with none of those, while not yet converged, is a **no-progress tick**. diff --git a/skills/allium/references/schemas/trace-entry.schema.json b/skills/allium/references/schemas/trace-entry.schema.json index abdd767..1e4ddd9 100644 --- a/skills/allium/references/schemas/trace-entry.schema.json +++ b/skills/allium/references/schemas/trace-entry.schema.json @@ -10,8 +10,16 @@ "tick": { "type": "integer", "description": "the tick this entry records, from 1" }, "phases": { "type": "array", - "description": "which phases ran this tick", - "items": { "type": "string" } + "description": "the phases run this tick, in order, each with why it was chosen — the routing decision, so a wrong or repeatedly ineffective call is visible in the trace", + "items": { + "type": "object", + "required": ["name"], + "additionalProperties": false, + "properties": { + "name": { "type": "string", "description": "the phase / subagent, e.g. weed, propagate" }, + "reason": { "type": "string", "description": "why it was chosen this tick, e.g. the field that triggered it" } + } + } }, "tests": { "type": "object", From f3b5f9faea5839f76a505943e557c94b5245d4a1 Mon Sep 17 00:00:00 2001 From: Yavor Panayotov Date: Sat, 22 Aug 2026 09:50:05 +0300 Subject: [PATCH 4/4] Bump plugin version to 3.14.0 --- .claude-plugin/plugin.json | 2 +- .codex-plugin/plugin.json | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/.claude-plugin/plugin.json b/.claude-plugin/plugin.json index 22e565a..b4648de 100644 --- a/.claude-plugin/plugin.json +++ b/.claude-plugin/plugin.json @@ -1,6 +1,6 @@ { "name": "allium", - "version": "3.13.0", + "version": "3.14.0", "description": "Velocity through clarity.", "author": { "name": "JUXT", diff --git a/.codex-plugin/plugin.json b/.codex-plugin/plugin.json index e8a6c3f..b44b980 100644 --- a/.codex-plugin/plugin.json +++ b/.codex-plugin/plugin.json @@ -1,6 +1,6 @@ { "name": "allium", - "version": "3.13.0", + "version": "3.14.0", "description": "Velocity through clarity.", "author": { "name": "JUXT",