/** * Debug logger for LLM API requests and responses. * * Enable via environment variable: DISPATCH_DEBUG_LLM=1 * * Logs every outgoing request body and incoming response body to timestamped * files under `DISPATCH_DEBUG_LLM_DIR` (default: /tmp/dispatch/llm-debug/). * * Each request/response pair shares a sequence number for easy correlation. * Files are named: `{seq}_{timestamp}_{direction}_{model}.json` * * For streaming responses (SSE), the raw chunks are captured as they arrive * and written out as a JSON array when the stream completes. * * Additional logging layers: * - Stream events: every AI SDK stream event (text-delta, tool-call, etc.) * - Step lifecycle: step start/end, tool execution timing * - Agent loop: step count, break conditions, tool call counts * * All output goes to stderr (console.error) for stream event logs, and to * files for request/response bodies (too large for console). */ import { mkdirSync, writeFileSync } from "node:fs"; import { join } from "node:path"; const ENABLED = !!process.env.DISPATCH_DEBUG_LLM; const LOG_DIR = process.env.DISPATCH_DEBUG_LLM_DIR || "/tmp/dispatch/llm-debug"; let seq = 0; /** Verbosity levels: * 1 = requests/responses only (files) * 2 = + stream events to stderr * 3 = + step lifecycle + agent loop details to stderr */ const VERBOSITY = Math.max(1, Number(process.env.DISPATCH_DEBUG_LLM_VERBOSITY) || 1); function ensureDir(): void { try { mkdirSync(LOG_DIR, { recursive: true }); } catch { // best effort } } function ts(): string { return new Date().toISOString().replace(/[:.]/g, "-"); } function sanitizeModel(model: string): string { return model.replace(/[^a-zA-Z0-9_.-]/g, "_").slice(0, 60); } function sanitizeTab(tabId?: string): string { if (!tabId) return "notab"; return tabId.replace(/[^a-zA-Z0-9_.-]/g, "_").slice(0, 40); } export function isDebugEnabled(): boolean { return ENABLED; } export function debugVerbosity(): number { return ENABLED ? VERBOSITY : 0; } /** * Allocate a fresh sequence number. Used by the fetch wrapper so the request * and the response share the same id without needing a separate `logRequest` * call from the agent loop (which doesn't see the actual HTTP body anyway). */ export function nextDebugSeq(): number { return ++seq; } /** * Log an outgoing request to the AI model endpoint. * Returns a request ID for correlating with the response. */ export function logRequest(data: { model: string; url?: string; method?: string; headers?: Record; body: unknown; tabId?: string; step?: number; provider?: string; }): number { if (!ENABLED) return -1; ensureDir(); const id = ++seq; const filename = `${String(id).padStart(5, "0")}_${ts()}_tab-${sanitizeTab(data.tabId)}_REQ_${sanitizeModel(data.model)}.json`; const payload = { _debug: { seq: id, direction: "request", timestamp: new Date().toISOString(), tabId: data.tabId, step: data.step, provider: data.provider, }, url: data.url, method: data.method ?? "POST", headers: data.headers, body: data.body, }; try { writeFileSync(join(LOG_DIR, filename), JSON.stringify(payload, null, 2)); } catch (err) { console.error(`[dispatch-debug] Failed to write request log: ${err}`); } console.error( `[dispatch-debug] REQ #${id} → ${data.model} (step=${data.step ?? "?"}, tab=${data.tabId ?? "?"})`, ); return id; } /** * Log the raw fetch-level request (the actual HTTP body sent to the provider). * Called from the instrumented fetch wrapper. */ export function logRawFetchRequest(data: { requestId: number; url: string; method: string; headers: Record; body: string | null; tabId?: string; }): void { if (!ENABLED) return; ensureDir(); const filename = `${String(data.requestId).padStart(5, "0")}_${ts()}_tab-${sanitizeTab(data.tabId)}_RAW_REQ.json`; const payload = { _debug: { seq: data.requestId, direction: "raw-request", timestamp: new Date().toISOString(), tabId: data.tabId, }, url: data.url, method: data.method, headers: data.headers, body: tryParseJson(data.body), }; try { writeFileSync(join(LOG_DIR, filename), JSON.stringify(payload, null, 2)); } catch (err) { console.error(`[dispatch-debug] Failed to write raw request log: ${err}`); } } /** * Log the raw fetch-level response (HTTP status, headers, body). */ export function logRawFetchResponse(data: { requestId: number; url: string; status: number; statusText: string; headers: Record; body: string | null; isStreaming: boolean; tabId?: string; }): void { if (!ENABLED) return; ensureDir(); const filename = `${String(data.requestId).padStart(5, "0")}_${ts()}_tab-${sanitizeTab(data.tabId)}_RAW_RES_${data.status}.json`; const payload = { _debug: { seq: data.requestId, direction: "raw-response", timestamp: new Date().toISOString(), isStreaming: data.isStreaming, tabId: data.tabId, }, url: data.url, status: data.status, statusText: data.statusText, headers: data.headers, body: tryParseJson(data.body), }; try { writeFileSync(join(LOG_DIR, filename), JSON.stringify(payload, null, 2)); } catch (err) { console.error(`[dispatch-debug] Failed to write raw response log: ${err}`); } } /** * Accumulator for streaming response chunks. Call `addChunk()` as SSE events * arrive, then `flush()` when the stream ends to write them all to disk. */ export class StreamResponseLogger { private requestId: number; private model: string; private tabId?: string; private chunks: Array<{ timestamp: string; data: string }> = []; private startTime: number; constructor(requestId: number, model: string, tabId?: string) { this.requestId = requestId; this.model = model; this.tabId = tabId; this.startTime = Date.now(); } addChunk(rawLine: string): void { if (!ENABLED) return; this.chunks.push({ timestamp: new Date().toISOString(), data: rawLine, }); } flush(meta?: { finishReason?: string; error?: string }): void { if (!ENABLED) return; ensureDir(); const elapsed = Date.now() - this.startTime; const filename = `${String(this.requestId).padStart(5, "0")}_${ts()}_tab-${sanitizeTab(this.tabId)}_STREAM_RES_${sanitizeModel(this.model)}.json`; const payload = { _debug: { seq: this.requestId, direction: "stream-response", timestamp: new Date().toISOString(), tabId: this.tabId, model: this.model, elapsedMs: elapsed, chunkCount: this.chunks.length, ...meta, }, chunks: this.chunks, }; try { writeFileSync(join(LOG_DIR, filename), JSON.stringify(payload, null, 2)); } catch (err) { console.error(`[dispatch-debug] Failed to write stream response log: ${err}`); } console.error( `[dispatch-debug] STREAM #${this.requestId} complete: ${this.chunks.length} chunks in ${elapsed}ms (${this.model})`, ); } } /** * Log an AI SDK stream event (text-delta, tool-call, finish-step, etc.). * Only logs at verbosity >= 2. */ export function logStreamEvent(data: { requestId: number; step: number; eventType: string; detail?: unknown; tabId?: string; }): void { if (!ENABLED || VERBOSITY < 2) return; const detail = data.detail !== undefined ? ` ${JSON.stringify(data.detail)}` : ""; console.error( `[dispatch-debug] STREAM_EVENT #${data.requestId} step=${data.step} ${data.eventType}${detail}`, ); } /** * Log step lifecycle events (step start, tool execution, step end). * Only logs at verbosity >= 3. */ export function logStepLifecycle(data: { tabId?: string; step: number; event: string; detail?: unknown; }): void { if (!ENABLED || VERBOSITY < 3) return; const detail = data.detail !== undefined ? ` ${JSON.stringify(data.detail)}` : ""; console.error( `[dispatch-debug] STEP tab=${data.tabId ?? "?"} step=${data.step} ${data.event}${detail}`, ); } /** * Log agent loop-level events (loop start, break conditions, etc.). * Only logs at verbosity >= 3. */ export function logAgentLoop(data: { tabId?: string; event: string; detail?: unknown }): void { if (!ENABLED || VERBOSITY < 3) return; const detail = data.detail !== undefined ? ` ${JSON.stringify(data.detail)}` : ""; console.error(`[dispatch-debug] AGENT tab=${data.tabId ?? "?"} ${data.event}${detail}`); } /** * Wrap a fetch function so every request/response pair is logged to disk * under `DISPATCH_DEBUG_LLM_DIR` when `DISPATCH_DEBUG_LLM` is set. When * disabled, returns the input fetch unchanged (zero overhead). * * Critical implementation note — SSE bodies: the AI SDK consumes * `response.body` as a `ReadableStream`. Reading it from anywhere else * (e.g. calling `.text()`) drains the stream and the SDK gets an empty * body. We therefore `response.clone()` the response and tee its body via * a `TransformStream` so each SSE line is forwarded to the SDK AND * captured into a `StreamResponseLogger`. The clone returns its own * Response object whose body the SDK reads normally. * * For non-streaming responses (`content-type` is not `text/event-stream`) * we just clone and read once via `.text()` — simpler and safe because * non-streaming bodies are bounded. */ export function wrapFetchWithLogging Promise | Response>( baseFetch: F, opts: { tabId?: string; modelHint?: string }, ): F { if (!ENABLED) return baseFetch; const wrapped = async (...args: Parameters) => { const requestId = ++seq; const [input, init] = args as unknown as [RequestInfo | URL, RequestInit | undefined]; const url = typeof input === "string" ? input : input instanceof URL ? input.toString() : (input as Request).url; const method = init?.method ?? (typeof input === "object" && "method" in input ? (input as Request).method : "POST"); // Snapshot headers as a plain object for logging. const headerObj: Record = {}; try { const h = new Headers(init?.headers); h.forEach((v, k) => { // Redact bearer / api-key headers — useful in shared logs. if (/^(authorization|x-api-key|cookie)$/i.test(k)) { headerObj[k] = ""; } else { headerObj[k] = v; } }); } catch { // best effort } // Capture request body. Most providers send a JSON string here; if it's // a stream/blob/etc. we skip body logging (rare in our codebase). let bodyStr: string | null = null; if (typeof init?.body === "string") { bodyStr = init.body; } else if (init?.body instanceof Uint8Array) { bodyStr = new TextDecoder().decode(init.body); } logRawFetchRequest({ requestId, url, method, headers: headerObj, body: bodyStr, tabId: opts.tabId, }); const response = await (baseFetch as unknown as typeof fetch)(input, init); const respHeaders: Record = {}; response.headers.forEach((v, k) => { respHeaders[k] = v; }); const contentType = response.headers.get("content-type") ?? ""; const isStreaming = contentType.includes("text/event-stream"); if (!isStreaming) { // Clone so we don't drain the SDK's copy. Bounded body — safe to read. try { const cloned = response.clone(); const text = await cloned.text(); logRawFetchResponse({ requestId, url, status: response.status, statusText: response.statusText, headers: respHeaders, body: text, isStreaming: false, tabId: opts.tabId, }); } catch (err) { console.error(`[dispatch-debug] Failed to clone non-stream response: ${err}`); } return response; } // Streaming path: write a header file with status + headers immediately // (the body file comes later via StreamResponseLogger.flush). logRawFetchResponse({ requestId, url, status: response.status, statusText: response.statusText, headers: respHeaders, body: null, isStreaming: true, tabId: opts.tabId, }); // Tee the body through a TransformStream so each SSE chunk is captured // without consuming the stream the SDK needs. const streamLogger = new StreamResponseLogger( requestId, opts.modelHint ?? "stream", opts.tabId, ); const decoder = new TextDecoder(); const tee = new TransformStream({ transform(chunk, controller) { try { streamLogger.addChunk(decoder.decode(chunk, { stream: true })); } catch { // never let logging break the stream } controller.enqueue(chunk); }, flush() { try { streamLogger.flush(); } catch { // best effort } }, }); // `response.body` is `ReadableStream | null`. If null (no // body), there's nothing to tee — return as-is. if (!response.body) return response; const teed = response.body.pipeThrough(tee); return new Response(teed, { status: response.status, statusText: response.statusText, headers: response.headers, }); }; return wrapped as unknown as F; } function tryParseJson(s: string | null): unknown { if (s === null) return null; try { return JSON.parse(s); } catch { return s; } }