Files
open-design/apps/daemon/tests/first-visible-output-telemetry-isolation.test.ts
lefarcenandGitHub 9810fc08fe fix(daemon): stamp first_visible_output when output is emitted, not decoded (#7364)
* fix(daemon): stamp first_visible_output when output is emitted, not decoded

`time_to_first_visible_output_ms` has been a byte-for-byte copy of
`time_to_first_token_ms` since it shipped: `noteFirstTokenAt()` marked
both `first_token` and `first_visible_output` from one call with one
timestamp, and marks are first-write-wins, so the real mark inside
`send()` could never fire. Across 205,795 `run_finished` events in the
last 7 days the difference was 0 for every single run — p50, p90, p99
and max all 0.

The daemon does not emit every token it decodes. The `<od-title>` marker
stripper, the fabricated-role-marker guard (#3247) and close-time stdout
buffering can all hold bytes back after a token has been recognised, and
that withheld window is exactly what this field exists to measure.

`send()` is now the sole owner of the mark: it is the last thing every
stream handler passes through, so a mark there means the bytes really
left the daemon. `stdout` now counts as visible output too — the plain /
BYOK / antigravity family has no structured `agent` stream, and
antigravity buffers stdout until close, so its first token and its first
visible byte can be a whole run apart.

No user-visible change. `first_token` keeps its current meaning, the
`?? firstTokenAt` fallback still covers runs that never emit anything,
and `last_observed_phase` keeps the same labels — a later
`first_visible_output` can only move a run from `tool_execution` to
`stream_output`, which is the more accurate answer.

* fix(daemon): read the decode clock before emitting the first text delta

Splitting `first_visible_output` off `first_token` exposed an ordering
flaw the shared timestamp had been hiding. On the qoder / json-event-
stream / pi-rpc, Copilot and ACP paths the gate reads

    if (emitTitleFilteredGuardedTextDelta(delta)) noteFirstTokenAt();

so the emit — which fans the delta out to every SSE client and stamps
`first_visible_output` on the way — completes BEFORE the clock is read
for the token. Two consequences: `time_to_first_token_ms` silently
included our own write latency, and on a loaded box the visible-output
mark could land a millisecond AHEAD of the token that produced it,
making the gap negative.

Capture the decode timestamp before the gate and hand it to
`noteFirstTokenAt`. The Claude and plain-stdout paths already stamped the
token first and are unchanged. With all five sites token-first,
`firstVisibleOutputAt >= firstTokenAt` now holds by construction rather
than by both marks sharing one call, and the straight-through spec
asserts it.

* fix(daemon): mark visible output on the strategy close-time tail

The OD Next machine protocol withholds any text that might still complete a
reserved `<open-design-...>` block. `finish()` is what finally rules that out,
at child close, and that release is persisted and broadcast directly instead of
going through `send()`. So a reply whose visible text was withheld in its
entirety recorded no visible output at all, and the analytics fallback
collapsed a real close-time wait back to `firstTokenAt` -- reproducing the
exact dead-field symptom this change exists to end. Both emission paths now
apply one shared visible-output rule; `first_model_event` stays on the live
path only, so a withheld reply cannot drag the phase anchor to run end.

Telemetry also stops being able to break the product. Every lifecycle mark in
this file rides the path the model's bytes travel on, so a throw from
instrumentation cost the user the whole reply rather than one analytics field:
a red test that injects a throwing tracer failed the run outright before this.
The marks now run inside a failure-isolated helper scoped to the marks alone,
logging once per run instead of swallowing silently.

The regression suite no longer inherits the OD Next rollout default -- that
default has been `active`, is expected to flip after 0.21.0, and is a
user-facing switch besides. Each case names the mode it runs under and the
strategy case asserts admission actually happened. `run_finished` delivery is
awaited through the daemon's own analytics flush instead of an arbitrary
15-second cutoff, while still failing when the event never arrives.
2026-08-25 07:37:10 +00:00

128 lines
4.8 KiB
TypeScript

import { mkdtemp, rm } from 'node:fs/promises';
import os from 'node:os';
import path from 'node:path';
import { afterEach, describe, expect, it, vi } from 'vitest';
import type { RunLifecycleMark } from '../src/run-lifecycle-tracer.js';
// The `first_visible_output` / `first_token` marks are stamped from inside
// `send()` — the single choke point EVERY stream event passes through on its
// way to the user — and from the strategy's close-time tail emission. That
// places pure instrumentation directly on the product's critical path, so the
// failure mode of a bug in it is not "one analytics field is missing", it is
// "the user never receives the reply".
//
// Today nothing in that block realistically throws: the classifier is written
// defensively and `mark` only spreads an object. But "safe because it is
// currently written carefully" is not an invariant — the next line added there
// can break it, and it would break the product, silently, for every run.
//
// So the fault is injected rather than argued about: the marker classifier and
// every mark this change owns are made to throw, and the run must still deliver
// its complete reply and reach `succeeded`. The blast radius of broken
// telemetry has to be the telemetry.
const FAULTED_MARKS = new Set<RunLifecycleMark>([
'first_token',
'first_visible_output',
'first_artifact_write',
]);
vi.mock('../src/run-lifecycle-tracer.js', async (importOriginal) => {
const actual = await importOriginal<typeof import('../src/run-lifecycle-tracer.js')>();
return {
...actual,
runLifecycleMarkersForStreamEvent: () => {
throw new Error('injected telemetry fault: stream-event marker classification');
},
createRunLifecycleTracer: (run: Parameters<typeof actual.createRunLifecycleTracer>[0]) => {
const tracer = actual.createRunLifecycleTracer(run);
return {
...tracer,
mark(mark: RunLifecycleMark, timestamp?: number) {
// Only the marks this change owns. The run-start marks stay real so
// this case cannot pass by breaking the run before it ever streams.
if (FAULTED_MARKS.has(mark)) {
throw new Error(`injected telemetry fault: ${mark}`);
}
tracer.mark(mark, timestamp);
},
markFirstModelEvent() {
throw new Error('injected telemetry fault: first model event');
},
};
},
};
});
const { startServer } = await import('../src/server.js');
const {
TEST_BUDGET_MS,
clearTelemetryEnv,
createChatProject,
putConfig,
readAssistantMessage,
restoreEnv,
sendRunAndWait,
snapshotEnv,
writeFakeOpencode,
} = await import('./first-visible-output-harness.js');
type StartedServer = import('./first-visible-output-harness.js').StartedServer;
const REPLY = 'Here is your answer, in full, exactly as the model produced it.';
describe('lifecycle instrumentation cannot cost the user their reply', () => {
const originalEnv = snapshotEnv();
let started: StartedServer | null = null;
let binDir: string | null = null;
afterEach(async () => {
await Promise.resolve(started?.shutdown?.());
if (started?.server) {
await new Promise<void>((resolve) => started?.server.close(() => resolve()));
}
started = null;
if (binDir) await rm(binDir, { force: true, recursive: true });
binDir = null;
restoreEnv(originalEnv);
});
it('delivers the whole reply when every lifecycle mark throws', async () => {
binDir = await mkdtemp(path.join(os.tmpdir(), 'od-fvo-fault-'));
// Two deltas, so the assertion covers both the first event (which is what
// carries the marks) and the ones after it.
const bin = await writeFakeOpencode(binDir, 'opencode-fault', `
emit({ type: 'text', part: { type: 'text', text: ${JSON.stringify(REPLY.slice(0, 21))} } });
emit({ type: 'text', part: { type: 'text', text: ${JSON.stringify(REPLY.slice(21))} } });
finishTurn();`);
clearTelemetryEnv();
// No telemetry sink: this case is about the product surface surviving, and
// a keyless daemon takes the same emission path.
process.env.OD_NEXT_STRATEGY_ROLLOUT = 'off';
started = (await startServer({ port: 0, returnServer: true })) as StartedServer;
await putConfig(started.url, {
agentId: 'opencode',
agentCliEnv: { opencode: { OPENCODE_BIN: bin } },
telemetry: { metrics: false, content: false, artifactManifest: false },
privacyDecisionAt: Date.now(),
});
const conversation = await createChatProject(started.url, 'telemetry-fault');
const { created, run } = await sendRunAndWait(
started.url,
conversation,
'render telemetry-fault',
);
expect(run.status).toBe('succeeded');
expect(
await readAssistantMessage(
started.url,
conversation,
created.assistantMessageId as string,
),
).toBe(REPLY);
}, TEST_BUDGET_MS);
});