traces: turn-level local spans — model calls (tokens/cache/errors) + tool calls, per-session JSONL

packages/extension/opencode-plugin/amicode_tools.ts

@@ -72,6 +72,7 @@ import {
   statusSummary,
   triggerOnboardingDistill,
 } from "./onboarding";
+import { makeTraceHooks } from "./traces";
 
 // Load line goes to STDERR, not stdout: `opencode debug config` imports plugin
 // modules before printing the resolved config as JSON on stdout (verified on
@@ -160,6 +161,9 @@ const RYDBERG_SCOPE_NOTE =
 // The plugin: exactly one export (see header). opencode calls it on session
 // creation with PluginInput; we need nothing from it today.
 export const AmicodeTools = async (_input: unknown) => ({
+  // Turn-level traces (traces.ts): every model call + tool call as a timed
+  // span in ~/.amico/amicode/traces/<session>.jsonl. AMICODE_TRACES=0 disables.
+  ...makeTraceHooks(),
   tool: {
     amicode_ask: {
       description:

packages/extension/opencode-plugin/traces.ts

@@ -0,0 +1,161 @@
+/** Turn-level traces (local-first observability).
+ *
+ *  One JSONL file per session under ~/.amico/amicode/traces/: every model call
+ *  and tool call as a timed SPAN, OTel-compatible in shape so a future
+ *  exporter is a mapping, not a rewrite. This is the record that answers
+ *  "why was that turn slow" (prefill × round-trips × cache misses), "which
+ *  turns silently errored" (the Gemini schema bug pattern), and "how do models
+ *  compare on interview discipline" — locally, greppable, never leaving the
+ *  machine (chats are research IP; scrub at record time like onboarding.ts).
+ *
+ *  CONTRACT (mirrored by the fork's GET /amicode/traces reader —
+ *  harmoniqs/opencode packages/opencode/src/server/amicode/traces.ts; change
+ *  both in one change-set):
+ *    {v:1, ts, session, span:"model"|"tool"|"turn", id, name,
+ *     dur_ms|null, attrs:{...}, error:string|null}
+ *  Append-only; malformed lines are skipped by readers. */
+import * as fs from "node:fs";
+import * as path from "node:path";
+import { opsDir, SECRET_RE } from "./onboarding";
+
+export function tracesDir(ops: string = opsDir()): string {
+  const env = process.env.AMICODE_TRACE_DIR;
+  if (env && env.trim() !== "") return env;
+  return path.join(ops, "traces");
+}
+
+/** Kill switch: AMICODE_TRACES=0 disables recording entirely. */
+export function tracesEnabled(): boolean {
+  return process.env.AMICODE_TRACES !== "0";
+}
+
+const ATTR_MAX = 2000;
+
+/** Bounded, secret-free stringification for attrs — a span is telemetry, not
+ *  a transcript; big payloads get truncated with an explicit marker. */
+export function scrubValue(v: unknown): unknown {
+  if (typeof v === "string") {
+    const cut = v.length > ATTR_MAX ? `${v.slice(0, ATTR_MAX)}…[truncated ${v.length}]` : v;
+    return SECRET_RE.test(cut) ? "«credential omitted»" : cut;
+  }
+  if (typeof v === "number" || typeof v === "boolean" || v === null) return v;
+  if (Array.isArray(v)) return v.slice(0, 32).map(scrubValue);
+  if (typeof v === "object" && v !== null) {
+    const out: Record<string, unknown> = {};
+    for (const [k, val] of Object.entries(v).slice(0, 32)) out[k] = scrubValue(val);
+    return out;
+  }
+  return undefined;
+}
+
+export interface Span {
+  v: 1;
+  ts: string;
+  session: string;
+  span: "model" | "tool" | "turn";
+  id: string;
+  name: string;
+  dur_ms: number | null;
+  attrs: Record<string, unknown>;
+  error: string | null;
+}
+
+export function recordSpan(span: Span, dir: string = tracesDir()): void {
+  if (!tracesEnabled()) return;
+  try {
+    fs.mkdirSync(dir, { recursive: true });
+    fs.appendFileSync(path.join(dir, `${span.session}.jsonl`), JSON.stringify(span) + "\n");
+  } catch {
+    /* telemetry must never break the session */
+  }
+}
+
+/** Assistant message.updated → a "model" span, emitted ONCE per message when
+ *  it completes (time.completed present). Carries the numbers that answer the
+ *  perf questions: tokens incl. cache read/write, model, duration, error. */
+export function spanFromMessageEvent(evt: unknown, seen: Set<string>): Span | undefined {
+  const e = evt as { type?: string; properties?: { info?: Record<string, any> } };
+  if (e?.type !== "message.updated") return undefined;
+  const info = e.properties?.info;
+  if (!info || info.role !== "assistant") return undefined;
+  const completed = info.time?.completed;
+  if (typeof completed !== "number" || typeof info.id !== "string" || seen.has(info.id)) return undefined;
+  seen.add(info.id);
+  const created = typeof info.time?.created === "number" ? info.time.created : null;
+  const err = info.error ? JSON.stringify(scrubValue(info.error)).slice(0, 500) : null;
+  return {
+    v: 1,
+    ts: new Date(completed).toISOString(),
+    session: String(info.sessionID ?? "unknown"),
+    span: "model",
+    id: info.id,
+    name: `${info.providerID ?? "?"}/${info.modelID ?? "?"}`,
+    dur_ms: created !== null ? Math.max(0, completed - created) : null,
+    attrs: {
+      tokens: scrubValue(info.tokens) ?? {},
+      cost: typeof info.cost === "number" ? info.cost : undefined,
+      agent: typeof info.agent === "string" ? info.agent : undefined,
+    },
+    error: err,
+  };
+}
+
+/** Hook bundle for the plugin: chat.message opens a turn span; the
+ *  tool.execute before/after pair yields tool spans with real durations. */
+export function makeTraceHooks(dir: string = tracesDir()) {
+  const toolStarts = new Map<string, { tool: string; at: number }>();
+  const seenMessages = new Set<string>();
+  return {
+    event: async ({ event }: { event: unknown }) => {
+      const span = spanFromMessageEvent(event, seenMessages);
+      if (span) recordSpan(span, dir);
+    },
+    "chat.message": async (
+      input: { sessionID: string; agent?: string; model?: { providerID: string; modelID: string }; messageID?: string },
+      _output: unknown,
+    ) => {
+      recordSpan(
+        {
+          v: 1,
+          ts: new Date().toISOString(),
+          session: input.sessionID,
+          span: "turn",
+          id: input.messageID ?? `turn-${Date.now()}`,
+          name: input.agent ?? "chat",
+          dur_ms: null,
+          attrs: { model: input.model ? `${input.model.providerID}/${input.model.modelID}` : undefined },
+          error: null,
+        },
+        dir,
+      );
+    },
+    "tool.execute.before": async (input: { tool: string; sessionID: string; callID: string }, _output: unknown) => {
+      toolStarts.set(input.callID, { tool: input.tool, at: Date.now() });
+    },
+    "tool.execute.after": async (
+      input: { tool: string; sessionID: string; callID: string; args: unknown },
+      output: { title?: string; output?: string },
+    ) => {
+      const start = toolStarts.get(input.callID);
+      toolStarts.delete(input.callID);
+      recordSpan(
+        {
+          v: 1,
+          ts: new Date().toISOString(),
+          session: input.sessionID,
+          span: "tool",
+          id: input.callID,
+          name: input.tool,
+          dur_ms: start ? Date.now() - start.at : null,
+          attrs: {
+            args: scrubValue(input.args) ?? {},
+            title: typeof output?.title === "string" ? scrubValue(output.title) : undefined,
+            output_chars: typeof output?.output === "string" ? output.output.length : undefined,
+          },
+          error: null,
+        },
+        dir,
+      );
+    },
+  };
+}

packages/extension/test/traces.test.ts

@@ -0,0 +1,111 @@
+import { describe, it, expect } from "vitest";
+import { mkdtempSync, readFileSync, existsSync } from "node:fs";
+import { join } from "node:path";
+import { tmpdir } from "node:os";
+import { recordSpan, spanFromMessageEvent, scrubValue, makeTraceHooks, type Span } from "../opencode-plugin/traces";
+
+const span = (over: Partial<Span> = {}): Span => ({
+  v: 1,
+  ts: "2026-07-09T00:00:00.000Z",
+  session: "ses_x",
+  span: "tool",
+  id: "call_1",
+  name: "amicode_solve",
+  dur_ms: 42,
+  attrs: {},
+  error: null,
+  ...over,
+});
+
+const readLines = (dir: string, ses: string) =>
+  readFileSync(join(dir, `${ses}.jsonl`), "utf8")
+    .trim()
+    .split("\n")
+    .map((l) => JSON.parse(l));
+
+describe("recordSpan", () => {
+  it("appends one JSON line per span, per-session file", () => {
+    const dir = mkdtempSync(join(tmpdir(), "traces-"));
+    recordSpan(span(), dir);
+    recordSpan(span({ id: "call_2", session: "ses_y" }), dir);
+    expect(readLines(dir, "ses_x")).toHaveLength(1);
+    expect(readLines(dir, "ses_y")[0].id).toBe("call_2");
+  });
+  it("AMICODE_TRACES=0 disables recording", () => {
+    const dir = mkdtempSync(join(tmpdir(), "traces-"));
+    process.env.AMICODE_TRACES = "0";
+    try {
+      recordSpan(span(), dir);
+    } finally {
+      delete process.env.AMICODE_TRACES;
+    }
+    expect(existsSync(join(dir, "ses_x.jsonl"))).toBe(false);
+  });
+});
+
+describe("scrubValue", () => {
+  it("omits credential-looking strings and truncates huge ones", () => {
+    expect(scrubValue("Bearer abc123")).toBe("«credential omitted»");
+    const big = scrubValue("x".repeat(5000)) as string;
+    expect(big.length).toBeLessThan(2100);
+    expect(big).toContain("[truncated 5000]");
+  });
+});
+
+describe("spanFromMessageEvent", () => {
+  const evt = (info: Record<string, unknown>) => ({ type: "message.updated", properties: { info } });
+  it("completed assistant message → model span with tokens/cache/duration, once", () => {
+    const seen = new Set<string>();
+    const info = {
+      id: "msg_1",
+      sessionID: "ses_x",
+      role: "assistant",
+      providerID: "google",
+      modelID: "gemini-2.5-flash",
+      time: { created: 1000, completed: 5200 },
+      tokens: { input: 25054, output: 168, cache: { read: 0, write: 0 } },
+    };
+    const s = spanFromMessageEvent(evt(info), seen)!;
+    expect(s).toMatchObject({ span: "model", name: "google/gemini-2.5-flash", dur_ms: 4200, session: "ses_x" });
+    expect((s.attrs.tokens as { input: number }).input).toBe(25054);
+    expect(spanFromMessageEvent(evt(info), seen)).toBeUndefined(); // dedupe
+  });
+  it("ignores user messages, incomplete messages, other event types", () => {
+    const seen = new Set<string>();
+    expect(spanFromMessageEvent(evt({ id: "m", role: "user", time: { completed: 1 } }), seen)).toBeUndefined();
+    expect(spanFromMessageEvent(evt({ id: "m", role: "assistant", time: {} }), seen)).toBeUndefined();
+    expect(spanFromMessageEvent({ type: "session.updated" }, seen)).toBeUndefined();
+  });
+  it("carries the error (scrubbed) — the silent-failure detector", () => {
+    const seen = new Set<string>();
+    const s = spanFromMessageEvent(
+      evt({
+        id: "m2",
+        sessionID: "s",
+        role: "assistant",
+        time: { created: 0, completed: 1 },
+        error: { name: "APIError", data: { message: "tools[0] rejected" } },
+      }),
+      seen,
+    )!;
+    expect(s.error).toContain("APIError");
+  });
+});
+
+describe("makeTraceHooks tool pairing", () => {
+  it("before/after yields a tool span with a real duration and bounded attrs", async () => {
+    const dir = mkdtempSync(join(tmpdir(), "traces-"));
+    const hooks = makeTraceHooks(dir);
+    await hooks["tool.execute.before"]({ tool: "amicode_solve", sessionID: "ses_t", callID: "c1" }, {});
+    await hooks["tool.execute.after"](
+      { tool: "amicode_solve", sessionID: "ses_t", callID: "c1", args: { note: "Bearer xyz" } },
+      { title: "Run", output: "y".repeat(9000) },
+    );
+    const [line] = readLines(dir, "ses_t");
+    expect(line.span).toBe("tool");
+    expect(line.name).toBe("amicode_solve");
+    expect(line.dur_ms).toBeGreaterThanOrEqual(0);
+    expect(line.attrs.args.note).toBe("«credential omitted»");
+    expect(line.attrs.output_chars).toBe(9000);
+  });
+});