mirror of
https://github.com/openclaw/openclaw.git
synced 2026-08-17 16:12:21 -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);
|
||||
|
||||
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();
|
||||
}
|
||||
|
||||
@@ -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;
|
||||
|
||||
Reference in New Issue
Block a user