diff --git a/packages/opencode/src/session/export.ts b/packages/opencode/src/session/export.ts index d9eecc7c3..220958101 100644 --- a/packages/opencode/src/session/export.ts +++ b/packages/opencode/src/session/export.ts @@ -25,6 +25,7 @@ import { isRecord } from "@/util/record" import { Glob } from "@/util/glob" import { safeToolFailureMetadata } from "./tool-failure" import { LLMTrace } from "./llm-trace" +import { safeErrorFingerprint, safeProviderCorrelation } from "./llm-trace/stream-diagnostics" export function getRuntimeNamespace(): "pawwork" | "opencode" { return Runtime.isPawWork() ? "pawwork" : "opencode" @@ -294,9 +295,7 @@ export namespace Export { const title_generations = collectTitleGenerations(node) return { ...(last ? { loop: { last } } : {}), - ...(llm_traces.length - ? { llm_trace_schema_version: LLMTrace.SCHEMA_VERSION, llm_traces } - : {}), + ...(llm_traces.length ? { llm_trace_schema_version: LLMTrace.SCHEMA_VERSION, llm_traces } : {}), ...(aborts.length ? { aborts } : {}), ...(title_generations.length ? { title_generations } : {}), } @@ -942,6 +941,14 @@ export namespace Export { structured: msg.info.structured === undefined ? undefined : { redacted: `assistant-structured:${msg.info.id}` }, error: namedError("assistant-error", msg.info.id, msg.info.error), + diagnostics: !msg.info.diagnostics + ? msg.info.diagnostics + : { + ...msg.info.diagnostics, + llm_trace: msg.info.diagnostics.llm_trace + ? sanitizeLLMTrace(msg.info.diagnostics.llm_trace) + : undefined, + }, }, parts: msg.parts.map(partFn), })), @@ -993,9 +1000,159 @@ export namespace Export { ? undefined : redact("title-generation-error-message", String(index), trace.error_message), })), + llm_traces: diagnostics.llm_traces?.map(sanitizeLLMTrace), } } + function sanitizeLLMTrace(trace: LLMTrace.Summary): LLMTrace.Summary { + const stream = trace.stream as Record | undefined + if (!stream) return trace + return { + ...trace, + stream: sanitizeStreamDiagnostics(stream), + } as LLMTrace.Summary + } + + function sanitizeStreamDiagnostics(stream: Record) { + const timeline = isRecord(stream.timeline) ? stream.timeline : undefined + const durations = timeline && isRecord(timeline.durations_ms) ? timeline.durations_ms : undefined + const watchdog = isRecord(stream.watchdog) ? stream.watchdog : undefined + const attempt = isRecord(stream.attempt) ? stream.attempt : undefined + const abort = isRecord(stream.abort) ? stream.abort : undefined + const rawError = isRecord(stream.error) ? stream.error : undefined + const safeError = rawError + ? compactObject({ + ...(typeof rawError.boundary === "string" ? { boundary: rawError.boundary } : {}), + ...(typeof rawError.confidence === "string" ? { confidence: rawError.confidence } : {}), + ...(Array.isArray(rawError.evidence) + ? { evidence: rawError.evidence.filter((item): item is string => typeof item === "string") } + : {}), + ...safeErrorFingerprint(rawError), + }) + : undefined + const rawProvider = isRecord(stream.provider) ? stream.provider : undefined + const safeProvider = rawProvider ? safeProviderCorrelation(rawProvider) : undefined + return compactObject({ + ...(stream.schema_version === 2 ? { schema_version: 2 } : {}), + ...(attempt + ? { + attempt: compactObject({ + ...(typeof attempt.attempt_index === "number" ? { attempt_index: attempt.attempt_index } : {}), + ...(typeof attempt.attempt_id === "string" ? { attempt_id: attempt.attempt_id } : {}), + ...(typeof attempt.terminal_attempt === "boolean" ? { terminal_attempt: attempt.terminal_attempt } : {}), + ...(attempt.note === "terminal_attempt_only" || attempt.note === "per_attempt_recorded" + ? { note: attempt.note } + : {}), + }), + } + : {}), + ...(stream.legacy_v1_counters === "terminal_attempt" || stream.legacy_v1_counters === "aggregate" + ? { legacy_v1_counters: stream.legacy_v1_counters } + : {}), + ...(timeline + ? { + timeline: compactObject({ + ...(typeof timeline.collector_created_at === "number" + ? { collector_created_at: timeline.collector_created_at } + : {}), + ...(typeof timeline.sdk_stream_returned_at === "number" + ? { sdk_stream_returned_at: timeline.sdk_stream_returned_at } + : {}), + ...(typeof timeline.watchdog_armed_at === "number" + ? { watchdog_armed_at: timeline.watchdog_armed_at } + : {}), + ...(typeof timeline.first_event_at === "number" ? { first_event_at: timeline.first_event_at } : {}), + ...(typeof timeline.first_provider_progress_at === "number" + ? { first_provider_progress_at: timeline.first_provider_progress_at } + : {}), + ...(typeof timeline.last_event_at === "number" ? { last_event_at: timeline.last_event_at } : {}), + ...(typeof timeline.last_provider_progress_at === "number" + ? { last_provider_progress_at: timeline.last_provider_progress_at } + : {}), + ...(typeof timeline.completed_at === "number" ? { completed_at: timeline.completed_at } : {}), + ...(typeof timeline.failed_at === "number" ? { failed_at: timeline.failed_at } : {}), + ...(durations + ? { + durations_ms: compactObject({ + ...(typeof durations.created_to_sdk_stream_returned === "number" + ? { created_to_sdk_stream_returned: durations.created_to_sdk_stream_returned } + : {}), + ...(typeof durations.watchdog_armed_to_first_event === "number" + ? { watchdog_armed_to_first_event: durations.watchdog_armed_to_first_event } + : {}), + ...(typeof durations.watchdog_armed_to_first_provider_progress === "number" + ? { + watchdog_armed_to_first_provider_progress: + durations.watchdog_armed_to_first_provider_progress, + } + : {}), + ...(typeof durations.first_to_last_provider_progress === "number" + ? { first_to_last_provider_progress: durations.first_to_last_provider_progress } + : {}), + ...(typeof durations.last_provider_progress_to_failure === "number" + ? { last_provider_progress_to_failure: durations.last_provider_progress_to_failure } + : {}), + ...(typeof durations.total === "number" ? { total: durations.total } : {}), + }), + } + : {}), + }), + } + : {}), + ...(watchdog + ? { + watchdog: compactObject({ + ...(typeof watchdog.connect_timeout_ms === "number" + ? { connect_timeout_ms: watchdog.connect_timeout_ms } + : {}), + ...(typeof watchdog.stream_timeout_ms === "number" + ? { stream_timeout_ms: watchdog.stream_timeout_ms } + : {}), + ...(typeof watchdog.provider_progressed === "boolean" + ? { provider_progressed: watchdog.provider_progressed } + : {}), + ...(watchdog.phase_at_end === "before_first_provider_progress" || + watchdog.phase_at_end === "between_provider_events" || + watchdog.phase_at_end === "completed" || + watchdog.phase_at_end === "unknown" + ? { phase_at_end: watchdog.phase_at_end } + : {}), + ...(typeof watchdog.fired === "boolean" ? { fired: watchdog.fired } : {}), + ...(watchdog.fired_phase === "connect" || watchdog.fired_phase === "silent_stream" + ? { fired_phase: watchdog.fired_phase } + : {}), + }), + } + : {}), + ...(abort + ? { + abort: compactObject({ + ...(typeof abort.signal_aborted_at_error === "boolean" + ? { signal_aborted_at_error: abort.signal_aborted_at_error } + : {}), + ...(typeof abort.provenance_source === "string" ? { provenance_source: abort.provenance_source } : {}), + ...(typeof abort.provenance_reason === "string" ? { provenance_reason: abort.provenance_reason } : {}), + ...(abort.provenance_mode === "soft" || abort.provenance_mode === "hard" + ? { provenance_mode: abort.provenance_mode } + : {}), + ...(typeof abort.provenance_recorded_at === "number" + ? { provenance_recorded_at: abort.provenance_recorded_at } + : {}), + ...(typeof abort.provenance_missing === "boolean" + ? { provenance_missing: abort.provenance_missing } + : {}), + }), + } + : {}), + ...(safeError && Object.keys(safeError).length > 0 ? { error: safeError } : {}), + ...(safeProvider ? { provider: safeProvider } : {}), + }) + } + + function compactObject>(input: T): T { + return Object.fromEntries(Object.entries(input).filter(([, value]) => value !== undefined)) as T + } + // Snapshot-level sanitize. Wraps sanitizeTree (the conversation tree) AND redacts top-level // runtime_context/diagnostic fields that may carry user-machine paths or raw tool args. // Other runtime_context fields (app_version, build_channel, locale, timezone, model_refs, diff --git a/packages/opencode/src/session/llm-trace/index.ts b/packages/opencode/src/session/llm-trace/index.ts index 993a9900f..0b077d2b1 100644 --- a/packages/opencode/src/session/llm-trace/index.ts +++ b/packages/opencode/src/session/llm-trace/index.ts @@ -5,6 +5,7 @@ import { } from "./recorder" import { SCHEMA_VERSION as VERSION } from "./types" import * as Types from "./types" +import { classifyBoundary as classify, safeProviderCorrelation as safeCorrelation } from "./stream-diagnostics" export namespace LLMTrace { export const SCHEMA_VERSION = VERSION @@ -12,12 +13,15 @@ export namespace LLMTrace { export const createRecorder = createTraceRecorder export const requestSummary = summarizeRequest export const storedPartCounts = countStoredParts + export const classifyBoundary = classify + export const safeProviderCorrelation = safeCorrelation export type RequestSummary = Types.RequestSummary export type StreamEvents = Types.StreamEvents export type StoredParts = Types.StoredParts export type Tokens = Types.Tokens export type Flags = Types.Flags + export type StreamDiagnostics = Types.StreamDiagnostics export type Summary = Types.Summary export type RequestSummaryInput = Types.RequestSummaryInput export type RecorderInput = Types.RecorderInput diff --git a/packages/opencode/src/session/llm-trace/recorder.ts b/packages/opencode/src/session/llm-trace/recorder.ts index 2fdb51e47..298153fff 100644 --- a/packages/opencode/src/session/llm-trace/recorder.ts +++ b/packages/opencode/src/session/llm-trace/recorder.ts @@ -11,6 +11,8 @@ import type { Tokens, } from "./types" import { SCHEMA_VERSION } from "./types" +import type { StreamDiagnostics } from "./types" +import { classifyBoundary, safeErrorFingerprint, safeProviderCorrelation } from "./stream-diagnostics" export function requestSummary(input: RequestSummaryInput): RequestSummary { const options = safeOptions(input.options) @@ -30,6 +32,8 @@ export function createRecorder(input: RecorderInput): Recorder { let request: RequestSummary | undefined let finishReason: string | undefined let tokens: MessageV2.Assistant["tokens"] | undefined + let stream: StreamDiagnostics | undefined + let streamMonotonicStart: number | undefined return { request(summary) { @@ -42,6 +46,113 @@ export function createRecorder(input: RecorderInput): Recorder { finishReason = reason tokens = nextTokens }, + beginStream(next) { + streamMonotonicStart = next.monotonicMs + stream = { + schema_version: 2, + legacy_v1_counters: "aggregate", + timeline: { + collector_created_at: next.collectorCreatedAt, + }, + watchdog: { + connect_timeout_ms: next.connectTimeoutMs, + stream_timeout_ms: next.streamTimeoutMs, + provider_progressed: false, + phase_at_end: "before_first_provider_progress", + fired: false, + }, + } + }, + recordStreamFailure(next) { + if (!stream) return + if (stream.error?.boundary === "watchdog" && stream.error.confidence === "high") return + const boundary = localAbortBoundary(stream) ?? { + boundary: next.boundary, + confidence: next.confidence, + evidence: next.evidence, + } + stream.timeline.failed_at = next.failedAt + stream.timeline.durations_ms = { + ...(stream.timeline.durations_ms ?? {}), + total: durationSince(streamMonotonicStart, next.monotonicMs), + } + stream.error = { + ...safeErrorFingerprint(next.error), + boundary: boundary.boundary, + confidence: boundary.confidence, + evidence: boundary.evidence, + } + }, + recordProviderProgress(next) { + if (!stream) return + stream.watchdog.provider_progressed = true + stream.watchdog.phase_at_end = "between_provider_events" + if (stream.timeline.first_provider_progress_at === undefined) { + stream.timeline.first_provider_progress_at = next.eventAt + stream.timeline.durations_ms = { + ...(stream.timeline.durations_ms ?? {}), + watchdog_armed_to_first_provider_progress: durationSince(streamMonotonicStart, next.monotonicMs), + } + } + stream.timeline.last_provider_progress_at = next.eventAt + }, + recordWatchdogFired(next) { + if (!stream) return + stream.watchdog.fired = true + stream.watchdog.fired_phase = next.phase + if (next.phase === "connect") stream.watchdog.phase_at_end = "before_first_provider_progress" + }, + recordStreamCompleted(next) { + if (!stream) return + stream.timeline.completed_at = next.completedAt + stream.watchdog.phase_at_end = "completed" + stream.timeline.durations_ms = { + ...(stream.timeline.durations_ms ?? {}), + total: durationSince(streamMonotonicStart, next.monotonicMs), + } + }, + recordAbortState(next) { + if (!stream) return + stream.abort = { + ...(stream.abort ?? {}), + ...(typeof next.signalAbortedAtError === "boolean" + ? { signal_aborted_at_error: next.signalAbortedAtError } + : {}), + ...(next.provenanceSource ? { provenance_source: next.provenanceSource } : {}), + ...(next.provenanceReason ? { provenance_reason: next.provenanceReason } : {}), + ...(next.provenanceMode ? { provenance_mode: next.provenanceMode } : {}), + ...(typeof next.provenanceRecordedAt === "number" ? { provenance_recorded_at: next.provenanceRecordedAt } : {}), + ...(typeof next.provenanceMissing === "boolean" ? { provenance_missing: next.provenanceMissing } : {}), + } + refreshLocalAbortBoundary(stream) + }, + recordProviderErrorEvent(next) { + if (!stream) return + if (stream.error?.boundary === "watchdog" && stream.error.confidence === "high") return + const provider = safeProviderCorrelation(next.provider) + stream.provider = provider + const boundary = classifyBoundary({ + providerErrorEvent: true, + iteratorError: true, + requestIdPresent: provider?.request_id !== undefined || provider?.response_id !== undefined, + providerCorrelationUnavailable: provider?.unavailable_reason !== undefined, + }) + stream.timeline.failed_at = next.failedAt + stream.timeline.durations_ms = { + ...(stream.timeline.durations_ms ?? {}), + total: durationSince(streamMonotonicStart, next.monotonicMs), + } + stream.error = { + ...safeErrorFingerprint(next.error), + boundary: boundary.boundary, + confidence: boundary.confidence, + evidence: boundary.evidence, + } + }, + recordProviderCorrelation(input) { + if (!stream) return + stream.provider = safeProviderCorrelation(input) + }, finalize(final: FinalizeInput) { const finalFinishReason = final.finishReason ?? finishReason const finalTokens = final.tokens ?? tokens @@ -71,11 +182,39 @@ export function createRecorder(input: RecorderInput): Recorder { flags, created_at: input.createdAt, completed_at: final.completedAt, + ...(stream ? { stream } : {}), } }, } } +function durationSince(start: number | undefined, end: number) { + if (start === undefined) return undefined + return Math.max(0, end - start) +} + +function hasAbortProvenance(stream: StreamDiagnostics) { + return !!stream.abort?.provenance_source +} + +function localAbortBoundary(stream: StreamDiagnostics) { + if (!stream.abort?.signal_aborted_at_error || !hasAbortProvenance(stream)) return undefined + return classifyBoundary({ abortSignalAborted: true, abortProvenancePresent: true, iteratorError: true }) +} + +function refreshLocalAbortBoundary(stream: StreamDiagnostics) { + if (stream.error?.boundary === "watchdog" && stream.error.confidence === "high") return + if (!stream.error || stream.error.boundary !== "unknown") return + const boundary = localAbortBoundary(stream) + if (!boundary) return + stream.error = { + ...stream.error, + boundary: boundary.boundary, + confidence: boundary.confidence, + evidence: boundary.evidence, + } +} + export function storedPartCounts(parts: MessageV2.Part[]): StoredParts { const counts: StoredParts = { text: 0, @@ -158,5 +297,7 @@ function tokenSummary(tokens: MessageV2.Assistant["tokens"]): Tokens { } function isEmptyCompletion(finishReason: string | undefined, stored: StoredParts) { - return finishReason === "stop" && stored.text === 0 && stored.reasoning === 0 && stored.tool === 0 && stored.file === 0 + return ( + finishReason === "stop" && stored.text === 0 && stored.reasoning === 0 && stored.tool === 0 && stored.file === 0 + ) } diff --git a/packages/opencode/src/session/llm-trace/stream-diagnostics.ts b/packages/opencode/src/session/llm-trace/stream-diagnostics.ts new file mode 100644 index 000000000..0eb91c894 --- /dev/null +++ b/packages/opencode/src/session/llm-trace/stream-diagnostics.ts @@ -0,0 +1,156 @@ +import { isRecord } from "@/util/record" + +export type StreamBoundary = "watchdog" | "local_abort" | "sdk_transport" | "provider_stream" | "unknown" +export type StreamConfidence = "low" | "medium" | "high" +export type StreamEvidence = + | "watchdog_fired" + | "watchdog_error" + | "abort_signal_aborted" + | "abort_provenance_present" + | "abort_provenance_missing" + | "provider_error_event" + | "iterator_error" + | "provider_progress_seen" + | "request_id_present" + | "provider_correlation_unavailable" + +export type BoundaryInput = { + watchdogFired?: boolean + watchdogError?: boolean + abortSignalAborted?: boolean + abortProvenancePresent?: boolean + providerErrorEvent?: boolean + iteratorError?: boolean + providerProgressSeen?: boolean + requestIdPresent?: boolean + providerCorrelationUnavailable?: boolean +} + +export type BoundaryResult = { + boundary: StreamBoundary + confidence: StreamConfidence + evidence: StreamEvidence[] +} + +export type ProviderCorrelation = { + request_id?: string + response_id?: string + status_code?: number + safe_headers?: Record + unavailable_reason?: string +} + +const SAFE_HEADER_NAMES = new Set(["x-request-id", "request-id", "x-correlation-id", "x-trace-id", "traceparent"]) + +export function classifyBoundary(input: BoundaryInput): BoundaryResult { + const evidence: StreamEvidence[] = [] + if (input.watchdogFired) evidence.push("watchdog_fired") + if (input.watchdogError) evidence.push("watchdog_error") + if (input.abortSignalAborted) evidence.push("abort_signal_aborted") + if (input.abortProvenancePresent === true) evidence.push("abort_provenance_present") + if (input.abortProvenancePresent === false) evidence.push("abort_provenance_missing") + if (input.providerErrorEvent) evidence.push("provider_error_event") + if (input.iteratorError) evidence.push("iterator_error") + if (input.providerProgressSeen) evidence.push("provider_progress_seen") + if (input.requestIdPresent) evidence.push("request_id_present") + if (input.providerCorrelationUnavailable) evidence.push("provider_correlation_unavailable") + + if (input.watchdogFired && input.watchdogError) return { boundary: "watchdog", confidence: "high", evidence } + if (input.abortSignalAborted && input.abortProvenancePresent) { + return { boundary: "local_abort", confidence: "high", evidence } + } + if (input.providerErrorEvent && input.requestIdPresent) { + return { boundary: "provider_stream", confidence: "high", evidence } + } + if (input.providerErrorEvent) return { boundary: "provider_stream", confidence: "medium", evidence } + if (input.abortSignalAborted && input.iteratorError) return { boundary: "unknown", confidence: "low", evidence } + if (input.providerProgressSeen && input.iteratorError) + return { boundary: "sdk_transport", confidence: "low", evidence } + if (input.iteratorError) return { boundary: "unknown", confidence: "low", evidence } + return { boundary: "unknown", confidence: "low", evidence } +} + +export function safeProviderCorrelation(input: unknown): ProviderCorrelation { + if (!isRecord(input)) return { unavailable_reason: "provider_correlation_unavailable" } + const requestID = safeIdentifier(input.request_id ?? input.requestId ?? input["x-request-id"]) + const responseID = safeIdentifier(input.response_id ?? input.responseId) + const statusCode = typeof input.status_code === "number" ? input.status_code : number(input.statusCode) + const safeHeaders = safeHeaderMap(input.headers ?? input.safe_headers) + const result: ProviderCorrelation = { + ...(requestID ? { request_id: requestID } : {}), + ...(responseID ? { response_id: responseID } : {}), + ...(statusCode !== undefined ? { status_code: statusCode } : {}), + ...(safeHeaders ? { safe_headers: safeHeaders } : {}), + } + return Object.keys(result).length ? result : { unavailable_reason: "provider_correlation_unavailable" } +} + +export function safeErrorFingerprint(error: unknown) { + const record = isRecord(error) ? error : undefined + const cause = record && isRecord(record.cause) ? record.cause : undefined + return { + constructor_name: safeLowCardinality(record?.constructor?.name), + name: safeLowCardinality(record?.name), + message: safeMessage(record?.message ?? (typeof error === "string" ? error : undefined)), + code: safeLowCardinality(record?.code), + cause_constructor_name: safeLowCardinality(cause?.constructor?.name), + cause_name: safeLowCardinality(cause?.name), + cause_message: safeMessage(cause?.message), + cause_code: safeLowCardinality(cause?.code), + stack_hint: safeStackHint(record?.stack), + } +} + +function safeHeaderMap(value: unknown) { + if (!isRecord(value)) return undefined + const result: Record = {} + for (const [rawName, rawValue] of Object.entries(value)) { + const name = rawName.toLowerCase() + if (!SAFE_HEADER_NAMES.has(name)) continue + const safeValue = safeIdentifier(rawValue) + if (!safeValue) continue + result[name] = safeValue + } + return Object.keys(result).length ? result : undefined +} + +function safeIdentifier(value: unknown) { + if (typeof value !== "string") return undefined + const trimmed = value.trim() + if (!trimmed || trimmed.length > 128) return undefined + if (/https?:\/\//i.test(trimmed)) return undefined + if (/bearer|cookie|token|secret|sk-/i.test(trimmed)) return undefined + if (!/^[a-zA-Z0-9_.:\/-]+$/.test(trimmed)) return undefined + return trimmed +} + +function safeLowCardinality(value: unknown) { + if (typeof value !== "string") return undefined + const trimmed = value.trim() + if (!trimmed || trimmed.length > 80) return undefined + if (!/^[a-zA-Z0-9_.:-]+$/.test(trimmed)) return undefined + return trimmed +} + +function safeMessage(value: unknown) { + if (typeof value !== "string") return undefined + let result = value.slice(0, 1024) + result = result.replace(/https?:\/\/\S+/gi, "[redacted:url]") + result = result.replace(/\bsk-[a-zA-Z0-9_-]+\b/g, "[redacted:secret]") + result = result.replace(/Bearer\s+[a-zA-Z0-9._~+/-]+/gi, "Bearer [redacted:secret]") + result = result.replace(/\/Users\/[^\s)]+/g, "[redacted:path]") + result = result.replace(/\\Users\\[^\s)]+/g, "[redacted:path]") + result = result.replace(/\/home\/[^\s)]+/g, "[redacted:path]") + return result.slice(0, 1024) +} + +function safeStackHint(value: unknown) { + if (typeof value !== "string") return undefined + const line = value.split("\n").find((entry) => entry.includes(" at ")) + if (!line) return undefined + return safeMessage(line)?.slice(0, 160) +} + +function number(value: unknown) { + return typeof value === "number" && Number.isFinite(value) ? value : undefined +} diff --git a/packages/opencode/src/session/llm-trace/types.ts b/packages/opencode/src/session/llm-trace/types.ts index f31c96fa7..b6f392fa0 100644 --- a/packages/opencode/src/session/llm-trace/types.ts +++ b/packages/opencode/src/session/llm-trace/types.ts @@ -1,6 +1,13 @@ import type { MessageV2 } from "../message-v2" import { MessageID, SessionID } from "../schema" import z from "zod" +import type { + BoundaryResult, + ProviderCorrelation, + StreamConfidence, + StreamEvidence, + StreamBoundary, +} from "./stream-diagnostics" export const SCHEMA_VERSION = 1 @@ -72,6 +79,67 @@ export const Flags = z.object({ }) export type Flags = z.infer +export type StreamDiagnostics = { + schema_version: 2 + attempt?: { + attempt_index?: number + attempt_id?: string + terminal_attempt?: boolean + note?: "terminal_attempt_only" | "per_attempt_recorded" + } + legacy_v1_counters?: "terminal_attempt" | "aggregate" + timeline: { + collector_created_at: number + sdk_stream_returned_at?: number + watchdog_armed_at?: number + first_event_at?: number + first_provider_progress_at?: number + last_event_at?: number + last_provider_progress_at?: number + completed_at?: number + failed_at?: number + durations_ms?: { + created_to_sdk_stream_returned?: number + watchdog_armed_to_first_event?: number + watchdog_armed_to_first_provider_progress?: number + first_to_last_provider_progress?: number + last_provider_progress_to_failure?: number + total?: number + } + } + watchdog: { + connect_timeout_ms: number + stream_timeout_ms: number + provider_progressed: boolean + phase_at_end: "before_first_provider_progress" | "between_provider_events" | "completed" | "unknown" + fired: boolean + fired_phase?: "connect" | "silent_stream" + } + abort?: { + signal_aborted_at_error?: boolean + provenance_source?: string + provenance_reason?: string + provenance_mode?: "soft" | "hard" + provenance_recorded_at?: number + provenance_missing?: boolean + } + error?: { + boundary: StreamBoundary + confidence?: StreamConfidence + evidence?: StreamEvidence[] + constructor_name?: string + name?: string + message?: string + code?: string + cause_constructor_name?: string + cause_name?: string + cause_message?: string + cause_code?: string + stack_hint?: string + } + provider?: ProviderCorrelation +} + export const Summary = z.object({ schema_version: z.literal(SCHEMA_VERSION), trace_id: MessageID.zod, @@ -89,6 +157,8 @@ export const Summary = z.object({ flags: Flags, created_at: z.number(), completed_at: z.number().optional(), + // Keep nested stream diagnostics permissive so older readers can parse exports as the v2 payload evolves. + stream: z.any().optional(), }) export type Summary = z.infer @@ -128,5 +198,32 @@ export type Recorder = { request(summary: RequestSummary): void observeEvent(event: { type: string } & Record): void finish(reason: string | undefined, tokens?: MessageV2.Assistant["tokens"]): void + beginStream(input: { + collectorCreatedAt: number + monotonicMs: number + connectTimeoutMs: number + streamTimeoutMs: number + }): void + recordStreamFailure(input: { + error: unknown + boundary: BoundaryResult["boundary"] + confidence: BoundaryResult["confidence"] + evidence: BoundaryResult["evidence"] + failedAt: number + monotonicMs: number + }): void + recordProviderProgress(input: { eventAt: number; monotonicMs: number }): void + recordWatchdogFired(input: { phase: "connect" | "silent_stream"; firedAt: number; monotonicMs: number }): void + recordStreamCompleted(input: { completedAt: number; monotonicMs: number }): void + recordAbortState(input: { + signalAbortedAtError?: boolean + provenanceSource?: string + provenanceReason?: string + provenanceMode?: "soft" | "hard" + provenanceRecordedAt?: number + provenanceMissing?: boolean + }): void + recordProviderErrorEvent(input: { error: unknown; provider?: unknown; failedAt: number; monotonicMs: number }): void + recordProviderCorrelation(input: unknown): void finalize(input: FinalizeInput): Summary } diff --git a/packages/opencode/src/session/llm.ts b/packages/opencode/src/session/llm.ts index 2ca93fd8f..9599e544b 100644 --- a/packages/opencode/src/session/llm.ts +++ b/packages/opencode/src/session/llm.ts @@ -47,7 +47,16 @@ export type StreamInput = { connectTimeoutMs?: number streamTimeoutMs?: number toolChoice?: "auto" | "required" | "none" - trace?: Pick + trace?: Pick< + LLMTrace.Recorder, + | "request" + | "beginStream" + | "recordProviderProgress" + | "recordWatchdogFired" + | "recordStreamFailure" + | "recordStreamCompleted" + | "recordAbortState" + > } export type StreamRequest = StreamInput & { @@ -449,6 +458,12 @@ const live: Layer.Layer< const request = yield* Effect.acquireRelease( Effect.sync(() => { const ctrl = new AbortController() + input.trace?.beginStream({ + collectorCreatedAt: Date.now(), + monotonicMs: performance.now(), + connectTimeoutMs, + streamTimeoutMs, + }) let disposed = false let providerProgressed = false let sequence = 0 @@ -466,11 +481,27 @@ const live: Layer.Layer< timeoutError = new Error( `LLM stream connection timed out after ${connectTimeoutMs}ms without provider progress`, ) + const now = Date.now() + const monotonicMs = performance.now() + input.trace?.recordWatchdogFired({ phase: "connect", firedAt: now, monotonicMs }) + input.trace?.recordStreamFailure({ + error: timeoutError, + boundary: "watchdog", + confidence: "high", + evidence: ["watchdog_fired", "watchdog_error"], + failedAt: now, + monotonicMs, + }) rejectTimeout?.(timeoutError) ctrl.abort() } const timeoutStream = () => { if (providerProgressed) { + input.trace?.recordWatchdogFired({ + phase: "silent_stream", + firedAt: Date.now(), + monotonicMs: performance.now(), + }) ctrl.abort() return } @@ -509,6 +540,32 @@ const live: Layer.Layer< timeoutError() { return timeoutError }, + recordIteratorError(error: unknown) { + input.trace?.recordAbortState({ + signalAbortedAtError: ctrl.signal.aborted, + provenanceMissing: ctrl.signal.aborted, + }) + const boundary = input.trace + ? LLMTrace.classifyBoundary({ + iteratorError: true, + providerProgressSeen: providerProgressed, + abortSignalAborted: ctrl.signal.aborted, + abortProvenancePresent: false, + }) + : undefined + if (!boundary) return + input.trace?.recordStreamFailure({ + error, + boundary: boundary.boundary, + confidence: boundary.confidence, + evidence: boundary.evidence, + failedAt: Date.now(), + monotonicMs: performance.now(), + }) + }, + recordCompleted() { + input.trace?.recordStreamCompleted({ completedAt: Date.now(), monotonicMs: performance.now() }) + }, // Start the connect timeout. Called after run() returns so the // timer only measures actual network/provider wait time, not // the internal setup work (provider lookup, config, plugins). @@ -518,6 +575,7 @@ const live: Layer.Layer< resetTimeout(event: Event) { if (!providerProgressed && !isProviderProgressEvent(event)) return providerProgressed = true + input.trace?.recordProviderProgress({ eventAt: Date.now(), monotonicMs: performance.now() }) if (timeout) clearTimeout(timeout) arm() }, @@ -574,6 +632,8 @@ function failOnTimeout( request: { timeoutFailure: Promise timeoutError: () => Error | undefined + recordIteratorError?: (error: unknown) => void + recordCompleted?: () => void }, ): AsyncIterable { return { @@ -585,9 +645,16 @@ function failOnTimeout( if (timeoutError) throw timeoutError const nextPromise = iterator.next() void nextPromise.catch(() => {}) - const next = await Promise.race([nextPromise, request.timeoutFailure]) + let next + try { + next = await Promise.race([nextPromise, request.timeoutFailure]) + } catch (error) { + request.recordIteratorError?.(error) + throw error + } const nextTimeoutError = request.timeoutError() if (nextTimeoutError) throw nextTimeoutError + if (next.done) request.recordCompleted?.() return next }, async return(value?: unknown) { diff --git a/packages/opencode/src/session/processor.ts b/packages/opencode/src/session/processor.ts index 113d818cd..4b15589ed 100644 --- a/packages/opencode/src/session/processor.ts +++ b/packages/opencode/src/session/processor.ts @@ -700,6 +700,12 @@ export const layer: Layer.Layer< } case "error": + ctx.trace.recordProviderErrorEvent({ + error: value.error, + provider: "providerMetadata" in value ? value.providerMetadata : undefined, + failedAt: Date.now(), + monotonicMs: performance.now(), + }) throw value.error case "start-step": @@ -950,6 +956,12 @@ export const layer: Layer.Layer< Effect.onInterrupt(() => Effect.gen(function* () { aborted = true + ctx.trace.recordAbortState({ + provenanceSource: "session.processor.onInterrupt", + provenanceReason: "aborted", + provenanceMode: "hard", + provenanceRecordedAt: Date.now(), + }) if (!ctx.assistantMessage.error) { yield* halt(new DOMException("Aborted", "AbortError")) } diff --git a/packages/opencode/test/session/export.test.ts b/packages/opencode/test/session/export.test.ts index cad710be0..29a6b4a24 100644 --- a/packages/opencode/test/session/export.test.ts +++ b/packages/opencode/test/session/export.test.ts @@ -1438,6 +1438,152 @@ describe("redactPart", () => { ) }) + test("sanitizeSnapshot redacts llm stream diagnostics in top-level and session tree copies", () => { + const rawTrace = { + schema_version: 1 as const, + trace_id: MessageID.make("msg_trace_sensitive"), + session_id: SessionID.make("ses_trace_sensitive"), + message_id: MessageID.make("msg_trace_sensitive"), + provider: "test", + model: "model", + agent: "build", + stream_events: { + start: 0, + start_step: 0, + finish_step: 0, + finish: 0, + text_start: 0, + text_delta: 0, + text_end: 0, + reasoning_start: 0, + reasoning_delta: 0, + reasoning_end: 0, + tool_input_start: 0, + tool_input_delta: 0, + tool_input_end: 0, + tool_call: 0, + tool_result: 0, + tool_error: 0, + error: 1, + }, + stored_parts: { text: 0, reasoning: 0, tool: 0, step_start: 0, step_finish: 0, patch: 0, file: 0, other: 0 }, + flags: { empty_completion: true, stream_error: true }, + created_at: 1, + stream: { + schema_version: 2, + legacy_v1_counters: "terminal_attempt", + timeline: { collector_created_at: 1 }, + watchdog: { + connect_timeout_ms: 30_000, + stream_timeout_ms: 600_000, + provider_progressed: true, + phase_at_end: "between_provider_events", + fired: false, + }, + error: { + boundary: "sdk_transport", + confidence: "low", + evidence: ["iterator_error"], + name: "TypeError", + message: "failed https://secret.example.invalid/body token sk-private /Users/alice/project/file.ts", + cause_message: "Authorization: Bearer secret", + stack_hint: "at /Users/alice/project/file.ts:1:1", + private_raw_body: "private response body should not export", + url: "https://secret.example.invalid/raw", + }, + provider: { + safe_headers: { + "x-request-id": "req_123", + authorization: "Bearer secret", + cookie: "session=secret", + }, + }, + prompt: "private prompt should not export", + tool_args: { command: "cat /Users/alice/.env" }, + raw_body: "raw provider body should not export", + url: "https://secret.example.invalid/top-level", + local_path: "/Users/alice/project/private.txt", + }, + } satisfies LLMTrace.Summary + + const fakeSnapshot: Export.Snapshot = { + schema_version: 1, + format: "pawwork-session-export", + exported_at: 1, + root_session_id: SessionID.make("ses_trace_sensitive"), + runtime_context: { + app_version: "test", + runtime_namespace: "pawwork", + platform: process.platform, + os_version: "test", + locale: "en-US", + timezone: "UTC", + instruction_sources: [], + model_refs: {}, + stats: { session_count: 1, message_count: 1, part_count: 0, omitted_attachment_count: 0 }, + }, + diagnostics: { llm_trace_schema_version: 1, llm_traces: [rawTrace] }, + session: { + info: { + id: SessionID.make("ses_trace_sensitive"), + version: "0.0.0", + time: { created: 1, updated: 1 }, + title: "x", + directory: "/tmp/project", + } as SessionNs.Info, + had_cloud_share: false, + diffs: [], + messages: [ + { + info: { + id: MessageID.make("msg_trace_sensitive"), + role: "assistant", + sessionID: SessionID.make("ses_trace_sensitive"), + parentID: MessageID.make("msg_parent_sensitive"), + mode: "build", + agent: "build", + path: { cwd: "/tmp/project", root: "/tmp/project" }, + cost: 0, + tokens: { input: 0, output: 0, reasoning: 0, cache: { read: 0, write: 0 } }, + modelID: "model", + providerID: "test", + time: { created: 1 }, + diagnostics: { llm_trace: rawTrace }, + } as MessageV2.Assistant, + parts: [], + }, + ], + children: [], + }, + } + + const sanitized = Export.sanitizeSnapshot(fakeSnapshot) + const serialized = JSON.stringify(sanitized) + expect(serialized).not.toContain("secret.example.invalid") + expect(serialized).not.toContain("sk-private") + expect(serialized).not.toContain("/Users/alice") + expect(serialized).not.toContain("Bearer secret") + expect(serialized).not.toContain("session=secret") + expect(serialized).not.toContain("private response body should not export") + expect(serialized).not.toContain("private_raw_body") + expect(serialized).not.toContain("private prompt should not export") + expect(serialized).not.toContain("raw provider body should not export") + expect(serialized).not.toContain("top-level") + expect(serialized).not.toContain("private.txt") + expect(serialized).not.toContain("tool_args") + expect(sanitized.diagnostics.llm_traces?.[0]?.stream?.error).not.toHaveProperty("url") + expect(sanitized.diagnostics.llm_traces?.[0]?.stream).not.toHaveProperty("prompt") + expect(sanitized.diagnostics.llm_traces?.[0]?.stream).not.toHaveProperty("raw_body") + expect(sanitized.diagnostics.llm_traces?.[0]?.stream?.provider?.safe_headers).toEqual({ + "x-request-id": "req_123", + }) + expect( + sanitized.session.messages[0].info.role === "assistant" + ? sanitized.session.messages[0].info.diagnostics?.llm_trace?.stream?.provider?.safe_headers + : undefined, + ).toEqual({ "x-request-id": "req_123" }) + }) + test("redacts data: url inside completed tool attachments", () => { const ctx = { count: { omitted: 0 } } const part: MessageV2.ToolPart = { diff --git a/packages/opencode/test/session/llm-trace.test.ts b/packages/opencode/test/session/llm-trace.test.ts index 950412969..b187175cd 100644 --- a/packages/opencode/test/session/llm-trace.test.ts +++ b/packages/opencode/test/session/llm-trace.test.ts @@ -112,4 +112,389 @@ describe("LLMTrace", () => { const empty = recorder.finalize({ completedAt: 3, finishReason: "stop", storedParts: [] }) expect(empty.flags.empty_completion).toBe(true) }) + + test("classifies overlapping watchdog abort evidence without treating signal state as local abort", () => { + expect( + LLMTrace.classifyBoundary({ + watchdogFired: true, + watchdogError: true, + abortSignalAborted: true, + iteratorError: true, + }), + ).toEqual({ + boundary: "watchdog", + confidence: "high", + evidence: ["watchdog_fired", "watchdog_error", "abort_signal_aborted", "iterator_error"], + }) + + expect( + LLMTrace.classifyBoundary({ + abortSignalAborted: true, + abortProvenancePresent: false, + iteratorError: true, + }), + ).toEqual({ + boundary: "unknown", + confidence: "low", + evidence: ["abort_signal_aborted", "abort_provenance_missing", "iterator_error"], + }) + }) + + test("records safe error fingerprints before persistence", () => { + const recorder = LLMTrace.createRecorder({ + traceID: MessageID.make("msg_trace"), + sessionID: SessionID.make("ses_trace"), + messageID: MessageID.make("msg_trace"), + providerID: "test", + modelID: "model", + agent: "build", + createdAt: 1, + }) + + recorder.beginStream({ + collectorCreatedAt: 10, + monotonicMs: 100, + connectTimeoutMs: 30_000, + streamTimeoutMs: 600_000, + }) + recorder.recordStreamFailure({ + error: { + name: "ProviderError", + message: + "request failed for https://secret.example.invalid/body with token sk-private and paths /Users/alice/project/file.ts /home/bob/project/file.ts", + code: "terminated", + cause: { name: "CauseError", message: "Authorization: Bearer secret" }, + stack: "ProviderError: boom\n at /Users/alice/project/file.ts:1:1", + }, + boundary: "sdk_transport", + confidence: "low", + evidence: ["iterator_error", "provider_progress_seen"], + failedAt: 20, + monotonicMs: 150, + }) + + const summary = recorder.finalize({ completedAt: 21, storedParts: [] }) + const serialized = JSON.stringify(summary) + expect(summary.stream?.error).toMatchObject({ + name: "ProviderError", + message: expect.stringContaining("[redacted:url]"), + code: "terminated", + cause_name: "CauseError", + cause_message: expect.stringContaining("[redacted:secret]"), + boundary: "sdk_transport", + confidence: "low", + }) + expect(serialized).not.toContain("secret.example.invalid") + expect(serialized).not.toContain("sk-private") + expect(serialized).not.toContain("/Users/alice") + expect(serialized).not.toContain("/home/bob") + expect(serialized).not.toContain("Bearer secret") + }) + + test("extracts provider correlation only from reviewed safe keys", () => { + const correlation = LLMTrace.safeProviderCorrelation({ + request_id: "req_123", + responseId: "resp_456", + status_code: 529, + headers: { + "x-request-id": "req_header", + authorization: "Bearer secret", + cookie: "session=secret", + "x-provider-body": "raw private body", + "x-trace-id": "trace_789", + }, + url: "https://secret.example.invalid/path?token=secret", + body: "private response body", + }) + + expect(correlation).toEqual({ + request_id: "req_123", + response_id: "resp_456", + status_code: 529, + safe_headers: { + "x-request-id": "req_header", + "x-trace-id": "trace_789", + }, + }) + expect(JSON.stringify(correlation)).not.toContain("Bearer") + expect(JSON.stringify(correlation)).not.toContain("private response body") + expect(JSON.stringify(correlation)).not.toContain("secret.example.invalid") + }) + + test("records explicit provider error events as safe provider stream failures", () => { + const recorder = LLMTrace.createRecorder({ + traceID: MessageID.make("msg_provider_error_trace"), + sessionID: SessionID.make("ses_provider_error_trace"), + messageID: MessageID.make("msg_provider_error_trace"), + providerID: "test", + modelID: "model", + agent: "build", + createdAt: 1, + }) + + recorder.beginStream({ + collectorCreatedAt: 10, + monotonicMs: 100, + connectTimeoutMs: 30_000, + streamTimeoutMs: 600_000, + }) + recorder.recordProviderErrorEvent({ + error: { name: "ProviderError", message: "raw body https://secret.example.invalid sk-private" }, + provider: { request_id: "req_provider", body: "private response body" }, + failedAt: 20, + monotonicMs: 130, + }) + + const summary = recorder.finalize({ completedAt: 21, storedParts: [], streamError: true }) + expect(summary.stream?.error).toMatchObject({ + boundary: "provider_stream", + confidence: "high", + evidence: expect.arrayContaining(["provider_error_event", "request_id_present"]), + name: "ProviderError", + }) + expect(summary.stream?.provider?.request_id).toBe("req_provider") + const serialized = JSON.stringify(summary) + expect(serialized).not.toContain("secret.example.invalid") + expect(serialized).not.toContain("sk-private") + expect(serialized).not.toContain("private response body") + }) + + test("keeps high-confidence watchdog diagnostics when a provider error follows", () => { + const recorder = LLMTrace.createRecorder({ + traceID: MessageID.make("msg_watchdog_provider_overlap"), + sessionID: SessionID.make("ses_watchdog_provider_overlap"), + messageID: MessageID.make("msg_watchdog_provider_overlap"), + providerID: "test", + modelID: "model", + agent: "build", + createdAt: 1, + }) + + recorder.beginStream({ + collectorCreatedAt: 10, + monotonicMs: 100, + connectTimeoutMs: 30_000, + streamTimeoutMs: 600_000, + }) + recorder.recordStreamFailure({ + error: new Error("LLM stream connection timed out after 30000ms"), + boundary: "watchdog", + confidence: "high", + evidence: ["watchdog_fired", "watchdog_error"], + failedAt: 20, + monotonicMs: 130, + }) + recorder.recordProviderErrorEvent({ + error: { name: "ProviderError", message: "late provider error" }, + provider: { request_id: "req_late" }, + failedAt: 21, + monotonicMs: 140, + }) + + const summary = recorder.finalize({ completedAt: 22, storedParts: [], streamError: true }) + expect(summary.stream?.error).toMatchObject({ + boundary: "watchdog", + confidence: "high", + evidence: ["watchdog_fired", "watchdog_error"], + }) + expect(summary.stream?.provider).toBeUndefined() + }) + + test("keeps monotonic durations non-negative when sampled clocks move backward", () => { + const recorder = LLMTrace.createRecorder({ + traceID: MessageID.make("msg_duration_trace"), + sessionID: SessionID.make("ses_duration_trace"), + messageID: MessageID.make("msg_duration_trace"), + providerID: "test", + modelID: "model", + agent: "build", + createdAt: 1, + }) + + recorder.beginStream({ + collectorCreatedAt: 10, + monotonicMs: 100, + connectTimeoutMs: 30_000, + streamTimeoutMs: 600_000, + }) + recorder.recordStreamFailure({ + error: new Error("terminated"), + boundary: "sdk_transport", + confidence: "low", + evidence: ["iterator_error"], + failedAt: 20, + monotonicMs: 90, + }) + + const summary = recorder.finalize({ completedAt: 21, storedParts: [], streamError: true }) + expect(summary.stream?.timeline.durations_ms?.total).toBe(0) + }) + + test("labels legacy v1 counters as aggregate when stream diagnostics track the terminal attempt", () => { + const recorder = LLMTrace.createRecorder({ + traceID: MessageID.make("msg_retry_trace"), + sessionID: SessionID.make("ses_retry_trace"), + messageID: MessageID.make("msg_retry_trace"), + providerID: "test", + modelID: "model", + agent: "build", + createdAt: 1, + }) + + recorder.beginStream({ + collectorCreatedAt: 10, + monotonicMs: 100, + connectTimeoutMs: 30_000, + streamTimeoutMs: 600_000, + }) + recorder.observeEvent({ type: "text-delta", text: "first attempt progress" }) + recorder.beginStream({ + collectorCreatedAt: 20, + monotonicMs: 200, + connectTimeoutMs: 30_000, + streamTimeoutMs: 600_000, + }) + recorder.recordStreamFailure({ + error: new Error("terminated"), + boundary: "sdk_transport", + confidence: "low", + evidence: ["iterator_error"], + failedAt: 30, + monotonicMs: 230, + }) + + const summary = recorder.finalize({ completedAt: 31, storedParts: [], streamError: true }) + expect(summary.stream_events.text_delta).toBe(1) + expect(summary.stream?.legacy_v1_counters).toBe("aggregate") + expect(summary.stream?.timeline.collector_created_at).toBe(20) + }) + + test("classifies local abort as high confidence when abort provenance is present", () => { + const recorder = LLMTrace.createRecorder({ + traceID: MessageID.make("msg_local_abort_trace"), + sessionID: SessionID.make("ses_local_abort_trace"), + messageID: MessageID.make("msg_local_abort_trace"), + providerID: "test", + modelID: "model", + agent: "build", + createdAt: 1, + }) + + recorder.beginStream({ + collectorCreatedAt: 10, + monotonicMs: 100, + connectTimeoutMs: 30_000, + streamTimeoutMs: 600_000, + }) + recorder.recordAbortState({ + signalAbortedAtError: true, + provenanceSource: "session.processor.onInterrupt", + provenanceReason: "aborted", + provenanceMode: "hard", + provenanceRecordedAt: 20, + }) + recorder.recordStreamFailure({ + error: new DOMException("Aborted", "AbortError"), + boundary: "unknown", + confidence: "low", + evidence: ["abort_signal_aborted", "abort_provenance_missing", "iterator_error"], + failedAt: 21, + monotonicMs: 130, + }) + + const summary = recorder.finalize({ completedAt: 22, storedParts: [], streamError: true, aborted: true }) + expect(summary.stream?.abort).toMatchObject({ + signal_aborted_at_error: true, + provenance_source: "session.processor.onInterrupt", + provenance_reason: "aborted", + provenance_mode: "hard", + provenance_recorded_at: 20, + }) + expect(summary.stream?.error).toMatchObject({ + boundary: "local_abort", + confidence: "high", + evidence: expect.arrayContaining(["abort_signal_aborted", "abort_provenance_present", "iterator_error"]), + }) + }) + + test("keeps watchdog boundary when local abort provenance overlaps watchdog failure", () => { + const recorder = LLMTrace.createRecorder({ + traceID: MessageID.make("msg_watchdog_abort_overlap"), + sessionID: SessionID.make("ses_watchdog_abort_overlap"), + messageID: MessageID.make("msg_watchdog_abort_overlap"), + providerID: "test", + modelID: "model", + agent: "build", + createdAt: 1, + }) + + recorder.beginStream({ + collectorCreatedAt: 10, + monotonicMs: 100, + connectTimeoutMs: 30_000, + streamTimeoutMs: 600_000, + }) + recorder.recordStreamFailure({ + error: new Error("LLM stream connection timed out after 30000ms"), + boundary: "watchdog", + confidence: "high", + evidence: ["watchdog_fired", "watchdog_error"], + failedAt: 20, + monotonicMs: 130, + }) + recorder.recordAbortState({ + signalAbortedAtError: true, + provenanceSource: "session.processor.onInterrupt", + provenanceReason: "aborted", + provenanceMode: "hard", + provenanceRecordedAt: 21, + }) + + const summary = recorder.finalize({ completedAt: 22, storedParts: [], streamError: true, aborted: true }) + expect(summary.stream?.error).toMatchObject({ + boundary: "watchdog", + confidence: "high", + evidence: ["watchdog_fired", "watchdog_error"], + }) + expect(summary.stream?.abort?.provenance_source).toBe("session.processor.onInterrupt") + }) + + test("keeps aborted iterator failures unknown without abort provenance", () => { + const recorder = LLMTrace.createRecorder({ + traceID: MessageID.make("msg_abort_missing_provenance"), + sessionID: SessionID.make("ses_abort_missing_provenance"), + messageID: MessageID.make("msg_abort_missing_provenance"), + providerID: "test", + modelID: "model", + agent: "build", + createdAt: 1, + }) + + recorder.beginStream({ + collectorCreatedAt: 10, + monotonicMs: 100, + connectTimeoutMs: 30_000, + streamTimeoutMs: 600_000, + }) + recorder.recordAbortState({ signalAbortedAtError: true, provenanceMissing: true }) + recorder.recordStreamFailure({ + error: new DOMException("Aborted", "AbortError"), + boundary: "unknown", + confidence: "low", + evidence: ["abort_signal_aborted", "abort_provenance_missing", "iterator_error"], + failedAt: 20, + monotonicMs: 130, + }) + + const summary = recorder.finalize({ completedAt: 21, storedParts: [], streamError: true, aborted: true }) + expect(summary.stream?.abort).toMatchObject({ + signal_aborted_at_error: true, + provenance_missing: true, + }) + expect(summary.stream?.error).toMatchObject({ + boundary: "unknown", + confidence: "low", + evidence: ["abort_signal_aborted", "abort_provenance_missing", "iterator_error"], + }) + }) }) diff --git a/packages/opencode/test/session/llm.test.ts b/packages/opencode/test/session/llm.test.ts index 7c432dbc3..c84ba25bb 100644 --- a/packages/opencode/test/session/llm.test.ts +++ b/packages/opencode/test/session/llm.test.ts @@ -17,6 +17,7 @@ import type { Agent } from "../../src/agent/agent" import { MessageV2 } from "../../src/session/message-v2" import { SessionID, MessageID } from "../../src/session/schema" import { AppRuntime } from "../../src/effect/app-runtime" +import { LLMTrace } from "../../src/session/llm-trace" async function getModel(providerID: ProviderID, modelID: ModelID) { return AppRuntime.runPromise( @@ -663,6 +664,15 @@ describe("session.llm.stream", () => { agent: agent.name, model: { providerID: ProviderID.make(providerID), modelID: resolved.id }, } satisfies MessageV2.User + const trace = LLMTrace.createRecorder({ + traceID: MessageID.make("trace-silent-timeout"), + sessionID, + messageID: MessageID.make("assistant-silent-timeout"), + providerID, + modelID: resolved.id, + agent: agent.name, + createdAt: Date.now(), + }) const exit = await llm.runPromiseExit((svc) => svc @@ -676,6 +686,7 @@ describe("session.llm.stream", () => { tools: {}, connectTimeoutMs: 1_000, streamTimeoutMs: 20, + trace, }) .pipe(Stream.runDrain), ) @@ -684,6 +695,13 @@ describe("session.llm.stream", () => { await Promise.race([pending.requestAborted, timeout(500)]).catch(() => undefined) await pending.request expect(Exit.isFailure(exit)).toBe(false) + const summary = trace.finalize({ completedAt: Date.now(), storedParts: [] }) + expect(summary.stream?.watchdog).toMatchObject({ + fired: true, + fired_phase: "silent_stream", + provider_progressed: true, + }) + expect(summary.stream?.error).toBeUndefined() }, }) }) @@ -737,6 +755,15 @@ describe("session.llm.stream", () => { agent: agent.name, model: { providerID: ProviderID.make(providerID), modelID: resolved.id }, } satisfies MessageV2.User + const trace = LLMTrace.createRecorder({ + traceID: MessageID.make("trace-connect-timeout"), + sessionID, + messageID: MessageID.make("assistant-connect-timeout"), + providerID, + modelID: resolved.id, + agent: agent.name, + createdAt: Date.now(), + }) const exit = await llm.runPromiseExit((svc) => svc @@ -750,6 +777,7 @@ describe("session.llm.stream", () => { tools: {}, connectTimeoutMs: 20, streamTimeoutMs: 1_000, + trace, }) .pipe(Stream.runDrain), ) @@ -758,6 +786,17 @@ describe("session.llm.stream", () => { await Promise.race([pending.requestAborted, timeout(500)]).catch(() => undefined) await pending.request expect(Exit.isFailure(exit)).toBe(true) + const summary = trace.finalize({ completedAt: Date.now(), storedParts: [], streamError: true }) + expect(summary.stream?.watchdog).toMatchObject({ + fired: true, + fired_phase: "connect", + provider_progressed: false, + }) + expect(summary.stream?.error).toMatchObject({ + boundary: "watchdog", + confidence: "high", + evidence: expect.arrayContaining(["watchdog_fired", "watchdog_error"]), + }) }, }) })