fix(diagnostics): bound recent phase attribution (#119625)

This commit is contained in:
Jason (Json)
2026-08-05 10:14:33 -06:00
committed by GitHub
parent 36dbbd72ed
commit 40b0b3da39
4 changed files with 105 additions and 5 deletions
+40 -1
View File
@@ -1,6 +1,7 @@
// Diagnostic phase tests cover phase timing and diagnostic event emission.
import { describe, expect, it } from "vitest";
import { describe, expect, it, vi } from "vitest";
import {
getCurrentDiagnosticPhase,
getRecentDiagnosticPhases,
resetDiagnosticPhasesForTest,
withDiagnosticPhase,
@@ -27,4 +28,42 @@ describe("getRecentDiagnosticPhases", () => {
expect(recent).toHaveLength(1);
expect(recent[0]?.name).toBe("phase-b");
});
it("filters completed phases by attribution time without discarding retained history", async () => {
resetDiagnosticPhasesForTest();
const nowSpy = vi.spyOn(Date, "now").mockReturnValue(1_000);
try {
await withDiagnosticPhase("phase-a", () => undefined);
expect(getRecentDiagnosticPhases(1, { completedAfter: 1_001 })).toEqual([]);
expect(getRecentDiagnosticPhases(1)).toEqual([
expect.objectContaining({ name: "phase-a", endedAt: 1_000 }),
]);
} finally {
nowSpy.mockRestore();
}
});
it("does not apply completed-phase recency filtering to active phases", async () => {
resetDiagnosticPhasesForTest();
let releasePhase: (() => void) | undefined;
const phase = withDiagnosticPhase(
"legitimate.long-running-work",
() =>
new Promise<void>((resolve) => {
releasePhase = resolve;
}),
);
if (!releasePhase) {
throw new Error("Expected diagnostic phase release callback to be initialized");
}
try {
expect(getRecentDiagnosticPhases(1, { completedAfter: Date.now() })).toEqual([]);
expect(getCurrentDiagnosticPhase()).toBe("legitimate.long-running-work");
} finally {
releasePhase();
await phase;
}
});
});
+12 -2
View File
@@ -47,12 +47,22 @@ function resolveRecentPhaseLimit(limit: number): number | null {
return Math.floor(limit);
}
export function getRecentDiagnosticPhases(limit = 8): DiagnosticPhaseSnapshot[] {
export function getRecentDiagnosticPhases(
limit = 8,
options?: { completedAfter?: number },
): DiagnosticPhaseSnapshot[] {
const resolved = resolveRecentPhaseLimit(limit);
if (resolved === null) {
return [];
}
return recentPhases.slice(-resolved).map((phase) => Object.assign({}, phase));
const completedAfter = options?.completedAfter;
const eligiblePhases =
completedAfter === undefined
? recentPhases
: recentPhases.filter(
(phase) => phase.endedAt !== undefined && phase.endedAt >= completedAfter,
);
return eligiblePhases.slice(-resolved).map((phase) => Object.assign({}, phase));
}
/** Records a completed phase in memory and emits it when diagnostics are enabled. */
+46
View File
@@ -2408,6 +2408,52 @@ describe("stuck session diagnostics threshold", () => {
).toBe(true);
});
it("attributes only phases completed during the measured liveness interval", async () => {
const warnSpy = vi.spyOn(diagnosticLogger, "warn").mockImplementation(() => undefined);
const events: DiagnosticEventPayload[] = [];
const unsubscribe = onDiagnosticEvent((event) => events.push(event));
await withDiagnosticPhase("stale.phase", () => undefined);
vi.advanceTimersByTime(60_000);
await withDiagnosticPhase("recent.phase", () => undefined);
try {
startDiagnosticHeartbeat(
{
diagnostics: {
enabled: true,
},
},
{
emitMemorySample: createEmitMemorySampleMock(),
sampleLiveness: () => ({
reasons: ["event_loop_delay"],
intervalMs: 30_000,
eventLoopDelayP99Ms: 1_500,
eventLoopDelayMaxMs: 2_000,
}),
},
);
logMessageQueued({ sessionId: "s1", sessionKey: "main", source: "test" });
vi.advanceTimersByTime(30_000);
} finally {
unsubscribe();
}
expectLoggerMessageContaining(warnSpy, "recentPhases=recent.phase:");
expectNoLoggerMessageContaining(warnSpy, "stale.phase");
const warning = requireRecord(
events.findLast((event) => event.type === "diagnostic.liveness.warning"),
"liveness warning event",
);
expect(warning.recentPhases).toEqual([
expect.objectContaining({
name: "recent.phase",
}),
]);
});
it("keeps transient event-loop max spikes debug-only when only background work is active", () => {
const warnSpy = vi.spyOn(diagnosticLogger, "warn").mockImplementation(() => undefined);
+7 -2
View File
@@ -421,9 +421,14 @@ function shouldEmitDiagnosticLivenessWarning(now: number, work: DiagnosticWorkSn
function emitDiagnosticLivenessWarning(
sample: DiagnosticLivenessSample,
work: DiagnosticWorkSnapshot,
now: number,
): void {
const phase = getCurrentDiagnosticPhase();
const recentPhases = getRecentDiagnosticPhases(6);
// Attribute only phases completed during this measured liveness interval.
// The retained ring is capacity-bounded history, not a temporal recency signal.
const recentPhases = getRecentDiagnosticPhases(6, {
completedAfter: now - Math.max(0, sample.intervalMs),
});
const recentPhaseSummary = formatRecentDiagnosticPhases(recentPhases);
const workLabelSummary = formatDiagnosticWorkLabels(work);
const message = `liveness warning: reasons=${sample.reasons.join(",")} interval=${Math.round(
@@ -1269,7 +1274,7 @@ export function startDiagnosticHeartbeat(
}
if (shouldEmitLivenessReport && livenessSample) {
emitDiagnosticLivenessWarning(livenessSample, work);
emitDiagnosticLivenessWarning(livenessSample, work, now);
}
diag.debug(