fix(telemetry): atribuir los reintentos al modelo que falla (v1.0.2)

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

README.es.md

@@ -203,7 +203,7 @@ Kill switch en runtime para la higiene de conexion: crea un archivo centinela ll
 | --- | --- |
 | `<state>/commandcode-sanitizer.log` | Cada reparacion de payload en vuelo, con las correcciones aplicadas |
 | `<state>/commandcode-watchdog.log` | Streams SSE abortados por inactividad |
-| `<state>/commandcode-retries.log` | Reintentos de transporte de Command Code (tipo, status, mensaje) |
+| `<state>/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 |
 | `<state>/commandcode-models-cache.json` | Ultimo catalogo de modelos bueno (TTL 12h) |
 
 `<state>` por defecto es `~/.local/state/opencode`.

README.md

@@ -197,7 +197,7 @@ Runtime kill switch for connection hygiene: create a sentinel file named
 | --- | --- |
 | `<state>/commandcode-sanitizer.log` | Every in-flight payload repair, with the fixes applied |
 | `<state>/commandcode-watchdog.log` | Aborted stalled SSE streams |
-| `<state>/commandcode-retries.log` | Command Code transport retries (type, status, message) |
+| `<state>/commandcode-retries.log` | Command Code transport retries: session, agent, provider, model, error type, HTTP status, attempt number, backoff delay and message |
 | `<state>/commandcode-models-cache.json` | Last known good model catalog (12h TTL) |
 
 `<state>` defaults to `~/.local/state/opencode`.

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":"[^"]*"' <state>/commandcode-retries.log | sort | uniq -c | sort -rn
+
+# the failing attempt and the backoff delay the runtime chose
+grep '"modelID"' <state>/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:

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":"[^"]*"' <state>/commandcode-retries.log | sort | uniq -c | sort -rn
+
+# el intento que fallo y el delay de backoff que eligio el runtime
+grep '"modelID"' <state>/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:

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",

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 {

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,
+  };
+}

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);
+  });
+});