From 548b82d97e0393760fad0c86db7bd4391de775ab Mon Sep 17 00:00:00 2001 From: Aikins Laryea Date: Fri, 30 Oct 2026 08:47:33 +0000 Subject: [PATCH] feat(cli): summarize a trace's failures and repeated calls, and suggest next commands trace lists the failed spans where failures began, with their path, and the operations that ran more than once with their wall time counted once for overlapping calls. traces, sessions, and trace suggest the likely next command on stderr in human output, keeping the project and passing option values as --name=value. --- packages/cli/src/commands.ts | 290 +++++++++++++++++++++++++++++++-- packages/cli/tests/cli.test.ts | 108 +++++++++++- packages/cli/tests/fixture.ts | 155 +++++++++++++++--- 3 files changed, 517 insertions(+), 36 deletions(-) diff --git a/packages/cli/src/commands.ts b/packages/cli/src/commands.ts index 5755555..c7dce66 100644 --- a/packages/cli/src/commands.ts +++ b/packages/cli/src/commands.ts @@ -15,6 +15,7 @@ import { clean, type Column, DASH, + displayWidth, formatAge, formatCost, formatCount, @@ -188,13 +189,59 @@ const choice = ( const DAYS = { "7d": 7, "30d": 30, "90d": 90 } as const; -/** `arg` quoted for a POSIX shell, so a suggested command runs as shown when pasted. */ +/** + * `arg` quoted for a POSIX shell, so a suggested command runs as shown when pasted. A + * leading `=` is quoted too: zsh expands `=name` to a command's path. + */ const shellQuote = (arg: string) => - /^[\w@%+=:,./-]+$/.test(arg) ? arg : `'${arg.replaceAll("'", `'\\''`)}'`; + /^[\w@%+:,./-][\w@%+=:,./-]*$/.test(arg) ? arg : `'${arg.replaceAll("'", `'\\''`)}'`; + +/** + * A telemetry command to suggest, quoted for a POSIX shell, that keeps this command's + * project so it reads the same one when pasted. Option values are joined with `=`, so a + * value starting with `-` isn't read as an option. Undefined when an id starts with `-` + * or a value holds characters the terminal line can't show as they are, since the + * printed command would then name something else. + */ +const suggestion = ( + context: Context, + command: string, + ids: readonly string[], + options: Readonly> = {}, +) => { + const project = string(context, "project"); + const values = { ...options, ...(project ? { project } : {}) }; + const shown = (text: string) => clean(text) === text && !/[\n\t]/.test(text); + + if (ids.some((id) => id.startsWith("-") || !shown(id))) return undefined; + + if (!Object.values(values).every(shown)) return undefined; + + return [ + "telemetry", + command, + ...ids, + ...Object.entries(values).map(([name, value]) => `--${name}=${value}`), + ] + .map(shellQuote) + .join(" "); +}; + +const labelled = (label: string, command: string | undefined) => + command === undefined ? undefined : `${label}: ${command}`; -/** Suggests the same command with the next page's cursor. */ -const suggestNextPage = (context: Context, cursor: string | null) => { - if (!cursor || json(context)) return; +/** Prints likely next commands as one dim block on stderr, never with --json. */ +const suggest = (context: Context, ...lines: (string | undefined)[]) => { + const shown = lines.filter((line): line is string => line !== undefined); + + if (json(context) || shown.length === 0) return; + + note(style.dim(`\n${shown.join("\n")}`, process.stderr)); +}; + +/** The same command with the next page's cursor. */ +const nextPage = (context: Context, cursor: string | null) => { + if (!cursor) return undefined; const kept: string[] = []; @@ -210,9 +257,10 @@ const suggestNextPage = (context: Context, cursor: string | null) => { kept.push(arg); } - const command = [...kept, "--cursor", cursor].map((arg) => shellQuote(clean(arg))).join(" "); + // A cursor is base64url, which can start with `-`. + const command = [...kept, `--cursor=${cursor}`].map((arg) => shellQuote(clean(arg))).join(" "); - note(style.dim(`\nMore: telemetry ${command}`, process.stderr)); + return `More: telemetry ${command}`; }; const statusCell = (status: string): Cell => @@ -509,7 +557,15 @@ export async function tracesCommand(context: Context) { ), ); - suggestNextPage(context, page.next_cursor); + const failure = page.traces.find((trace) => trace.status === "error"); + + suggest( + context, + failure + ? labelled("Inspect the newest failure", suggestion(context, "trace", [failure.id])) + : labelled("Inspect the newest trace", suggestion(context, "trace", [page.traces[0]!.id])), + nextPage(context, page.next_cursor), + ); }); } @@ -571,7 +627,14 @@ export async function sessionsCommand(context: Context) { ), ); - suggestNextPage(context, page.next_cursor); + suggest( + context, + labelled( + "List the most recent session's traces", + suggestion(context, "traces", [], { session: page.sessions[0]!.id }), + ), + nextPage(context, page.next_cursor), + ); }); } @@ -668,7 +731,7 @@ export async function traceCommand(context: Context) { if (!traceId) throw usageError("Name the trace to show: telemetry trace "); - await withApi(async (api) => { + await withApi(async (api, session) => { const project = await resolveProject(api, context); let page = await api.call( "get_trace", @@ -713,9 +776,209 @@ export async function traceCommand(context: Context) { ), ); } + + // The span list carries only the start of an error; payload reads all of it. + const explained = failureCauses(spans).find((span) => span.error?.trim()); + + suggest( + context, + explained && grantedScopes(session).has(PAYLOADS_SCOPE) + ? labelled( + "Read the full error", + suggestion(context, "payload", [page.trace.id, explained.id], { field: "error" }), + ) + : undefined, + ); }); } +/** + * Failed spans with no failed child, in the order they started. Instrumentation marks + * every span an exception passes through as failed, so these are where failures began. + */ +const failureCauses = (spans: readonly Span[]) => { + const failed = spans.filter((span) => span.status === "error"); + const failedParents = new Set(failed.map((span) => span.parent_span_id)); + + return failed + .filter((span) => !failedParents.has(span.id)) + .sort((left, right) => Date.parse(left.started_at) - Date.parse(right.started_at)); +}; + +// The Errors and Repeated sections each show this many rows, then a count of the rest. +const SECTION_ROWS = 5; + +/** A section title like Logs, saying so when it covers only the spans read so far. */ +const sectionTitle = (title: string, count: number, partialOf: number | undefined) => + style.bold( + `${title} ${style.dim(`(${formatInteger(count)}${partialOf === undefined ? "" : ` in the first ${formatInteger(partialOf)} spans`})`)}`, + ); + +const more = (count: number) => + count > SECTION_ROWS ? [style.dim(` and ${formatInteger(count - SECTION_ROWS)} more`)] : []; + +/** The first line of the span's error text, after its type unless the text starts with it. */ +const errorSummary = (span: Span) => { + const type = oneLine(span.error_type ?? ""); + const first = + (span.error ?? "") + .split(/\r\n|\r|\n/) + .map(oneLine) + .find(Boolean) ?? ""; + + if (!first) return type || "error"; + + return !type || first.startsWith(type) ? first : `${type}: ${first}`; +}; + +const PATH = " › "; + +// On a narrow terminal the error text is cut to this many columns before any ancestor +// is dropped from the path, and is left out when fewer than ERROR_MIN columns remain. +const ERROR_ROOM = 30; +const ERROR_MIN = 8; +// The fewest columns worth giving the ancestors before leaving them out. +const ANCESTRY_MIN = 4; + +/** + * A failed span on one line: its ancestors, the span, and its error, fitted to `width`. + * The span's full error text is in the tree below, so the path keeps priority. + */ +const failureLine = (span: Span, byId: ReadonlyMap, width: number) => { + const ancestors: string[] = []; + const seen = new Set([span.id]); + let parent = span.parent_span_id ? byId.get(span.parent_span_id) : undefined; + + while (parent && !seen.has(parent.id)) { + seen.add(parent.id); + ancestors.push(spanLabel(parent)); + parent = parent.parent_span_id ? byId.get(parent.parent_span_id) : undefined; + } + + ancestors.reverse(); + + const leaf = spanLabel(span); + const error = errorSummary(span); + const room = width - 2; + const errorWidth = displayWidth(error); + const reserve = Math.min(errorWidth, ERROR_ROOM); + const pathWidth = (kept: readonly string[]) => displayWidth([...kept, leaf].join(PATH)); + let kept = ancestors; + + // The root stays, so the path still says which agent or request it was under. + for ( + let dropped = 1; + dropped < ancestors.length && pathWidth(kept) + 2 + reserve > room; + dropped += 1 + ) { + kept = [ancestors[0]!, "…", ...ancestors.slice(dropped + 1)]; + } + + // When even the shortened path is too wide, the ancestors are cut, not the failed span. + const ancestry = kept.join(PATH); + const ancestryRoom = room - displayWidth(leaf) - displayWidth(PATH); + const lead = + kept.length === 0 + ? "" + : displayWidth(ancestry) <= ancestryRoom + ? `${ancestry}${PATH}` + : ancestryRoom >= ANCESTRY_MIN + ? `${fit(ancestry, ancestryRoom)}${PATH}` + : ""; + const path = fit(`${lead}${leaf}`, room); + const painted = path === `${lead}${leaf}` ? `${style.dim(lead)}${leaf}` : path; + const left = room - displayWidth(path) - 2; + const shown = left >= Math.min(errorWidth, ERROR_MIN) ? ` ${style.red(fit(error, left))}` : ""; + + return ` ${painted}${shown}`; +}; + +/** Milliseconds covered by at least one interval, so calls that overlap count once. */ +const wallTime = (intervals: readonly (readonly [number, number])[]) => { + let covered = 0; + let reached = Number.NEGATIVE_INFINITY; + + for (const [start, end] of [...intervals].sort((left, right) => left[0] - right[0])) { + if (end <= reached) continue; + covered += end - Math.max(start, reached); + reached = end; + } + + return covered; +}; + +/** + * Where a long trace went wrong and where its time went, above the span tree: failed + * spans with their path, and operations that ran more than once. + */ +const traceSummary = (spans: readonly Span[], total: number, partialOf: number | undefined) => { + const lines: string[] = []; + const byId = new Map(spans.map((span) => [span.id, span])); + const failed = failureCauses(spans); + const only = failed.length === 1 ? failed[0] : undefined; + // A root that failed with no message says nothing the header doesn't. + const rootOnly = + only !== undefined && + !only.error?.trim() && + !(only.parent_span_id && byId.has(only.parent_span_id)); + + if (failed.length > 0 && !rootOnly) { + lines.push(sectionTitle("Errors", failed.length, partialOf)); + + for (const span of failed.slice(0, SECTION_ROWS)) + lines.push(failureLine(span, byId, outputWidth())); + lines.push(...more(failed.length), ""); + } + + // Grouped by the label the span tree shows: the name with its model, tool, or agent. + const groups = new Map(); + + for (const span of spans) { + const start = Date.parse(span.started_at); + + if (!Number.isFinite(start)) continue; + + const label = spanLabel(span); + const intervals = groups.get(label) ?? []; + + intervals.push([start, start + Math.max(0, span.duration_ms ?? 0)]); + groups.set(label, intervals); + } + + const repeated = [...groups] + .filter(([, intervals]) => intervals.length > 1) + .map(([label, intervals]) => ({ label, count: intervals.length, wall: wallTime(intervals) })) + .sort((left, right) => right.wall - left.wall); + + if (repeated.length > 0) { + lines.push(sectionTitle("Repeated", repeated.length, partialOf)); + + // The empty first column indents the rows; its header line is dropped. + const rows = table( + [ + { header: "" }, + { header: "", flex: true }, + { header: "", align: "right" }, + { header: "", align: "right" }, + { header: "", align: "right" }, + ], + repeated + .slice(0, SECTION_ROWS) + .map(({ label, count, wall }) => [ + "", + label, + `×${formatInteger(count)}`, + formatDuration(wall), + { text: total > 0 ? formatPercent((wall / total) * 100) : DASH, paint: dim }, + ]), + ); + + lines.push(...rows.split("\n").slice(1), ...more(repeated.length), ""); + } + + return lines; +}; + function renderTrace(page: TraceDetailPage, spans: readonly Span[], logs: TraceDetailPage["logs"]) { const { trace } = page; const failed = trace.status === "error"; @@ -757,6 +1020,13 @@ function renderTrace(page: TraceDetailPage, spans: readonly Span[], logs: TraceD const end = Math.max(...spans.map((span, index) => starts[index]! + (span.duration_ms ?? 0))); const total = Math.max(end - origin, trace.duration_ms ?? 0); + for (const line of traceSummary( + spans, + total, + page.next_cursor === null ? undefined : spans.length, + )) + out(line); + const terminal = process.stdout.isTTY === true; const timelineWidth = terminal ? Math.min(60, Math.max(16, outputWidth() - 72)) : 0; diff --git a/packages/cli/tests/cli.test.ts b/packages/cli/tests/cli.test.ts index 71a80e6..6b17515 100644 --- a/packages/cli/tests/cli.test.ts +++ b/packages/cli/tests/cli.test.ts @@ -11,11 +11,14 @@ import { beforeRefresh, calls, EMAIL, + PARALLEL_TRACE_ID, PAYLOADS, PROJECTS, + QUIET_TRACE_ID, REFRESH_TOKEN, startFixture, TOKEN, + TRACE_ID, traces, } from "./fixture.ts"; @@ -34,17 +37,16 @@ afterAll(async () => { const sessionPath = () => join(home, sessionFile(fixture.url)); -const signIn = (project?: (typeof PROJECTS)[number]) => +const signIn = ( + project?: (typeof PROJECTS)[number], + scope = "openid email offline_access telemetry:read telemetry:payloads", +) => writeFile( sessionPath(), JSON.stringify({ server: fixture.url, client: { client_id: "fixture-client" }, - tokens: { - access_token: TOKEN, - token_type: "Bearer", - scope: "openid email offline_access telemetry:read telemetry:payloads", - }, + tokens: { access_token: TOKEN, token_type: "Bearer", scope }, email: "ada@acme.dev", ...(project ? { project: { id: project.id, name: "support-bot" } } : {}), }), @@ -154,6 +156,100 @@ test("payload --field prints the whole text across pages", async () => { expect(calls.filter((call) => call.tool === "get_span_payload").length).toBeGreaterThan(1); }); +test("trace leads with where the run failed and which calls repeated, counting parallel calls once", async () => { + await signIn(PROJECTS[0]); + + const result = await run("trace", PARALLEL_TRACE_ID); + expect(result.code).toBe(0); + + const lines = result.stdout.split("\n"); + // Three 1 s searches started 50 ms apart cover 100 ms to 1,200 ms: 1.1 s of the 3 s + // trace, where adding them up would say 3 s and 100%. + expect(lines).toContain(" execute_tool web_search ×3 1.10s 37%"); + // The request that failed, under the tool that made it, under the agent. + expect(lines).toContain( + " invoke_agent researcher › execute_tool fetch_page › GET /page TimeoutError: Request timed out after 700 ms", + ); + expect(lines.indexOf("Errors (1)")).toBeGreaterThan(0); + expect(lines.indexOf("Repeated (1)")).toBeGreaterThan(lines.indexOf("Errors (1)")); + expect(lines.findIndex((line) => line.startsWith("SPAN"))).toBeGreaterThan( + lines.indexOf("Repeated (1)"), + ); + // Only the request where the failure began is listed and offered, not the tool and the + // agent it passed through. + expect(result.stderr.match(/telemetry payload .*/g)).toEqual([ + `telemetry payload ${PARALLEL_TRACE_ID} t2 --field=error`, + ]); + + // Two chat calls that don't overlap cover 1.18 s + 1.42 s of the 4.21 s trace. Measuring + // from the first start to the last end would say 2.64 s. + const sequential = await run("trace", TRACE_ID); + expect(sequential.stdout.split("\n")).toContain(" chat gpt-5 ×2 2.60s 62%"); + + // A sign-in without the payloads scope isn't pointed at a command that would refuse it. + await signIn(PROJECTS[0], "openid email offline_access telemetry:read"); + const unscoped = await run("trace", PARALLEL_TRACE_ID); + expect(unscoped.code).toBe(0); + expect(unscoped.stderr).not.toContain("telemetry payload"); +}); + +test("a trace with no failures and no repeated calls goes straight to the span tree", async () => { + await signIn(PROJECTS[0]); + + const result = await run("trace", QUIET_TRACE_ID); + expect(result.code).toBe(0); + expect(result.stdout).toMatch(/^SPAN /m); + expect(result.stdout).not.toMatch(/^(Errors|Repeated) /m); + expect(result.stderr).toBe(""); +}); + +/** The words a POSIX shell makes of a pasted command line. */ +const shellWords = (command: string) => + new Promise((resolve, reject) => { + execFile("sh", ["-c", `printf '%s\\n' ${command}`], (error, stdout) => + error ? reject(error) : resolve(stdout.trimEnd().split("\n")), + ); + }); + +test("suggested next commands run as pasted, in the same project, and never print with --json", async () => { + await signIn(); + + // The newest trace succeeded, so the suggestion names the failed one after it. + const listed = await run("traces", "-p", "support-bot"); + expect(listed.code).toBe(0); + const inspect = listed.stderr.match(/Inspect the newest failure: (.*)/)?.[1]; + expect(await shellWords(inspect!)).toEqual([ + "telemetry", + "trace", + TRACE_ID, + "--project=support-bot", + ]); + + const sessions = await run("sessions", "--project=support-bot"); + expect(sessions.code).toBe(0); + const words = await shellWords(sessions.stderr.match(/telemetry traces .*/)![0]); + expect(words).toEqual([ + "telemetry", + "traces", + "--session=Ada's thread 42", + "--project=support-bot", + ]); + + // Run as pasted, it asks for that session in that project. + calls.length = 0; + expect((await run(...words.slice(1))).code).toBe(0); + expect(calls.find((call) => call.tool === "search_traces")?.args).toMatchObject({ + project_id: PROJECTS[0]!.id, + session_id: "Ada's thread 42", + }); + + for (const args of [["traces"], ["sessions"], ["trace", PARALLEL_TRACE_ID]]) { + const result = await run(...args, "-p", "support-bot", "--json"); + expect(result.code).toBe(0); + expect(result.stderr).toBe(""); + } +}); + test("use saves the default project in a file only its owner can read", async () => { await signIn(); diff --git a/packages/cli/tests/fixture.ts b/packages/cli/tests/fixture.ts index f0dc89c..707483c 100644 --- a/packages/cli/tests/fixture.ts +++ b/packages/cli/tests/fixture.ts @@ -24,10 +24,31 @@ export const PROJECTS = [ const minutesAgo = (minutes: number) => new Date(Date.now() - minutes * 60_000).toISOString(); -const TRACE_ID = "4bf92f3577b34da6a3ce929d0e0e4736"; +export const TRACE_ID = "4bf92f3577b34da6a3ce929d0e0e4736"; +export const QUIET_TRACE_ID = "9a0b7c6d5e4f30211a2b3c4d5e6f7081"; +export const PARALLEL_TRACE_ID = "3e8a1c5b7d9f40e2a6b4c8d0e2f4a6b8"; export const traces = () => ({ traces: [ + // The newest trace succeeded, so a suggestion to inspect a failure has to look past it. + { + id: QUIET_TRACE_ID, + name: "support.answer", + status: "success", + error_type: null, + started_at: minutesAgo(1), + duration_ms: 1870, + environment: "production", + service_name: "support-api", + session_id: "conv_8f2a91", + user_id: "user_4821", + models: ["gpt-5"], + span_count: 3, + error_span_count: 0, + input_tokens: 1934, + output_tokens: 211, + cost_usd: 0.00718, + }, { id: TRACE_ID, name: "support.answer", @@ -46,24 +67,6 @@ export const traces = () => ({ output_tokens: 373, cost_usd: 0.01234, }, - { - id: "9a0b7c6d5e4f30211a2b3c4d5e6f7081", - name: "support.answer", - status: "success", - error_type: null, - started_at: minutesAgo(9), - duration_ms: 1870, - environment: "production", - service_name: "support-api", - session_id: "conv_8f2a91", - user_id: "user_4821", - models: ["gpt-5"], - span_count: 5, - error_span_count: 0, - input_tokens: 1934, - output_tokens: 211, - cost_usd: 0.00718, - }, { id: "1f2e3d4c5b6a79880a9b8c7d6e5f4a3b", // Captured text can carry terminal escapes; the CLI must never pass them through. @@ -184,8 +187,116 @@ export const traceDetail = () => ({ next_cursor: null, }); +/** A run that succeeded with each operation once: nothing to summarize above the tree. */ +const quietTraceDetail = () => ({ + trace: { + id: QUIET_TRACE_ID, + name: "support.answer", + status: "success", + error_type: null, + started_at: minutesAgo(1), + duration_ms: 1870, + environment: "production", + service_name: "support-api", + framework: "ai-sdk", + session_id: "conv_8f2a91", + user_id: "user_4821", + input_tokens: 1934, + output_tokens: 211, + cost_usd: 0.00718, + }, + span_count: 3, + log_count: 0, + spans: [ + span("q1", null, "invoke_agent support-bot", 0, 1870, { + agent_name: "support-bot", + operation: "invoke_agent", + }), + span("q2", "q1", "execute_tool lookup_order", 30, 240, { tool_name: "lookup_order" }), + span("q3", "q1", "chat gpt-5", 290, 1560, { + model: "gpt-5", + provider: "openai", + input_tokens: 1934, + output_tokens: 211, + cost_usd: 0.00718, + }), + ], + logs: [], + next_cursor: null, +}); + +/** + * An agent that runs three 1 s searches at once, so they cover 1.1 s of a 3 s trace, then + * fails two levels down, in the request a tool made. The failure is marked on the tool + * and the agent too, as instrumentation does when an exception passes through them. + */ +const parallelTraceDetail = () => ({ + trace: { + id: PARALLEL_TRACE_ID, + name: "research.report", + status: "error", + error_type: "TimeoutError", + started_at: minutesAgo(2), + duration_ms: 3000, + environment: "production", + service_name: "research-api", + framework: "ai-sdk", + session_id: null, + user_id: null, + input_tokens: null, + output_tokens: null, + cost_usd: null, + }, + span_count: 6, + log_count: 0, + spans: [ + span("r1", null, "invoke_agent researcher", 0, 3000, { + agent_name: "researcher", + operation: "invoke_agent", + status: "error", + error_type: "TimeoutError", + error: "TimeoutError: tool fetch_page failed", + }), + span("s1", "r1", "execute_tool web_search", 100, 1000, { tool_name: "web_search" }), + span("s2", "r1", "execute_tool web_search", 150, 1000, { tool_name: "web_search" }), + span("s3", "r1", "execute_tool web_search", 200, 1000, { tool_name: "web_search" }), + span("t1", "r1", "execute_tool fetch_page", 1300, 800, { + tool_name: "fetch_page", + status: "error", + error_type: "TimeoutError", + error: "TimeoutError: Request timed out after 700 ms", + }), + span("t2", "t1", "GET /page", 1350, 700, { + status: "error", + error_type: "TimeoutError", + error: "Request timed out after 700 ms\n at fetchPage (tools.ts:41:11)", + }), + ], + logs: [], + next_cursor: null, +}); + +const TRACE_DETAILS: Record unknown> = { + [TRACE_ID]: traceDetail, + [QUIET_TRACE_ID]: quietTraceDetail, + [PARALLEL_TRACE_ID]: parallelTraceDetail, +}; + export const sessions = () => ({ sessions: [ + { + // Session ids come from the user's app and can hold spaces and quotes. + id: "Ada's thread 42", + last_active_at: minutesAgo(1), + user_id: "user_4821", + agent_name: "support-bot", + models: ["gpt-5"], + trace_count: 2, + error_trace_count: 0, + input_tokens: 3120, + output_tokens: 402, + cost_usd: 0.0114, + }, { id: "conv_8f2a91", last_active_at: minutesAgo(2), @@ -337,7 +448,11 @@ const server = () => { tool("list_projects", () => ({ organization_id: "org_fixture", projects: PROJECTS })); tool("search_traces", () => traces()); tool("search_sessions", () => sessions()); - tool("get_trace", (args) => (args.trace_id === TRACE_ID ? traceDetail() : "Trace not found.")); + tool("get_trace", (args) => + Object.hasOwn(TRACE_DETAILS, String(args.trace_id)) + ? TRACE_DETAILS[String(args.trace_id)]!() + : "Trace not found.", + ); tool("list_logs", () => logs()); tool("get_usage_summary", () => usage()); tool("get_span_payload", (args) => {