diff --git a/docs/PRD.md b/docs/PRD.md index d2ec2780..7117d291 100644 --- a/docs/PRD.md +++ b/docs/PRD.md @@ -2,7 +2,15 @@ **Status:** Phase 1 complete (de-fork executed). Phase 2 not started. **Owner:** Linh Doan -**Last updated:** 2026-09-30 (the cheap-first ladder no longer carries a model's +**Last updated:** 2026-10-05 (a run record is no longer written one attempt +short: the `turn/end` listener now drains settled usage itself, because the +turn's closing model call is only settled by `agent/request` as that handler +returns — after this listener ran. Measured in the Desktop app: `steps` +equalled the session log's `assistant/message` count minus one in 8 of 8 runs, +and the missing step is the turn's most expensive one. See §8 and +`test/plugin-approval.test.ts` § "the closing drain") + +Earlier: 2026-09-30 (the cheap-first ladder no longer carries a model's reasoning effort onto the wrong route — `routeForStep` hands the rung's own effort over and a rung with none drops the session's, so a profile whose rungs are gateway aliases works beside a UI selection instead of failing every turn @@ -273,10 +281,14 @@ estimate is now **denied** rather than dispatched. at versions CI cannot resolve. It is typechecked locally against the prebuilt packages. Closing this needs a lockfile, which needs published harness versions. -- **Spend is observed, not metered by the plugin.** `LoopBudget.spend()` must be - called with real usage for the cost ceiling to mean anything; the plugin - currently reads spend from the budget snapshot rather than pricing each settled - attempt from `agent/request` usage. **This is the largest correctness gap.** +- **Spend is observed, not metered by the plugin.** `LoopBudget.spend()` is + called with the real usage of every settled attempt, but the *cadence* was + wrong until 2026-10-05: `agent/pre-step` and `agent/request` both drain, and + a turn's last attempt is settled only as the `agent/request` handler returns + — after `turn/end` had already snapshotted the budget. Every record was + therefore one attempt short (8 of 8 runs in the Desktop app), losing the + turn's most expensive step. `turn/end` now drains before it builds the + record. The ceiling is still bounded by step count, not by spend alone. - **A reasoning effort belongs to a model, so a route change must drop it.** `Route.reasoningEffort` is the rung's own, and the harness refuses any explicit effort a model does not advertise (`UNSUPPORTED_REASONING_EFFORT`, thrown diff --git a/src/plugin.ts b/src/plugin.ts index 97ded0fa..d9275e1b 100644 --- a/src/plugin.ts +++ b/src/plugin.ts @@ -2247,8 +2247,21 @@ export function apply( // it. Without this a run that wrote a perfectly good research note and then // finished its turn left the pipeline in `research` with the note sitting // there, and the next turn re-entered a phase that was already done. + // + // The final drain belongs HERE, before the record is built: the last + // attempt of a turn is settled by `agent/request` as that handler returns, + // which is after this `turn/end` listener runs. Without this the record + // is written one attempt short — a turn of N model calls recorded + // `steps: N-1` and priced N-1 of them, and the missing one is the most + // expensive step of the turn (the final answer, on the longest context). + // Measured 2026-10-05 in the Desktop app against the session log: + // `steps` equalled `assistant/message` count minus one in 8 of 8 runs. const turnAgent = agentOfSession(agents, session) - if (turnAgent !== undefined) advanceIfGated(policyFor(turnAgent), turnAgent) + if (turnAgent !== undefined) { + const policy = policyFor(turnAgent) + advanceIfGated(policy, turnAgent) + spendSettledUsage(policy, turnAgent) + } void recordTurn({ session, event: end, options, policyFor, state, historyPath: path, agents }) .catch((error: unknown) => { // A failed append must never fail the turn: the record is diff --git a/test/plugin-approval.test.ts b/test/plugin-approval.test.ts index 62a5cc5e..c1c66acb 100644 --- a/test/plugin-approval.test.ts +++ b/test/plugin-approval.test.ts @@ -41,14 +41,17 @@ type Decision = { kind: string, reason?: string } type Handler = (payload: unknown, next: () => Promise) => Promise /** - * A context that records handlers instead of dispatching them. + * A context that records handlers instead of dispatching them, plus an + * optional `agents` service so a test can prove the per-agent lookup. * - * Only `on` is needed: `apply` reads nothing else from the context, and the - * handlers it registers are invoked directly by the tests below. + * `on` is what `apply` needs to register; `get` is optional because + * `apply` reads it defensively and a context without one is a real + * deployment shape (the plugin falls back to the shared agent-less policy). * - * @returns the fake context and a reader for the handlers it captured. + * @param agents - what `ctx.get('agents')` returns, when supplied. + * @returns the fake context and readers for what it captured. */ -function fakeCtx(): { +function fakeCtx(agents?: unknown): { ctx: unknown handler: (event: string) => Handler registered: () => string[] @@ -60,6 +63,9 @@ function fakeCtx(): { handlers.set(event, fn) return () => { handlers.delete(event) } }, + ...agents === undefined + ? {} + : { get(service: string): unknown { return service === 'agents' ? agents : undefined } }, }, handler(event: string): Handler { const fn = handlers.get(event) @@ -396,3 +402,79 @@ test('a blocked turn records a blocked run', async () => { const record = JSON.parse(readFileSync(historyPath, 'utf8').trim().split('\n')[0]!) as Record assert.equal(record.outcome, 'blocked') }) + +test('the closing drain prices the turn\'s LAST attempt, so steps count every call', async () => { + // The off-by-one this pins was measured in the Desktop app on 2026-10-05: + // every recorded run reported `steps` exactly one below the session log's + // `assistant/message` count, because the closing attempt is settled by + // `agent/request` as that handler RETURNS — after this `turn/end` listener + // has already snapshotted the budget. The last attempt of a turn is also its + // most expensive one (the final answer, on the longest context), so the + // undercount is not spread evenly across the run. + // + // The fixture models the real ORDER, which is the whole point: a step + // boundary drains first with the closing answer still unmaterialised, then + // the answer lands, then `turn/end` arrives. A log that already contained the + // answer at the first boundary would pass with or without the fix. + const dir = mkdtempSync(join(tmpdir(), 'dsh-hist-')) + const historyPath = join(dir, 'runs.jsonl') + const closing = { + seq: 98, + type: 'assistant/message', + data: { + usage: { inputTokens: 1_000, outputTokens: 100 }, + message: { source: { provider: 'deepseek', model: 'deepseek-v4-flash' } }, + }, + } + // The session log as it exists at each point in the turn. + const log: unknown[] = [{ seq: 90, type: 'tool/result', data: {} }] + const session = { + // `id` is what `sessionIdOf` reads, so the registry lookup is keyed by it; + // without it the lookup falls to 'unknown-session' and the drain lands on + // the shared agent-less policy, which prices nothing — a real deployment + // shape, and the reason this fixture carries the id. + // + // `seq` is where the drain cursor OPENS on its first call, so a real run + // starts it at the head of step 1, where no answer exists yet. + id: 'sess-drain', + seq: 0, + snapshotEvents(from: number): unknown[] { + return log.filter(event => (event as { seq: number }).seq >= from) + }, + } + // The agent the registry hands back for this session — without it the + // plugin falls to the shared agent-less policy, which never sees a step. + const agent = { id: 'agent-1', session } + const registry = { get: (id: unknown): unknown => (id === 'sess-drain' ? agent : undefined) } + const { ctx, handler } = fakeCtx(registry) + const dispose = apply(ctx as never, { + spec: { ...SPEC, prices: { 'deepseek/deepseek-v4-flash': { inputPerMTok: 0.14, outputPerMTok: 0.28 } } }, + dashboard: { enabled: false }, + optimize: { history: historyPath }, + }) + const preStep = handler('agent/pre-step') as unknown as (p: unknown, n: () => Promise) => Promise + // Step boundary: only the tool result is settled, no answer yet. + await preStep({ agent, turn: 1, step: 1 }, async () => ALLOW) + // The closing answer lands AFTER the last step boundary — this is the event + // only the `turn/end` drain can price. + log.push(closing) + const fn = handler('session/event') as unknown as (s: unknown, e: unknown) => unknown + fn(session, { type: 'turn/end', data: { turn: 1, reason: { kind: 'completed' } } }) + const deadline = Date.now() + 5000 + for (;;) { + try { + if (readFileSync(historyPath, 'utf8').trim() !== '') break + } catch { /* not written yet */ } + if (Date.now() > deadline) { dispose(); assert.fail('run record never landed') } + await new Promise(resolve => setTimeout(resolve, 10)) + } + dispose() + const record = JSON.parse(readFileSync(historyPath, 'utf8').trim().split('\n')[0]!) as Record + // One model call priced, not zero: this is the step count the history file + // reports and the cost the ceiling prices against. + assert.equal(record.steps, 1) + assert.ok( + Math.abs((record.costUSD as number) - (1000 * 0.14 + 100 * 0.28) / 1_000_000) < 1e-12, + `expected the closing attempt priced, got ${String(record.costUSD)}`, + ) +})