diff --git a/README.md b/README.md index 83cedd1..8d3d70c 100644 --- a/README.md +++ b/README.md @@ -143,6 +143,26 @@ target config. `options.headers` (with a leading `Bearer ` stripped). If neither is present, requests are sent unauthenticated and CommandCode will reject them. +## Debug tracing + +Set `COMMANDCODE_DEBUG=1` to write a trace of every request and stream event to a log file. +Silent (and no file is created) unless enabled. Every line is passed through `redact()` so +credentials never reach disk. + +```powershell +$env:COMMANDCODE_DEBUG = "1" +opencode run "Reply with exactly: pong" -m commandcode/deepseek/deepseek-v4.1-flash +``` + +| Env var | Default | Description | +| --- | --- | --- | +| `COMMANDCODE_DEBUG` | unset | `1`/`true`/`yes` enables tracing. | +| `COMMANDCODE_DEBUG_FILE` | `/commandcode-debug.log` | Where the trace is appended. | + +The log captures the request (model id, body byte length), each HTTP attempt (status, retry +wait, elapsed ms), every stream event payload, and the terminal finish reason + usage. It is +useful for diagnosing model selection, retry, tool-call, and finish-reason issues. + ## Features | Capability | Status | @@ -192,6 +212,7 @@ src/transform.ts LanguageModelV3CallOptions -> /alpha/generate envelope (JSON s src/events.ts NDJSON/SSE line iterator over the upstream response body. src/usage.ts finish event -> V3 usage; finish-reason unification. src/redact.ts Credential scrubbing for error surfaces. +src/log.ts Opt-in tracing (COMMANDCODE_DEBUG) to a log file. src/constants.ts Defaults, header names, passthrough params, static config block. scripts/smoke.mjs Live end-to-end check against api.commandcode.ai. scripts/sync-models.mjs Generate provider.commandcode.models from the live catalog. @@ -252,6 +273,7 @@ opencode run "Use the glob tool to list *.mjs and report the filenames." -m comm | `stream ended ... no finish` / truncated output | Upstream closed the connection early. The provider emits a synthetic `finish`, but the response is incomplete; retry the turn. | | Images are ignored by the model | The selected model is not vision-capable. Mark it with `"attachment": true` and `modalities.input: ["text","image"]` in `models`, and pick a vision model id. | | Upstream 400 about tool calls | A `tool-call` or `tool-result` without a matching pair slipped through. Pairing is enforced in `src/transform.ts`; report a repro if it still occurs. | +| Need to see what the provider sends/receives | Set `COMMANDCODE_DEBUG=1` and read the appended log file (see [Debug tracing](#debug-tracing)). | | `tool_choice` seemingly ignored | Expected for `required`; upstream cannot force a call. `none` and named-tool are emulated via the tool list. | | Config change had no effect | opencode reads config once at startup. Restart it. | diff --git a/src/events.ts b/src/events.ts index 25768ca..b6dcded 100644 --- a/src/events.ts +++ b/src/events.ts @@ -1,4 +1,6 @@ /** CommandCode streams NDJSON; tolerate SSE-style `data:` prefixes and `[DONE]` sentinels. */ +import { debug } from "./log.js"; + export async function* iterateEvents(body: ReadableStream): AsyncGenerator> { const reader = body.getReader(); const decoder = new TextDecoder(); @@ -39,6 +41,7 @@ function parseLine(raw: string): Record | null { const parsed = JSON.parse(line); return parsed && typeof parsed === "object" ? parsed : null; } catch { + debug("events", "parse-skip", `line=${line.slice(0, 512)}`); return null; } } diff --git a/src/log.ts b/src/log.ts new file mode 100644 index 0000000..1eb1246 --- /dev/null +++ b/src/log.ts @@ -0,0 +1,36 @@ +// Opt-in tracing to a log file. Gated on COMMANDCODE_DEBUG=1; silent (and no file +// created) by default. Uses only Node built-ins so the built output stays dependency-free. + +import { appendFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { redact } from "./redact.js"; + +const ENABLED = /^(1|true|yes)$/i.test(process.env["COMMANDCODE_DEBUG"] ?? ""); +const FILE = process.env["COMMANDCODE_DEBUG_FILE"] ?? join(tmpdir(), "commandcode-debug.log"); + +function serialize(value: unknown): string { + if (typeof value === "string") return value; + try { + return JSON.stringify(value); + } catch { + return String(value); + } +} + +/** Write a trace line (appended) if tracing is enabled. Values are redacted before write. */ +export function debug(scope: string, ...args: unknown[]): void { + if (!ENABLED) return; + const parts = args.map(serialize); + const line = `[commandcode] ${new Date().toISOString()} [${scope}] ${parts.join(" ")}`; + try { + appendFileSync(FILE, redact(line) + "\n", "utf8"); + } catch { + // Never let tracing break the request path. + try { + process.stderr.write(redact(line) + "\n"); + } catch { + /* ignore */ + } + } +} diff --git a/src/model.ts b/src/model.ts index d0ad2e6..b602a19 100644 --- a/src/model.ts +++ b/src/model.ts @@ -18,6 +18,7 @@ import { GENERATE_PATH, } from "./constants.js"; import { iterateEvents } from "./events.js"; +import { debug } from "./log.js"; import { redact } from "./redact.js"; import { transform } from "./transform.js"; import { finishReasonFrom, usageFromFinish, type FinishEvent } from "./usage.js"; @@ -149,12 +150,17 @@ class CommandCodeLanguageModel implements LanguageModelV3 { private async fetchWithRetry(body: string, options: LanguageModelV3CallOptions): Promise { const headers = this.requestHeaders(options.headers); let lastError: unknown; + const url = `${this.opts.baseURL}${GENERATE_PATH}`; for (let attempt = 0; attempt <= this.opts.maxRetries; attempt++) { - if (options.abortSignal?.aborted) throw options.abortSignal.reason ?? new Error("Aborted"); + if (options.abortSignal?.aborted) { + debug("fetch", "aborted", `attempt=${attempt}`); + throw options.abortSignal.reason ?? new Error("Aborted"); + } + const started = Date.now(); let response: Response; try { - response = await fetch(`${this.opts.baseURL}${GENERATE_PATH}`, { + response = await fetch(url, { method: "POST", headers, body, @@ -162,16 +168,35 @@ class CommandCodeLanguageModel implements LanguageModelV3 { }); } catch (error) { lastError = error; + const wait = retryDelay(attempt, null, this.opts.retryMaxDelay); + debug( + "fetch", + "network-error", + `url=${url}`, + `attempt=${attempt}`, + `elapsedMs=${Date.now() - started}`, + `error=${redact(error instanceof Error ? error.message : String(error))}`, + ); if (attempt < this.opts.maxRetries && !options.abortSignal?.aborted) { - await sleep(retryDelay(attempt, null, this.opts.retryMaxDelay)); + await sleep(wait); continue; } throw error; } - if (isRetryable(response.status) && attempt < this.opts.maxRetries) { + const status = response.status; + if (isRetryable(status) && attempt < this.opts.maxRetries) { const wait = retryDelay(attempt, response.headers.get("retry-after"), this.opts.retryMaxDelay); if (wait >= 0) { + debug( + "fetch", + "retry", + `url=${url}`, + `attempt=${attempt}`, + `status=${status}`, + `retryAfter=${response.headers.get("retry-after") ?? "none"}`, + `waitMs=${wait}`, + ); try { await response.body?.cancel(); } catch { @@ -181,6 +206,7 @@ class CommandCodeLanguageModel implements LanguageModelV3 { continue; } } + debug("fetch", "response", `url=${url}`, `attempt=${attempt}`, `status=${status}`, `elapsedMs=${Date.now() - started}`); return response; } @@ -203,13 +229,17 @@ class CommandCodeLanguageModel implements LanguageModelV3 { } catch { /* keep raw body */ } - return new Error(redact(message.slice(0, 2000) || `Upstream returned ${response.status}`)); + const surfaced = redact(message.slice(0, 2000) || `Upstream returned ${response.status}`); + debug("error", `status=${response.status}`, `body=${surfaced}`); + return new Error(surfaced); } async doStream(options: LanguageModelV3CallOptions): Promise { const body = transform(options, this.modelId); + debug("doStream", `model=${this.modelId}`, `bodyBytes=${Buffer.byteLength(body, "utf8")}`); const response = await this.fetchWithRetry(body, options); if (!response.ok || !response.body) throw await this.errorFrom(response); + debug("doStream", "ok", `status=${response.status}`); const stream = toReadableStream(this.streamParts(response.body)); return { @@ -266,6 +296,17 @@ class CommandCodeLanguageModel implements LanguageModelV3 { if (text) content.push({ type: "text", text }); content.push(...toolCalls); + debug( + "doGenerate", + "done", + `model=${this.modelId}`, + `textChars=${text.length}`, + `reasoningChars=${reasoning.length}`, + `toolCalls=${toolCalls.length}`, + `finish=${finishReason.unified ?? "?"}`, + `usage=${JSON.stringify(usage)}`, + ); + return { content, finishReason, usage, warnings, request, response }; } @@ -283,6 +324,8 @@ class CommandCodeLanguageModel implements LanguageModelV3 { let errored = false; for await (const evt of iterateEvents(body)) { + const payload = JSON.stringify(evt); + debug("stream", `event=${evt.type}`, `payload=${payload && payload.length > 4096 ? payload.slice(0, 4096) + "…" : payload}`); switch (evt.type) { case "text-start": if (!textOpen) { @@ -372,9 +415,13 @@ class CommandCodeLanguageModel implements LanguageModelV3 { } } - if (errored) return; + if (errored) { + debug("stream", "terminal", "errored"); + return; + } if (textOpen) yield { type: "text-end", id: textId }; if (reasoningOpen) yield { type: "reasoning-end", id: reasoningId }; + debug("stream", "terminal", `finish=${finishReason ? (finishReason.unified ?? "?") : "synthesized"}`, `usage=${JSON.stringify(usage ?? zeroUsage())}`); yield { type: "finish", usage: usage ?? zeroUsage(),