From 304cf6871e6c75b772cbf561f73c0ab14f8b31ca Mon Sep 17 00:00:00 2001 From: linhdmn Date: Mon, 5 Oct 2026 16:04:37 +0700 Subject: [PATCH] fix: a run record must include the turn's closing model call MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The run history reported `steps` and `costUSD` one attempt short on every turn. Measured in the Desktop app on 2026-10-05: `steps` equalled the session log's `assistant/message` count minus one in 8 of 8 runs. The cause is ordering, not a missing drain. `spendSettledUsage` runs at `agent/pre-step` and at `agent/request`, but a turn's LAST attempt is settled only as the `agent/request` handler RETURNS — after the `turn/end` listener has already snapshotted the budget and written the record. So the record is built from a budget that has not yet been charged for its final step, and the step it misses is the turn's most expensive one: the closing answer, on the longest context. `turn/end` now drains before it builds the record. The gate check that was already there stays first in the same block — it is the phase-advance that must not be reordered behind a price read — and the duplicated `agentOfSession` lookup is folded into the one call that now needs it. test/plugin-approval.test.ts gains a fixture that models the real ORDER: a step boundary drains with the closing answer still unmaterialised, the answer lands, then `turn/end` arrives. It fails `steps: 0 !== 1` on the old code and passes on the new one. A log that already contained the answer at the first boundary would pass either way, which is why the fixture orders the events instead of just declaring them. 689 tests pass, typecheck clean, pre-commit scan clean. --- docs/PRD.md | 22 +++++++-- src/plugin.ts | 15 +++++- test/plugin-approval.test.ts | 92 ++++++++++++++++++++++++++++++++++-- 3 files changed, 118 insertions(+), 11 deletions(-) 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)}`, + ) +})