diff options
| author | Adam Malczewski <[email protected]> | 2026-05-31 22:32:34 +0900 |
|---|---|---|
| committer | Adam Malczewski <[email protected]> | 2026-05-31 22:32:34 +0900 |
| commit | 1853dd1d40308deb829bc621beb79c5d39b9c57f (patch) | |
| tree | ee5657560480130f3056694c31cdcc27c9430c5a | |
| parent | cb640f25b577a68ceea76b7c9a95a198e5e91441 (diff) | |
| download | dispatch-1853dd1d40308deb829bc621beb79c5d39b9c57f.tar.gz dispatch-1853dd1d40308deb829bc621beb79c5d39b9c57f.zip | |
feat(debug): wire LLM debug logger end-to-end
The debug-logger.ts module existed but was completely orphaned — none of
its functions had any callsites, so DISPATCH_DEBUG_LLM=1 did nothing.
Wires it in across the stack:
- llm/debug-logger.ts: add wrapFetchWithLogging() that tees SSE bodies via
TransformStream + response.clone() so we capture every chunk without
draining the body the AI SDK consumes. Redacts authorization / x-api-key
/ cookie headers in logs. Also exports nextDebugSeq() so requests and
log files share an id.
- llm/provider.ts: all 3 factories (Claude OAuth, plain-API-key Anthropic,
OpenAI-compatible) now pass fetch: wrapFetchWithLogging(globalThis.fetch).
For Claude OAuth the wrap goes on the inner base fetch so logged bodies
reflect the post-transform shape + Claude-Code session headers. Added
tabId to ProviderConfig for log labelling.
- agent/agent.ts: threads tabId through createProvider and emits
logAgentLoop / logStepLifecycle / logStreamEvent at every meaningful
point in the run loop — step start/end, tool count, every fullStream
event. All are no-ops when DISPATCH_DEBUG_LLM is unset.
- core/index.ts: re-exports the debug helpers.
- tests/llm/provider.test.ts: switch one full-object equality assertion
to property assertions so the test survives the new fetch: wrapper.
Plumbing the env var into the container required three more fixes:
- bin/up: re-export DISPATCH_DEBUG_LLM* so docker compose forwards them
(compose only forwards vars referenced in the environment: block).
Also pre-creates /tmp/dispatch/llm-debug and chowns it on first run so
the container's UID-1000 bun process can write into it without EACCES.
- docker-compose.yml: declare the debug vars on api.environment and
bind-mount /tmp/dispatch/llm-debug:/tmp/dispatch/llm-debug so logs are
inspectable from the host without docker exec.
- docker/entrypoint.dev.sh: explicitly forward DISPATCH_DEBUG_* through
the 'su -' login-shell barrier — su - resets the environment to TERM/
PATH/HOME/SHELL/USER/LOGNAME only, silently stripping everything else.
This is why the vars appeared via 'docker exec env' (which spawns a
new process inheriting the container env) but were absent from the
actual bun process's /proc/<pid>/environ.
bin/build: drop stray sudo for consistency with bin/up and bin/down.
| -rwxr-xr-x | bin/build | 2 | ||||
| -rwxr-xr-x | bin/up | 31 | ||||
| -rw-r--r-- | docker-compose.yml | 10 | ||||
| -rwxr-xr-x[-rw-r--r--] | docker/entrypoint.dev.sh | 26 | ||||
| -rw-r--r-- | packages/core/src/agent/agent.ts | bin | 56551 -> 57628 bytes | |||
| -rw-r--r-- | packages/core/src/index.ts | 7 | ||||
| -rw-r--r-- | packages/core/src/llm/debug-logger.ts | 453 | ||||
| -rw-r--r-- | packages/core/src/llm/provider.ts | 33 | ||||
| -rw-r--r-- | packages/core/tests/llm/provider.test.ts | 15 |
9 files changed, 569 insertions, 8 deletions
@@ -4,4 +4,4 @@ set -euo pipefail SCRIPT_DIR="$(cd "$(dirname "$0")" && pwd)" PROJECT_DIR="$(dirname "$SCRIPT_DIR")" -sudo docker compose -f "$PROJECT_DIR/docker-compose.yml" build "$@" +docker compose -f "$PROJECT_DIR/docker-compose.yml" build "$@" @@ -9,5 +9,36 @@ export HOST_UID="$(id -u)" export HOST_GID="$(id -g)" export HOST_USER="$(whoami)" +# Debug-logger pass-through. docker-compose only forwards env vars that are +# (a) set in the parent shell AND (b) referenced in docker-compose.yml's +# `environment:` block — so without this `export` step the variables would +# be invisible to the container even when the user prefixes the command with +# DISPATCH_DEBUG_LLM=1. We re-export here (rather than relying on the shell's +# inline `VAR=… cmd` syntax) so it works whether the user sets them inline, +# in their shell rc, or via `.env`. +# +# All variables default to empty — when unset, the logger short-circuits and +# does nothing. +export DISPATCH_DEBUG_LLM="${DISPATCH_DEBUG_LLM:-}" +export DISPATCH_DEBUG_LLM_VERBOSITY="${DISPATCH_DEBUG_LLM_VERBOSITY:-}" +export DISPATCH_DEBUG_USAGE="${DISPATCH_DEBUG_USAGE:-}" + +# Pre-create the LLM debug log directory owned by the host user. Without +# this, docker auto-creates the bind-mount source as root on first start, +# and the container's bun process (running as host UID) then gets EACCES +# on every log write — silent except for `[dispatch-debug] Failed to +# write ...: EACCES` lines drowned in stderr. +# +# If the directory already exists and is NOT owned by us (likely from a +# prior root-mkdir by docker), fix it with sudo. This prompts once and +# then never again — files we write afterwards are owned correctly. +LOG_DIR=/tmp/dispatch/llm-debug +mkdir -p "$LOG_DIR" 2>/dev/null || true +if [ ! -O "$LOG_DIR" ]; then + current_owner=$(stat -c '%U' "$LOG_DIR" 2>/dev/null || echo "unknown") + echo "bin/up: $LOG_DIR is owned by '$current_owner', fixing ownership to '$HOST_USER'..." + sudo chown -R "$HOST_UID:$HOST_GID" "$LOG_DIR" +fi + # Start all services docker compose -f "$PROJECT_DIR/docker-compose.yml" up "$@" diff --git a/docker-compose.yml b/docker-compose.yml index c1b009f..aedd0f2 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -11,6 +11,11 @@ services: - ${HOME}/.local/share/dispatch:/home/${HOST_USER:-dispatch}/.local/share/dispatch - ${HOME}/.skills:/home/${HOST_USER:-dispatch}/.skills - ${HOME}/.config/dispatch:/home/${HOST_USER:-dispatch}/.config/dispatch + # Surface LLM debug logs on the host so they're inspectable without + # `docker exec`. The container path is fixed to the same default the + # debug-logger uses (DISPATCH_DEBUG_LLM_DIR), so on the host you can + # `tail -F /tmp/dispatch/llm-debug/*.json` while running. + - /tmp/dispatch/llm-debug:/tmp/dispatch/llm-debug env_file: - .env.dispatch environment: @@ -18,6 +23,11 @@ services: HOST_GID: ${HOST_GID:-1000} HOST_USER: ${HOST_USER:-dispatch} DISPATCH_WORKING_DIR: /app + # Debug logger — forwarded from host via bin/up. When unset, the logger + # is a no-op (early-return on the !ENABLED guard in debug-logger.ts). + DISPATCH_DEBUG_LLM: ${DISPATCH_DEBUG_LLM:-} + DISPATCH_DEBUG_LLM_VERBOSITY: ${DISPATCH_DEBUG_LLM_VERBOSITY:-} + DISPATCH_DEBUG_USAGE: ${DISPATCH_DEBUG_USAGE:-} frontend: build: diff --git a/docker/entrypoint.dev.sh b/docker/entrypoint.dev.sh index dd0d423..0feb37a 100644..100755 --- a/docker/entrypoint.dev.sh +++ b/docker/entrypoint.dev.sh @@ -43,5 +43,29 @@ if [ "${SKIP_INSTALL:-}" != "1" ]; then su -s /bin/bash - "$USER_NAME" -c "export HOME=$USER_HOME && cd /app && bun install" fi +# ─── Env vars that must survive the `su -` login-shell barrier ── +# `su -` resets the environment to a clean login profile (TERM, PATH, +# HOME, SHELL, USER, LOGNAME, MAIL only — everything else is wiped). +# Anything compose/Dockerfile set on PID 1 that the actual app process +# needs has to be re-exported explicitly here. The +# `${VAR-}` form (note: NOT `${VAR:-}`) preserves the empty-string case +# so a deliberately-blank var stays blank instead of going undefined. +FORWARD_VARS=( + DISPATCH_DEBUG_LLM + DISPATCH_DEBUG_LLM_VERBOSITY + DISPATCH_DEBUG_LLM_DIR + DISPATCH_DEBUG_USAGE + DISPATCH_WORKING_DIR + PORT +) +EXPORTS="" +for var in "${FORWARD_VARS[@]}"; do + # Use indirect expansion to read the var's current value, default to empty. + val="${!var-}" + # Single-quote-escape the value so shell-meaningful chars survive. + esc=${val//\'/\'\\\'\'} + EXPORTS+="export $var='$esc'; " +done + # Execute the main command as the target user -exec su -s /bin/bash - "$USER_NAME" -c "export HOME=$USER_HOME && cd /app && exec $*" +exec su -s /bin/bash - "$USER_NAME" -c "export HOME=$USER_HOME && $EXPORTS cd /app && exec $*" diff --git a/packages/core/src/agent/agent.ts b/packages/core/src/agent/agent.ts Binary files differindex d4bb761..c2dfef1 100644 --- a/packages/core/src/agent/agent.ts +++ b/packages/core/src/agent/agent.ts diff --git a/packages/core/src/index.ts b/packages/core/src/index.ts index 3445301..a3816ea 100644 --- a/packages/core/src/index.ts +++ b/packages/core/src/index.ts @@ -54,6 +54,13 @@ export { updateTabStatus, updateTabTitle, } from "./db/tabs.js"; +export { + debugVerbosity, + isDebugEnabled, + logAgentLoop, + logStepLifecycle, + logStreamEvent, +} from "./llm/debug-logger.js"; export { createProvider } from "./llm/provider.js"; // Models export { ModelRegistry } from "./models/index.js"; diff --git a/packages/core/src/llm/debug-logger.ts b/packages/core/src/llm/debug-logger.ts new file mode 100644 index 0000000..2b7420c --- /dev/null +++ b/packages/core/src/llm/debug-logger.ts @@ -0,0 +1,453 @@ +/** + * 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<string, string>; + 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<string, string>; + 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<string, string>; + 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< + F extends (...args: never[]) => Promise<Response> | Response, +>(baseFetch: F, opts: { tabId?: string; modelHint?: string }): F { + if (!ENABLED) return baseFetch; + const wrapped = async (...args: Parameters<F>) => { + 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<string, string> = {}; + 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] = "<redacted>"; + } 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<string, string> = {}; + 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<Uint8Array, Uint8Array>({ + 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<Uint8Array> | 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; + } +} diff --git a/packages/core/src/llm/provider.ts b/packages/core/src/llm/provider.ts index 9e8475f..ca734f9 100644 --- a/packages/core/src/llm/provider.ts +++ b/packages/core/src/llm/provider.ts @@ -5,6 +5,7 @@ import type { LanguageModelV3 } from "@ai-sdk/provider"; import type { FetchFunction } from "@ai-sdk/provider-utils"; import { getAnthropicBetas } from "../credentials/anthropic-betas.js"; import { transformClaudeOAuthBody } from "./anthropic-oauth-transform.js"; +import { wrapFetchWithLogging } from "./debug-logger.js"; export interface ProviderConfig { apiKey: string; @@ -13,6 +14,9 @@ export interface ProviderConfig { claudeCredentials?: { accessToken: string; }; + /** Optional tab id for labelling debug logs. No effect when + * `DISPATCH_DEBUG_LLM` is unset. */ + tabId?: string; } const MCP_PREFIX = "mcp_"; @@ -61,10 +65,21 @@ export function createProvider(config: ProviderConfig): ModelFactory { // prompts, which use `providerOptions`. The result was that // reasoning_content never reached the wire and DeepSeek rejected the // follow-up turn with "must be passed back".) + // + // Debug logging: when DISPATCH_DEBUG_LLM is set, wrap the base fetch + // so every wire request/response (including SSE chunks) is captured. + // When disabled, `wrapFetchWithLogging` returns the input unchanged + // (zero overhead). + const loggingFetch = wrapFetchWithLogging(globalThis.fetch, { + tabId: config.tabId, + modelHint: "opencode-zen", + }) as unknown as FetchFunction; + const provider = createOpenAICompatible({ name: "opencode-zen", apiKey: config.apiKey, baseURL: config.baseURL, + fetch: loggingFetch, }); return (modelId: string) => provider(modelId); @@ -90,7 +105,17 @@ function createClaudeOAuthProvider(config: ProviderConfig): ModelFactory { // Stable per-provider session id — mirrors the Claude Code CLI, which sends // the same `X-Claude-Code-Session-Id` across a session's requests. const sessionId = randomUUID(); - const baseFetch = globalThis.fetch; + + // Wrap the base fetch FIRST so the logging wrapper sees the genuine + // outgoing HTTP body — i.e. AFTER the OAuth body transform and AFTER the + // Claude-Code session headers have been stamped on. Order matters: if we + // wrapped the inner `baseFetch` instead, the logs would show the pre- + // transform body and miss the session headers, defeating the point of + // capturing the wire for cache/billing debugging. + const baseFetch = wrapFetchWithLogging(globalThis.fetch, { + tabId: config.tabId, + modelHint: "claude-oauth", + }); // Custom fetch that (1) restructures the request body into the genuine // Claude Code system layout — required for Anthropic to bill correctly and @@ -138,9 +163,15 @@ function createClaudeOAuthProvider(config: ProviderConfig): ModelFactory { * authentication path. */ function createApiKeyAnthropicProvider(config: ProviderConfig): ModelFactory { + const loggingFetch = wrapFetchWithLogging(globalThis.fetch, { + tabId: config.tabId, + modelHint: "opencode-anthropic", + }) as unknown as FetchFunction; + const anthropic = createAnthropic({ apiKey: config.apiKey, baseURL: config.baseURL || "https://opencode.ai/zen/go/v1", + fetch: loggingFetch, }); return (modelId: string) => anthropic(modelId); diff --git a/packages/core/tests/llm/provider.test.ts b/packages/core/tests/llm/provider.test.ts index 12b6350..c8c0877 100644 --- a/packages/core/tests/llm/provider.test.ts +++ b/packages/core/tests/llm/provider.test.ts @@ -59,11 +59,16 @@ describe("createProvider (default OpenAI-compatible path)", () => { baseURL: "https://opencode.ai/zen/v1", })("deepseek-v4-pro"); - expect(mockCreateOpenAICompatible).toHaveBeenCalledWith({ - name: "opencode-zen", - apiKey: "zen-key", - baseURL: "https://opencode.ai/zen/v1", - }); + // We assert by property rather than full-object equality because the + // provider also passes a `fetch:` wrapper (the debug-logger tee). The + // load-bearing wiring is name/apiKey/baseURL; the fetch field is + // tested separately via the wrap-fetch tests. + expect(mockCreateOpenAICompatible).toHaveBeenCalledOnce(); + const zenArgs = mockCreateOpenAICompatible.mock.calls[0]?.[0] as Record<string, unknown>; + expect(zenArgs.name).toBe("opencode-zen"); + expect(zenArgs.apiKey).toBe("zen-key"); + expect(zenArgs.baseURL).toBe("https://opencode.ai/zen/v1"); + expect(typeof zenArgs.fetch).toBe("function"); }); }); |
