Files
nexu-io__open-design/apps/daemon/tests/codex-rollout-usage.test.ts
lefarcen ccfdc50929 feat(analytics): first-call cache-hit + is_followup_turn telemetry (session-reuse baseline) (#4725)
* feat(analytics): measure first-call cache hit + is_followup_turn on run_finished

Instrumentation-first (telemetry before optimization) for the session-reuse
work: ship a v0.12.0 baseline that measures the cache-hit rate of the FIRST
model call of each turn, then compare it against the post-optimization release.

Why first-call: the existing run_finished usage scan is a REVERSE scan that
takes the LAST usage event of the turn. Within a turn, every call after the
first re-reads the growing prefix, so the last/aggregate cache-hit ratio is
high regardless of whether the session was reused — it masks the signal. The
session-reuse win shows up only on the OPENING call of a follow-up turn.

- scanRunEventsForUsageAnalytics now also forward-scans for the first usage
  event and emits first_call_input_tokens / first_call_cache_read_input_tokens
  / first_call_cache_hit_ratio (anthropic vs openai cache accounting mirrored
  from the existing last-call path). The group is gated on a real first-call
  input so cache-only alias payloads don't emit a dangling cache_read.
- run_finished carries is_followup_turn (a prior completed assistant turn
  exists) so first_call_cache_hit_ratio can be sliced to the turns where
  session reuse actually applies.
- The first-call fields are reliable only for per-call-usage agents
  (claude / opencode / codebuddy / pi). codex reports a single cumulative
  turn.completed usage, so its first stream event is the whole-session
  aggregate, not the opening call — gated out of the stream path here; its
  per-call number must come from the rollout last_token_usage (follow-up).

* feat(analytics): recover codex first-call cache hit from the rollout

Completes the first-call cache-hit telemetry for codex. codex emits only a
cumulative `turn.completed` usage on the exec/json stream the daemon consumes,
so the stream cannot reveal the cache-hit of a turn's OPENING model call — the
number that moves when a session is reused. codex does record per-call usage in
its rollout JSONL (`token_count.info.last_token_usage`), so we read it there.

- codex-rollout-usage.ts: pure `extractCodexLastTurnFirstCallUsage` takes the
  first `token_count` after the last `task_started` (the turn the daemon just
  finished), skipping zero-input placeholder calls. Validated against real
  codex 0.133.0 rollouts: a warm resume turn reads ~95-96% cache hit, a cold
  open ~15-18% — the exact baseline-vs-optimized signal. `readCodexRolloutFirstCall`
  locates the rollout best-effort (newest-first walk of
  `$CODEX_HOME/sessions/**/rollout-*-<thread_id>.jsonl`) and never throws.
- json-event-stream.ts surfaces codex's `thread.started` thread_id on the same
  `sessionId` status channel claude uses, so run_finished can find the rollout
  (and a future native-resume path can reuse it). `codexSessionIdFromRunEvents`
  recovers it from the stored run events.
- run_finished now resolves first-call usage per agent: codex from the rollout,
  every other agent from the stream forward-scan, behind one `firstCallUsage`
  object. CODEX_HOME comes from the drift-proof `spawnEnvForAgent('codex')`
  resolver so it honors sandbox relocation.

* fix(analytics): default codex rollout home to ~/.codex when CODEX_HOME unset

End-to-end testing through a real daemon surfaced this: codex's first-call
fields were silently dropped on every non-sandboxed run. The daemon only sets
CODEX_HOME when sandbox mode relocates it; with sandbox off, `spawnEnvForAgent`
returns an empty CODEX_HOME, codex itself falls back to ~/.codex and writes the
rollout there — but readCodexRolloutFirstCall bailed on the empty value instead
of mirroring codex's `$CODEX_HOME || ~/.codex` resolution.

Verified against a real daemon-driven codex run: the emitted run_finished now
carries first_call_input_tokens / first_call_cache_read_input_tokens /
first_call_cache_hit_ratio alongside is_followup_turn. Adds hermetic tests for
the locate-and-read layer (plant a rollout under <home>/sessions/.../, read it
back by session id) which previously had only the pure extractor covered.

* fix(analytics): harden first-call telemetry per release-readiness review

Adversarial review of the first-call cache-hit telemetry before a release
cherry-pick surfaced four fixable items; all are read-only/additive and keep
the feature best-effort:

- Contain throws in the codex run_finished branch. spawnEnvForAgent /
  agentCliEnvForAgent ran outside any local guard, so a throw there bubbled to
  the outer run_finished `.catch` and would have dropped the ENTIRE completion
  event for that run (not just the codex first-call fields). Wrap them so a
  failure degrades to "no first-call fields".
- Match the anthropic first-call denominator to the last-call one: include
  cache_creation_input_tokens in the effective-input sum. Previously first-call
  omitted it, skewing the very cross-turn comparison the metric exists for.
  Added a regression test with non-zero cache_creation.
- Bound the codex rollout locator. On a miss (session captured but file
  relocated/deleted) it walked the user's entire codex history; cap the scan to
  the newest few day-dirs since the run's own rollout is always recent.
- Declare first_call_* and is_followup_turn on RunFinishedProps in
  packages/contracts so the analytics shape is typed at the boundary.

* refactor(analytics): share one cache-token extraction for first/last-call

Review follow-up: the first-call cache-creation extraction only matched two of
the aliases the last-call path accepts (it missed cache_write_input_tokens,
cache_creation_tokens, and nested cache_creation.input_tokens), so a provider
emitting one of those on the opening usage event would compute
first_call_cache_hit_ratio with too small a denominator and overstate the cache
hit — the exact baseline metric this PR adds.

Extract one `extractUsageCacheFields` helper carrying the full provider alias
matrix and route BOTH the last-call reverse scan and the first-call forward
scan through it, so the two effective-input denominators can never drift. Adds
a fixture using the nested `cache_creation.input_tokens` alias to lock it.
2026-06-24 08:20:47 +00:00

170 lines
6.5 KiB
TypeScript
Raw Permalink Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
import { mkdtempSync, mkdirSync, writeFileSync } from 'node:fs';
import { tmpdir } from 'node:os';
import path from 'node:path';
import { describe, expect, it } from 'vitest';
import {
codexSessionIdFromRunEvents,
extractCodexLastTurnFirstCallUsage,
readCodexRolloutFirstCall,
} from '../src/codex-rollout-usage.js';
// Shapes mirror real codex 0.133.0 rollout JSONL (`~/.codex/sessions/**/rollout-*.jsonl`):
// each turn opens with a `task_started` event_msg, and every model call emits a
// `token_count` event_msg whose `info.last_token_usage` is that single call's
// usage (OpenAI-style: input_tokens INCLUDES the cached_input_tokens subset).
function taskStarted(): string {
return JSON.stringify({ type: 'event_msg', payload: { type: 'task_started' } });
}
function tokenCount(input: number | null, cached: number | null): string {
return JSON.stringify({
type: 'event_msg',
payload: {
type: 'token_count',
info:
input === null
? { last_token_usage: null }
: { last_token_usage: { input_tokens: input, cached_input_tokens: cached } },
},
});
}
describe('extractCodexLastTurnFirstCallUsage', () => {
it('reports the first call of the LAST turn, not the whole-session aggregate', () => {
// Real numbers from a 3-turn session: turn-1 is a cold open (18.5%), turn-2
// a warm resume (96.2%). The daemon just finished turn-3 (95%).
const rollout = [
taskStarted(),
tokenCount(13137, 2432), // turn-1 first call
tokenCount(13160, 2560), // within-turn-1 follow-up — must be ignored
taskStarted(),
tokenCount(13171, 12672), // turn-2 first call (the 96% spec number)
taskStarted(),
tokenCount(13342, 12672), // turn-3 first call — this is what we want
tokenCount(20000, 18000), // within-turn-3 follow-up — must be ignored
].join('\n');
const result = extractCodexLastTurnFirstCallUsage(rollout);
expect(result).toEqual({
first_call_input_tokens: 13342,
first_call_cache_read_input_tokens: 12672,
first_call_cache_hit_ratio: 12672 / 13342,
});
});
it('skips zero-input placeholder calls and uses the turn’s real first call', () => {
const rollout = [
taskStarted(),
tokenCount(0, 0), // interrupted/placeholder call — no usable ratio
tokenCount(40318, 15744), // the turn’s real opening call
].join('\n');
const result = extractCodexLastTurnFirstCallUsage(rollout);
expect(result?.first_call_input_tokens).toBe(40318);
expect(result?.first_call_cache_hit_ratio).toBeCloseTo(15744 / 40318);
});
it('treats a missing cached subset as a zero cache hit on a cold open', () => {
const rollout = [taskStarted(), tokenCount(15761, null)].join('\n');
const result = extractCodexLastTurnFirstCallUsage(rollout);
expect(result).toEqual({
first_call_input_tokens: 15761,
first_call_cache_read_input_tokens: 0,
first_call_cache_hit_ratio: 0,
});
});
it('returns null when the last turn produced no usable token_count yet', () => {
const rollout = [
taskStarted(),
tokenCount(13171, 12672),
taskStarted(), // a fresh turn opened but no call has landed
tokenCount(null, null),
].join('\n');
expect(extractCodexLastTurnFirstCallUsage(rollout)).toBeNull();
});
it('tolerates blank lines and non-JSON noise without throwing', () => {
const rollout = ['', 'not json', taskStarted(), ' ', tokenCount(13342, 12672)].join('\n');
const result = extractCodexLastTurnFirstCallUsage(rollout);
expect(result?.first_call_cache_hit_ratio).toBeCloseTo(12672 / 13342);
});
});
describe('codexSessionIdFromRunEvents', () => {
const statusEvent = (extra: Record<string, unknown>) => ({
event: 'agent',
data: { type: 'status', label: 'initializing', ...extra },
});
it('returns the thread id from the initializing status event', () => {
const events = [
statusEvent({ sessionId: '019eef4f-7409-7c82-bebe-30504eed3959' }),
{ event: 'agent', data: { type: 'status', label: 'thinking' } },
];
expect(codexSessionIdFromRunEvents(events)).toBe(
'019eef4f-7409-7c82-bebe-30504eed3959',
);
});
it('ignores status events without a session id and non-status events', () => {
const events = [
{ event: 'agent', data: { type: 'usage', usage: { input_tokens: 1 } } },
statusEvent({ label: 'thinking' }),
];
expect(codexSessionIdFromRunEvents(events)).toBeNull();
});
it('returns null for malformed input', () => {
expect(codexSessionIdFromRunEvents(null)).toBeNull();
expect(codexSessionIdFromRunEvents('nope')).toBeNull();
expect(codexSessionIdFromRunEvents([{ event: 'agent' }, 42])).toBeNull();
});
});
describe('readCodexRolloutFirstCall', () => {
// Plants a rollout under <home>/sessions/<y>/<m>/<d>/ exactly as codex names
// them, so the locate-and-read layer is covered (not just the pure extractor).
function plantRollout(sessionId: string, lines: string[]): string {
const home = mkdtempSync(path.join(tmpdir(), 'codex-home-'));
const dayDir = path.join(home, 'sessions', '2026', '06', '24');
mkdirSync(dayDir, { recursive: true });
writeFileSync(
path.join(dayDir, `rollout-2026-06-24T12-00-00-${sessionId}.jsonl`),
lines.join('\n'),
);
return home;
}
const rollout = (sid: string) => [
JSON.stringify({ type: 'event_msg', payload: { type: 'task_started' } }),
JSON.stringify({
type: 'event_msg',
payload: {
type: 'token_count',
info: { last_token_usage: { input_tokens: 13342, cached_input_tokens: 12672 } },
},
}),
];
it('locates the rollout by session id under CODEX_HOME and extracts first-call', async () => {
const sid = '019eef4f-7409-7c82-bebe-30504eed3959';
const home = plantRollout(sid, rollout(sid));
const result = await readCodexRolloutFirstCall({ codexHome: home, sessionId: sid });
expect(result?.first_call_input_tokens).toBe(13342);
expect(result?.first_call_cache_hit_ratio).toBeCloseTo(12672 / 13342);
});
it('returns null (never throws) when the session id has no matching rollout', async () => {
const home = plantRollout('some-other-session', rollout('some-other-session'));
await expect(
readCodexRolloutFirstCall({ codexHome: home, sessionId: 'missing-session' }),
).resolves.toBeNull();
});
it('returns null when no session id is given', async () => {
await expect(
readCodexRolloutFirstCall({ codexHome: '/nonexistent', sessionId: null }),
).resolves.toBeNull();
});
});