diff --git a/src/logging/diagnostic-phase.test.ts b/src/logging/diagnostic-phase.test.ts index 5c1d09d67d31..11e77c67f3be 100644 --- a/src/logging/diagnostic-phase.test.ts +++ b/src/logging/diagnostic-phase.test.ts @@ -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((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; + } + }); }); diff --git a/src/logging/diagnostic-phase.ts b/src/logging/diagnostic-phase.ts index c4c7b3a32b72..58cc6d8cfc90 100644 --- a/src/logging/diagnostic-phase.ts +++ b/src/logging/diagnostic-phase.ts @@ -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. */ diff --git a/src/logging/diagnostic.test.ts b/src/logging/diagnostic.test.ts index 493a12a71920..ee9c627c7a2c 100644 --- a/src/logging/diagnostic.test.ts +++ b/src/logging/diagnostic.test.ts @@ -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); diff --git a/src/logging/diagnostic.ts b/src/logging/diagnostic.ts index fe259a3cbf93..e3157ffb8b98 100644 --- a/src/logging/diagnostic.ts +++ b/src/logging/diagnostic.ts @@ -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(