Skip to content

Commit 93676aa

Browse files
burrows99claude
andauthored
fix(collector): bound emit failure memory and word network failures accurately (#6)
* fix(collector): bound emit failure memory and word network failures accurately Follow-up to the emit-feedback diagnostics (#5), addressing two Copilot review notes: - Cli.ts kept every failed EmitResult in an array but only ever read the count and the last one. On a run that emits per onProgress, repeated failures grew that array unbounded. Replace it with a counter plus the most recent failure. - The emit diagnostic said the collector "rejected" the emits even when the POST never reached it (connection refused/timeout/DNS — no HTTP status). Word an HTTP rejection and a delivery failure distinctly. - Collector.emit returned the full rejection body, which a caller retains; a large error page could bloat memory. Cap the stored body at 10k chars (the log line still truncates to 500 independently). Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * fix(trace): make empty/aborted runs fail loudly instead of silently "running" (#7) A chrome run that captured nothing and recorded nothing was reported as success (ok:true, exit 0) and could sit on the dashboard's "running" badge forever — the agent had no signal it was broken. Root cause: the failure signals lived in stderr logs or dashboard-only state, never in the JSON envelope the agent reads. This closes those gaps and the matching violations of the logger's own two-channel contract (codes.ts: the stderr log and the envelope diagnostic for one event should carry the SAME code). - Terminal envelope on abort. If a run throws (attach failed, engine crashed, recording threw), DynamicCommand now emits a terminal envelope via onProgress — no `running` flag, ok:false, an ENGINE_FATAL diagnostic — so the collector resolves the session instead of leaving its initial "running" partial orphaned. Cli flushes that emit before exiting non-zero. - Recording outcomes are now envelope diagnostics, not just stderr. RECORD_EMPTY (no frames → empty video) and RECORD (render/upload threw) were log-only, so "no video" was invisible to a --json reader. Both now push a warn diagnostic carrying the same code as the log. - Upload failure no longer masquerades as a clean local save. S3ArtifactStore swallows failures and returns null, which #record could not tell apart from "no S3 configured". It now distinguishes the two and emits an UPLOAD diagnostic when a configured upload fails (link missing, local copy kept). - ENGINE_FATAL is now logged as well as diagnosed, so it appears in both channels per the contract. Adds test/dynamic-diagnostics.test.js (fake-tracer unit tests for the abort terminal envelope, captured-fatal, and clean-empty cases). typecheck + build clean; 44/45 tests pass (1 DB round-trip skipped). Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * fix(collector): bound the rejection body at the stream, add emit-diagnostic tests Addresses the two Copilot review notes on the PR: - Collector.emit buffered the whole rejection body via response.text() before slicing, so an oversized error page still caused a transient memory spike and download latency even though the stored body was capped. Read only up to MAX_BODY_CHARS off the stream, then cancel it — bounding memory and latency at the source. - Extract the emit-failure diagnostic wording into an exported emitFailureMessage() helper and cover it with focused tests: HTTP status → "rejected", no status (network) → "failed" (the regression guard so a POST that never landed isn't reported as a rejection), plus the no-body / missing-error / oversized-body edge cases. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * fix(collector): flush the TextDecoder so a split multi-byte char isn't dropped readCappedText decoded chunks with { stream: true } but never did a final decode() flush. A response ending on a multi-byte UTF-8 sequence split across the last chunk boundary would drop/garble that trailing character in the stored body and logged reason. Flush after the read loop. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent ce8ffe1 commit 93676aa

5 files changed

Lines changed: 192 additions & 22 deletions

File tree

src/cli/Cli.ts

Lines changed: 38 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,18 @@ export function condense(json: Record<string, unknown>): Record<string, unknown>
6767
return json;
6868
}
6969

70+
/**
71+
* emitFailureMessage — the end-of-run diagnostic for collector emit failures. An HTTP status means the collector
72+
* received the request and rejected it; no status means the POST never landed (connection refused/timeout/DNS),
73+
* so word each distinctly rather than calling both "rejected". `count` is the total failed emits this run; `last`
74+
* is the most recent failure (whose reason is shown). Extracted so the wording/count stay unit-testable.
75+
*/
76+
export function emitFailureMessage(collector: string, count: number, last: EmitResult): string {
77+
return last.status
78+
? `collector ${collector} rejected ${count} emit(s): HTTP ${last.status}${last.body ? ` — ${last.body.slice(0, 200)}` : ""}`
79+
: `${count} emit(s) to collector ${collector} failed: ${last.error ?? "unknown error"}`;
80+
}
81+
7082
/** emit policy: bare --json → JSON to stdout; --json <path> → file (stdout stays human); else human. */
7183
function emit(trace: Trace, renderHuman: () => string, options: any): void {
7284
// Enforce the envelope contract before it leaves the process: structural violations become error
@@ -120,31 +132,42 @@ export class Cli {
120132
// dashboard updates live as it runs.
121133
const collector = await Collector.resolve(options.emit);
122134
let emitChain: Promise<unknown> = Promise.resolve();
123-
const emitFailures: EmitResult[] = [];
135+
// Only the count and the most recent failure are surfaced, so keep just those — not every failed result.
136+
// onProgress can emit on a hot path, and retaining each failure would grow memory without bound.
137+
let emitFailureCount = 0;
138+
let lastEmitFailure: EmitResult | undefined;
124139
const emitToCollector = collector
125-
? (envelope: unknown) => { emitChain = emitChain.then(async () => { const result = await Collector.emit(collector, envelope); if (!result.ok) emitFailures.push(result); }); }
140+
? (envelope: unknown) => { emitChain = emitChain.then(async () => { const result = await Collector.emit(collector, envelope); if (!result.ok) { emitFailureCount++; lastEmitFailure = result; } }); }
126141
: undefined;
127142

128-
const { trace } = await this.#dynamic.run({
129-
target, port, launch,
130-
breakpoints: options.breakpoint, exprs: options.expression,
131-
steps, curl: options.curl,
132-
root: options.root, maxHits: options.maxHits,
133-
recordOut: options.output,
134-
args: { target, ...(launch ? { launch: true } : { port }), breakpoints: options.breakpoint, ...(options.root ? { root: options.root } : {}), ...(options.maxHits ? { maxHits: options.maxHits } : {}), ...(steps.length ? { steps: steps.map(redactStep) } : {}), ...(options.curl ? { curl: options.curl } : {}) },
135-
...(emitToCollector ? { onProgress: (intermediateTrace: Trace) => emitToCollector(intermediateTrace.toJSON()) } : {}),
136-
});
143+
let trace: Trace;
144+
try {
145+
({ trace } = await this.#dynamic.run({
146+
target, port, launch,
147+
breakpoints: options.breakpoint, exprs: options.expression,
148+
steps, curl: options.curl,
149+
root: options.root, maxHits: options.maxHits,
150+
recordOut: options.output,
151+
args: { target, ...(launch ? { launch: true } : { port }), breakpoints: options.breakpoint, ...(options.root ? { root: options.root } : {}), ...(options.maxHits ? { maxHits: options.maxHits } : {}), ...(steps.length ? { steps: steps.map(redactStep) } : {}), ...(options.curl ? { curl: options.curl } : {}) },
152+
...(emitToCollector ? { onProgress: (intermediateTrace: Trace) => emitToCollector(intermediateTrace.toJSON()) } : {}),
153+
}));
154+
} catch (error) {
155+
// The run threw (attach failed, engine crashed, recording threw). It already emitted a TERMINAL envelope
156+
// via onProgress that clears the dashboard's "running" session — flush the chain so that POST actually
157+
// lands before we exit, then surface the failure (non-zero exit + the same ENGINE_FATAL code in the log).
158+
if (emitToCollector) await emitChain;
159+
log.error("dynamic trace aborted before completion", { code: Code.ENGINE_FATAL, err: error });
160+
process.exit(1);
161+
}
137162

138163
// Flush the final (complete) envelope and all pending emits BEFORE rendering, so a rejected emit
139164
// (a 400 schema error, a 503 dead store) becomes a visible diagnostic in the printed/--json envelope
140165
// instead of vanishing into an info log — the gap that sent a debugging loop chasing the wrong cause.
141166
if (emitToCollector) {
142167
emitToCollector(trace.toJSON());
143168
await emitChain;
144-
if (emitFailures.length) {
145-
const last = emitFailures[emitFailures.length - 1];
146-
const reason = last.status ? `HTTP ${last.status}${last.body ? ` — ${last.body.slice(0, 200)}` : ""}` : (last.error ?? "unknown error");
147-
trace.diagnostics.push(Diagnostic.warn(Code.EMIT, `collector ${collector} rejected ${emitFailures.length} emit(s): ${reason}`));
169+
if (lastEmitFailure && collector) {
170+
trace.diagnostics.push(Diagnostic.warn(Code.EMIT, emitFailureMessage(collector, emitFailureCount, lastEmitFailure)));
148171
}
149172
}
150173
emit(trace, () => this.#dynamic.render(trace), options);

src/cli/commands/DynamicCommand.ts

Lines changed: 49 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -79,11 +79,33 @@ export class DynamicCommand extends TraceCommand<DynamicRequest, DynamicResult>
7979
const trace = this.#toTrace(capture, { sessionId, args: request.args ?? {}, startedAtMs });
8080
if (isChrome) await this.#record(capture, trace, sessionId, request.recordOut);
8181
return { trace, capture };
82+
} catch (error) {
83+
// A throw here (attach failed, engine crashed, recording threw) would otherwise leave the initial
84+
// `running` partial (emitted above) orphaned in the dashboard forever — the session never resolves.
85+
// Emit a TERMINAL envelope (no `running` flag → meta.running absent; ok:false via the error diagnostic)
86+
// so the dashboard flips it to failed, and surface the cause in the stderr trail with the same code.
87+
log.error("trace run aborted before completion", { code: Code.ENGINE_FATAL, sessionId, err: error });
88+
request.onProgress?.(this.#abortedTrace(error, context));
89+
throw error;
8290
} finally {
8391
launched?.kill();
8492
}
8593
}
8694

95+
/** A terminal envelope for a run that threw: empty data, an ENGINE_FATAL error, and crucially NO `running`
96+
* flag, so the collector resolves the session instead of leaving its initial running partial hanging. */
97+
#abortedTrace(error: unknown, context: RunCtx): Trace {
98+
return this.envelope({
99+
command: `run.${context.target}`,
100+
data: new TraceData({ events: [] }),
101+
diagnostics: [Diagnostic.error(Code.ENGINE_FATAL, String((error as Error)?.message ?? error).split("\n")[0])],
102+
sessionId: context.sessionId,
103+
args: context.args,
104+
startedAtMs: context.startedAtMs,
105+
target: new TargetReference({ kind: context.target, source: "cdp", trigger: context.trigger }),
106+
});
107+
}
108+
87109
/**
88110
* A partial, mid-run envelope: the same shape as the finished trace but flagged `running` and carrying only
89111
* the events captured so far (lineage/recording/diagnostics are computed once at the end in {@link #toTrace}).
@@ -103,7 +125,10 @@ export class DynamicCommand extends TraceCommand<DynamicRequest, DynamicResult>
103125
#toTrace(capture: CaptureResult, context: { sessionId: string; args: Record<string, unknown>; startedAtMs: number }): Trace {
104126
const source = "cdp";
105127
const diagnostics: Diagnostic[] = [];
106-
if (capture.fatal) diagnostics.push(Diagnostic.error(Code.ENGINE_FATAL, String(capture.fatal).split("\n")[0]));
128+
if (capture.fatal) {
129+
log.error("engine reported a fatal error", { code: Code.ENGINE_FATAL, sessionId: context.sessionId, fatal: String(capture.fatal).split("\n")[0] });
130+
diagnostics.push(Diagnostic.error(Code.ENGINE_FATAL, String(capture.fatal).split("\n")[0]));
131+
}
107132
// A failed journey step (selector not found / timed out) flips the envelope's `ok` — same gate the old
108133
// `journey` command applied to its exit code, now expressed as an error diagnostic.
109134
for (const step of capture.steps ?? []) if (!step.ok) diagnostics.push(Diagnostic.error(Code.STEP_FAILED, `#${step.sequence} ${step.step}${step.note ? " — " + step.note : ""}`));
@@ -150,13 +175,32 @@ export class DynamicCommand extends TraceCommand<DynamicRequest, DynamicResult>
150175
try {
151176
const videoOutputPath = outputPath ?? join(tmpdir(), `trace-${sessionId}.mp4`);
152177
const videoPath = await Recorder.renderJourney(capture.frames ?? [], capture.traced ?? [], videoOutputPath);
153-
if (!videoPath) { log.warn("no frames captured — nothing to record", { code: Code.RECORD_EMPTY, sessionId }); return; }
154-
const upload = this.artifacts && this.artifacts.isConfigured() ? await this.artifacts.upload(videoPath, `recordings/${sessionId}.mp4`, "video/mp4") : null;
178+
if (!videoPath) {
179+
// Both channels carry the same code: the stderr trail AND an envelope diagnostic, so an agent reading
180+
// --json learns the chrome run produced no video (instead of inferring it from a missing `recording`).
181+
log.warn("no frames captured — nothing to record", { code: Code.RECORD_EMPTY, sessionId });
182+
trace.diagnostics.push(Diagnostic.warn(Code.RECORD_EMPTY, "no frames captured — the debug-replay video is empty (no breakpoint hits, or the journey produced no frames)."));
183+
return;
184+
}
185+
const uploadConfigured = this.artifacts?.isConfigured() ?? false;
186+
const upload = uploadConfigured ? await this.artifacts!.upload(videoPath, `recordings/${sessionId}.mp4`, "video/mp4") : null;
155187
trace.data.recording = upload ? new Recording({ url: upload.url, bytes: upload.bytes }) : new Recording({ path: videoPath });
156-
if (upload) log.info("recording uploaded", { sessionId, url: upload.url, bytes: upload.bytes });
157-
else log.info("recording saved locally — set S3_ENDPOINT to upload + get a link", { sessionId, path: videoPath });
188+
if (upload) {
189+
log.info("recording uploaded", { sessionId, url: upload.url, bytes: upload.bytes });
190+
} else if (uploadConfigured) {
191+
// S3 WAS configured but upload() returned null → it failed (the error was logged inside the store).
192+
// The video is still saved locally, but the dashboard gets no link — surface that instead of
193+
// reporting a clean local save, so "no video link" isn't silently indistinguishable from success.
194+
log.warn("recording upload failed — keeping local copy", { code: Code.UPLOAD, sessionId, path: videoPath });
195+
trace.diagnostics.push(Diagnostic.warn(Code.UPLOAD, `recording upload failed — video saved locally at ${videoPath}, no dashboard link (check S3_ENDPOINT / credentials).`));
196+
} else {
197+
log.info("recording saved locally — set S3_ENDPOINT to upload + get a link", { sessionId, path: videoPath });
198+
}
158199
} catch (error: any) {
200+
// Render or upload threw. Surface it in the envelope too (a warn — the trace data is still valid, only
201+
// the replay is missing) so "no video" is never silent. Previously this was a stderr log the agent never saw.
159202
log.error("recording failed", { code: Code.RECORD, sessionId, err: error });
203+
trace.diagnostics.push(Diagnostic.warn(Code.RECORD, `debug-replay recording failed — ${String(error?.message ?? error).split("\n")[0]}`));
160204
}
161205
}
162206
}

src/collector/Collector.ts

Lines changed: 33 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,35 @@ export interface EmitResult { ok: boolean; status?: number; body?: string; error
1515
* (14747, the compose-published host port from README/compose/scenarios), then the native `trace serve` default (4000). */
1616
const DEFAULT_CANDIDATES = ["http://localhost:14747", "http://localhost:4000"];
1717
const PROBE_TIMEOUT_MS = 500;
18+
/** Cap on the rejection body kept in an {@link EmitResult}: enough to carry a real error message, bounded so a
19+
* large error page can't bloat a caller that retains the result (e.g. across many onProgress emits). */
20+
const MAX_BODY_CHARS = 10_000;
21+
22+
/**
23+
* Read at most `maxChars` of a response body, then cancel the stream — so an oversized rejection page (an HTML
24+
* 500, a stack-trace dump) can't cause a large transient buffer or extra download latency, not just an oversized
25+
* *stored* body. Best-effort: a mid-read network error or a non-stream body falls back to keeping what we have.
26+
*/
27+
async function readCappedText(response: Response, maxChars: number): Promise<string> {
28+
const stream = response.body;
29+
if (!stream) return (await response.text().catch(() => "")).slice(0, maxChars);
30+
const reader = stream.getReader();
31+
const decoder = new TextDecoder();
32+
let text = "";
33+
try {
34+
while (text.length < maxChars) {
35+
const { done, value } = await reader.read();
36+
if (done) break;
37+
text += decoder.decode(value, { stream: true });
38+
}
39+
text += decoder.decode(); // flush bytes buffered from a multi-byte char split across the last chunk boundary
40+
} catch {
41+
// mid-read failure (connection dropped while reading the error body) — surface whatever arrived
42+
} finally {
43+
await reader.cancel().catch(() => {}); // stop downloading the rest once we have enough
44+
}
45+
return text.slice(0, maxChars);
46+
}
1847

1948
/**
2049
* Collector — the client-side emit helper for shipping trace envelopes to a remote collector.
@@ -36,7 +65,10 @@ export class Collector {
3665
}
3766
// A rejection is a real failure — log it at error with the collector's reason (e.g. "invalid envelope",
3867
// "trace store unavailable"), not at info. The caller folds this into the envelope's diagnostics.
39-
const body = await response.text().catch(() => "");
68+
// Cap the body at the source: read only up to MAX_BODY_CHARS off the stream and cancel, so a collector
69+
// that answers with a giant HTML error page can't bloat process memory or stall on the download — callers
70+
// hold onto the result. (The log line truncates further, to 500, separately.)
71+
const body = await readCappedText(response, MAX_BODY_CHARS);
4072
log.error("emit rejected", { code: Code.EMIT, endpoint, status: response.status, body: body.slice(0, 500) });
4173
return { ok: false, status: response.status, body };
4274
} catch (error: any) {

test/dynamic-diagnostics.test.js

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,51 @@
1+
// DynamicCommand diagnostics: a trace run must make its failures legible in the envelope (not just stderr),
2+
// and a thrown run must emit a TERMINAL envelope so the dashboard's "running" session resolves instead of
3+
// hanging forever. Injects a fake tracer so we exercise the envelope/diagnostic logic without a real CDP target.
4+
import "reflect-metadata";
5+
import { test } from "node:test";
6+
import assert from "node:assert/strict";
7+
8+
import { DynamicCommand } from "../dist/cli/commands/DynamicCommand.js";
9+
import { TargetKind } from "../dist/domain/Target.js";
10+
11+
const fakeTracer = (behavior) => ({
12+
async traceNode() { return behavior(); },
13+
async traceChrome() { return behavior(); },
14+
});
15+
16+
const nodeCapture = (over = {}) => ({ target: TargetKind.Node, trigger: "curl localhost", breakpoints: [], events: [], ...over });
17+
18+
test("a thrown run emits a TERMINAL envelope (running cleared, ENGINE_FATAL) so the dashboard resolves", async () => {
19+
const seen = [];
20+
const cmd = new DynamicCommand(fakeTracer(() => { throw new Error("attach failed: ECONNREFUSED"); }));
21+
22+
await assert.rejects(
23+
cmd.run({ target: TargetKind.Node, port: 9229, onProgress: (t) => seen.push(t) }),
24+
/attach failed/,
25+
);
26+
27+
// The first envelope is the initial running partial; the last must be the terminal abort.
28+
assert.ok(seen.length >= 2, "expected an initial running partial AND a terminal abort envelope");
29+
assert.equal(seen[0].meta.running, true, "the first envelope is the running partial");
30+
const terminal = seen[seen.length - 1];
31+
assert.notEqual(terminal.meta.running, true, "the terminal envelope is NOT running — the session resolves");
32+
assert.equal(terminal.ok, false, "a terminal abort is not ok");
33+
assert.ok(
34+
terminal.diagnostics.some((d) => d.code === "ENGINE_FATAL" && d.level === "error"),
35+
"the terminal envelope carries an ENGINE_FATAL error",
36+
);
37+
});
38+
39+
test("a captured fatal (no throw) yields ok:false + an ENGINE_FATAL diagnostic in the envelope", async () => {
40+
const cmd = new DynamicCommand(fakeTracer(() => nodeCapture({ fatal: "debugger disconnected" })));
41+
const { trace } = await cmd.run({ target: TargetKind.Node, port: 9229 });
42+
assert.equal(trace.ok, false);
43+
assert.ok(trace.diagnostics.some((d) => d.code === "ENGINE_FATAL"));
44+
});
45+
46+
test("a clean empty node trace stays ok:true and not running (no false alarms)", async () => {
47+
const cmd = new DynamicCommand(fakeTracer(() => nodeCapture()));
48+
const { trace } = await cmd.run({ target: TargetKind.Node, port: 9229 });
49+
assert.equal(trace.ok, true);
50+
assert.equal(trace.meta.running, undefined, "the final envelope is not flagged running");
51+
});

test/output.test.js

Lines changed: 21 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,7 @@ import "reflect-metadata";
44
import { test } from "node:test";
55
import assert from "node:assert/strict";
66

7-
import { condense } from "../dist/cli/Cli.js";
7+
import { condense, emitFailureMessage } from "../dist/cli/Cli.js";
88
import { Code } from "../dist/shared/codes.js";
99
import { Collector } from "../dist/collector/Collector.js";
1010

@@ -81,3 +81,23 @@ test("Collector.emit: a failed POST resolves to a rich result (never throws, nev
8181
assert.equal(typeof result.error, "string", "the failure reason is carried back, not dropped");
8282
assert.ok(result.error.length > 0, "error message is non-empty");
8383
});
84+
85+
test("emitFailureMessage: an HTTP status reads as a 'rejected' diagnostic with the status + reason", () => {
86+
const msg = emitFailureMessage("http://localhost:4000", 3, { ok: false, status: 400, body: "invalid envelope" });
87+
assert.equal(msg, "collector http://localhost:4000 rejected 3 emit(s): HTTP 400 — invalid envelope");
88+
});
89+
90+
test("emitFailureMessage: a no-status (network) failure reads as 'failed', never 'rejected'", () => {
91+
// The bug this guards: a POST that never landed (connection refused/timeout/DNS) was reported as the collector
92+
// having "rejected" a request it never received. A status-less failure must use the delivery wording instead.
93+
const msg = emitFailureMessage("http://localhost:4000", 2, { ok: false, error: "fetch failed" });
94+
assert.equal(msg, "2 emit(s) to collector http://localhost:4000 failed: fetch failed");
95+
assert.doesNotMatch(msg, /rejected/, "a delivery failure must not claim the collector rejected anything");
96+
});
97+
98+
test("emitFailureMessage: edge cases — no body omits the reason, missing error falls back, body caps at 200", () => {
99+
assert.equal(emitFailureMessage("u", 1, { ok: false, status: 503 }), "collector u rejected 1 emit(s): HTTP 503");
100+
assert.equal(emitFailureMessage("u", 1, { ok: false }), "1 emit(s) to collector u failed: unknown error");
101+
const huge = emitFailureMessage("u", 1, { ok: false, status: 500, body: "x".repeat(5000) });
102+
assert.equal(huge, "collector u rejected 1 emit(s): HTTP 500 — " + "x".repeat(200), "an oversized body is truncated to 200 chars in the diagnostic");
103+
});

0 commit comments

Comments
 (0)