Add opt-in file tracing for debugging

Introduce COMMANDCODE_DEBUG=1 (and COMMANDCODE_DEBUG_FILE) to append a
request/stream trace to a log file. Trace points cover HTTP attempts
(status, retry wait, elapsed), stream event payloads, terminal finish and
usage, and redacted error bodies. Silent and no file created by default.

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` | `<os tempdir>/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. |
 

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<Uint8Array>): AsyncGenerator<Record<string, any>> {
   const reader = body.getReader();
   const decoder = new TextDecoder();
@@ -39,6 +41,7 @@ function parseLine(raw: string): Record<string, any> | 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;
   }
 }

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 */
+    }
+  }
+}

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<Response> {
     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<LanguageModelV3StreamResult> {
     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(),