From 1ead16f8e05f4b5a81083e751feec3b189a56f13 Mon Sep 17 00:00:00 2001 From: JoshRob297 <99092299+JoshRob297@users.noreply.github.com> Date: Mon, 19 Oct 2026 13:11:26 -0600 Subject: [PATCH] fix(telemetry): attribute retries to the failing model (v1.0.2) The retry hook in OpenCode v2.0.32 exposes the model as model.id / model.providerID. There is no modelID field, so the previous mapping logged undefined in all 175 entries recorded so far, making it impossible to tell which model was failing. - src/telemetry.ts: pure helpers to normalize the retry event (model, provider, agent, attempt, backoff delay, error type, status, message). - The retry log now records modelID, providerID, agent, attempt, retry and delayMs. - 6 new unit tests, including one built from the real event shape captured from a probe server that cuts the SSE stream mid-flight. - Troubleshooting docs (EN/ES): how to attribute resets per model, and how to tell an upstream timeout from a runtime retry loop using delayMs. --- CHANGELOG.md | 18 +++++++++ README.es.md | 2 +- README.md | 2 +- docs/TROUBLESHOOTING.md | 24 ++++++++++++ docs/es/troubleshooting.md | 24 ++++++++++++ package.json | 2 +- src/index.ts | 21 +++++++---- src/telemetry.ts | 75 ++++++++++++++++++++++++++++++++++++++ tests/telemetry.test.ts | 73 +++++++++++++++++++++++++++++++++++++ 9 files changed, 230 insertions(+), 11 deletions(-) create mode 100644 src/telemetry.ts create mode 100644 tests/telemetry.test.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index 2e2a3bb..43d25a4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,24 @@ Format: [Keep a Changelog](https://keepachangelog.com/en/1.1.0/) - SemVer. ## [Unreleased] +## [1.0.2] - 2026-10-19 + +### Fixed + +- Retry telemetry recorded the model as `undefined` in every single entry. The OpenCode v2 + `retry` hook exposes the model as `model.id` / `model.providerID`, and there is no + `modelID` field, so the previous mapping always produced `undefined`. Verified against + the real event shape captured from a probe server that cuts the stream mid-flight. +- The retry log now also records the agent, the attempt number and the backoff delay the + runtime chose, which makes it possible to tell an upstream timeout (large gap between + entries) from a runtime-side retry loop. + +### Added + +- `src/telemetry.ts` with pure helpers (`describeRetryEvent`, `extractModelId`, + `extractProviderId`) and 6 unit tests covering the real event shape. +- Troubleshooting section (English and Spanish) on attributing resets to a specific model. + ## [1.0.1] - 2026-10-19 ### Added diff --git a/README.es.md b/README.es.md index 082d023..f3cae27 100644 --- a/README.es.md +++ b/README.es.md @@ -203,7 +203,7 @@ Kill switch en runtime para la higiene de conexion: crea un archivo centinela ll | --- | --- | | `/commandcode-sanitizer.log` | Cada reparacion de payload en vuelo, con las correcciones aplicadas | | `/commandcode-watchdog.log` | Streams SSE abortados por inactividad | -| `/commandcode-retries.log` | Reintentos de transporte de Command Code (tipo, status, mensaje) | +| `/commandcode-retries.log` | Reintentos de transporte de Command Code: sesion, agente, proveedor, modelo, tipo de error, status HTTP, numero de intento, delay del backoff y mensaje | | `/commandcode-models-cache.json` | Ultimo catalogo de modelos bueno (TTL 12h) | `` por defecto es `~/.local/state/opencode`. diff --git a/README.md b/README.md index 12b665b..d297ddc 100644 --- a/README.md +++ b/README.md @@ -197,7 +197,7 @@ Runtime kill switch for connection hygiene: create a sentinel file named | --- | --- | | `/commandcode-sanitizer.log` | Every in-flight payload repair, with the fixes applied | | `/commandcode-watchdog.log` | Aborted stalled SSE streams | -| `/commandcode-retries.log` | Command Code transport retries (type, status, message) | +| `/commandcode-retries.log` | Command Code transport retries: session, agent, provider, model, error type, HTTP status, attempt number, backoff delay and message | | `/commandcode-models-cache.json` | Last known good model catalog (12h TTL) | `` defaults to `~/.local/state/opencode`. diff --git a/docs/TROUBLESHOOTING.md b/docs/TROUBLESHOOTING.md index 9cbead6..5064743 100644 --- a/docs/TROUBLESHOOTING.md +++ b/docs/TROUBLESHOOTING.md @@ -116,6 +116,30 @@ To measure the injection's effect, disable it and compare: export CC_NO_CONNECTION_CLOSE=1 # keep-alive reuse restored ``` +### Which model is failing? + +Since v1.0.2 the retry log records the model and the attempt, so resets can be attributed +to a specific model instead of a session-wide blob: + +```bash +# resets per model +grep -o '"modelID":"[^"]*"' /commandcode-retries.log | sort | uniq -c | sort -rn + +# the failing attempt and the backoff delay the runtime chose +grep '"modelID"' /commandcode-retries.log | tail -5 +``` + +| Field | Meaning | +| --- | --- | +| `modelID` / `providerID` | Model and provider of the failed request | +| `attempt` | Retry attempt number (1 is the original request) | +| `delayMs` | Backoff delay the runtime chose before the next attempt | +| `agent` | Agent that issued the request | + +Note that the runtime's own backoff is 2s to 10s. Gaps much larger than `delayMs` between +two log lines mean the failed request itself took that long before the connection broke: +that is an upstream timeout, not a stale keep-alive socket. + ## A turn hangs with a tool stuck in `streaming` The watchdog aborts a silent SSE stream after 60s: diff --git a/docs/es/troubleshooting.md b/docs/es/troubleshooting.md index 4f29a46..e4675b8 100644 --- a/docs/es/troubleshooting.md +++ b/docs/es/troubleshooting.md @@ -118,6 +118,30 @@ Para medir el efecto de la inyeccion, deshabilitala y compara: export CC_NO_CONNECTION_CLOSE=1 # se restaura la reutilizacion de keep-alive ``` +### Que modelo esta fallando? + +Desde la v1.0.2 el log de reintentos registra el modelo y el intento, asi que los resets se +pueden atribuir a un modelo concreto en lugar de a un bloque indistinto de sesion: + +```bash +# resets por modelo +grep -o '"modelID":"[^"]*"' /commandcode-retries.log | sort | uniq -c | sort -rn + +# el intento que fallo y el delay de backoff que eligio el runtime +grep '"modelID"' /commandcode-retries.log | tail -5 +``` + +| Campo | Significado | +| --- | --- | +| `modelID` / `providerID` | Modelo y proveedor del request fallido | +| `attempt` | Numero de intento (1 es el request original) | +| `delayMs` | Delay de backoff elegido por el runtime antes del siguiente intento | +| `agent` | Agente que emitio el request | + +Ojo: el backoff propio del runtime va de 2s a 10s. Huecos mucho mayores que `delayMs` entre +dos lineas del log significan que el request fallido tardo eso en romperse: es un timeout +upstream, no un socket keep-alive obsoleto. + ## Un turno se cuelga con una herramienta en `streaming` El watchdog aborta un stream SSE mudo despues de 60s: diff --git a/package.json b/package.json index c4d3b8f..9848207 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "opencode-commandcode", - "version": "1.0.1", + "version": "1.0.2", "description": "Production-grade OpenCode plugin for Command Code: dynamic model discovery, stability hooks and quota telemetry", "main": "index.ts", "type": "module", diff --git a/src/index.ts b/src/index.ts index 1b79447..50866b4 100644 --- a/src/index.ts +++ b/src/index.ts @@ -14,6 +14,7 @@ import { supportsVision, } from "./hooks/resilience.ts"; import { getQuotaReport } from "./tools/quota.ts"; +import { describeRetryEvent } from "./telemetry.ts"; export const PROVIDER_ID = "commandcode"; const WATCHDOG_TIMEOUT_MS = 60_000; @@ -200,15 +201,19 @@ export default { // Keep the log meaningful: only Command Code retries belong here. if (providerID && !providerID.includes(PROVIDER_ID)) return; - const e = event?.error || {}; + const telemetry = describeRetryEvent(event); await appendEvent(logPath("commandcode-retries.log"), { - at: new Date().toISOString(), - sessionID: event?.sessionID, - providerID: providerID || undefined, - modelID: event?.modelID ?? event?.model?.modelID, - type: e.type, - status: e.status, - message: typeof e.message === "string" ? e.message.slice(0, 400) : undefined, + at: telemetry.at, + sessionID: telemetry.sessionID, + agent: telemetry.agent, + providerID: telemetry.providerID || undefined, + modelID: telemetry.modelID, + type: telemetry.type, + status: telemetry.status, + attempt: telemetry.attempt, + retry: telemetry.retry, + delayMs: telemetry.delayMs, + message: telemetry.message, }); }); } catch { diff --git a/src/telemetry.ts b/src/telemetry.ts new file mode 100644 index 0000000..35c1de6 --- /dev/null +++ b/src/telemetry.ts @@ -0,0 +1,75 @@ +/** + * Telemetry helpers for Command Code. + * + * The OpenCode v2 `retry` hook delivers an event shaped like: + * + * { + * sessionID, agent, + * model: { id, providerID }, + * error: { type, message, status }, + * attempt: number, + * decision: { retry: boolean, delay: number } + * } + * + * Note that the model is exposed as `model.id` / `model.providerID`. There is no + * `modelID` field, so reading `event.modelID` yields undefined and every retry + * would be logged without attribution. + */ + +export interface RetryEventLike { + sessionID?: string; + agent?: string; + model?: { id?: string; providerID?: string; modelID?: string } | string; + modelID?: string; + providerID?: string; + error?: { type?: string; message?: string; status?: number }; + type?: string; + status?: number; + message?: string; + attempt?: number; + decision?: { retry?: boolean; delay?: number }; +} + +export interface RetryTelemetry { + at: string; + sessionID?: string; + agent?: string; + providerID?: string; + modelID?: string; + type?: string; + status?: number; + attempt?: number; + retry?: boolean; + delayMs?: number; + message?: string; +} + +/** Extracts the model id from any of the shapes OpenCode may deliver. */ +export function extractModelId(event: RetryEventLike): string | undefined { + if (typeof event?.model === "string") return event.model; + return event?.model?.id ?? event?.model?.modelID ?? event?.modelID; +} + +/** Extracts the provider id from any of the shapes OpenCode may deliver. */ +export function extractProviderId(event: RetryEventLike): string | undefined { + if (typeof event?.model === "string") return event?.providerID; + return event?.model?.providerID ?? event?.providerID; +} + +/** Normalizes a raw retry hook event into the telemetry line we persist. */ +export function describeRetryEvent(event: RetryEventLike, at: string = new Date().toISOString()): RetryTelemetry { + const message = event?.error?.message ?? event?.message; + return { + at, + sessionID: event?.sessionID, + agent: event?.agent, + providerID: extractProviderId(event), + modelID: extractModelId(event), + type: event?.error?.type ?? event?.type, + status: event?.error?.status ?? event?.status, + attempt: event?.attempt, + retry: event?.decision?.retry, + delayMs: event?.decision?.delay, + message: typeof message === "string" ? message.slice(0, 400) : undefined, + }; +} diff --git a/tests/telemetry.test.ts b/tests/telemetry.test.ts new file mode 100644 index 0000000..c32a864 --- /dev/null +++ b/tests/telemetry.test.ts @@ -0,0 +1,73 @@ +import { describe, expect, test } from "bun:test"; +import { describeRetryEvent, extractModelId, extractProviderId } from "../src/telemetry.ts"; + +// Forma real del evento `retry` capturada en OpenCode v2.0.32 con un servidor +// de prueba que corta el stream a mitad (verificacion de campo). +const REAL_EVENT = { + sessionID: "ses_eaa6f80fbffe0Tv4gX6eSqfnGl", + agent: "build", + model: { id: "probe-model", providerID: "probe" }, + error: { + type: "provider.transport", + message: + "Connection lost while reading the response: ECONNRESET: The socket connection was closed unexpectedly.", + status: 200, + }, + attempt: 2, + decision: { retry: true, delay: 2281 }, +}; + +describe("retry telemetry", () => { + test("extrae el modelo desde model.id (no existe modelID)", () => { + expect(extractModelId(REAL_EVENT as any)).toBe("probe-model"); + expect(extractProviderId(REAL_EVENT as any)).toBe("probe"); + }); + + test("no pierde la atribucion cuando el evento trae modelID", () => { + expect(extractModelId({ modelID: "legacy-model" } as any)).toBe("legacy-model"); + expect(extractModelId({ model: { modelID: "nested" } } as any)).toBe("nested"); + expect(extractModelId({ model: "plain-string" } as any)).toBe("plain-string"); + }); + + test("normaliza el evento real a la linea de telemetria", () => { + const t = describeRetryEvent(REAL_EVENT as any, "2026-10-19T19:08:20.424Z"); + expect(t.at).toBe("2026-10-19T19:08:20.424Z"); + expect(t.sessionID).toBe("ses_eaa6f80fbffe0Tv4gX6eSqfnGl"); + expect(t.agent).toBe("build"); + expect(t.providerID).toBe("probe"); + expect(t.modelID).toBe("probe-model"); + expect(t.type).toBe("provider.transport"); + expect(t.status).toBe(200); + expect(t.attempt).toBe(2); + expect(t.retry).toBe(true); + expect(t.delayMs).toBe(2281); + expect(t.message).toContain("ECONNRESET"); + }); + + test("trunca el mensaje a 400 caracteres", () => { + const long = { error: { type: "provider.transport", message: "x".repeat(900) } } as any; + const t = describeRetryEvent(long); + expect(t.message!.length).toBe(400); + }); + + test("tolera eventos incompletos sin lanzar", () => { + const t = describeRetryEvent({} as any); + expect(t.modelID).toBeUndefined(); + expect(t.type).toBeUndefined(); + expect(t.message).toBeUndefined(); + }); + + test("soporta el formato plano (sin objeto model)", () => { + const t = describeRetryEvent({ + sessionID: "s", + modelID: "m", + providerID: "p", + type: "provider.internal", + status: 503, + } as any); + expect(t.modelID).toBe("m"); + expect(t.providerID).toBe("p"); + expect(t.type).toBe("provider.internal"); + expect(t.status).toBe(503); + }); +});