From 377b27775243a23530f974eb58cee4a101d622a1 Mon Sep 17 00:00:00 2001 From: Relayflow Date: Mon, 21 Sep 2026 15:48:51 +0000 Subject: [PATCH 1/2] fix(sdk): name the failing test in a step failure report MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The step-failure render cut every captured stream to its last 1,024 bytes. For any runner that streams results and prints its totals last — TAP (`node --test`), cargo, vitest, pytest — that last kilobyte is by construction the summary and the final few passing cases, so the one `not ok` was exactly the part that got cut. The report proved a failure happened and withheld which one, pushing diagnosis back to a local re-run. The bytes were never lost by the kernel: `exec_det.rs` captures 64 KiB per stream and `preserve_failure_output` keeps it on a failed deterministic completion. This is a render fix, and no kernel change is needed. `cli/step-excerpt.ts` selects three disjoint ranges of the journaled field in source order — a head of whole lines, the lines in the elided middle that match a built-in failure marker (TAP `not ok`, `FAIL`/`FAILED`, a vitest or jest glyph, cargo's `... FAILED` and `---- stdout ----`, Rust's `panicked at`), and a tail — inside a 4,096-byte bound, with the elision stated in band. Markers are matched on an escape-stripped view of each line, so a coloured header still matches; journal data is not mutated. The header becomes `Stdout (captured excerpt):`. `(last 1,024 bytes)` was a promise about the excerpt's shape made where it could no longer be true; the marker now makes it in band, only when it is. The absence of a marker means the field the journal carried fit whole — not that the command printed nothing more, which no renderer can know. Field names `stdoutTail`/`stderrTail` are unchanged for compatibility; the new semantics are documented on them and in docs/SURFACE.md. Co-Authored-By: Claude Opus 5 --- docs/SURFACE.md | 37 +- packages/sdk/src/cli/step-excerpt.ts | 317 ++++++++++++++++++ packages/sdk/src/cli/step-failure.ts | 29 +- packages/sdk/src/failure-kinds.ts | 12 +- .../sdk/tests/authored-node-result.test.ts | 22 ++ .../authored-run-failure-evidence.test.ts | 66 ++++ packages/sdk/tests/direct-run-failure.test.ts | 2 +- packages/sdk/tests/resume-failure.test.ts | 2 +- .../sdk/tests/step-failure-diagnostic.test.ts | 92 ++++- .../sdk/tests/step-failure-excerpt.test.ts | 241 +++++++++++++ 10 files changed, 783 insertions(+), 37 deletions(-) create mode 100644 packages/sdk/src/cli/step-excerpt.ts create mode 100644 packages/sdk/tests/step-failure-excerpt.test.ts diff --git a/docs/SURFACE.md b/docs/SURFACE.md index 8b98dad6f..3d21ebb4c 100644 --- a/docs/SURFACE.md +++ b/docs/SURFACE.md @@ -796,15 +796,44 @@ uses the opening shown here; an authored child failure opens with FAILED [step_failed] Run "" failed with completionReason: step_failed. Step "" () completionReason: attempt=/ exit=. Detail: -Stdout (last 1,024 bytes): - -Stderr (last 1,024 bytes): - +Stdout (captured excerpt): + +Stderr (captured excerpt): + Transcript: Inspect: flows replay --at Journal: /runs/.sqlite3 ``` +An excerpt is at most 4,096 UTF-8 bytes of the stream the journal carried. A +stream that fits is printed whole and carries no marker; one that does not is +printed as a head, the lines from the elided middle that match a built-in +failure marker (TAP `not ok`, `FAIL`/`FAILED`, a vitest or jest failure glyph, +cargo's `... FAILED` and `---- stdout ----` headings, and Rust's +`panicked at`), and a tail — with the elision stated in band: + +```text +Stdout (captured excerpt): +TAP version 13 +ok 1 - pty: spawns +… 61,204 bytes elided; 2 lines matched a failure marker … +not ok 5 - pty-exit: child reaped twice +not ok 9 - pty-exit: fd leak +… end of elided region … +1..14 +# tests 14 +# fail 2 +``` + +The markers are hints, not a parser: an unrecognised format still gets head and +tail context, and prose can match one. Two limits bound what any excerpt can +show. The absence of an elision marker means the field the journal carried fit +whole, not that the command printed nothing more: a deterministic step's +capture is itself the last 64 KiB of each stream, and an `agent` or `llm` +step's evidence survives only as the daemon's bounded render in +`verification.detail`. A failure printed before those windows is not in the +journal to be excerpted. + Each clause is present only when the journal holds the fact behind it; nothing is defaulted. The same fields appear as named keys on the `--json` diagnostic (`stepId`, `stepType`, `completionReason`, `attempt`, `maxIterations`, diff --git a/packages/sdk/src/cli/step-excerpt.ts b/packages/sdk/src/cli/step-excerpt.ts new file mode 100644 index 000000000..db1f18c1b --- /dev/null +++ b/packages/sdk/src/cli/step-excerpt.ts @@ -0,0 +1,317 @@ +/** + * One captured stream, cut to something a terminal can print WITHOUT throwing + * away the line that says what failed. + * + * The render this replaces kept the last 1,024 bytes. For any runner that + * streams results and prints its summary last — TAP (`node --test`), cargo, + * vitest, pytest — the last kilobyte is by construction the totals and the + * final few passing cases, so the one `not ok` was always the part that got + * cut. A report that proves a failure happened and withholds which one costs + * the reader a local re-run, which is the loop the gate exists to avoid. + * + * So the excerpt is three disjoint ranges of the same source, in source order: + * a head, the lines in the elided middle that look like a failing case, and a + * tail. The elision is stated in band, in bytes, so the reader is never left + * guessing whether what they are looking at is all of it. + * + * What this can and cannot promise: + * + * - It selects from the field the journal carried, which for a deterministic + * step is the last 64 KiB the kernel captured (`OUTPUT_TAIL_BYTES`, + * relayflowd/src/exec_det.rs). A failure printed before that window is not + * here to be found, and no marker can say so — hence `captured excerpt` + * rather than a claim about the command's whole output. + * - The absence of an elision marker means the supplied field fit whole. It + * does not mean the command printed nothing more. + * - The markers are hints, not a parser. They find the common runners' failing + * lines; ordinary prose can match one, and an unknown format matches none + * and still gets head-and-tail context. + */ + +/** Default excerpt budget, in UTF-8 bytes, for one captured stream. */ +export const EXCERPT_BYTES = 4_096; + +/** + * Below this there is no room to both elide and say so, and an excerpt that + * silently drops the claim it makes about itself is the bug being fixed. The + * budget is a constant of this module, not configuration, so a caller that + * asks for less has made a programming error and is told at the call. + */ +export const MIN_EXCERPT_BYTES = 256; + +/** How many matched lines the elided middle may contribute. */ +const MAX_HIGHLIGHT_LINES = 20; + +/** A highlight cut short is only worth showing if some of the line survives. */ +const MIN_HIGHLIGHT_BYTES = 24; + +/** Newlines this module inserts between ranges and markers. */ +const SEPARATOR_RESERVE = 16; + +const END_MARKER = '… end of elided region …'; +const TRUNCATED_MARKER = '… line truncated …'; + +/** + * Lines that name a failing case, for the runners this repo actually runs. + * + * Each is anchored after optional indentation (nested TAP indents its + * subtests) and is matched against a comparison view of the line with + * terminal escapes removed, so a coloured `FAIL` header still matches. They + * are constants rather than user input, which is why `RegExp` is correct + * here; a spec-supplied pattern would be untrusted and would have to go + * through `re2js`. + */ +const FAILURE_MARKERS: readonly RegExp[] = [ + /^\s*not ok\b/u, // TAP: node --test, prove + /^\s*FAILED\b/u, // pytest short test summary: `FAILED tests/x.py::y - ...` + /^\s*FAIL\b/u, // vitest / jest file header: `FAIL src/x.test.ts` + /^\s*[✖✗×]\s/u, // vitest / jest failure glyph + /\.\.\.\s*FAILED\b/u, // cargo: `test pty::exit ... FAILED` + /^\s*---- .* ----\s*$/u, // cargo: `---- pty::exit stdout ----` + /\bpanicked at\b/u, // rust panic +]; + +interface Range { start: number; end: number } + +/** + * Cut `value` to at most `budget` UTF-8 bytes, markers included. + * + * A stream that already fits is returned whole (sanitised) with no marker. One + * that does not keeps a head of whole lines, up to `MAX_HIGHLIGHT_LINES` + * matched lines from the elided middle, and a tail that fills what is left. + * Every cut is at a code-point boundary, so slicing never invents a U+FFFD. + */ +export function formatStepExcerpt(value: string, budget: number = EXCERPT_BYTES): string { + if (!Number.isSafeInteger(budget) || budget < MIN_EXCERPT_BYTES) { + throw new Error(`step excerpt budget must be an integer of at least ${MIN_EXCERPT_BYTES} bytes`); + } + const source = Buffer.from(value, 'utf8'); + // Sanitised from the original string, not from the round trip: a lone + // surrogate the wire delivered is the caller's to keep, and re-encoding it + // would be this module inventing a replacement character. + if (source.length <= budget) return sanitise(value); + + const lines = lineRanges(source); + const matches = lines.filter(isFailureLine(source)); + // Content space is what is left after the markers can be afforded at their + // widest, so the excerpt can always state its own elision. + const content = Math.max(0, budget - markerReserve(source.length, matches.length)); + const tailShare = Math.floor(content / 2); + const headShare = Math.floor(content / 4); + const highlightShare = content - tailShare - headShare; + + const head = headRange(source, lines, headShare); + // Provisional tail, which with the head defines the middle the highlights + // are drawn from. + const highlights = selectHighlights(source, matches, highlightShare, + head.end, tailRange(source, tailShare, head.end).start); + + // Every byte the head and the highlights did not need goes to the tail, + // which is where a runner puts the summary. The tail may not cross the last + // highlight, so the ranges stay disjoint and in source order. + const spare = headShare - size(head) + + highlightShare - highlights.reduce((sum, highlight) => sum + size(highlight.range), 0); + const tail = tailRange(source, tailShare + spare, highlights.at(-1)?.range.end ?? head.end); + + const selected = [head, ...highlights.map(highlight => highlight.range), tail] + .filter(range => size(range) > 0); + const elided = source.length - selected.reduce((sum, range) => sum + size(range), 0); + // Positional, not textual: two identical failing lines at two positions are + // two observations, and one of them may be visible while the other is not. + // A line shown in part — a truncated highlight, or one the tail starts in + // the middle of — was not omitted, so only a line with nothing on screen is + // counted here. + const omitted = matches.filter(match => + !selected.some(range => match.start < range.end && match.end > range.start)).length; + + const parts: string[] = []; + const terminated = (chunk: string): string => chunk.endsWith('\n') ? chunk : `${chunk}\n`; + if (size(head) > 0) parts.push(terminated(text(source, head))); + parts.push(`${openMarker(elided, highlights.length, omitted)}\n`); + for (const highlight of highlights) { + parts.push(terminated(text(source, highlight.range) + (highlight.truncated ? ` ${TRUNCATED_MARKER}` : ''))); + } + if (highlights.length > 0) { + if (omitted > 0) parts.push(`${moreMarker(omitted)}\n`); + parts.push(`${END_MARKER}\n`); + } + if (size(tail) > 0) parts.push(text(source, tail)); + // Sanitising replaces, never expands, so it cannot push the result over the + // budget; the clamp is where the byte bound is enforced, for every path. + return clampBytes(sanitise(parts.join('')), budget); +} + +/** + * `N bytes elided` counts raw source bytes represented by no selected range, + * including the omitted portion of a line shown only in part. Source bytes + * shown plus source bytes elided is the input, exactly; the markers this + * module inserts are not source bytes, and sanitising can shrink what is + * displayed without changing what was selected. + */ +function openMarker(elided: number, shown: number, omitted: number): string { + const matched = shown > 0 + ? `; ${plural(shown, 'line')} matched a failure marker` + : omitted > 0 ? `; ${plural(omitted, 'line')} matched a failure marker, none shown` : ''; + return `… ${group(elided)} bytes elided${matched} …`; +} + +function moreMarker(omitted: number): string { + return `… +${group(omitted)} more matching ${omitted === 1 ? 'line' : 'lines'} …`; +} + +/** Every marker at its widest, so content space can be assigned once. */ +function markerReserve(sourceBytes: number, matches: number): number { + const open = Math.max( + byteLength(openMarker(sourceBytes, matches, matches)), + byteLength(openMarker(sourceBytes, 0, matches)), + byteLength(openMarker(sourceBytes, 0, 0)), + ); + const highlighted = matches === 0 ? 0 + : byteLength(moreMarker(matches)) + byteLength(END_MARKER) + byteLength(TRUNCATED_MARKER) + 1; + return open + highlighted + SEPARATOR_RESERVE; +} + +/** + * Matched lines from the middle, in source order, bounded by both the line cap + * and the byte share. A whole line is preferred; when the first candidate does + * not fit at all, a code-point-safe prefix of it is shown under a truncation + * marker, because a cut failing line still names the failing case and no + * highlight at all does not. + */ +function selectHighlights( + source: Buffer, matches: readonly Range[], share: number, from: number, to: number, +): Array<{ range: Range; truncated: boolean }> { + const selected: Array<{ range: Range; truncated: boolean }> = []; + let remaining = share; + for (const match of matches) { + // Already visible in the head or the tail, or straddling one of them: a + // line is reported once, at its own position. + if (match.start < from || match.end > to) continue; + if (selected.length >= MAX_HIGHLIGHT_LINES) break; + if (size(match) <= remaining) { + selected.push({ range: match, truncated: false }); + remaining -= size(match); + continue; + } + if (selected.length === 0 && remaining >= MIN_HIGHLIGHT_BYTES) { + const end = floorBoundary(source, match.start + remaining); + if (end > match.start) selected.push({ range: { start: match.start, end }, truncated: true }); + } + break; + } + return selected; +} + +/** + * Whole lines from the start, or a bounded prefix when the first line alone is + * longer than the share — a long first line must not consume the excerpt. + * Whatever whole lines leave unspent is returned to the tail by the caller. + */ +function headRange(source: Buffer, lines: readonly Range[], limit: number): Range { + let end = 0; + for (const line of lines) { + if (line.end > limit) break; + end = line.end; + } + return { start: 0, end: end === 0 ? floorBoundary(source, limit) : end }; +} + +/** + * The last `limit` bytes, cut at a code-point boundary and never crossing + * `stop` (the end of the head or of the last highlight). + * + * Unlike the head, the tail fills its share rather than stopping at a line + * boundary. A stream can be one enormous line followed by a one-byte last + * line; taking whole lines only would spend one byte of a two-kilobyte share + * and drop the summary that the old last-1,024-bytes render always kept. + */ +function tailRange(source: Buffer, limit: number, stop: number): Range { + return { start: Math.max(ceilBoundary(source, source.length - limit), stop), end: source.length }; +} + +function isFailureLine(source: Buffer): (line: Range) => boolean { + return line => { + const comparable = comparableLine(text(source, line)); + return FAILURE_MARKERS.some(marker => marker.test(comparable)); + }; +} + +/** + * The view a marker is matched against: terminal escape sequences and control + * characters removed so a coloured `not ok` or `FAIL` header still matches. + * This never touches what is rendered — journal data is not mutated, and the + * display sanitiser is a separate, later step. + */ +function comparableLine(line: string): string { + return line + .replace(/\u001b\[[0-9;:?]*[ -/]*[@-~]|\u001b[@-Z\\-_]|\u009b[0-9;:?]*[ -/]*[@-~]/gu, '') + .replace(/[\p{Cc}\p{Cf}]/gu, character => character === '\t' ? ' ' : ''); +} + +/** Line ranges over the raw bytes; each end includes its own `\n` when it has one. */ +function lineRanges(source: Buffer): Range[] { + const ranges: Range[] = []; + let start = 0; + for (let index = 0; index < source.length; index++) { + if (source[index] === 0x0a) { + ranges.push({ start, end: index + 1 }); + start = index + 1; + } + } + if (start < source.length) ranges.push({ start, end: source.length }); + return ranges; +} + +/** + * Preserve tabs and newlines; replace binary controls (including ESC and CR), + * C1 controls and Unicode formatting controls without growing the excerpt. + * Applied on every path, short inputs included: a control sequence in a + * two-line stderr is as able to rewrite the terminal as one in a long stream. + */ +function sanitise(value: string): string { + return value.replace(/[\p{Cc}\p{Cf}]/gu, character => + character === '\n' || character === '\t' ? character : '?'); +} + +function clampBytes(value: string, budget: number): string { + const bytes = Buffer.from(value, 'utf8'); + if (bytes.length <= budget) return value; + return bytes.subarray(0, floorBoundary(bytes, budget)).toString('utf8'); +} + +function text(source: Buffer, range: Range): string { + return source.subarray(range.start, range.end).toString('utf8'); +} + +function size(range: Range): number { + return range.end - range.start; +} + +function isBoundary(source: Buffer, index: number): boolean { + return index >= source.length || (source[index]! & 0xc0) !== 0x80; +} + +function floorBoundary(source: Buffer, index: number): number { + let at = Math.max(0, Math.min(index, source.length)); + while (at > 0 && !isBoundary(source, at)) at -= 1; + return at; +} + +function ceilBoundary(source: Buffer, index: number): number { + let at = Math.max(0, Math.min(index, source.length)); + while (at < source.length && !isBoundary(source, at)) at += 1; + return at; +} + +function byteLength(value: string): number { + return Buffer.byteLength(value, 'utf8'); +} + +function plural(count: number, noun: string): string { + return `${group(count)} ${noun}${count === 1 ? '' : 's'}`; +} + +/** Locale-independent digit grouping: the same excerpt everywhere it is read. */ +function group(value: number): string { + return String(value).replace(/\B(?=(\d{3})+(?!\d))/gu, ','); +} diff --git a/packages/sdk/src/cli/step-failure.ts b/packages/sdk/src/cli/step-failure.ts index d04e10ba1..5e8187639 100644 --- a/packages/sdk/src/cli/step-failure.ts +++ b/packages/sdk/src/cli/step-failure.ts @@ -2,8 +2,7 @@ import { join } from 'node:path'; import { DEFAULT_DATA_DIR } from '../daemon-connection.js'; import type { StepFailedDetails } from '../failure-kinds.js'; import type { JournalClient } from '../journal-client.js'; - -const TAIL_BYTES = 1_024; +import { formatStepExcerpt } from './step-excerpt.js'; /** * Read what a failed step left in the journal — for any step type. @@ -117,8 +116,8 @@ export function renderStepEvidence(details: StepFailedDetails): string { + (details.exitCode === undefined ? '' : ` exit=${details.exitCode}`) + '.' + (details.detail === undefined ? '' : `\nDetail: ${details.detail}`) - + (details.stdoutTail ? `\nStdout (last 1,024 bytes):\n${details.stdoutTail}` : '') - + (details.stderrTail ? `\nStderr (last 1,024 bytes):\n${details.stderrTail}` : '') + + (details.stdoutTail ? `\nStdout (captured excerpt):\n${details.stdoutTail}` : '') + + (details.stderrTail ? `\nStderr (captured excerpt):\n${details.stderrTail}` : '') + (details.transcriptPath === undefined ? '' : `\nTranscript: ${details.transcriptPath}`); } @@ -195,22 +194,22 @@ function evidence(payload: Record): Partial const structuredShape = structured !== undefined && processShaped(structured); const transcript = record(record(payload['trajectory_tail'])?.['transcript']); const failure = record(transcript?.['failure']); - const excerpt = failure?.['excerpt']; + const failureExcerpt = failure?.['excerpt']; const transcriptPath = record(transcript?.['file'])?.['path']; // The excerpt is the worker's own pick of the failure; a `stderr` excerpt // is the same bytes as `stderrTail`, so it is not printed twice. - const excerptDetail = typeof excerpt === 'string' && excerpt.length > 0 + const excerptDetail = typeof failureExcerpt === 'string' && failureExcerpt.length > 0 && !(failure?.['kind'] === 'stderr' && typeof stderr === 'string') - ? tail(excerpt) : undefined; + ? formatStepExcerpt(failureExcerpt) : undefined; return { ...(typeof exitCode === 'number' && Number.isSafeInteger(exitCode) ? { exitCode } : {}), - ...(typeof stdout === 'string' && stdout.length > 0 ? { stdoutTail: tail(stdout) } : {}), - ...(typeof stderr === 'string' ? { stderrTail: tail(stderr) } : {}), + ...(typeof stdout === 'string' && stdout.length > 0 ? { stdoutTail: formatStepExcerpt(stdout) } : {}), + ...(typeof stderr === 'string' ? { stderrTail: formatStepExcerpt(stderr) } : {}), // Keep the daemon's account only when it was NOT just a render of the // fields above — otherwise the same bytes print twice. ...(excerptDetail !== undefined ? { detail: excerptDetail } : typeof detail === 'string' && detail.length > 0 && !structuredShape - ? { detail: tail(detail) } : {}), + ? { detail: formatStepExcerpt(detail) } : {}), ...(typeof transcriptPath === 'string' && transcriptPath.length > 0 ? { transcriptPath } : {}), }; } @@ -233,16 +232,6 @@ function record(value: unknown): Record | undefined { ? value as Record : undefined; } -function tail(value: string): string { - const bytes = Buffer.from(value, 'utf8'); - let start = Math.max(0, bytes.length - TAIL_BYTES); - // Drop a partial leading code point, avoiding replacement-byte expansion. - while (start < bytes.length && (bytes[start]! & 0xc0) === 0x80) start += 1; - // Preserve tabs/newlines; replace binary controls (including ESC and CR), - // C1 controls and Unicode formatting controls without growing the excerpt. - return bytes.subarray(start).toString('utf8') - .replace(/[\p{Cc}\p{Cf}]/gu, character => character === '\n' || character === '\t' ? character : '?'); -} function shellQuote(value: string): string { return /^[A-Za-z0-9_-]+$/.test(value) && !value.startsWith('-') diff --git a/packages/sdk/src/failure-kinds.ts b/packages/sdk/src/failure-kinds.ts index 46b704693..72f3d0af5 100644 --- a/packages/sdk/src/failure-kinds.ts +++ b/packages/sdk/src/failure-kinds.ts @@ -177,9 +177,17 @@ export interface StepFailedDetails { */ maxIterations?: number; exitCode?: number; - /** Terminal-safe UTF-8 excerpt, at most 1,024 bytes. */ + /** + * Terminal-safe UTF-8 excerpt of the captured stdout, at most + * `EXCERPT_BYTES` (cli/step-excerpt.ts). The field name is kept for + * compatibility; it is no longer a plain tail. When the captured field did + * not fit, the excerpt keeps a head, the lines from the elided middle that + * match a failure marker, and a tail, and states the elision in band. The + * absence of an elision marker means the field the journal carried fit + * whole — not that the command printed no more than this. + */ stdoutTail?: string; - /** Terminal-safe UTF-8 excerpt, at most 1,024 bytes. */ + /** Terminal-safe UTF-8 excerpt of the captured stderr; see `stdoutTail`. */ stderrTail?: string; /** * The daemon's own account when it was not a render of the fields above, or diff --git a/packages/sdk/tests/authored-node-result.test.ts b/packages/sdk/tests/authored-node-result.test.ts index 9a6e2d9d5..8b9c57528 100644 --- a/packages/sdk/tests/authored-node-result.test.ts +++ b/packages/sdk/tests/authored-node-result.test.ts @@ -1,6 +1,7 @@ import { beforeEach, describe, expect, it, vi } from 'vitest'; import { stepFailedFrame, verifyAuthoredNodeResult } from '../src/authored-node-runner.js'; import { parseAuthoredParentPid } from '../src/authored-runtime-capability.js'; +import { EXCERPT_BYTES, formatStepExcerpt } from '../src/cli/step-excerpt.js'; import type { AuthoredFlowExecutionResult } from '../src/authored-flow-executor.js'; import type { AuthoredRootMetadata } from '../src/authored-root.js'; @@ -162,6 +163,27 @@ describe('step evidence crossing the authored IPC boundary', () => { // of `{}` still marks the diagnostic as carrying evidence it does not have. expect(stepFailedFrame(frame)).toBeUndefined(); }); + it('carries a rendered excerpt across the bridge byte for byte', () => { + // The live `executeAuthoredFlow` fixture never crosses the Bun-to-Node IPC + // hop, and this is where a second, silent truncation would happen: the + // frame reader re-cuts every string field at 8,192 code units. A 4,096 + // UTF-8-byte excerpt is at most 4,096 code units, so it must survive + // whole — a cut here would land mid-marker and say nothing about it. + const lines = ['TAP version 13']; + for (let index = 1; index <= 400; index++) { + lines.push(index === 200 ? `not ok ${index} - the one that matters` + : `ok ${index} - pty: a passing case with a realistically long name`); + } + lines.push('1..400', '# fail 1'); + const stdoutTail = formatStepExcerpt(lines.join('\n') + '\n'); + expect(Buffer.byteLength(stdoutTail)).toBeGreaterThan(1_024); + expect(Buffer.byteLength(stdoutTail)).toBeLessThanOrEqual(EXCERPT_BYTES); + expect(stdoutTail).toContain('not ok 200 - the one that matters'); + + const details = stepFailedFrame({ stepId: 'run-1', stdoutTail, stderrTail: stdoutTail }); + expect(details?.stdoutTail).toBe(stdoutTail); + expect(details?.stderrTail).toBe(stdoutTail); + }); it('bounds a tail the child did not bound', () => { const details = stepFailedFrame({ stderrTail: 'x'.repeat(20_000) }); expect(details?.stderrTail).toHaveLength(8192); diff --git a/packages/sdk/tests/authored-run-failure-evidence.test.ts b/packages/sdk/tests/authored-run-failure-evidence.test.ts index 0160b9a5e..2846efec2 100644 --- a/packages/sdk/tests/authored-run-failure-evidence.test.ts +++ b/packages/sdk/tests/authored-run-failure-evidence.test.ts @@ -6,6 +6,10 @@ import { readCompletedStepOutput, readSuccessfulOutput } from '../src/authored-s import type { RunOutcome } from '../src/protocol.js'; import type { JournalClient } from '../src/journal-client.js'; import { chainFixture } from './flow-chain-fixture.js'; +import { EXCERPT_BYTES } from '../src/cli/step-excerpt.js'; + +/** The one line the report has to name, and the one the old render always cut. */ +const MARKER = 'not ok 111 - pty-exit: child process exit is detected'; const cleanup: Array<() => Promise> = []; afterEach(async () => { for (const close of cleanup.splice(0)) await close(); }); @@ -59,6 +63,68 @@ describe('a failing f.run through the live kernel', () => { expect(message).toContain('Inspect: flows replay'); }); + it('names the failing case from the middle of a real test run', async () => { + // The reported bug, end to end: kernel capture -> journal -> + // `preserve_failure_output` -> SDK render. A runner that streams results + // and prints its totals last puts `ok` lines and a summary in the final + // kilobyte by construction, so the one `not ok` was exactly the part the + // old last-1,024-bytes render cut. + const passing = (index: number) => `ok ${index} - pty: a passing case with a realistically long name`; + const expected = [ + ...Array.from({ length: 110 }, (_, index) => passing(index + 1)), + MARKER, + ...Array.from({ length: 110 }, (_, index) => passing(index + 112)), + '1..221', '# tests 221', '# pass 220', '# fail 1', + ].join('\n') + '\n'; + const stream = Buffer.from(expected, 'utf8'); + const at = Buffer.byteLength(expected.slice(0, expected.indexOf(MARKER)), 'utf8'); + // The fixture is only evidence if the failure sits where the old render + // could not reach and where head-and-tail context alone would not either: + // past the first 4 KiB, before the last 4 KiB, and inside the 64 KiB the + // kernel captures (`OUTPUT_TAIL_BYTES`, relayflowd/src/exec_det.rs). + expect(at).toBeGreaterThan(4_096); + expect(stream.length - at).toBeGreaterThan(4_096); + expect(stream.length).toBeGreaterThan(12 * 1_024); + expect(stream.length).toBeLessThan(20 * 1_024); + expect(stream.subarray(-1_024).toString('utf8')).not.toContain(MARKER); + + const fixture = chainFixture(); + cleanup.push(() => fixture.close()); + const journal = await fixture.connect(); + + const handle = flow('streamed-test-run', async (f) => { + await f.run(`i=1; while [ $i -le 110 ]; do printf 'ok %s - pty: a passing case with a realistically long name\\n' "$i"; i=$((i+1)); done +printf '${MARKER}\\n' +i=112; while [ $i -le 221 ]; do printf 'ok %s - pty: a passing case with a realistically long name\\n' "$i"; i=$((i+1)); done +printf '1..221\\n# tests 221\\n# pass 220\\n# fail 1\\n' +exit 1`); + f.done('success'); + }); + + const failure = await executeAuthoredFlow(handle, journal, undefined, { dataDir: fixture.data }) + .then(() => undefined, (error) => error as { message: string; details?: Record }); + + // The journal is the record: check the failing line is in the completion + // the kernel wrote before asking what the renderer did with it. + const childRunId = /flows replay (\S+)/u.exec(String(failure?.details?.['hint']))?.[1]; + expect(childRunId).toMatch(/^[0-9A-HJKMNP-TV-Z]{26}$/u); + const entries = (await journal.journalRead(childRunId!, 1)).entries as Array<{ + entry_type: string; payload?: { output?: { stdout_tail?: string } }; + }>; + const journaled = entries.find(entry => entry.entry_type === 'step.completed')?.payload?.output?.stdout_tail; + expect(journaled).toBe(expected); + + // And the render names it, inside its own byte bound, with the head and + // the summary still beside it. + const excerpt = String(failure?.details?.['stdoutTail']); + expect(excerpt).toContain(MARKER); + expect(excerpt).toContain('ok 1 - pty: a passing case with a realistically long name'); + expect(excerpt).toContain('# fail 1'); + expect(Buffer.byteLength(excerpt, 'utf8')).toBeLessThanOrEqual(EXCERPT_BYTES); + expect(failure?.message).toContain('Stdout (captured excerpt):'); + expect(failure?.message).toContain(MARKER); + }, 30_000); + it('carries the same facts structurally, not only rendered into the message', async () => { const fixture = chainFixture(); cleanup.push(() => fixture.close()); diff --git a/packages/sdk/tests/direct-run-failure.test.ts b/packages/sdk/tests/direct-run-failure.test.ts index 4a3b390c9..51765f0eb 100644 --- a/packages/sdk/tests/direct-run-failure.test.ts +++ b/packages/sdk/tests/direct-run-failure.test.ts @@ -40,7 +40,7 @@ it('reports an authored step failure as step_failed with a known status, not pro vi.mocked(executeDurableAuthoredFlow).mockRejectedValueOnce(new AuthoredFlowExecutionError( 'step_failed', 'Run "child-run" failed with completionReason: step_failed. Step "agent-2" (agent) ' - + 'completionReason: worker_error exit=1.\nStderr (last 1,024 bytes):\nno such model', + + 'completionReason: worker_error exit=1.\nStderr (captured excerpt):\nno such model', undefined, 'child-run', )); diff --git a/packages/sdk/tests/resume-failure.test.ts b/packages/sdk/tests/resume-failure.test.ts index 401732f2e..4750a4afa 100644 --- a/packages/sdk/tests/resume-failure.test.ts +++ b/packages/sdk/tests/resume-failure.test.ts @@ -12,7 +12,7 @@ import { PROTOCOL_VERSION } from '../src/protocol.js'; const RUN_ID = '01M2NDS2RYK3MH6YBSB1CHA9SE'; const EVIDENCE = `Run "${RUN_ID}" failed with completionReason: step_failed.` + ' Step "agent-2" (agent) completionReason: worker_error exit=1.' - + '\nStderr (last 1,024 bytes):\nclaude: permission denied: /work/out' + + '\nStderr (captured excerpt):\nclaude: permission denied: /work/out' + `\nInspect: flows replay ${RUN_ID} --at agent-2`; const directories: string[] = []; diff --git a/packages/sdk/tests/step-failure-diagnostic.test.ts b/packages/sdk/tests/step-failure-diagnostic.test.ts index 7172944e5..5241b9a15 100644 --- a/packages/sdk/tests/step-failure-diagnostic.test.ts +++ b/packages/sdk/tests/step-failure-diagnostic.test.ts @@ -5,6 +5,7 @@ import { join } from 'node:path'; import { afterEach, describe, expect, it, vi } from 'vitest'; import { runCli } from '../src/cli.js'; import { classifyOutcome, emptyReport, type RunDiagnostic, type RunReport } from '../src/cli/run.js'; +import { EXCERPT_BYTES } from '../src/cli/step-excerpt.js'; import { socketPathFor } from '../src/daemon-connection.js'; import * as daemonLifecycle from '../src/daemon-lifecycle.js'; import { JournalClient } from '../src/journal-client.js'; @@ -41,6 +42,18 @@ async function classify(client: JournalClient, outcome = failure) { return classifyOutcome(client, 'run', outcome, emptyReport('run'), '/tmp/diagnostic.sock', {}); } +/** A TAP run whose failing case is at `failing` and whose totals come last. */ +function tapRun(cases: number, failing: number): string { + const lines = ['TAP version 13']; + for (let index = 1; index <= cases; index++) { + lines.push(index === failing + ? `not ok ${index} - pty-exit: child reaped twice` + : `ok ${index} - pty: a passing case with a realistically long name`); + } + lines.push(`1..${cases}`, `# tests ${cases}`, `# pass ${cases - 1}`, '# fail 1'); + return lines.join('\n') + '\n'; +} + async function diagnosticFor(stderr: string) { const { client } = stub([[completion(1, stderr)]]); return (await classify(client)).report.diagnostics.at(-1) as RunDiagnostic; @@ -98,17 +111,78 @@ describe('step failure diagnostic', () => { } }); - it('keeps the last 1,024 bytes, not the prefix', async () => { - const diagnostic = await diagnosticFor('discarded-prefix' + 'x'.repeat(2_000) + 'last error'); - expect(diagnostic.stderrTail).toBe('x'.repeat(1_014) + 'last error'); - expect(Buffer.byteLength(diagnostic.stderrTail!)).toBe(1_024); - expect(diagnostic.message).not.toContain('discarded-prefix'); + it.each([false, true])('exposes the middle failure through the CLI itself (json=%s)', async json => { + // The unit above proves the renderer; this proves the whole CLI path, + // human and machine-readable, carries the failing case to the operator. + const dir = mkdtempSync(join(tmpdir(), 'flows-failure-')); + directories.push(dir); + writeFileSync(join(dir, 'flows.json'), '{}'); + const path = join(dir, 'tap-run.yaml'); + writeFileSync(path, 'version: "0.1.0"\nname: tap-run\nsteps:\n - id: fail-command\n type: deterministic\n command: \'node --test\'\n'); + const stream = tapRun(400, 200); + vi.spyOn(daemonLifecycle, 'ensureDaemon').mockResolvedValue({ + kind: 'attached', socketPath: socketPathFor(dir), connection: null, + }); + vi.spyOn(JournalClient.prototype, 'connect').mockResolvedValue(undefined); + vi.spyOn(JournalClient.prototype, 'hello').mockResolvedValue({ protocol: PROTOCOL_VERSION, server: 'relayflowd-test' }); + vi.spyOn(JournalClient.prototype, 'runStart').mockResolvedValue(failure); + vi.spyOn(JournalClient.prototype, 'runGet').mockResolvedValue({ + run_id: failure.run_id, status: 'failed', budget: { tokens_in: 0, tokens_out: 0, dollars: '0' }, + steps: { 'fail-command': { type: 'deterministic', state: 'done' } }, + }); + vi.spyOn(JournalClient.prototype, 'journalRead').mockImplementation(async (_runId, fromSeq) => ({ + entries: fromSeq === 1 ? [completion(1, stream, 1)] : [], + })); + const stdout: string[] = []; + const stderr: string[] = []; + const code = await runCli(['run', '--no-spawn', '--data-dir', dir, ...(json ? ['--json'] : []), path], { + stdout: line => stdout.push(line), stderr: line => stderr.push(line), + }); + expect(code).toBe(1); + const output = json ? stdout.join('\n') : stderr.join('\n'); + expect(output).toContain('not ok 200 - pty-exit: child reaped twice'); + if (json) { + const report = JSON.parse(output) as RunReport; + const diagnostic = report.diagnostics.at(-1) as RunDiagnostic; + expect(diagnostic.stderrTail).toContain('not ok 200 - pty-exit: child reaped twice'); + expect(Buffer.byteLength(diagnostic.stderrTail!)).toBeLessThanOrEqual(EXCERPT_BYTES); + } + }); + + it('keeps the head the last-1,024-bytes render discarded outright', async () => { + // This assertion is the inverse of the one it replaces, and the inversion + // is the bug: `discarded-prefix` is the head of the stream, and a render + // that could only ever show its last kilobyte threw it away. + const diagnostic = await diagnosticFor('discarded-prefix\n' + 'x\n'.repeat(4_000) + 'last error\n'); + expect(diagnostic.stderrTail).toContain('discarded-prefix'); + expect(diagnostic.stderrTail).toContain('last error'); + expect(diagnostic.stderrTail).toMatch(/… [\d,]+ bytes elided …/u); + expect(diagnostic.message).toContain('discarded-prefix'); + expect(Buffer.byteLength(diagnostic.stderrTail!)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + + it('names the failing case from the middle of a streamed test run', async () => { + // The reported case. A runner that streams results and prints its totals + // last puts `ok` lines and a summary in the final kilobyte by + // construction, so the one `not ok` was exactly the part that got cut. + const diagnostic = await diagnosticFor(tapRun(400, 200)); + expect(diagnostic.message).toContain('Stderr (captured excerpt):'); + expect(diagnostic.message).toContain('not ok 200 - pty-exit: child reaped twice'); + expect(diagnostic.message).toContain('# fail 1'); + expect(diagnostic.message).toContain('TAP version 13'); + }); + + it('returns a stream that fits whole, so no marker means no elision', async () => { + const stream = tapRun(14, 5); + expect(Buffer.byteLength(stream)).toBeLessThan(EXCERPT_BYTES); + const diagnostic = await diagnosticFor(stream); + expect(diagnostic.stderrTail).toBe(stream); + expect(diagnostic.stderrTail).not.toContain('elided'); }); it('truncates at UTF-8 boundaries without splitting multibyte characters', async () => { - const diagnostic = await diagnosticFor('🙂'.repeat(400) + 'é'); - expect(diagnostic.stderrTail).toBe('🙂'.repeat(255) + 'é'); - expect(Buffer.byteLength(diagnostic.stderrTail!)).toBeLessThanOrEqual(1_024); + const diagnostic = await diagnosticFor('🙂'.repeat(2_000) + 'é'); + expect(Buffer.byteLength(diagnostic.stderrTail!)).toBeLessThanOrEqual(EXCERPT_BYTES); expect(diagnostic.stderrTail).not.toContain('\ufffd'); }); @@ -117,7 +191,7 @@ describe('step failure diagnostic', () => { const diagnostic = await diagnosticFor(binary.repeat(1_000) + '\u009b31m\u202eEND\n\t'); expect(diagnostic.stderrTail).toMatch(/END\n\t$/); expect(diagnostic.stderrTail).not.toMatch(/[\x00-\x08\x0b-\x1f\x7f-\x9f\p{Cf}]/u); - expect(Buffer.byteLength(diagnostic.stderrTail!)).toBeLessThanOrEqual(1_024); + expect(Buffer.byteLength(diagnostic.stderrTail!)).toBeLessThanOrEqual(EXCERPT_BYTES); }); it('includes an empty stderr field for a silent nonzero exit', async () => { diff --git a/packages/sdk/tests/step-failure-excerpt.test.ts b/packages/sdk/tests/step-failure-excerpt.test.ts new file mode 100644 index 000000000..e2a0d6beb --- /dev/null +++ b/packages/sdk/tests/step-failure-excerpt.test.ts @@ -0,0 +1,241 @@ +import { describe, expect, it } from 'vitest'; +import { EXCERPT_BYTES, MIN_EXCERPT_BYTES, formatStepExcerpt } from '../src/cli/step-excerpt.js'; + +/** Every marker this module prints is a line of its own, fenced by `…`. */ +const MARKER = /^… .* …$/u; + +function bytes(value: string): number { + return Buffer.byteLength(value, 'utf8'); +} + +/** + * The bytes of the source that the excerpt actually shows. + * + * Only valid for a fixture of non-empty, newline-terminated, control-free + * lines: then every content line of the output is a whole source line, worth + * its own bytes plus the `\n` the split removed. + */ +function shownBytes(output: string): number { + return output.split('\n') + .filter((line, index, all) => !MARKER.test(line) && !(line === '' && index === all.length - 1)) + .reduce((sum, line) => sum + bytes(line) + 1, 0); +} + +function elidedBytes(output: string): number { + const stated = /… ([\d,]+) bytes elided/u.exec(output); + expect(stated).not.toBeNull(); + return Number(stated![1]!.replaceAll(',', '')); +} + +/** The reported case: a `not ok` early in a stream whose summary is last. */ +function tapStream(cases: number, failing: readonly number[]): string { + const lines = ['TAP version 13']; + for (let index = 1; index <= cases; index++) { + lines.push(failing.includes(index) + ? `not ok ${index} - pty-exit: child reaped twice` + : `ok ${index} - pty: a passing case with a realistically long name`); + } + lines.push(`1..${cases}`, `# tests ${cases}`, `# pass ${cases - failing.length}`, `# fail ${failing.length}`); + return lines.join('\n') + '\n'; +} + +describe('formatStepExcerpt: what it keeps', () => { + it('returns a stream that fits whole, and says nothing about elision', () => { + const stream = tapStream(14, [5]); + expect(bytes(stream)).toBeLessThan(EXCERPT_BYTES); + const excerpt = formatStepExcerpt(stream); + expect(excerpt).toBe(stream); + expect(excerpt).not.toMatch(/elided/u); + }); + + it.each([ + ['an empty stream', ''], + ['a single line with no newline', 'boom on stderr'], + ['a stream of exactly the budget', 'x'.repeat(EXCERPT_BYTES - 1) + '\n'], + ])('returns %s unchanged', (_label, stream) => { + expect(formatStepExcerpt(stream)).toBe(stream); + }); + + it('elides one byte over the budget, and stays within it', () => { + const excerpt = formatStepExcerpt('x'.repeat(EXCERPT_BYTES) + '\n'); + expect(excerpt).toMatch(/… [\d,]+ bytes elided …/u); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + + it('shows the failing case that the old last-1,024-bytes tail always cut', () => { + // The reported case, scaled until it no longer fits and with the failing + // case where a streaming runner leaves it — past the head, well before + // the summary. Every byte of the last kilobyte of this stream is `ok` or + // a total. + const stream = tapStream(400, [200]); + expect(bytes(stream)).toBeGreaterThan(EXCERPT_BYTES); + expect(Buffer.from(stream, 'utf8').subarray(-1_024).toString('utf8')) + .not.toContain('not ok 200'); + + const excerpt = formatStepExcerpt(stream); + expect(excerpt).toContain('not ok 200 - pty-exit: child reaped twice'); + // Head, marker and tail are all still there: the failing line arrives with + // the run's opening and its summary, not instead of them. + expect(excerpt).toContain('TAP version 13'); + expect(excerpt).toContain('# fail 1'); + expect(excerpt).toMatch(/… [\d,]+ bytes elided; 1 line matched a failure marker …/u); + expect(excerpt).toContain('… end of elided region …'); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + + it('keeps the head, which the tail-only render discarded outright', () => { + const excerpt = formatStepExcerpt('discarded-prefix\n' + 'x\n'.repeat(4_000) + 'last error\n'); + expect(excerpt.startsWith('discarded-prefix\n')).toBe(true); + expect(excerpt.endsWith('last error\n')).toBe(true); + }); + + it('accounts for every source byte: shown plus elided is the input', () => { + const stream = tapStream(400, [200, 210]); + const excerpt = formatStepExcerpt(stream); + expect(shownBytes(excerpt) + elidedBytes(excerpt)).toBe(bytes(stream)); + }); +}); + +describe('formatStepExcerpt: which lines it highlights', () => { + it.each([ + ['TAP', 'not ok 13 - pty-exit: child process exit is detected'], + ['indented TAP subtests', ' not ok 2 - nested subtest'], + ['pytest', 'FAILED tests/test_pty.py::test_exit - assert 1 == 0'], + ['vitest file headers', ' FAIL tests/pty-exit.test.ts > exit is detected'], + ['vitest failure glyphs', ' × pty-exit: child process exit is detected'], + ['cargo case results', 'test pty::exit::child_is_reaped ... FAILED'], + ['cargo failure headings', '---- pty::exit::child_is_reaped stdout ----'], + ['rust panics', "thread 'main' panicked at kernel/src/lib.rs:41:9:"], + ['ANSI-coloured headers', '\u001b[31m FAIL \u001b[39m tests/pty-exit.test.ts'], + ])('recognises a %s failure line from anywhere in the stream', (_runner, line) => { + const filler = 'ok - a passing case with a realistically long name\n'; + const excerpt = formatStepExcerpt(filler.repeat(40) + line + '\n' + filler.repeat(120)); + // The ANSI case is matched on an escape-stripped view but rendered through + // the display sanitiser, so compare on what survives sanitising. + expect(excerpt).toContain(line.replaceAll(/[\p{Cc}\p{Cf}]/gu, '?')); + expect(excerpt).toMatch(/1 line matched a failure marker/u); + }); + + it('gives an unrecognised format head and tail context without claiming a match', () => { + const excerpt = formatStepExcerpt('first line\n' + 'noise\n'.repeat(2_000) + 'last line\n'); + expect(excerpt).toContain('first line'); + expect(excerpt).toContain('last line'); + expect(excerpt).toMatch(/^… [\d,]+ bytes elided …$/mu); + expect(excerpt).not.toContain('failure marker'); + expect(excerpt).not.toContain('… end of elided region …'); + }); + + it('does not repeat a failure that is already visible in the head or the tail', () => { + const filler = 'ok - a passing case with a realistically long name\n'; + const stream = 'not ok 1 - in the head\n' + filler.repeat(200) + 'not ok 999 - in the tail\n'; + const excerpt = formatStepExcerpt(stream); + expect(excerpt.split('not ok 1 - in the head')).toHaveLength(2); + expect(excerpt.split('not ok 999 - in the tail')).toHaveLength(2); + // Both are shown at their own position, so neither is reported as omitted. + expect(excerpt).not.toContain('more matching lines'); + }); + + it('treats two identical failing lines at two positions as two observations', () => { + const filler = 'ok - a passing case with a realistically long name\n'; + const repeated = 'not ok 7 - the same name twice\n'; + const excerpt = formatStepExcerpt( + filler.repeat(40) + repeated + filler.repeat(40) + repeated + filler.repeat(120)); + expect(excerpt.split(repeated.trimEnd())).toHaveLength(3); + expect(excerpt).toMatch(/2 lines matched a failure marker/u); + }); + + it('caps the highlights at twenty lines and counts the rest', () => { + const filler = 'ok - a passing case with a realistically long name\n'; + const failures = Array.from({ length: 50 }, (_, index) => `not ok ${index + 1} - middle failure\n`).join(''); + const excerpt = formatStepExcerpt(filler.repeat(40) + failures + filler.repeat(200)); + expect(excerpt.match(/^not ok /gmu)).toHaveLength(20); + expect(excerpt).toMatch(/20 lines matched a failure marker/u); + expect(excerpt).toContain('… +30 more matching lines …'); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + + it('shows part of a failing line too long to fit, and says it was cut', () => { + const filler = 'ok - a passing case with a realistically long name\n'; + const excerpt = formatStepExcerpt( + filler.repeat(40) + 'not ok 5 - ' + 'D'.repeat(8_000) + '\n' + filler.repeat(120)); + expect(excerpt).toContain('not ok 5 - DDDD'); + expect(excerpt).toContain('… line truncated …'); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + + it('reports matches it had no room to show at all', () => { + // One very long matching line consumes the highlight share; the rest of + // the middle matches are counted rather than silently dropped. + const long = 'not ok 1 - ' + 'D'.repeat(4_000) + '\n'; + const filler = 'ok - a passing case with a realistically long name\n'; + const excerpt = formatStepExcerpt( + filler.repeat(40) + long + 'not ok 2 - short\nnot ok 3 - short\n' + filler.repeat(120)); + expect(excerpt).toContain('… +2 more matching lines …'); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); +}); + +describe('formatStepExcerpt: what it is safe to print', () => { + it('never splits a multibyte character and never invents a replacement', () => { + const excerpt = formatStepExcerpt('🙂'.repeat(2_000) + 'é'); + expect(excerpt).not.toContain('�'); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + + it('keeps a replacement character the capture itself produced', () => { + // The Rust capture decodes lossily and may hand over a U+FFFD of its own + // at its 64 KiB boundary. That is data, not damage this module did. + const excerpt = formatStepExcerpt('� head\n' + 'x\n'.repeat(4_000) + '� tail\n'); + expect(excerpt).toContain('� head'); + expect(excerpt).toContain('� tail'); + }); + + it('replaces controls and bidi overrides on a short stream too, without growing it', () => { + const stream = '\u001b[31mred\u009b0m‮overridden\u0000\r\n\tkept\n'; + const excerpt = formatStepExcerpt(stream); + expect(excerpt).not.toMatch(/(?![\n\t])[\p{Cc}\p{Cf}]/u); + expect(excerpt).toContain('\n\tkept\n'); + expect(bytes(excerpt)).toBeLessThanOrEqual(bytes(stream)); + }); + + it('replaces controls in an elided stream and stays inside the budget', () => { + const binary = Buffer.from([0, 0xff, 0x1b, 13, 8]).toString('utf8'); + const excerpt = formatStepExcerpt(binary.repeat(1_000) + '\u009b31m‮END\n\t'); + expect(excerpt).toMatch(/END\n\t$/u); + expect(excerpt).not.toMatch(/[\x00-\x08\x0b-\x1f\x7f-\x9f\p{Cf}]/u); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + + it('handles CRLF, tabs and a final line with no newline', () => { + const stream = 'first\r\n' + '\tindented\r\n'.repeat(1_000) + 'not ok 4 - crlf case\r\nno trailing newline'; + const excerpt = formatStepExcerpt(stream); + expect(excerpt).toContain('first'); + expect(excerpt).toContain('no trailing newline'); + expect(excerpt).toContain('\tindented'); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + + it('bounds a single enormous line with no newline at all', () => { + const excerpt = formatStepExcerpt('A'.repeat(70_000)); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + expect(excerpt).toMatch(/… [\d,]+ bytes elided …/u); + expect(excerpt.startsWith('A')).toBe(true); + expect(excerpt.endsWith('A')).toBe(true); + }); + + it.each([1_024, MIN_EXCERPT_BYTES, EXCERPT_BYTES, 8_192])('stays inside a %s byte budget', budget => { + for (const stream of [ + tapStream(400, [200]), + '🙂'.repeat(20_000), + 'A'.repeat(70_000), + Array.from({ length: 300 }, (_, index) => `not ok ${index} - failure`).join('\n'), + ]) { + expect(bytes(formatStepExcerpt(stream, budget))).toBeLessThanOrEqual(budget); + } + }); + + it.each([0, -1, 255, 1.5, Number.NaN])('refuses the unusable budget %s rather than eliding in silence', budget => { + expect(() => formatStepExcerpt('x'.repeat(10_000), budget)) + .toThrow('step excerpt budget must be an integer of at least 256 bytes'); + }); +}); From a754dc64333d7203b86151f87a9bbbfb02506f6a Mon Sep 17 00:00:00 2001 From: Relayflow Date: Mon, 21 Sep 2026 16:11:01 +0000 Subject: [PATCH 2/2] fix(sdk): keep the failing name when the tail cut lands inside the line MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review of #539 found the reported bug one layout further in. The tail is cut at a byte offset, not a line boundary, so a matching line longer than the tail's share has its `not ok` and its test name ahead of the cut while the tail shows only the uninformative rest. `selectHighlights` skipped such a line as "already visible in the tail", and the omission counter treated any overlap as visibility, so the excerpt neither named the failing case nor disclosed that it had recognised one. A match is covered only when its own start is on screen, because the start is what names the case. So the middle now ends where the tail begins on a line, not where its byte cut lands: a line the tail starts in the middle of is a highlight candidate like any other, shown from its own start, whole or under `… line truncated …`. The omission counter asks the same question, so a crossing line the share cannot fit is counted in `… +N more matching lines …` rather than passed off as seen. A kept prefix can end exactly where the tail begins. Printing those as two ranges would announce a truncation and an elided region between two halves of one unbroken run of source, so the tail starts at the highlight instead — the same bytes, one fewer false claim. Four regressions pin it: the reviewer's case; a 400-stream sweep sliding the failing line one byte at a time across the boundary, covering every alignment including its first byte landing exactly on the cut; the no-invented-cut rendering; and the omission count. Mutation-verified both ways — the whole fix reverted fails three of the four, the merge alone reverted fails the fourth. Co-Authored-By: Claude Opus 5 --- packages/sdk/src/cli/step-excerpt.ts | 31 +++++++--- .../sdk/tests/step-failure-excerpt.test.ts | 61 +++++++++++++++++++ 2 files changed, 84 insertions(+), 8 deletions(-) diff --git a/packages/sdk/src/cli/step-excerpt.ts b/packages/sdk/src/cli/step-excerpt.ts index db1f18c1b..b3b6d0656 100644 --- a/packages/sdk/src/cli/step-excerpt.ts +++ b/packages/sdk/src/cli/step-excerpt.ts @@ -111,18 +111,26 @@ export function formatStepExcerpt(value: string, budget: number = EXCERPT_BYTES) // highlight, so the ranges stay disjoint and in source order. const spare = headShare - size(head) + highlightShare - highlights.reduce((sum, highlight) => sum + size(highlight.range), 0); - const tail = tailRange(source, tailShare + spare, highlights.at(-1)?.range.end ?? head.end); + let tail = tailRange(source, tailShare + spare, highlights.at(-1)?.range.end ?? head.end); + // A highlight the tail resumes at the very byte it ends is not a range of + // its own: the two are one unbroken run of source, so the tail starts at + // the highlight instead. The same bytes either way, with no marker between + // them claiming a cut the reader can see did not happen. + while (highlights.length > 0 && highlights.at(-1)!.range.end === tail.start) { + tail = { start: highlights.pop()!.range.start, end: tail.end }; + } const selected = [head, ...highlights.map(highlight => highlight.range), tail] .filter(range => size(range) > 0); const elided = source.length - selected.reduce((sum, range) => sum + size(range), 0); // Positional, not textual: two identical failing lines at two positions are // two observations, and one of them may be visible while the other is not. - // A line shown in part — a truncated highlight, or one the tail starts in - // the middle of — was not omitted, so only a line with nothing on screen is - // counted here. + // Shown means the line's own start is on screen, because the start is what + // names the failing case: a highlight cut short still reports it, while a + // range that begins in the middle of the line — a tail whose cut landed + // there — shows only the part after the name and reports nothing. const omitted = matches.filter(match => - !selected.some(range => match.start < range.end && match.end > range.start)).length; + !selected.some(range => range.start <= match.start && range.end > match.start)).length; const parts: string[] = []; const terminated = (chunk: string): string => chunk.endsWith('\n') ? chunk : `${chunk}\n`; @@ -177,6 +185,12 @@ function markerReserve(sourceBytes: number, matches: number): number { * not fit at all, a code-point-safe prefix of it is shown under a truncation * marker, because a cut failing line still names the failing case and no * highlight at all does not. + * + * The middle ends where the tail begins, but a line the tail begins in the + * middle of belongs to the middle: the tail shows its tail, and the marker + * that names the failing case is ahead of the cut. Such a line is a candidate + * like any other, and the caller keeps the ranges disjoint by starting the + * tail after whatever prefix is kept. */ function selectHighlights( source: Buffer, matches: readonly Range[], share: number, from: number, to: number, @@ -184,9 +198,10 @@ function selectHighlights( const selected: Array<{ range: Range; truncated: boolean }> = []; let remaining = share; for (const match of matches) { - // Already visible in the head or the tail, or straddling one of them: a - // line is reported once, at its own position. - if (match.start < from || match.end > to) continue; + // Reported once, at its own position: a line whose own start is already + // on screen — inside the head, or at or after the start of the tail — + // needs no highlight. + if (match.start < from || match.start >= to) continue; if (selected.length >= MAX_HIGHLIGHT_LINES) break; if (size(match) <= remaining) { selected.push({ range: match, truncated: false }); diff --git a/packages/sdk/tests/step-failure-excerpt.test.ts b/packages/sdk/tests/step-failure-excerpt.test.ts index e2a0d6beb..29a020178 100644 --- a/packages/sdk/tests/step-failure-excerpt.test.ts +++ b/packages/sdk/tests/step-failure-excerpt.test.ts @@ -163,6 +163,67 @@ describe('formatStepExcerpt: which lines it highlights', () => { expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); }); + it('names a failing case that the tail cut lands in the middle of', () => { + // The tail is cut at a byte offset, not at a line boundary. A failing + // line longer than the tail's share therefore keeps its uninformative + // rest on screen while its marker and its name sit ahead of the cut — + // the reported bug, one layout further in. + const failure = 'not ok 5 - pty-exit: child reaped twice'; + const stream = 'ok - passing\n'.repeat(400) + failure + ' D'.repeat(2_000) + '\n# fail 1\n'; + const excerpt = formatStepExcerpt(stream); + expect(excerpt).toContain(failure); + expect(excerpt).toMatch(/… [\d,]+ bytes elided; 1 line matched a failure marker …/u); + expect(excerpt).toContain('# fail 1'); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + + it('keeps naming it wherever the cut lands, including exactly on its first byte', () => { + // One byte of padding at a time slides the failing line across the tail + // boundary, so the sweep covers every alignment there is: wholly in the + // middle, cut anywhere inside, starting exactly at the tail, and wholly + // inside the tail. It is named once in all of them — once, because a + // line reported twice is two failures to the reader. + const failure = 'not ok 5 - pty-exit: child reaped twice'; + for (const rest of [' D'.repeat(1_000), ' D'.repeat(2_000)]) { + for (let pad = 0; pad < 200; pad++) { + const stream = 'ok - passing\n'.repeat(400) + + failure + rest + '\n' + 'x'.repeat(pad) + '\n# fail 1\n'; + const excerpt = formatStepExcerpt(stream); + expect(excerpt.split(failure)).toHaveLength(2); + expect(excerpt).toContain('# fail 1'); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + } + } + }); + + it('does not claim a truncation when the tail resumes the line at the cut', () => { + // A kept prefix the tail picks up at the very byte it ended is one + // unbroken run of source: the tail starts at the line instead, and the + // excerpt shows the whole of it with no marker in the middle. + const failing = 'not ok 5 - pty-exit: child reaped twice' + ' D'.repeat(1_000) + '\n'; + const excerpt = formatStepExcerpt('ok - passing\n'.repeat(400) + failing + '# fail 1\n'); + expect(excerpt).toContain(failing); + expect(excerpt).not.toContain('… line truncated …'); + expect(excerpt.endsWith('# fail 1\n')).toBe(true); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + + it('counts a failing line the cut hides and the share could not fit', () => { + // Thirty short matches spend the highlight share, so the long line the + // tail cuts into gets no prefix of its own. What the tail shows of it + // names nothing, so it is reported as omitted rather than as seen. + const filler = 'ok - a passing case with a realistically long name\n'; + const middle = Array.from({ length: 30 }, + (_, index) => `not ok ${index + 1} - a middle failure with a realistically long name\n`).join(''); + const excerpt = formatStepExcerpt(filler.repeat(40) + middle + filler.repeat(20) + + 'not ok 99 - crosses the tail cut' + ' D'.repeat(2_000) + '\n# fail 31\n'); + expect(excerpt).not.toContain('not ok 99 - crosses the tail cut'); + const shown = Number(/([\d,]+) lines matched a failure marker/u.exec(excerpt)![1]!.replaceAll(',', '')); + const more = Number(/\+([\d,]+) more matching lines/u.exec(excerpt)![1]!.replaceAll(',', '')); + expect(shown + more).toBe(31); + expect(bytes(excerpt)).toBeLessThanOrEqual(EXCERPT_BYTES); + }); + it('reports matches it had no room to show at all', () => { // One very long matching line consumes the highlight share; the rest of // the middle matches are counted rather than silently dropped.