Skip to content

Commit 0005814

Browse files
galinilievgaliniliev
committed
fix(diagnostics): surface delayed fetch timeout events
1 parent f237c05 commit 0005814

8 files changed

Lines changed: 246 additions & 3 deletions

File tree

‎extensions/diagnostics-otel/src/service.test.ts‎

Lines changed: 59 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -655,6 +655,65 @@ describe("diagnostics-otel service", () => {
655655
await service.stop?.(ctx);
656656
});
657657

658+
test("records delayed fetch timeout diagnostics", async () => {
659+
const service = createDiagnosticsOtelService();
660+
const ctx = createOtelContext(OTEL_TEST_ENDPOINT, { traces: true, metrics: true });
661+
662+
await service.start(ctx);
663+
emitDiagnosticEvent({
664+
type: "fetch.timeout.delayed",
665+
timeoutMs: 10_000,
666+
elapsedMs: 17_175,
667+
timerDelayMs: 7_175,
668+
eventLoopDelayHint: "timer delayed 7175ms, likely event-loop starvation",
669+
operation: "matrix.guarded-redirect-fetch",
670+
url: "https://api.telegram.org/bot[REDACTED]/getMe",
671+
});
672+
await flushDiagnosticEvents();
673+
674+
expect(telemetryState.counters.get("openclaw.fetch.timeout.delayed")?.add).toHaveBeenCalledWith(
675+
1,
676+
{
677+
"openclaw.operation": "matrix.guarded-redirect-fetch",
678+
},
679+
);
680+
expect(
681+
telemetryState.histograms.get("openclaw.fetch.timeout.configured_ms")?.record,
682+
).toHaveBeenCalledWith(10_000, {
683+
"openclaw.operation": "matrix.guarded-redirect-fetch",
684+
});
685+
expect(
686+
telemetryState.histograms.get("openclaw.fetch.timeout.elapsed_ms")?.record,
687+
).toHaveBeenCalledWith(17_175, {
688+
"openclaw.operation": "matrix.guarded-redirect-fetch",
689+
});
690+
expect(
691+
telemetryState.histograms.get("openclaw.fetch.timeout.timer_delay_ms")?.record,
692+
).toHaveBeenCalledWith(7_175, {
693+
"openclaw.operation": "matrix.guarded-redirect-fetch",
694+
});
695+
const fetchTimeoutSpanOptions = startedSpanOptions("openclaw.fetch.timeout.delayed");
696+
expect(fetchTimeoutSpanOptions?.attributes?.["openclaw.operation"]).toBe(
697+
"matrix.guarded-redirect-fetch",
698+
);
699+
expect(fetchTimeoutSpanOptions?.attributes?.["openclaw.fetch.timeout_ms"]).toBe(10_000);
700+
expect(fetchTimeoutSpanOptions?.attributes?.["openclaw.fetch.elapsed_ms"]).toBe(17_175);
701+
expect(fetchTimeoutSpanOptions?.attributes?.["openclaw.fetch.timer_delay_ms"]).toBe(7_175);
702+
expect(fetchTimeoutSpanOptions?.attributes).not.toHaveProperty("openclaw.fetch.url");
703+
expect(fetchTimeoutSpanOptions?.attributes).not.toHaveProperty(
704+
"openclaw.fetch.event_loop_delay_hint",
705+
);
706+
const span = telemetryState.spans.find(
707+
(item) => item.name === "openclaw.fetch.timeout.delayed",
708+
);
709+
expect(span?.setStatus).toHaveBeenCalledWith({
710+
code: 2,
711+
message: "fetch timeout delayed",
712+
});
713+
714+
await service.stop?.(ctx);
715+
});
716+
658717
test("reports log exporter emit failures without exporting raw error text", async () => {
659718
const events: Array<Parameters<Parameters<typeof onInternalDiagnosticEvent>[0]>[0]> = [];
660719
const unsubscribe = onInternalDiagnosticEvent((event) => {

‎extensions/diagnostics-otel/src/service.ts‎

Lines changed: 59 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -92,6 +92,10 @@ type TelemetryExporterDiagnosticEvent = Extract<
9292
DiagnosticEventPayload,
9393
{ type: "telemetry.exporter" }
9494
>;
95+
type FetchTimeoutDelayedDiagnosticEvent = Extract<
96+
DiagnosticEventPayload,
97+
{ type: "fetch.timeout.delayed" }
98+
>;
9599
type SessionRecoveryDiagnosticEvent = Extract<
96100
DiagnosticEventPayload,
97101
{ type: "session.recovery.requested" | "session.recovery.completed" }
@@ -961,6 +965,31 @@ export function createDiagnosticsOtelService(): OpenClawPluginService {
961965
description: "CPU core ratio reported by diagnostic liveness warnings",
962966
},
963967
);
968+
const fetchTimeoutDelayedCounter = meter.createCounter("openclaw.fetch.timeout.delayed", {
969+
unit: "1",
970+
description: "Fetch timeout timers that fired late enough to indicate event-loop delay",
971+
});
972+
const fetchTimeoutConfiguredMsHistogram = meter.createHistogram(
973+
"openclaw.fetch.timeout.configured_ms",
974+
{
975+
unit: "ms",
976+
description: "Configured fetch timeout for delayed timeout diagnostics",
977+
},
978+
);
979+
const fetchTimeoutElapsedMsHistogram = meter.createHistogram(
980+
"openclaw.fetch.timeout.elapsed_ms",
981+
{
982+
unit: "ms",
983+
description: "Elapsed time before delayed fetch timeout aborts",
984+
},
985+
);
986+
const fetchTimeoutTimerDelayMsHistogram = meter.createHistogram(
987+
"openclaw.fetch.timeout.timer_delay_ms",
988+
{
989+
unit: "ms",
990+
description: "Timer delay reported by delayed fetch timeout diagnostics",
991+
},
992+
);
964993
const telemetryExporterCounter = meter.createCounter("openclaw.telemetry.exporter.events", {
965994
unit: "1",
966995
description: "Diagnostic telemetry exporter lifecycle and failure events",
@@ -2309,6 +2338,33 @@ export function createDiagnosticsOtelService(): OpenClawPluginService {
23092338
span.end(evt.ts);
23102339
};
23112340

2341+
const recordFetchTimeoutDelayed = (evt: FetchTimeoutDelayedDiagnosticEvent) => {
2342+
const attrs = {
2343+
"openclaw.operation": lowCardinalityAttr(evt.operation, "unknown"),
2344+
};
2345+
fetchTimeoutDelayedCounter.add(1, attrs);
2346+
fetchTimeoutConfiguredMsHistogram.record(evt.timeoutMs, attrs);
2347+
fetchTimeoutElapsedMsHistogram.record(evt.elapsedMs, attrs);
2348+
fetchTimeoutTimerDelayMsHistogram.record(evt.timerDelayMs, attrs);
2349+
if (!tracesEnabled) {
2350+
return;
2351+
}
2352+
const spanAttrs: Record<string, string | number> = {
2353+
...attrs,
2354+
"openclaw.fetch.timeout_ms": evt.timeoutMs,
2355+
"openclaw.fetch.elapsed_ms": evt.elapsedMs,
2356+
"openclaw.fetch.timer_delay_ms": evt.timerDelayMs,
2357+
};
2358+
const span = spanWithDuration("openclaw.fetch.timeout.delayed", spanAttrs, 0, {
2359+
endTimeMs: evt.ts,
2360+
});
2361+
span.setStatus({
2362+
code: SpanStatusCode.ERROR,
2363+
message: "fetch timeout delayed",
2364+
});
2365+
span.end(evt.ts);
2366+
};
2367+
23122368
const recordTelemetryExporter = (
23132369
evt: TelemetryExporterDiagnosticEvent,
23142370
metadata: DiagnosticEventMetadata,
@@ -2398,6 +2454,9 @@ export function createDiagnosticsOtelService(): OpenClawPluginService {
23982454
case "diagnostic.liveness.warning":
23992455
recordLivenessWarning(evt);
24002456
return;
2457+
case "fetch.timeout.delayed":
2458+
recordFetchTimeoutDelayed(evt);
2459+
return;
24012460
case "diagnostic.phase.completed":
24022461
recordDiagnosticPhaseCompleted(evt);
24032462
return;

‎src/cli/gateway-cli.coverage.test.ts‎

Lines changed: 14 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -271,10 +271,10 @@ describe("gateway-cli coverage", () => {
271271
snapshot: {
272272
generatedAt: "2026-04-22T12:00:00.000Z",
273273
capacity: 1000,
274-
count: 1,
274+
count: 2,
275275
dropped: 0,
276276
firstSeq: 1,
277-
lastSeq: 1,
277+
lastSeq: 2,
278278
events: [
279279
{
280280
seq: 1,
@@ -285,9 +285,18 @@ describe("gateway-cli coverage", () => {
285285
bytes: 2048,
286286
limitBytes: 1024,
287287
},
288+
{
289+
seq: 2,
290+
ts: Date.parse("2026-04-22T12:00:01.000Z"),
291+
type: "fetch.timeout.delayed",
292+
timeoutMs: 10_000,
293+
elapsedMs: 17_175,
294+
timerDelayMs: 7_175,
295+
operation: "matrix.guarded-redirect-fetch",
296+
},
288297
],
289298
summary: {
290-
byType: { "payload.large": 1 },
299+
byType: { "payload.large": 1, "fetch.timeout.delayed": 1 },
291300
payloadLarge: {
292301
count: 1,
293302
rejected: 1,
@@ -315,6 +324,8 @@ describe("gateway-cli coverage", () => {
315324
expect(output).toContain("agents/<agent>/sessions/<session>.jsonl");
316325
expect(output).toContain("payload.large");
317326
expect(output).toContain("gateway.http.json");
327+
expect(output).toContain("fetch.timeout.delayed");
328+
expect(output).toContain("timerDelayMs=7175");
318329
} finally {
319330
fs.rmSync(tempDir, { recursive: true, force: true });
320331
}

‎src/cli/gateway-cli/register.ts‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -208,6 +208,10 @@ function formatStabilityEvent(record: DiagnosticStabilityEventRecord): string {
208208
record.channel ? `channel=${record.channel}` : "",
209209
record.pluginId ? `plugin=${record.pluginId}` : "",
210210
record.reason ? `reason=${record.reason}` : "",
211+
record.operation ? `operation=${record.operation}` : "",
212+
record.timeoutMs !== undefined ? `timeoutMs=${record.timeoutMs}` : "",
213+
record.elapsedMs !== undefined ? `elapsedMs=${record.elapsedMs}` : "",
214+
record.timerDelayMs !== undefined ? `timerDelayMs=${record.timerDelayMs}` : "",
211215
record.bytes !== undefined ? `bytes=${formatBytes(record.bytes)}` : "",
212216
record.limitBytes !== undefined ? `limit=${formatBytes(record.limitBytes)}` : "",
213217
record.queueDepth !== undefined ? `queueDepth=${record.queueDepth}` : "",

‎src/logging/diagnostic-stability-bundle.test.ts‎

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -333,6 +333,45 @@ describe("diagnostic stability bundles", () => {
333333
}
334334
});
335335

336+
it("preserves delayed fetch timeout fields when reading bundles", () => {
337+
const file = path.join(tempDir, "bundle.json");
338+
const bundle = createImportedBundle();
339+
const snapshot = bundle.snapshot as Record<string, unknown>;
340+
Object.assign(snapshot, {
341+
events: [
342+
{
343+
seq: 1,
344+
ts: 1,
345+
type: "fetch.timeout.delayed",
346+
timeoutMs: 10_000,
347+
elapsedMs: 17_175,
348+
timerDelayMs: 7_175,
349+
operation: "matrix.guarded-redirect-fetch",
350+
eventLoopDelayHint: "timer delayed 7175ms, likely event-loop starvation",
351+
url: "https://api.telegram.org/bot-secret/getMe",
352+
},
353+
],
354+
summary: { byType: { "fetch.timeout.delayed": 1 } },
355+
});
356+
fs.writeFileSync(file, `${JSON.stringify(bundle, null, 2)}\n`, "utf8");
357+
358+
const result = readDiagnosticStabilityBundleFileSync(file);
359+
360+
expect(result.status).toBe("found");
361+
if (result.status !== "found") {
362+
return;
363+
}
364+
expect(result.bundle.snapshot.events[0]).toEqual({
365+
seq: 1,
366+
ts: 1,
367+
type: "fetch.timeout.delayed",
368+
timeoutMs: 10_000,
369+
elapsedMs: 17_175,
370+
timerDelayMs: 7_175,
371+
operation: "matrix.guarded-redirect-fetch",
372+
});
373+
});
374+
336375
it("rejects malformed bundle files", () => {
337376
const file = path.join(tempDir, "invalid.json");
338377
fs.writeFileSync(file, "{}\n", "utf8");

‎src/logging/diagnostic-stability-bundle.ts‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -710,6 +710,7 @@ function readStabilityEventRecord(
710710
);
711711
assignOptionalCodeString(sanitized, "provider", record.provider, `${label}.provider`);
712712
assignOptionalCodeString(sanitized, "model", record.model, `${label}.model`);
713+
assignOptionalCodeString(sanitized, "operation", record.operation, `${label}.operation`);
713714

714715
assignOptionalNumber(sanitized, "durationMs", record.durationMs, `${label}.durationMs`);
715716
assignOptionalNumber(sanitized, "requestBytes", record.requestBytes, `${label}.requestBytes`);
@@ -720,6 +721,9 @@ function readStabilityEventRecord(
720721
record.timeToFirstByteMs,
721722
`${label}.timeToFirstByteMs`,
722723
);
724+
assignOptionalNumber(sanitized, "timeoutMs", record.timeoutMs, `${label}.timeoutMs`);
725+
assignOptionalNumber(sanitized, "elapsedMs", record.elapsedMs, `${label}.elapsedMs`);
726+
assignOptionalNumber(sanitized, "timerDelayMs", record.timerDelayMs, `${label}.timerDelayMs`);
723727
assignOptionalNumber(sanitized, "costUsd", record.costUsd, `${label}.costUsd`);
724728
assignOptionalNumber(sanitized, "count", record.count, `${label}.count`);
725729
assignOptionalNumber(sanitized, "bytes", record.bytes, `${label}.bytes`);

‎src/logging/diagnostic-stability.test.ts‎

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -176,6 +176,58 @@ describe("diagnostic stability recorder", () => {
176176
expect(snapshot.events[0]).not.toHaveProperty("systemPromptChars");
177177
});
178178

179+
it("projects delayed fetch timeout diagnostics with sanitized context", () => {
180+
startDiagnosticStabilityRecorder();
181+
182+
emitDiagnosticEvent({
183+
type: "fetch.timeout.delayed",
184+
timeoutMs: 10_000,
185+
elapsedMs: 17_175,
186+
timerDelayMs: 7_175,
187+
eventLoopDelayHint: "timer delayed 7175ms, likely event-loop starvation",
188+
operation: "matrix.guarded-redirect-fetch",
189+
url: "https://api.telegram.org/bot[REDACTED]/getMe",
190+
});
191+
192+
const snapshot = getDiagnosticStabilitySnapshot({ limit: 10 });
193+
194+
expectFields(snapshot.summary.byType, {
195+
"fetch.timeout.delayed": 1,
196+
});
197+
expectFields(snapshot.events[0], {
198+
type: "fetch.timeout.delayed",
199+
timeoutMs: 10_000,
200+
elapsedMs: 17_175,
201+
timerDelayMs: 7_175,
202+
operation: "matrix.guarded-redirect-fetch",
203+
});
204+
expect(snapshot.events[0]).not.toHaveProperty("eventLoopDelayHint");
205+
expect(snapshot.events[0]).not.toHaveProperty("url");
206+
});
207+
208+
it("drops unsafe delayed fetch timeout operation labels", () => {
209+
startDiagnosticStabilityRecorder();
210+
211+
emitDiagnosticEvent({
212+
type: "fetch.timeout.delayed",
213+
timeoutMs: 10_000,
214+
elapsedMs: 17_175,
215+
timerDelayMs: 7_175,
216+
eventLoopDelayHint: "timer delayed 7175ms, likely event-loop starvation",
217+
operation: "fetch token=secret",
218+
});
219+
220+
const snapshot = getDiagnosticStabilitySnapshot({ limit: 10 });
221+
222+
expectFields(snapshot.events[0], {
223+
type: "fetch.timeout.delayed",
224+
timeoutMs: 10_000,
225+
elapsedMs: 17_175,
226+
timerDelayMs: 7_175,
227+
});
228+
expect(snapshot.events[0]).not.toHaveProperty("operation");
229+
});
230+
179231
it("sanitizes tool and model diagnostic error categories", async () => {
180232
startDiagnosticStabilityRecorder();
181233

‎src/logging/diagnostic-stability.ts‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -36,10 +36,14 @@ export type DiagnosticStabilityEventRecord = {
3636
pairedToolName?: string;
3737
provider?: string;
3838
model?: string;
39+
operation?: string;
3940
durationMs?: number;
4041
requestBytes?: number;
4142
responseBytes?: number;
4243
timeToFirstByteMs?: number;
44+
timeoutMs?: number;
45+
elapsedMs?: number;
46+
timerDelayMs?: number;
4347
resultCount?: number;
4448
commandLength?: number;
4549
exitCode?: number;
@@ -345,6 +349,17 @@ function sanitizeDiagnosticEvent(event: DiagnosticEventPayload): DiagnosticStabi
345349
record.source = event.queuedWorkLabels[0];
346350
}
347351
break;
352+
case "fetch.timeout.delayed":
353+
record.timeoutMs = event.timeoutMs;
354+
record.elapsedMs = event.elapsedMs;
355+
record.timerDelayMs = event.timerDelayMs;
356+
{
357+
const operation = copyReasonCode(event.operation);
358+
if (operation) {
359+
record.operation = operation;
360+
}
361+
}
362+
break;
348363
case "diagnostic.phase.completed":
349364
record.phase = event.name;
350365
record.durationMs = event.durationMs;

0 commit comments

Comments
 (0)