fix(diagnostics): suppress startup-only heartbeat delay warnings (#123461)

* fix(diagnostics): suppress startup heartbeat delay warning

* chore: leave release changelog generation to release tooling
This commit is contained in:
Peter Steinberger
2026-08-13 21:42:11 -07:00
committed by GitHub
parent 9496a4b199
commit d60a98ec87
2 changed files with 23 additions and 3 deletions
+20
View File
@@ -520,6 +520,12 @@ describe("stuck session diagnostics threshold", () => {
vi.advanceTimersByTime(30_000);
expectLoggerMessageContaining(warnSpy, "liveness heartbeat delayed");
const delayedHeartbeat = loggerMessages(warnSpy).find((message) =>
message.includes("liveness heartbeat delayed"),
);
expect(delayedHeartbeat).toMatch(/overdue=\d+ms elapsed=\d+ms/u);
const timing = delayedHeartbeat?.match(/overdue=(\d+)ms elapsed=(\d+)ms/u);
expect(Number(timing?.[2]) - Number(timing?.[1])).toBe(30_000);
expect(recoverStuckSession).not.toHaveBeenCalled();
vi.advanceTimersByTime(30_000);
@@ -2394,6 +2400,7 @@ describe("stuck session diagnostics threshold", () => {
it("suppresses liveness warnings during startupGraceMs while still sampling", () => {
const warnSpy = vi.spyOn(diagnosticLogger, "warn").mockImplementation(() => undefined);
const events: string[] = [];
const recoverStuckSession = vi.fn();
const sampleLiveness = vi.fn(() => ({
reasons: ["event_loop_delay" as const],
intervalMs: 30_000,
@@ -2403,6 +2410,7 @@ describe("stuck session diagnostics threshold", () => {
const unsubscribe = onDiagnosticEvent((event) => events.push(event.type));
try {
vi.setSystemTime(0);
startDiagnosticHeartbeat(
{
diagnostics: {
@@ -2411,23 +2419,35 @@ describe("stuck session diagnostics threshold", () => {
},
{
emitMemorySample: createEmitMemorySampleMock(),
recoverStuckSession,
sampleLiveness,
startupGraceMs: 60_000,
testTimings: { stuckSessionWarnMs: 1_000, stuckSessionAbortMs: 1_000 },
},
);
logMessageQueued({ sessionId: "s1", sessionKey: "main", source: "test" });
logSessionStateChange({ sessionId: "s1", sessionKey: "main", state: "processing" });
markDiagnosticEmbeddedRunStarted({ sessionId: "s1", sessionKey: "main" });
vi.setSystemTime(1_001);
vi.advanceTimersByTime(30_000);
expect(sampleLiveness).toHaveBeenCalledTimes(1);
expectNoLoggerMessageContaining(warnSpy, "liveness heartbeat delayed");
expectNoLoggerMessageContaining(warnSpy, "liveness warning:");
expect(events).not.toContain("diagnostic.liveness.warning");
expect(recoverStuckSession).not.toHaveBeenCalled();
vi.advanceTimersByTime(30_000);
expect(sampleLiveness).toHaveBeenCalledTimes(2);
expectLoggerMessageContaining(warnSpy, "liveness warning:");
expect(events).toContain("diagnostic.liveness.warning");
expectRecoveryCall(
recoverStuckSession,
{ sessionId: "s1", sessionKey: "main", queueDepth: 0, allowActiveAbort: true },
["ageMs", "stateGeneration"],
);
} finally {
unsubscribe();
}
+3 -3
View File
@@ -1176,19 +1176,19 @@ export function startDiagnosticHeartbeat(
lastDiagnosticHeartbeatTickAt === undefined ? 0 : now - lastDiagnosticHeartbeatTickAt;
lastDiagnosticHeartbeatTickAt = now;
const heartbeatOverdueMs = Math.max(0, heartbeatElapsedMs - DIAGNOSTIC_HEARTBEAT_INTERVAL_MS);
const inStartupGrace = livenessGraceUntil > 0 && now < livenessGraceUntil;
// Observe ordinary timer jitter at the scheduled tick so it cannot consume
// a run's remaining recovery budget. Material lateness can also hide queued
// progress events, so the next healthy heartbeat owns recovery instead.
const recoveryObservationNow = now - heartbeatOverdueMs;
const shouldDeferRecovery = heartbeatOverdueMs >= DEFAULT_LIVENESS_EVENT_LOOP_DELAY_WARN_MS;
if (shouldDeferRecovery) {
if (shouldDeferRecovery && !inStartupGrace) {
diag.warn(
`liveness heartbeat delayed ${Math.round(heartbeatElapsedMs)}ms; deferring recovery decisions`,
`liveness heartbeat delayed: overdue=${Math.round(heartbeatOverdueMs)}ms elapsed=${Math.round(heartbeatElapsedMs)}ms; deferring recovery decisions`,
);
}
pruneDiagnosticSessionStates(now, true);
const work = getDiagnosticWorkSnapshot(now);
const inStartupGrace = livenessGraceUntil > 0 && now < livenessGraceUntil;
const rawLivenessSample = (opts?.sampleLiveness ?? sampleDiagnosticLiveness)(now, work);
// Keep sampling during grace so event-loop delay baselines reset, but suppress startup-only reports.
const livenessSample = inStartupGrace ? null : rawLivenessSample;