Files
nexu-io__open-design/apps/daemon/tests/run-analytics-observability.test.ts
lefarcen f9c07517b7 fix: make DeepSeek Harness cancellation authoritative (#6880)
* fix deepseek harness cancellation lifecycle

* fix DeepSeek canceled status rendering

* fix DeepSeek cancellation handshake race

* feat support reasoning selection in composer

* test DeepSeek pre-execute cancellation protocol

* test reasoning selector visual surface
2026-08-14 06:40:10 +00:00

1505 lines
43 KiB
TypeScript

import { describe, expect, it } from 'vitest';
import {
scanRunEventsForUsageAnalytics,
summarizeRunTimingAnalytics,
summarizeToolAnalytics,
} from '../src/run-analytics-observability.js';
describe('scanRunEventsForUsageAnalytics', () => {
it('extracts provider usage, cache tokens, and estimated context tokens', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: { type: 'status', label: 'initializing', model: 'claude-opus-4' },
},
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 1000,
output_tokens: 50,
cache_read_input_tokens: 250,
cache_creation_input_tokens: 100,
},
},
},
],
'',
40,
);
expect(result).toMatchObject({
input_tokens: 1000,
input_tokens_provider: 1000,
input_tokens_effective: 1350,
output_tokens: 50,
total_tokens: 1400,
cache_read_input_tokens: 250,
cache_creation_input_tokens: 100,
uncached_input_tokens: 1000,
estimated_context_tokens: 1310,
cache_token_source: 'anthropic',
token_count_source: 'provider_usage',
agent_reported_model: 'claude-opus-4',
});
expect(result.cache_hit_ratio).toBeCloseTo(250 / 1350);
});
it('reads OpenAI-style cached prompt token details', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
prompt_tokens: 200,
completion_tokens: 20,
prompt_tokens_details: { cached_tokens: 80 },
},
},
},
],
'gpt-4o',
0,
);
expect(result.cache_read_input_tokens).toBe(80);
expect(result.input_tokens_effective).toBe(200);
expect(result.uncached_input_tokens).toBe(120);
expect(result.cache_token_source).toBe('openai');
expect(result.cache_hit_ratio).toBe(0.4);
});
it('does not invent cache split fields when provider usage lacks cache data', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 300,
output_tokens: 30,
},
},
},
],
'',
10,
);
expect(result).toMatchObject({
input_tokens_provider: 300,
input_tokens_effective: 300,
output_tokens: 30,
total_tokens: 330,
estimated_context_tokens: 290,
cache_token_source: 'unavailable',
});
expect(result.cache_read_input_tokens).toBeUndefined();
expect(result.uncached_input_tokens).toBeUndefined();
expect(result.cache_hit_ratio).toBeUndefined();
});
it('uses provider-qualified model attribution from DeepSeek Harness usage', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
provider: 'deepseek-official',
model: 'deepseek-v4-flash',
usage: {
input_tokens: 300,
output_tokens: 30,
},
},
},
],
'default',
10,
);
expect(result.agent_reported_model).toBe(
'deepseek-official/deepseek-v4-flash',
);
expect(result.token_count_source).toBe('provider_usage');
});
it('treats normalized cached_read_tokens / cached_write_tokens aliases as input subsets', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 400,
output_tokens: 20,
cached_read_tokens: 120,
cached_write_tokens: 30,
},
},
},
],
'gpt-5',
0,
);
expect(result).toMatchObject({
input_tokens_provider: 400,
input_tokens_effective: 400,
output_tokens: 20,
total_tokens: 420,
cache_read_input_tokens: 120,
cache_creation_input_tokens: 30,
uncached_input_tokens: 280,
cache_token_source: 'openai',
});
expect(result.cache_hit_ratio).toBeCloseTo(120 / 400);
});
it('preserves ACP provider totals when cache read tokens are already included in input', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 31_711,
output_tokens: 30,
cached_read_tokens: 2_560,
thought_tokens: 20,
total_tokens: 31_741,
},
},
},
],
'',
0,
);
expect(result).toMatchObject({
input_tokens_provider: 31_711,
input_tokens_effective: 31_711,
output_tokens: 30,
total_tokens: 31_741,
thought_tokens: 20,
cache_read_input_tokens: 2_560,
uncached_input_tokens: 29_151,
cache_token_source: 'openai',
token_count_source: 'provider_usage',
});
expect(result.cache_hit_ratio).toBeCloseTo(2_560 / 31_711);
});
it('extracts ACP-shaped usage with thought_tokens + cached_read_tokens as provider_usage', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 12_000,
output_tokens: 400,
cached_read_tokens: 8_000,
thought_tokens: 256,
total_tokens: 12_656,
},
},
},
],
'amr-model',
0,
);
expect(result).toMatchObject({
input_tokens: 12_000,
output_tokens: 400,
thought_tokens: 256,
total_tokens: 12_656,
cache_read_input_tokens: 8_000,
token_count_source: 'provider_usage',
cache_token_source: 'openai',
});
});
it('marks provider_usage when only thought_tokens are present', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: { thought_tokens: 42 },
},
},
],
'',
0,
);
expect(result.thought_tokens).toBe(42);
expect(result.token_count_source).toBe('provider_usage');
});
it('merges a later thought-only usage frame with earlier complete input/output', () => {
// ACP runtimes can emit a complete usage frame, then a trailing partial
// frame with only thought_tokens (or cache counters). Reverse-scan must
// keep the complete fields and layer the later thought tokens on top.
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 12_000,
output_tokens: 400,
total_tokens: 12_400,
},
},
},
{
event: 'agent',
data: {
type: 'usage',
usage: { thought_tokens: 256 },
},
},
],
'amr-model',
0,
);
expect(result).toMatchObject({
input_tokens: 12_000,
output_tokens: 400,
total_tokens: 12_400,
thought_tokens: 256,
token_count_source: 'provider_usage',
});
});
it('merges a later cache-only usage frame without dropping earlier input/output', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 1000,
output_tokens: 50,
},
},
},
{
event: 'agent',
data: {
type: 'usage',
usage: {
cache_read_input_tokens: 250,
cache_creation_input_tokens: 100,
},
},
},
],
'',
0,
);
expect(result).toMatchObject({
input_tokens: 1000,
output_tokens: 50,
cache_read_input_tokens: 250,
cache_creation_input_tokens: 100,
cache_token_source: 'anthropic',
token_count_source: 'provider_usage',
});
});
it('merges earlier cache counters when a later frame already has input and output', () => {
// Inverse of the trailing cache-only case: providers may emit cache on an
// earlier frame and a complete input/output pair later. Reverse-scan must
// keep walking after primary is filled so cache_read/cache_creation still merge.
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
cache_read_input_tokens: 250,
cache_creation_input_tokens: 100,
},
},
},
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 1000,
output_tokens: 50,
total_tokens: 1050,
},
},
},
],
'',
0,
);
expect(result).toMatchObject({
input_tokens: 1000,
output_tokens: 50,
total_tokens: 1050,
cache_read_input_tokens: 250,
cache_creation_input_tokens: 100,
cache_token_source: 'anthropic',
token_count_source: 'provider_usage',
});
});
it('merges a later output-only usage frame with earlier input and cache fields', () => {
// A trailing frame with only output_tokens must not freeze the reverse
// scan: earlier input/cache counters still need to merge into run_finished.
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 8_000,
cache_read_input_tokens: 2_000,
cache_creation_input_tokens: 500,
},
},
},
{
event: 'agent',
data: {
type: 'usage',
usage: { output_tokens: 120 },
},
},
],
'amr-model',
0,
);
expect(result).toMatchObject({
input_tokens: 8_000,
output_tokens: 120,
cache_read_input_tokens: 2_000,
cache_creation_input_tokens: 500,
cache_token_source: 'anthropic',
token_count_source: 'provider_usage',
});
});
it('merges a later input-only usage frame with earlier output tokens', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: { output_tokens: 90, total_tokens: 4_090 },
},
},
{
event: 'agent',
data: {
type: 'usage',
usage: { input_tokens: 4_000 },
},
},
],
'',
0,
);
expect(result).toMatchObject({
input_tokens: 4_000,
output_tokens: 90,
total_tokens: 4_090,
token_count_source: 'provider_usage',
});
});
it('normalizes additive Responses-API / ACP usage where cache_read exceeds input_tokens', () => {
// Real AMR/vela follow-up shape: the stream reports input_tokens as the
// UNCACHED remainder with cached_input_tokens reported separately ON TOP, so
// cache_read > input. Treating it as inclusive (cache_read ⊆ input) made the
// denominator far too small and produced cache_hit_ratio ≫ 1 (the corrupt
// ~78% of AMR follow-up runs). It must resolve to a sane <=1 ratio with the
// cache-read folded into the effective input.
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 140_187,
output_tokens: 64,
cached_input_tokens: 659_456,
},
},
},
],
'',
0,
);
expect(result).toMatchObject({
input_tokens_provider: 140_187,
input_tokens_effective: 799_643,
cache_read_input_tokens: 659_456,
uncached_input_tokens: 140_187,
cache_token_source: 'openai',
});
expect(result.cache_hit_ratio).toBeCloseTo(659_456 / 799_643);
expect(result.cache_hit_ratio).toBeLessThanOrEqual(1);
// The first model call of the turn shares the same denominator definition,
// so first_call_cache_hit_ratio must be repaired in lockstep.
expect(result.first_call_input_tokens).toBe(140_187);
expect(result.first_call_cache_read_input_tokens).toBe(659_456);
expect(result.first_call_cache_hit_ratio).toBeCloseTo(659_456 / 799_643);
expect(result.first_call_cache_hit_ratio).toBeLessThanOrEqual(1);
});
it('keeps inclusive OpenAI usage (cache_read <= input) byte-identical after the additive fix', () => {
// Guards the discriminator: an inclusive payload (cached ⊆ input) must stay
// on the input-as-total path — effective = input, uncached = input - read —
// exactly as before, so the additive repair cannot regress codex/openai.
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 1_000,
output_tokens: 20,
cached_input_tokens: 250,
},
},
},
],
'',
0,
);
expect(result).toMatchObject({
input_tokens_provider: 1_000,
input_tokens_effective: 1_000,
cache_read_input_tokens: 250,
uncached_input_tokens: 750,
cache_token_source: 'openai',
});
expect(result.cache_hit_ratio).toBeCloseTo(250 / 1_000);
expect(result.first_call_cache_hit_ratio).toBeCloseTo(250 / 1_000);
});
it.each([
{
name: 'claude anthropic usage',
usage: {
input_tokens: 100,
output_tokens: 10,
cache_read_input_tokens: 20,
cache_creation_input_tokens: 5,
},
expected: {
input_tokens_provider: 100,
input_tokens_effective: 125,
output_tokens: 10,
total_tokens: 135,
cache_read_input_tokens: 20,
cache_creation_input_tokens: 5,
cache_token_source: 'anthropic',
token_count_source: 'provider_usage',
},
},
{
name: 'codex cached input usage',
usage: {
input_tokens: 200,
output_tokens: 11,
cached_input_tokens: 40,
},
expected: {
input_tokens_provider: 200,
input_tokens_effective: 200,
output_tokens: 11,
total_tokens: 211,
cache_read_input_tokens: 40,
uncached_input_tokens: 160,
cache_token_source: 'openai',
token_count_source: 'provider_usage',
},
},
{
name: 'opencode normalized cache usage',
usage: {
input_tokens: 300,
output_tokens: 12,
cached_read_tokens: 60,
cached_write_tokens: 7,
},
expected: {
input_tokens_provider: 300,
input_tokens_effective: 300,
output_tokens: 12,
total_tokens: 312,
cache_read_input_tokens: 60,
cache_creation_input_tokens: 7,
uncached_input_tokens: 240,
cache_token_source: 'openai',
token_count_source: 'provider_usage',
},
},
{
name: 'gemini cached usage',
usage: {
input_tokens: 400,
output_tokens: 13,
cached_read_tokens: 80,
},
expected: {
input_tokens_provider: 400,
input_tokens_effective: 400,
output_tokens: 13,
total_tokens: 413,
cache_read_input_tokens: 80,
uncached_input_tokens: 320,
cache_token_source: 'openai',
token_count_source: 'provider_usage',
},
},
{
name: 'cursor cache usage',
usage: {
input_tokens: 500,
output_tokens: 14,
cached_read_tokens: 90,
cached_write_tokens: 8,
},
expected: {
input_tokens_provider: 500,
input_tokens_effective: 500,
output_tokens: 14,
total_tokens: 514,
cache_read_input_tokens: 90,
cache_creation_input_tokens: 8,
uncached_input_tokens: 410,
cache_token_source: 'openai',
token_count_source: 'provider_usage',
},
},
{
name: 'acp hermes cache usage',
usage: {
input_tokens: 600,
output_tokens: 15,
cached_read_tokens: 120,
total_tokens: 615,
},
expected: {
input_tokens_provider: 600,
input_tokens_effective: 600,
output_tokens: 15,
total_tokens: 615,
cache_read_input_tokens: 120,
uncached_input_tokens: 480,
cache_token_source: 'openai',
token_count_source: 'provider_usage',
},
},
{
name: 'amr vela usage without cache',
usage: {
input_tokens: 12,
output_tokens: 7,
total_tokens: 19,
},
expected: {
input_tokens_provider: 12,
input_tokens_effective: 12,
output_tokens: 7,
total_tokens: 19,
cache_token_source: 'unavailable',
input_accounting_mode: 'unknown',
token_count_source: 'provider_usage',
},
},
{
name: 'pi rpc usage with cache and provider total',
usage: {
input_tokens: 700,
output_tokens: 16,
cached_read_tokens: 140,
cached_write_tokens: 9,
total_tokens: 716,
},
expected: {
input_tokens_provider: 700,
input_tokens_effective: 700,
output_tokens: 16,
total_tokens: 716,
cache_read_input_tokens: 140,
cache_creation_input_tokens: 9,
uncached_input_tokens: 560,
cache_token_source: 'openai',
token_count_source: 'provider_usage',
},
},
{
name: 'qoder usage without cache',
usage: {
input_tokens: 800,
output_tokens: 17,
},
expected: {
input_tokens_provider: 800,
input_tokens_effective: 800,
output_tokens: 17,
total_tokens: 817,
cache_token_source: 'unavailable',
token_count_source: 'provider_usage',
},
},
{
name: 'copilot result usage',
usage: {
input_tokens: 900,
output_tokens: 18,
},
expected: {
input_tokens_provider: 900,
input_tokens_effective: 900,
output_tokens: 18,
total_tokens: 918,
cache_token_source: 'unavailable',
token_count_source: 'provider_usage',
},
},
])('normalizes $name for run_finished token analytics', ({ usage, expected }) => {
const result = scanRunEventsForUsageAnalytics(
[{ event: 'agent', data: { type: 'usage', usage } }],
'',
0,
);
expect(result).toMatchObject(expected);
});
it('prefers the latest usage event and latest reported model when multiple usage snapshots exist', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'status',
label: 'initializing',
model: 'claude-sonnet-4-5',
},
},
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 120,
output_tokens: 12,
cached_read_tokens: 20,
},
},
},
{
event: 'agent',
data: {
type: 'status',
label: 'model',
detail: 'claude-opus-4-1',
},
},
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 240,
output_tokens: 24,
cached_read_tokens: 60,
cached_write_tokens: 5,
},
},
},
],
'',
20,
);
expect(result).toMatchObject({
input_tokens_provider: 240,
input_tokens_effective: 240,
output_tokens: 24,
total_tokens: 264,
cache_read_input_tokens: 60,
cache_creation_input_tokens: 5,
uncached_input_tokens: 180,
estimated_context_tokens: 220,
cache_token_source: 'openai',
input_accounting_mode: 'inclusive',
token_count_source: 'provider_usage',
agent_reported_model: 'claude-opus-4-1',
});
expect(result.cache_hit_ratio).toBeCloseTo(60 / 240);
// The reverse scan above takes the LAST usage event (240 / cache_read 60).
// The forward first-call scan must instead surface the turn's OPENING call
// (120 / cache_read 20) — the session-reuse signal that the within-turn
// aggregate masks.
expect(result.first_call_input_tokens).toBe(120);
expect(result.first_call_cache_read_input_tokens).toBe(20);
expect(result.first_call_cache_hit_ratio).toBeCloseTo(20 / 120);
});
it('reports the anthropic first-call cache hit independently of later within-turn calls', () => {
const result = scanRunEventsForUsageAnalytics(
[
// Opening call of a resumed turn: tiny uncached delta over a fully
// cached prefix — the cache-hit signal session reuse produces.
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 100,
output_tokens: 10,
cache_read_input_tokens: 8_000,
cache_creation_input_tokens: 0,
},
},
},
// A later within-turn call grows the prefix; the reverse scan lands here.
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 300,
output_tokens: 30,
cache_read_input_tokens: 8_400,
cache_creation_input_tokens: 200,
},
},
},
],
'',
0,
);
// Anthropic input_tokens is the UNCACHED portion, so effective = input + cache_read.
expect(result.first_call_input_tokens).toBe(100);
expect(result.first_call_cache_read_input_tokens).toBe(8_000);
expect(result.first_call_cache_hit_ratio).toBeCloseTo(8_000 / 8_100);
// Last-call aggregate stays distinct from the first-call signal.
expect(result.cache_read_input_tokens).toBe(8_400);
});
it('includes anthropic cache_creation in the first-call denominator (matches last-call)', () => {
// A cold opening call writes a large cache (cache_creation) while reading
// little. The first-call denominator must be input + cache_read +
// cache_creation — identical to the last-call definition — so the two
// ratios are comparable. A single usage event makes first == last.
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 1_000,
output_tokens: 20,
cache_read_input_tokens: 500,
cache_creation_input_tokens: 8_500,
},
},
},
],
'',
0,
);
// denominator = 1000 + 500 + 8500 = 10000, not 1500.
expect(result.first_call_input_tokens).toBe(1_000);
expect(result.first_call_cache_read_input_tokens).toBe(500);
expect(result.first_call_cache_hit_ratio).toBeCloseTo(500 / 10_000);
expect(result.first_call_cache_hit_ratio).toBeCloseTo(result.cache_hit_ratio ?? 0);
});
it('honors the full cache-creation alias matrix on the first call (nested cache_creation)', () => {
// A provider that emits cache creation only via the nested
// `cache_creation.input_tokens` alias (not the flat key) must still land in
// the first-call denominator — otherwise it overstates the cache hit. This
// locks the first-call extraction to the same alias matrix the last-call
// path already supports.
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 1_000,
output_tokens: 20,
cache_read_input_tokens: 500,
cache_creation: { input_tokens: 8_500 },
},
},
},
],
'',
0,
);
expect(result.first_call_cache_hit_ratio).toBeCloseTo(500 / 10_000);
// Locked to the last-call definition, which also reads the nested alias.
expect(result.first_call_cache_hit_ratio).toBeCloseTo(result.cache_hit_ratio ?? 0);
});
it('mirrors first-call onto last-call for a single-call turn', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 500,
output_tokens: 50,
cache_read_input_tokens: 100,
},
},
},
],
'',
0,
);
expect(result.first_call_input_tokens).toBe(500);
expect(result.first_call_cache_read_input_tokens).toBe(100);
expect(result.first_call_cache_hit_ratio).toBeCloseTo(result.cache_hit_ratio ?? 0);
});
it('falls back to modelUsage and totalTokens aliases when usage is nested under modelUsage', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
modelUsage: {
prompt_tokens: 150,
completion_tokens: 30,
totalTokens: 180,
prompt_tokens_details: { cached_tokens: 50 },
},
},
},
],
'gpt-5.5',
25,
);
expect(result).toMatchObject({
input_tokens_provider: 150,
input_tokens_effective: 150,
output_tokens: 30,
total_tokens: 180,
cache_read_input_tokens: 50,
uncached_input_tokens: 100,
estimated_context_tokens: 125,
cache_token_source: 'openai',
token_count_source: 'provider_usage',
agent_reported_model: null,
});
expect(result.cache_hit_ratio).toBeCloseTo(50 / 150);
});
it('prefers canonical token fields over alias fields instead of double-counting conflicting values', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 220,
prompt_tokens: 999,
output_tokens: 22,
completion_tokens: 777,
total_tokens: 242,
totalTokens: 1_776,
cached_read_tokens: 20,
},
},
},
],
'gpt-5.5',
20,
);
expect(result).toMatchObject({
input_tokens_provider: 220,
input_tokens_effective: 220,
output_tokens: 22,
total_tokens: 242,
cache_read_input_tokens: 20,
uncached_input_tokens: 200,
estimated_context_tokens: 200,
cache_token_source: 'openai',
token_count_source: 'provider_usage',
});
expect(result.cache_hit_ratio).toBeCloseTo(20 / 220);
});
it('falls back to totalTokens-only payloads without fabricating input/output splits', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
totalTokens: 345,
},
},
},
],
'gpt-4.1',
0,
);
expect(result).toEqual({
total_tokens: 345,
cache_token_source: 'unavailable',
input_accounting_mode: 'unknown',
// Any real provider token field (including total-only) is provider_usage.
token_count_source: 'provider_usage',
agent_reported_model: null,
});
});
it('keeps anthropic cache write tokens additive while leaving uncached_input_tokens on provider input', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
input_tokens: 500,
output_tokens: 40,
cache_read_input_tokens: 120,
cache_creation_input_tokens: 30,
},
},
},
],
'claude-opus-4-1',
50,
);
expect(result).toMatchObject({
input_tokens_provider: 500,
input_tokens_effective: 650,
output_tokens: 40,
total_tokens: 690,
cache_read_input_tokens: 120,
cache_creation_input_tokens: 30,
uncached_input_tokens: 500,
estimated_context_tokens: 600,
cache_token_source: 'anthropic',
token_count_source: 'provider_usage',
});
expect(result.cache_hit_ratio).toBeCloseTo(120 / 650);
});
it('marks provider_usage when only cache-adjacent aliases exist without concrete input totals', () => {
const result = scanRunEventsForUsageAnalytics(
[
{
event: 'agent',
data: {
type: 'usage',
usage: {
cached_read_tokens: 33,
cached_write_tokens: 7,
},
},
},
],
'',
0,
);
expect(result).toEqual({
cache_read_input_tokens: 33,
cache_creation_input_tokens: 7,
cache_token_source: 'openai',
input_accounting_mode: 'unknown',
token_count_source: 'provider_usage',
agent_reported_model: null,
});
});
it('reports unknown token source for plain mock agents without usage events', () => {
const result = scanRunEventsForUsageAnalytics(
[{ event: 'agent', data: { type: 'text_delta', delta: 'plain output' } }],
'',
0,
);
expect(result).toEqual({
cache_token_source: 'unavailable',
input_accounting_mode: 'unknown',
token_count_source: 'unknown',
agent_reported_model: null,
});
});
});
describe('summarizeRunTimingAnalytics', () => {
it('summarizes main run-path timings and aggregate tool duration', () => {
const result = summarizeRunTimingAnalytics({
runCreatedAt: 1_000,
runUpdatedAt: 8_000,
analyticsCapturedAt: 8_020,
telemetry: {
startRequestedAt: 1_100,
startChatRunStartedAt: 1_200,
promptBuildStartAt: 1_220,
promptBuildEndAt: 1_300,
launchPreflightStartAt: 1_300,
launchPreflightEndAt: 1_650,
processSpawnStartedAt: 1_700,
processSpawnedAt: 1_760,
modelCallStartAt: 1_800,
stdinWriteStartAt: 1_810,
stdinWriteEndAt: 1_850,
firstModelEventAt: 2_000,
firstModelEventType: 'text_delta',
firstTokenAt: 2_500,
firstVisibleOutputAt: 2_500,
firstArtifactWriteAt: 4_250,
attemptIndex: 1,
attemptStartedAt: 1_200,
},
events: [
{
id: 1,
event: 'agent',
timestamp: 3_000,
data: { type: 'tool_use', id: 'tool-1', name: 'Read' },
},
{
id: 2,
event: 'agent',
timestamp: 3_400,
data: { type: 'tool_result', toolUseId: 'tool-1' },
},
{
id: 3,
event: 'agent',
timestamp: 4_000,
data: { type: 'tool_use', id: 'tool-2', name: 'Write' },
},
{
id: 4,
event: 'agent',
timestamp: 4_250,
data: { type: 'tool_result', toolUseId: 'tool-2' },
},
],
});
expect(result).toEqual({
queue_duration_ms: 200,
pre_spawn_duration_ms: 500,
prompt_build_duration_ms: 80,
launch_preflight_duration_ms: 350,
process_spawn_duration_ms: 60,
stdin_write_duration_ms: 40,
time_to_first_model_event_ms: 800,
first_model_event_type: 'text_delta',
time_to_first_token_ms: 1300,
time_to_first_visible_output_ms: 1300,
runtime_init_to_first_token_ms: 650,
spawn_to_first_token_ms: 740,
time_to_first_artifact_ms: 3050,
// No subsegment markers were observed, so the whole spawn->first-token
// span is unattributed and falls into the remainder.
spawn_to_first_token_remainder_ms: 740,
generation_duration_ms: 5500,
tool_call_count: 2,
tool_duration_ms: 650,
artifact_write_duration_ms: 250,
artifact_write_status: 'completed',
artifact_write_source: 'write_tool',
finalize_duration_ms: 20,
total_duration_ms: 7020,
bottleneck_phase: 'stream_output',
last_observed_phase: 'artifact_write',
phase_timing_status: 'complete',
attempt_index: 1,
attempt_duration_ms: 6800,
attempt_time_to_first_token_ms: 1300,
attempt_terminal_phase: 'artifact_write',
});
});
it('splits spawn->first-token into subsegments that sum back exactly', () => {
const result = summarizeRunTimingAnalytics({
runCreatedAt: 1_000,
runUpdatedAt: 8_000,
analyticsCapturedAt: 8_020,
telemetry: {
startChatRunStartedAt: 1_200,
processSpawnStartedAt: 1_700,
processSpawnedAt: 1_760,
// 1760 -> 1900 cli-ready, 1900 -> 2100 session-init, 2100 -> 2500 model.
cliReadyAt: 1_900,
sessionInitDoneAt: 2_100,
firstTokenAt: 2_500,
},
events: [],
});
expect(result.spawn_to_first_token_ms).toBe(740);
expect(result.cli_ready_ms).toBe(140);
expect(result.session_init_ms).toBe(200);
expect(result.model_first_token_ms).toBe(400);
expect(result.spawn_to_first_token_remainder_ms).toBe(0);
// The auditable invariant: the four parts reconstruct the parent span.
expect(
(result.cli_ready_ms ?? 0) +
(result.session_init_ms ?? 0) +
(result.model_first_token_ms ?? 0) +
(result.spawn_to_first_token_remainder_ms ?? 0),
).toBe(result.spawn_to_first_token_ms);
});
it('folds an unobservable session-init boundary into the remainder', () => {
// Stream/plain families stamp cliReadyAt but never sessionInitDoneAt, so
// session_init/model_first_token stay undefined and their time rolls into
// the remainder while the sum invariant still holds.
const result = summarizeRunTimingAnalytics({
runCreatedAt: 1_000,
runUpdatedAt: 8_000,
analyticsCapturedAt: 8_020,
telemetry: {
startChatRunStartedAt: 1_200,
processSpawnedAt: 1_760,
cliReadyAt: 1_900,
firstTokenAt: 2_500,
},
events: [],
});
expect(result.spawn_to_first_token_ms).toBe(740);
expect(result.cli_ready_ms).toBe(140);
expect(result.session_init_ms).toBeUndefined();
expect(result.model_first_token_ms).toBeUndefined();
expect(result.spawn_to_first_token_remainder_ms).toBe(600);
expect(
(result.cli_ready_ms ?? 0) +
(result.session_init_ms ?? 0) +
(result.model_first_token_ms ?? 0) +
(result.spawn_to_first_token_remainder_ms ?? 0),
).toBe(result.spawn_to_first_token_ms);
});
it('drops negative timing segments and ignores orphan tool results', () => {
const result = summarizeRunTimingAnalytics({
runCreatedAt: 5_000,
runUpdatedAt: 7_500,
analyticsCapturedAt: 7_450,
telemetry: {
startRequestedAt: 4_900,
startChatRunStartedAt: 5_100,
processSpawnStartedAt: 5_080,
processSpawnedAt: 5_070,
firstTokenAt: 5_060,
},
events: [
{
id: 1,
event: 'agent',
timestamp: 6_000,
data: { type: 'tool_result', toolUseId: 'orphan-tool' },
},
],
});
expect(result).toEqual({
queue_duration_ms: 100,
generation_duration_ms: 2440,
tool_call_count: 0,
artifact_write_status: 'none',
total_duration_ms: 2450,
first_model_event_type: 'text_delta',
bottleneck_phase: 'stream_output',
last_observed_phase: 'stream_output',
phase_timing_status: 'partial',
attempt_duration_ms: 2400,
attempt_terminal_phase: 'stream_output',
});
expect(result.pre_spawn_duration_ms).toBeUndefined();
expect(result.process_spawn_duration_ms).toBeUndefined();
expect(result.time_to_first_token_ms).toBeUndefined();
expect(result.spawn_to_first_token_ms).toBeUndefined();
expect(result.tool_duration_ms).toBeUndefined();
expect(result.finalize_duration_ms).toBeUndefined();
});
it('records first model event for tool-first runs without inventing first-token timing', () => {
const result = summarizeRunTimingAnalytics({
runCreatedAt: 1_000,
runUpdatedAt: 3_000,
analyticsCapturedAt: 3_010,
telemetry: {
startChatRunStartedAt: 1_100,
processSpawnStartedAt: 1_200,
processSpawnedAt: 1_250,
stdinWriteEndAt: 1_300,
},
events: [
{
id: 1,
event: 'agent',
timestamp: 1_700,
data: { type: 'tool_use', id: 'tool-1', name: 'Read' },
},
],
});
expect(result.time_to_first_model_event_ms).toBe(600);
expect(result.first_model_event_type).toBe('tool_use');
expect(result.time_to_first_token_ms).toBeUndefined();
expect(result.last_observed_phase).toBe('tool_execution');
expect(result.attempt_terminal_phase).toBe('tool_execution');
});
it('counts unique tool_use ids for tool_call_count (duplicate ids do not inflate)', () => {
const result = summarizeRunTimingAnalytics({
runCreatedAt: 1_000,
runUpdatedAt: 5_000,
analyticsCapturedAt: 5_010,
telemetry: {
startChatRunStartedAt: 1_100,
},
events: [
{
id: 1,
event: 'agent',
timestamp: 2_000,
data: { type: 'tool_use', id: 'dup-1', name: 'Read' },
},
{
id: 2,
event: 'agent',
timestamp: 2_100,
data: {
type: 'tool_use',
id: 'dup-1',
name: 'Read',
input: { file_path: 'late.html' },
},
},
{
id: 3,
event: 'agent',
timestamp: 2_500,
data: { type: 'tool_result', toolUseId: 'dup-1' },
},
{
id: 4,
event: 'agent',
timestamp: 3_000,
data: { type: 'tool_use', id: 'other', name: 'Bash' },
},
{
id: 5,
event: 'agent',
timestamp: 3_200,
data: { type: 'tool_result', toolUseId: 'other' },
},
],
});
expect(result.tool_call_count).toBe(2);
// Duration pairs from first tool_use timestamp, not the duplicate.
expect(result.tool_duration_ms).toBe(500 + 200);
});
it('prefers tool_use.startedAt over event timestamp for tool duration', () => {
const result = summarizeRunTimingAnalytics({
runCreatedAt: 1_000,
runUpdatedAt: 10_000,
analyticsCapturedAt: 10_010,
telemetry: {
startChatRunStartedAt: 1_100,
},
events: [
{
id: 1,
event: 'agent',
// Event log time is late (terminal emit); startedAt is first frame.
timestamp: 5_000,
data: {
type: 'tool_use',
id: 'acp-1',
name: 'Bash',
startedAt: 2_000,
},
},
{
id: 2,
event: 'agent',
timestamp: 5_500,
data: { type: 'tool_result', toolUseId: 'acp-1' },
},
],
});
expect(result.tool_call_count).toBe(1);
// 5500 (result) - 2000 (startedAt) = 3500, not 5500 - 5000 = 500.
expect(result.tool_duration_ms).toBe(3_500);
});
});
describe('summarizeToolAnalytics', () => {
it('counts unique canonical families and unique tool_result errors', () => {
const result = summarizeToolAnalytics([
{
event: 'agent',
data: { type: 'tool_use', id: 't1', name: 'Read' },
},
{
event: 'agent',
data: { type: 'tool_result', toolUseId: 't1', isError: false },
},
{
event: 'agent',
data: { type: 'tool_use', id: 't2', name: 'Bash' },
},
{
event: 'agent',
data: { type: 'tool_result', toolUseId: 't2', isError: true },
},
{
event: 'agent',
data: { type: 'tool_use', id: 't3', name: 'Read' },
},
{
event: 'agent',
data: { type: 'tool_result', toolUseId: 't3', isError: true },
},
// Duplicate tool_use id must not inflate unique names.
{
event: 'agent',
data: { type: 'tool_use', id: 't1', name: 'Read' },
},
// Duplicate error result frames for the same toolUseId must not inflate.
{
event: 'agent',
data: { type: 'tool_result', toolUseId: 't2', isError: true },
},
]);
expect(result.tool_error_count).toBe(2);
expect(result.tool_name_count).toBe(2);
// Allowlist order: Read before Bash.
expect(result.tool_names).toEqual(['Read', 'Bash']);
expect(result.tool_names_csv).toBe('Read,Bash');
});
it('canonicalizes arbitrary ACP names and never ships raw free-text', () => {
const result = summarizeToolAnalytics([
{
event: 'agent',
data: { type: 'tool_use', id: 'a', name: 'MultiEdit' },
},
{
event: 'agent',
data: { type: 'tool_use', id: 'b', name: 'web_fetch' },
},
{
event: 'agent',
data: { type: 'tool_use', id: 'c', name: 'Glob' },
},
{
event: 'agent',
data: { type: 'tool_use', id: 'd', name: 'mcp__custom__do_thing' },
},
{
event: 'agent',
data: { type: 'tool_use', id: 'e', name: '/Users/secret/path.ts' },
},
{
event: 'agent',
data: { type: 'tool_use', id: 'f', name: 'https://evil.example/x' },
},
{
event: 'agent',
data: { type: 'tool_use', id: 'g', name: 'read' },
},
]);
// MultiEdit→Edit, web_fetch→Fetch, Glob→Search, mcp/path/url → other,
// read→Read. Allowlist order; other last.
expect(result.tool_names).toEqual(['Edit', 'Read', 'Search', 'Fetch', 'other']);
expect(result.tool_name_count).toBe(5);
expect(result.tool_names_csv).toBe('Edit,Read,Search,Fetch,other');
expect(result.tool_names.every((n) => !n.includes('/') && !n.includes('://'))).toBe(
true,
);
});
it('maps unknown raw names to other (bounded family set, not 25 raw names)', () => {
const events = Array.from({ length: 30 }, (_, i) => ({
event: 'agent' as const,
data: { type: 'tool_use', id: `id-${i}`, name: `Tool${i}` },
}));
const result = summarizeToolAnalytics(events);
// All ToolN collapse to `other` (not the Tool family — ToolN ≠ Tool).
expect(result.tool_name_count).toBe(1);
expect(result.tool_names).toEqual(['other']);
expect(result.tool_names_csv).toBe('other');
});
it('aliases case-insensitive known families including Tool', () => {
const result = summarizeToolAnalytics([
{ event: 'agent', data: { type: 'tool_use', id: '1', name: 'WRITE' } },
{ event: 'agent', data: { type: 'tool_use', id: '2', name: 'tool' } },
{ event: 'agent', data: { type: 'tool_use', id: '3', name: 'Shell' } },
{ event: 'agent', data: { type: 'tool_use', id: '4', name: 'WebFetch' } },
]);
expect(result.tool_names).toEqual(['Write', 'Bash', 'Fetch', 'Tool']);
expect(result.tool_name_count).toBe(4);
});
});