diff --git a/packages/extension/opencode-plugin/amicode_tools.ts b/packages/extension/opencode-plugin/amicode_tools.ts index dc97916c..4e104e2a 100644 --- a/packages/extension/opencode-plugin/amicode_tools.ts +++ b/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/.jsonl. AMICODE_TRACES=0 disables. + ...makeTraceHooks(), tool: { amicode_ask: { description: diff --git a/packages/extension/opencode-plugin/traces.ts b/packages/extension/opencode-plugin/traces.ts new file mode 100644 index 00000000..29c38d4b --- /dev/null +++ b/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 = {}; + 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; + 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): Span | undefined { + const e = evt as { type?: string; properties?: { info?: Record } }; + 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(); + const seenMessages = new Set(); + 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, + ); + }, + }; +} diff --git a/packages/extension/test/traces.test.ts b/packages/extension/test/traces.test.ts new file mode 100644 index 00000000..06968774 --- /dev/null +++ b/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 => ({ + 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) => ({ type: "message.updated", properties: { info } }); + it("completed assistant message → model span with tokens/cache/duration, once", () => { + const seen = new Set(); + 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(); + 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(); + 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); + }); +});