Skip to content

Commit 834622a

Browse files
authored
fix(telemetry): attribute retries to the failing model (v1.0.2) (#3)
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.
1 parent 4ffe3d3 commit 834622a

9 files changed

Lines changed: 230 additions & 11 deletions

File tree

‎CHANGELOG.md‎

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,24 @@ Format: [Keep a Changelog](https://keepachangelog.com/en/1.1.0/) - SemVer.
55

66
## [Unreleased]
77

8+
## [1.0.2] - 2026-10-19
9+
10+
### Fixed
11+
12+
- Retry telemetry recorded the model as `undefined` in every single entry. The OpenCode v2
13+
`retry` hook exposes the model as `model.id` / `model.providerID`, and there is no
14+
`modelID` field, so the previous mapping always produced `undefined`. Verified against
15+
the real event shape captured from a probe server that cuts the stream mid-flight.
16+
- The retry log now also records the agent, the attempt number and the backoff delay the
17+
runtime chose, which makes it possible to tell an upstream timeout (large gap between
18+
entries) from a runtime-side retry loop.
19+
20+
### Added
21+
22+
- `src/telemetry.ts` with pure helpers (`describeRetryEvent`, `extractModelId`,
23+
`extractProviderId`) and 6 unit tests covering the real event shape.
24+
- Troubleshooting section (English and Spanish) on attributing resets to a specific model.
25+
826
## [1.0.1] - 2026-10-19
927

1028
### Added

‎README.es.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -203,7 +203,7 @@ Kill switch en runtime para la higiene de conexion: crea un archivo centinela ll
203203
| --- | --- |
204204
| `<state>/commandcode-sanitizer.log` | Cada reparacion de payload en vuelo, con las correcciones aplicadas |
205205
| `<state>/commandcode-watchdog.log` | Streams SSE abortados por inactividad |
206-
| `<state>/commandcode-retries.log` | Reintentos de transporte de Command Code (tipo, status, mensaje) |
206+
| `<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 |
207207
| `<state>/commandcode-models-cache.json` | Ultimo catalogo de modelos bueno (TTL 12h) |
208208

209209
`<state>` por defecto es `~/.local/state/opencode`.

‎README.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -197,7 +197,7 @@ Runtime kill switch for connection hygiene: create a sentinel file named
197197
| --- | --- |
198198
| `<state>/commandcode-sanitizer.log` | Every in-flight payload repair, with the fixes applied |
199199
| `<state>/commandcode-watchdog.log` | Aborted stalled SSE streams |
200-
| `<state>/commandcode-retries.log` | Command Code transport retries (type, status, message) |
200+
| `<state>/commandcode-retries.log` | Command Code transport retries: session, agent, provider, model, error type, HTTP status, attempt number, backoff delay and message |
201201
| `<state>/commandcode-models-cache.json` | Last known good model catalog (12h TTL) |
202202

203203
`<state>` defaults to `~/.local/state/opencode`.

‎docs/TROUBLESHOOTING.md‎

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -116,6 +116,30 @@ To measure the injection's effect, disable it and compare:
116116
export CC_NO_CONNECTION_CLOSE=1 # keep-alive reuse restored
117117
```
118118

119+
### Which model is failing?
120+
121+
Since v1.0.2 the retry log records the model and the attempt, so resets can be attributed
122+
to a specific model instead of a session-wide blob:
123+
124+
```bash
125+
# resets per model
126+
grep -o '"modelID":"[^"]*"' <state>/commandcode-retries.log | sort | uniq -c | sort -rn
127+
128+
# the failing attempt and the backoff delay the runtime chose
129+
grep '"modelID"' <state>/commandcode-retries.log | tail -5
130+
```
131+
132+
| Field | Meaning |
133+
| --- | --- |
134+
| `modelID` / `providerID` | Model and provider of the failed request |
135+
| `attempt` | Retry attempt number (1 is the original request) |
136+
| `delayMs` | Backoff delay the runtime chose before the next attempt |
137+
| `agent` | Agent that issued the request |
138+
139+
Note that the runtime's own backoff is 2s to 10s. Gaps much larger than `delayMs` between
140+
two log lines mean the failed request itself took that long before the connection broke:
141+
that is an upstream timeout, not a stale keep-alive socket.
142+
119143
## A turn hangs with a tool stuck in `streaming`
120144

121145
The watchdog aborts a silent SSE stream after 60s:

‎docs/es/troubleshooting.md‎

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -118,6 +118,30 @@ Para medir el efecto de la inyeccion, deshabilitala y compara:
118118
export CC_NO_CONNECTION_CLOSE=1 # se restaura la reutilizacion de keep-alive
119119
```
120120

121+
### Que modelo esta fallando?
122+
123+
Desde la v1.0.2 el log de reintentos registra el modelo y el intento, asi que los resets se
124+
pueden atribuir a un modelo concreto en lugar de a un bloque indistinto de sesion:
125+
126+
```bash
127+
# resets por modelo
128+
grep -o '"modelID":"[^"]*"' <state>/commandcode-retries.log | sort | uniq -c | sort -rn
129+
130+
# el intento que fallo y el delay de backoff que eligio el runtime
131+
grep '"modelID"' <state>/commandcode-retries.log | tail -5
132+
```
133+
134+
| Campo | Significado |
135+
| --- | --- |
136+
| `modelID` / `providerID` | Modelo y proveedor del request fallido |
137+
| `attempt` | Numero de intento (1 es el request original) |
138+
| `delayMs` | Delay de backoff elegido por el runtime antes del siguiente intento |
139+
| `agent` | Agente que emitio el request |
140+
141+
Ojo: el backoff propio del runtime va de 2s a 10s. Huecos mucho mayores que `delayMs` entre
142+
dos lineas del log significan que el request fallido tardo eso en romperse: es un timeout
143+
upstream, no un socket keep-alive obsoleto.
144+
121145
## Un turno se cuelga con una herramienta en `streaming`
122146

123147
El watchdog aborta un stream SSE mudo despues de 60s:

‎package.json‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,6 @@
11
{
22
"name": "opencode-commandcode",
3-
"version": "1.0.1",
3+
"version": "1.0.2",
44
"description": "Production-grade OpenCode plugin for Command Code: dynamic model discovery, stability hooks and quota telemetry",
55
"main": "index.ts",
66
"type": "module",

‎src/index.ts‎

Lines changed: 13 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ import {
1414
supportsVision,
1515
} from "./hooks/resilience.ts";
1616
import { getQuotaReport } from "./tools/quota.ts";
17+
import { describeRetryEvent } from "./telemetry.ts";
1718

1819
export const PROVIDER_ID = "commandcode";
1920
const WATCHDOG_TIMEOUT_MS = 60_000;
@@ -200,15 +201,19 @@ export default {
200201
// Keep the log meaningful: only Command Code retries belong here.
201202
if (providerID && !providerID.includes(PROVIDER_ID)) return;
202203

203-
const e = event?.error || {};
204+
const telemetry = describeRetryEvent(event);
204205
await appendEvent(logPath("commandcode-retries.log"), {
205-
at: new Date().toISOString(),
206-
sessionID: event?.sessionID,
207-
providerID: providerID || undefined,
208-
modelID: event?.modelID ?? event?.model?.modelID,
209-
type: e.type,
210-
status: e.status,
211-
message: typeof e.message === "string" ? e.message.slice(0, 400) : undefined,
206+
at: telemetry.at,
207+
sessionID: telemetry.sessionID,
208+
agent: telemetry.agent,
209+
providerID: telemetry.providerID || undefined,
210+
modelID: telemetry.modelID,
211+
type: telemetry.type,
212+
status: telemetry.status,
213+
attempt: telemetry.attempt,
214+
retry: telemetry.retry,
215+
delayMs: telemetry.delayMs,
216+
message: telemetry.message,
212217
});
213218
});
214219
} catch {

‎src/telemetry.ts‎

Lines changed: 75 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,75 @@
1+
/**
2+
* Telemetry helpers for Command Code.
3+
*
4+
* The OpenCode v2 `retry` hook delivers an event shaped like:
5+
*
6+
* {
7+
* sessionID, agent,
8+
* model: { id, providerID },
9+
* error: { type, message, status },
10+
* attempt: number,
11+
* decision: { retry: boolean, delay: number }
12+
* }
13+
*
14+
* Note that the model is exposed as `model.id` / `model.providerID`. There is no
15+
* `modelID` field, so reading `event.modelID` yields undefined and every retry
16+
* would be logged without attribution.
17+
*/
18+
19+
export interface RetryEventLike {
20+
sessionID?: string;
21+
agent?: string;
22+
model?: { id?: string; providerID?: string; modelID?: string } | string;
23+
modelID?: string;
24+
providerID?: string;
25+
error?: { type?: string; message?: string; status?: number };
26+
type?: string;
27+
status?: number;
28+
message?: string;
29+
attempt?: number;
30+
decision?: { retry?: boolean; delay?: number };
31+
}
32+
33+
export interface RetryTelemetry {
34+
at: string;
35+
sessionID?: string;
36+
agent?: string;
37+
providerID?: string;
38+
modelID?: string;
39+
type?: string;
40+
status?: number;
41+
attempt?: number;
42+
retry?: boolean;
43+
delayMs?: number;
44+
message?: string;
45+
}
46+
47+
/** Extracts the model id from any of the shapes OpenCode may deliver. */
48+
export function extractModelId(event: RetryEventLike): string | undefined {
49+
if (typeof event?.model === "string") return event.model;
50+
return event?.model?.id ?? event?.model?.modelID ?? event?.modelID;
51+
}
52+
53+
/** Extracts the provider id from any of the shapes OpenCode may deliver. */
54+
export function extractProviderId(event: RetryEventLike): string | undefined {
55+
if (typeof event?.model === "string") return event?.providerID;
56+
return event?.model?.providerID ?? event?.providerID;
57+
}
58+
59+
/** Normalizes a raw retry hook event into the telemetry line we persist. */
60+
export function describeRetryEvent(event: RetryEventLike, at: string = new Date().toISOString()): RetryTelemetry {
61+
const message = event?.error?.message ?? event?.message;
62+
return {
63+
at,
64+
sessionID: event?.sessionID,
65+
agent: event?.agent,
66+
providerID: extractProviderId(event),
67+
modelID: extractModelId(event),
68+
type: event?.error?.type ?? event?.type,
69+
status: event?.error?.status ?? event?.status,
70+
attempt: event?.attempt,
71+
retry: event?.decision?.retry,
72+
delayMs: event?.decision?.delay,
73+
message: typeof message === "string" ? message.slice(0, 400) : undefined,
74+
};
75+
}

‎tests/telemetry.test.ts‎

Lines changed: 73 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,73 @@
1+
import { describe, expect, test } from "bun:test";
2+
import { describeRetryEvent, extractModelId, extractProviderId } from "../src/telemetry.ts";
3+
4+
// Forma real del evento `retry` capturada en OpenCode v2.0.32 con un servidor
5+
// de prueba que corta el stream a mitad (verificacion de campo).
6+
const REAL_EVENT = {
7+
sessionID: "ses_eaa6f80fbffe0Tv4gX6eSqfnGl",
8+
agent: "build",
9+
model: { id: "probe-model", providerID: "probe" },
10+
error: {
11+
type: "provider.transport",
12+
message:
13+
"Connection lost while reading the response: ECONNRESET: The socket connection was closed unexpectedly.",
14+
status: 200,
15+
},
16+
attempt: 2,
17+
decision: { retry: true, delay: 2281 },
18+
};
19+
20+
describe("retry telemetry", () => {
21+
test("extrae el modelo desde model.id (no existe modelID)", () => {
22+
expect(extractModelId(REAL_EVENT as any)).toBe("probe-model");
23+
expect(extractProviderId(REAL_EVENT as any)).toBe("probe");
24+
});
25+
26+
test("no pierde la atribucion cuando el evento trae modelID", () => {
27+
expect(extractModelId({ modelID: "legacy-model" } as any)).toBe("legacy-model");
28+
expect(extractModelId({ model: { modelID: "nested" } } as any)).toBe("nested");
29+
expect(extractModelId({ model: "plain-string" } as any)).toBe("plain-string");
30+
});
31+
32+
test("normaliza el evento real a la linea de telemetria", () => {
33+
const t = describeRetryEvent(REAL_EVENT as any, "2026-10-19T19:08:20.424Z");
34+
expect(t.at).toBe("2026-10-19T19:08:20.424Z");
35+
expect(t.sessionID).toBe("ses_eaa6f80fbffe0Tv4gX6eSqfnGl");
36+
expect(t.agent).toBe("build");
37+
expect(t.providerID).toBe("probe");
38+
expect(t.modelID).toBe("probe-model");
39+
expect(t.type).toBe("provider.transport");
40+
expect(t.status).toBe(200);
41+
expect(t.attempt).toBe(2);
42+
expect(t.retry).toBe(true);
43+
expect(t.delayMs).toBe(2281);
44+
expect(t.message).toContain("ECONNRESET");
45+
});
46+
47+
test("trunca el mensaje a 400 caracteres", () => {
48+
const long = { error: { type: "provider.transport", message: "x".repeat(900) } } as any;
49+
const t = describeRetryEvent(long);
50+
expect(t.message!.length).toBe(400);
51+
});
52+
53+
test("tolera eventos incompletos sin lanzar", () => {
54+
const t = describeRetryEvent({} as any);
55+
expect(t.modelID).toBeUndefined();
56+
expect(t.type).toBeUndefined();
57+
expect(t.message).toBeUndefined();
58+
});
59+
60+
test("soporta el formato plano (sin objeto model)", () => {
61+
const t = describeRetryEvent({
62+
sessionID: "s",
63+
modelID: "m",
64+
providerID: "p",
65+
type: "provider.internal",
66+
status: 503,
67+
} as any);
68+
expect(t.modelID).toBe("m");
69+
expect(t.providerID).toBe("p");
70+
expect(t.type).toBe("provider.internal");
71+
expect(t.status).toBe(503);
72+
});
73+
});

0 commit comments

Comments
 (0)