mirror of
https://github.com/openclaw/openclaw.git
synced 2026-08-25 11:55:47 -06:00
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:
committed by
GitHub
parent
9496a4b199
commit
d60a98ec87
@@ -520,6 +520,12 @@ describe("stuck session diagnostics threshold", () => {
|
|||||||
vi.advanceTimersByTime(30_000);
|
vi.advanceTimersByTime(30_000);
|
||||||
|
|
||||||
expectLoggerMessageContaining(warnSpy, "liveness heartbeat delayed");
|
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();
|
expect(recoverStuckSession).not.toHaveBeenCalled();
|
||||||
|
|
||||||
vi.advanceTimersByTime(30_000);
|
vi.advanceTimersByTime(30_000);
|
||||||
@@ -2394,6 +2400,7 @@ describe("stuck session diagnostics threshold", () => {
|
|||||||
it("suppresses liveness warnings during startupGraceMs while still sampling", () => {
|
it("suppresses liveness warnings during startupGraceMs while still sampling", () => {
|
||||||
const warnSpy = vi.spyOn(diagnosticLogger, "warn").mockImplementation(() => undefined);
|
const warnSpy = vi.spyOn(diagnosticLogger, "warn").mockImplementation(() => undefined);
|
||||||
const events: string[] = [];
|
const events: string[] = [];
|
||||||
|
const recoverStuckSession = vi.fn();
|
||||||
const sampleLiveness = vi.fn(() => ({
|
const sampleLiveness = vi.fn(() => ({
|
||||||
reasons: ["event_loop_delay" as const],
|
reasons: ["event_loop_delay" as const],
|
||||||
intervalMs: 30_000,
|
intervalMs: 30_000,
|
||||||
@@ -2403,6 +2410,7 @@ describe("stuck session diagnostics threshold", () => {
|
|||||||
const unsubscribe = onDiagnosticEvent((event) => events.push(event.type));
|
const unsubscribe = onDiagnosticEvent((event) => events.push(event.type));
|
||||||
|
|
||||||
try {
|
try {
|
||||||
|
vi.setSystemTime(0);
|
||||||
startDiagnosticHeartbeat(
|
startDiagnosticHeartbeat(
|
||||||
{
|
{
|
||||||
diagnostics: {
|
diagnostics: {
|
||||||
@@ -2411,23 +2419,35 @@ describe("stuck session diagnostics threshold", () => {
|
|||||||
},
|
},
|
||||||
{
|
{
|
||||||
emitMemorySample: createEmitMemorySampleMock(),
|
emitMemorySample: createEmitMemorySampleMock(),
|
||||||
|
recoverStuckSession,
|
||||||
sampleLiveness,
|
sampleLiveness,
|
||||||
startupGraceMs: 60_000,
|
startupGraceMs: 60_000,
|
||||||
|
testTimings: { stuckSessionWarnMs: 1_000, stuckSessionAbortMs: 1_000 },
|
||||||
},
|
},
|
||||||
);
|
);
|
||||||
|
|
||||||
logMessageQueued({ sessionId: "s1", sessionKey: "main", source: "test" });
|
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);
|
vi.advanceTimersByTime(30_000);
|
||||||
|
|
||||||
expect(sampleLiveness).toHaveBeenCalledTimes(1);
|
expect(sampleLiveness).toHaveBeenCalledTimes(1);
|
||||||
|
expectNoLoggerMessageContaining(warnSpy, "liveness heartbeat delayed");
|
||||||
expectNoLoggerMessageContaining(warnSpy, "liveness warning:");
|
expectNoLoggerMessageContaining(warnSpy, "liveness warning:");
|
||||||
expect(events).not.toContain("diagnostic.liveness.warning");
|
expect(events).not.toContain("diagnostic.liveness.warning");
|
||||||
|
expect(recoverStuckSession).not.toHaveBeenCalled();
|
||||||
|
|
||||||
vi.advanceTimersByTime(30_000);
|
vi.advanceTimersByTime(30_000);
|
||||||
|
|
||||||
expect(sampleLiveness).toHaveBeenCalledTimes(2);
|
expect(sampleLiveness).toHaveBeenCalledTimes(2);
|
||||||
expectLoggerMessageContaining(warnSpy, "liveness warning:");
|
expectLoggerMessageContaining(warnSpy, "liveness warning:");
|
||||||
expect(events).toContain("diagnostic.liveness.warning");
|
expect(events).toContain("diagnostic.liveness.warning");
|
||||||
|
expectRecoveryCall(
|
||||||
|
recoverStuckSession,
|
||||||
|
{ sessionId: "s1", sessionKey: "main", queueDepth: 0, allowActiveAbort: true },
|
||||||
|
["ageMs", "stateGeneration"],
|
||||||
|
);
|
||||||
} finally {
|
} finally {
|
||||||
unsubscribe();
|
unsubscribe();
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -1176,19 +1176,19 @@ export function startDiagnosticHeartbeat(
|
|||||||
lastDiagnosticHeartbeatTickAt === undefined ? 0 : now - lastDiagnosticHeartbeatTickAt;
|
lastDiagnosticHeartbeatTickAt === undefined ? 0 : now - lastDiagnosticHeartbeatTickAt;
|
||||||
lastDiagnosticHeartbeatTickAt = now;
|
lastDiagnosticHeartbeatTickAt = now;
|
||||||
const heartbeatOverdueMs = Math.max(0, heartbeatElapsedMs - DIAGNOSTIC_HEARTBEAT_INTERVAL_MS);
|
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
|
// Observe ordinary timer jitter at the scheduled tick so it cannot consume
|
||||||
// a run's remaining recovery budget. Material lateness can also hide queued
|
// a run's remaining recovery budget. Material lateness can also hide queued
|
||||||
// progress events, so the next healthy heartbeat owns recovery instead.
|
// progress events, so the next healthy heartbeat owns recovery instead.
|
||||||
const recoveryObservationNow = now - heartbeatOverdueMs;
|
const recoveryObservationNow = now - heartbeatOverdueMs;
|
||||||
const shouldDeferRecovery = heartbeatOverdueMs >= DEFAULT_LIVENESS_EVENT_LOOP_DELAY_WARN_MS;
|
const shouldDeferRecovery = heartbeatOverdueMs >= DEFAULT_LIVENESS_EVENT_LOOP_DELAY_WARN_MS;
|
||||||
if (shouldDeferRecovery) {
|
if (shouldDeferRecovery && !inStartupGrace) {
|
||||||
diag.warn(
|
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);
|
pruneDiagnosticSessionStates(now, true);
|
||||||
const work = getDiagnosticWorkSnapshot(now);
|
const work = getDiagnosticWorkSnapshot(now);
|
||||||
const inStartupGrace = livenessGraceUntil > 0 && now < livenessGraceUntil;
|
|
||||||
const rawLivenessSample = (opts?.sampleLiveness ?? sampleDiagnosticLiveness)(now, work);
|
const rawLivenessSample = (opts?.sampleLiveness ?? sampleDiagnosticLiveness)(now, work);
|
||||||
// Keep sampling during grace so event-loop delay baselines reset, but suppress startup-only reports.
|
// Keep sampling during grace so event-loop delay baselines reset, but suppress startup-only reports.
|
||||||
const livenessSample = inStartupGrace ? null : rawLivenessSample;
|
const livenessSample = inStartupGrace ? null : rawLivenessSample;
|
||||||
|
|||||||
Reference in New Issue
Block a user