fix(heartbeat): stop zombie-timer audit churning live-but-skipping timers (#2271)
## Problem Permanent (durable) agent heartbeats went silent while the rest of the engine kept running. Investigation of the live DB showed **every** permanent agent's `heartbeatTimerRepair` metadata carrying `nonAdvancingEscalated: true` with **3–63 consecutive** zombie re-arms — the audit re-arming a timer every 60s for hours while emitting `heartbeat-rearm-nonadvancing-escalated` warnings that never recovered anything. ## Root cause The heartbeat trigger audit classified a "zombie" (dead) timer **solely from a stale `lastHeartbeatAt`**. But that column advances *only* on a successful `"ok"` delivery (`agent-store.ts` `recordHeartbeat`). It stays frozen whenever a heartbeat is intentionally skipped or no-op'd: - agent over budget / over budget threshold - `globalPause` / `enginePaused` - `skipHeartbeatWhenIdle` on an idle agent - idle "org" agents whose runs complete as `no_assignment_identity_run` In all of these the interval keeps firing perfectly — the timer is alive, delivery is just (correctly) skipped. Keying zombie detection off `lastHeartbeatAt` misread those healthy timers as dead, re-armed them every 60s, and escalated forever. Re-arming a live timer is a no-op, so the loop could never recover — it only produced churn and phantom warnings. ## Fix (the invariant) Key zombie detection off **whether the interval physically fired**, not whether delivery advanced. - New `lastTimerFireAtMs` map, stamped at the top of `onTimerTick` **before any gate** — a fired-but-skipped tick still counts as proof of liveness. - In the audit: a present + stale timer that fired within its stale window is **left untouched** (no re-arm, no escalation, non-advancing counter reset). Only a timer with **no recent fire** (a genuinely dead interval) falls through to the existing re-arm/escalation path. - Map cleaned up in `unregisterAgent()` / `stop()`. This preserves the FN-7645 zombie repair (a timer that stops firing goes stale in lockstep on both clocks and is still re-armed) and the FN-7939 watchdog, while eliminating the phantom churn for live-but-skipping timers. Why not "force a heartbeat" or "park the agent": forcing delivery would bypass budget/pause governance, and parking a healthy idle agent would be wrong. The correct action for a live-but-skipping timer is to leave it alone — its next real tick delivers once the skip condition clears. ## Tests - Rewrote the old `skipHeartbeatWhenIdle` test that codified the buggy escalation → now asserts a **live** idle-skipping timer is left untouched (no zombie re-arm, no escalation). - Added a budget/no-assignment surface: a live timer that dispatches but leaves `lastHeartbeatAt` frozen must not be misclassified. `heartbeat-scheduler.test.ts` 120/120; broader heartbeat + concurrency suites 349/349; `@fusion/engine` typecheck 0 errors. ## Review Self-reviewed at medium effort. Two acknowledged, bounded trade-offs (kept intentionally): a genuinely-dead-but-recently-fired timer's repair latency is bounded at ~2× interval (same as the original FN-7645 latency), and the escalation warning is suppressed for live timers (it only ever fired because of the churn this removes; per-tick error logs + a new "left live-but-skipping timer" log retain visibility). One trivial cleanup applied (single `Date.now()` sample). ## Notes - Engine is a private package → no changeset. - Complementary to a separate in-flight fix for the agentStore/scheduler-not-constructed bug (why heartbeats stopped *entirely*); this PR ensures that once the scheduler runs again, the audit stops the phantom churn/escalation. 🤖 Generated with [Claude Code](https://claude.com/claude-code) <!-- This is an auto-generated comment: release notes by coderabbit.ai --> ## Summary by CodeRabbit * **Bug Fixes** * Improved heartbeat timer monitoring to distinguish healthy timers from genuinely stopped timers. * Prevented unnecessary timer re-registration and warning escalation when heartbeats are intentionally skipped due to idle, paused, budget-limited, or unassigned states. * Improved recovery when a replacement timer stops firing, ensuring it is detected and repaired reliably. <!-- end of auto-generated comment: release notes by coderabbit.ai --> --------- Co-authored-by: Claude Opus 4.8 <noreply@anthropic.com>
This commit is contained in:
gsxdsm
@@ -377,6 +377,11 @@ describe("HeartbeatTriggerScheduler", () => {
|
||||
expect((scheduler as any).nonAdvancingRearmState.has(agent.id)).toBe(false);
|
||||
|
||||
agent.lastHeartbeatAt = new Date(Date.now() - 162_000_001).toISOString();
|
||||
// A genuinely dead interval also has no physical fire within the shared
|
||||
// window — age the timer-liveness marker too, which is what now
|
||||
// distinguishes a zombie from a live-but-skipping timer (frozen
|
||||
// lastHeartbeatAt alone no longer implies death).
|
||||
(scheduler as any).lastTimerFireAtMs.set(agent.id, Date.now() - 162_000_001);
|
||||
await (scheduler as any).auditTimerRegistrations("interval");
|
||||
expect(heartbeatLog.warn).toHaveBeenCalledWith(expect.stringContaining("zombie-timer-rearmed"));
|
||||
});
|
||||
@@ -818,6 +823,145 @@ describe("HeartbeatTriggerScheduler", () => {
|
||||
expect(callback).toHaveBeenCalledWith("agent-long", "timer", expect.anything());
|
||||
});
|
||||
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-16:30:
|
||||
* Greptile PR #2271 P1 regression: liveness must be anchored to the CURRENT
|
||||
* timer, not to a fire recorded before the timer was (re-)armed. After an
|
||||
* interval increase, an old timer's fire must not vouch for the replacement
|
||||
* against the new (larger) stale window. `applyTimerRegistration` re-stamps
|
||||
* `lastTimerFireAtMs` at arm time, so the staleness clock restarts on every
|
||||
* (re-)registration and a dead replacement is still repaired on schedule.
|
||||
*/
|
||||
it("re-anchors the fire-liveness marker to the current timer on re-registration (interval increase)", async () => {
|
||||
vi.useFakeTimers();
|
||||
vi.setSystemTime(new Date("2026-01-01T00:00:00.000Z"));
|
||||
|
||||
// Short interval first; a real fire records liveness under the old timer.
|
||||
const agent = buildAgent({ id: "agent-reReg", heartbeatIntervalMs: 300_000 });
|
||||
vi.mocked(store.listAgents).mockImplementation(async () => [agent]);
|
||||
vi.mocked(store.getAgent).mockResolvedValue(agent);
|
||||
vi.mocked(store.getActiveHeartbeatRun).mockResolvedValue(null);
|
||||
|
||||
scheduler = new HeartbeatTriggerScheduler(store, callback);
|
||||
scheduler.start();
|
||||
await vi.advanceTimersByTimeAsync(6 * 60_000); // fires at 5min under the 5min interval
|
||||
|
||||
const t0 = Date.parse("2026-01-01T00:00:00.000Z");
|
||||
const fireMarkers = (scheduler as unknown as { lastTimerFireAtMs: Map<string, number> }).lastTimerFireAtMs;
|
||||
expect(fireMarkers.get("agent-reReg")).toBe(t0 + 5 * 60_000); // last physical fire at 5min
|
||||
|
||||
// Interval increases to 1h; syncTimerForAgent-style re-registration replaces
|
||||
// the timer. The marker MUST re-anchor to NOW (6min) so the old 5min fire
|
||||
// cannot vouch for the new 1h timer against the new 2h stale window.
|
||||
(agent.runtimeConfig as Record<string, unknown>).heartbeatIntervalMs = 3_600_000;
|
||||
scheduler.registerAgent("agent-reReg", { enabled: true, heartbeatIntervalMs: 3_600_000 }, { lastHeartbeatAt: agent.lastHeartbeatAt });
|
||||
expect(fireMarkers.get("agent-reReg")).toBe(t0 + 6 * 60_000); // re-anchored to re-registration time
|
||||
|
||||
// Kill the freshly-armed replacement — a genuinely dead replacement timer.
|
||||
const timers = (scheduler as unknown as { timers: Map<string, { handle: unknown; kind: string }> }).timers;
|
||||
clearInterval(timers.get("agent-reReg")!.handle as ReturnType<typeof setInterval>);
|
||||
callback.mockClear();
|
||||
vi.mocked(heartbeatLog.warn).mockClear();
|
||||
|
||||
// Advance well past the new 2h window (measured from the ~6min
|
||||
// re-registration), plus a trailing tick to let the catch-up dispatch
|
||||
// fire. The dead replacement must be repaired, not masked forever.
|
||||
await vi.advanceTimersByTimeAsync(2 * 60 * 60 * 1000 + 10 * 60_000);
|
||||
await vi.advanceTimersByTimeAsync(5_000);
|
||||
|
||||
expect(heartbeatLog.warn).toHaveBeenCalledWith(expect.stringContaining("zombie-timer-rearmed"));
|
||||
expect(callback).toHaveBeenCalledWith("agent-reReg", "timer", expect.anything());
|
||||
});
|
||||
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-18:15:
|
||||
* Greptile PR #2271 P1 (queued-callback ordering): a callback from a
|
||||
* superseded timer that runs AFTER re-registration must not stamp liveness
|
||||
* or dispatch for the replacement timer. Timer callbacks carry their per-arm
|
||||
* identity; onTimerTick rejects a mismatched arm before recording
|
||||
* lastTimerFireAtMs or invoking the callback.
|
||||
*/
|
||||
it("rejects a superseded timer tick (stale arm identity) so it neither dispatches nor records liveness", async () => {
|
||||
vi.useFakeTimers();
|
||||
vi.setSystemTime(new Date("2026-01-01T00:00:00.000Z"));
|
||||
|
||||
const agent = buildAgent({ id: "agent-arm", heartbeatIntervalMs: 3_600_000 });
|
||||
vi.mocked(store.listAgents).mockResolvedValue([agent]);
|
||||
vi.mocked(store.getAgent).mockResolvedValue(agent);
|
||||
vi.mocked(store.getActiveHeartbeatRun).mockResolvedValue(null);
|
||||
|
||||
scheduler = new HeartbeatTriggerScheduler(store, callback);
|
||||
scheduler.start();
|
||||
await vi.advanceTimersByTimeAsync(0);
|
||||
|
||||
const arms = (scheduler as unknown as { currentTimerArm: Map<string, number> }).currentTimerArm;
|
||||
const fireMarkers = (scheduler as unknown as { lastTimerFireAtMs: Map<string, number> }).lastTimerFireAtMs;
|
||||
const currentArm = arms.get("agent-arm")!;
|
||||
const staleArm = currentArm - 1;
|
||||
|
||||
callback.mockClear();
|
||||
fireMarkers.delete("agent-arm"); // so any stamp below is detectable
|
||||
|
||||
// A leftover callback from a superseded arm fires with the OLD arm id.
|
||||
await (scheduler as unknown as { onTimerTick: (id: string, ms: number, arm?: number) => Promise<void> })
|
||||
.onTimerTick("agent-arm", 3_600_000, staleArm);
|
||||
expect(callback).not.toHaveBeenCalled();
|
||||
expect(fireMarkers.has("agent-arm")).toBe(false);
|
||||
|
||||
// A tick from the CURRENT arm is honored: it records liveness and dispatches.
|
||||
await (scheduler as unknown as { onTimerTick: (id: string, ms: number, arm?: number) => Promise<void> })
|
||||
.onTimerTick("agent-arm", 3_600_000, currentArm);
|
||||
expect(callback).toHaveBeenCalledWith("agent-arm", "timer", expect.anything());
|
||||
expect(fireMarkers.has("agent-arm")).toBe(true);
|
||||
});
|
||||
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-18:15:
|
||||
* Greptile PR #2271 P1 (interval-transition leak): a phase-alignment timeout
|
||||
* whose arm has been superseded must NOT transition to a steady interval,
|
||||
* else it installs an untracked interval over the live replacement in
|
||||
* this.timers — leaking a duplicate-firing timer that later cleanup never
|
||||
* reaches. The timeout→interval transition is gated on the arm still being
|
||||
* current.
|
||||
*/
|
||||
it("a superseded phase-alignment timeout does not install a steady interval (no leaked/untracked timer)", async () => {
|
||||
vi.useFakeTimers();
|
||||
// now = 00:30, lastHeartbeatAt = 00:00, interval 1h → a phase-alignment
|
||||
// setTimeout that fires 30min out (deterministic, not the random overdue jitter).
|
||||
vi.setSystemTime(new Date("2026-01-01T00:30:00.000Z"));
|
||||
|
||||
const agent = buildAgent({
|
||||
id: "agent-leak",
|
||||
heartbeatIntervalMs: 3_600_000,
|
||||
lastHeartbeatAt: "2026-01-01T00:00:00.000Z",
|
||||
});
|
||||
vi.mocked(store.listAgents).mockResolvedValue([agent]);
|
||||
vi.mocked(store.getAgent).mockResolvedValue(agent);
|
||||
vi.mocked(store.getActiveHeartbeatRun).mockResolvedValue(null);
|
||||
|
||||
scheduler = new HeartbeatTriggerScheduler(store, callback);
|
||||
scheduler.start();
|
||||
await vi.advanceTimersByTimeAsync(0);
|
||||
|
||||
const timers = (scheduler as unknown as { timers: Map<string, { kind: string }> }).timers;
|
||||
const arms = (scheduler as unknown as { currentTimerArm: Map<string, number> }).currentTimerArm;
|
||||
expect(timers.get("agent-leak")?.kind).toBe("timeout"); // phase-alignment timeout armed
|
||||
callback.mockClear();
|
||||
|
||||
// Simulate the queued-callback race: a re-registration superseded THIS arm
|
||||
// (advance the current arm) while the already-scheduled timeout still fires.
|
||||
arms.set("agent-leak", arms.get("agent-leak")! + 1);
|
||||
|
||||
// Fire the (now superseded) phase timeout.
|
||||
await vi.advanceTimersByTimeAsync(31 * 60_000);
|
||||
|
||||
// The superseded timeout must neither dispatch nor transition to a steady
|
||||
// interval — the tracked entry stays the (now-consumed) timeout, and no
|
||||
// untracked interval was installed over a replacement.
|
||||
expect(callback).not.toHaveBeenCalledWith("agent-leak", "timer", expect.anything());
|
||||
expect(timers.get("agent-leak")?.kind).not.toBe("interval");
|
||||
});
|
||||
|
||||
it("pause guards still suppress dispatch after a zombie re-arm (does not regress FN-2658)", async () => {
|
||||
vi.useFakeTimers();
|
||||
vi.setSystemTime(new Date("2026-01-01T00:00:00.000Z"));
|
||||
@@ -1050,7 +1194,19 @@ describe("HeartbeatTriggerScheduler", () => {
|
||||
expect(heartbeatLog.warn).not.toHaveBeenCalledWith(expect.stringContaining("reason=heartbeat-rearm-nonadvancing-escalated"));
|
||||
});
|
||||
|
||||
it("escalates repeated zombie re-arms when skipHeartbeatWhenIdle prevents lastHeartbeatAt from advancing", async () => {
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-15:40:
|
||||
* Corrected invariant (supersedes the prior FN-7939 behavior that escalated
|
||||
* here): a LIVE timer whose delivery is intentionally skipped
|
||||
* (`skipHeartbeatWhenIdle` on an idle agent) freezes `lastHeartbeatAt`
|
||||
* without being a dead "zombie". Because the interval keeps physically
|
||||
* firing, the audit must recognize it via `lastTimerFireAtMs` and leave it
|
||||
* alone — no zombie re-arm churn and no `heartbeat-rearm-nonadvancing-escalated`
|
||||
* warning. The prior test killed the interval (mis-modeling a dead timer)
|
||||
* and asserted escalation; that escalation was the bug — an idle skip-agent
|
||||
* with a healthy timer was being flagged for hours.
|
||||
*/
|
||||
it("does NOT escalate or churn zombie re-arms for a live-but-idle-skipping timer (frozen lastHeartbeatAt is intentional, not a dead timer)", async () => {
|
||||
vi.useFakeTimers();
|
||||
vi.setSystemTime(new Date("2026-01-01T00:00:00.000Z"));
|
||||
|
||||
@@ -1058,6 +1214,7 @@ describe("HeartbeatTriggerScheduler", () => {
|
||||
"agent-churn": buildAgent({
|
||||
id: "agent-churn",
|
||||
heartbeatIntervalMs: 120_000,
|
||||
taskId: undefined,
|
||||
runtimeConfig: { enabled: true, heartbeatIntervalMs: 120_000, skipHeartbeatWhenIdle: true },
|
||||
}),
|
||||
};
|
||||
@@ -1073,21 +1230,71 @@ describe("HeartbeatTriggerScheduler", () => {
|
||||
scheduler.start();
|
||||
await vi.advanceTimersByTimeAsync(0);
|
||||
|
||||
const timers = (scheduler as unknown as { timers: Map<string, { handle: unknown; kind: string }> }).timers;
|
||||
clearInterval(timers.get("agent-churn")!.handle as ReturnType<typeof setInterval>);
|
||||
callback.mockClear();
|
||||
vi.mocked(heartbeatLog.warn).mockClear();
|
||||
|
||||
// Leave the interval ALIVE. It fires every 2min and returns early at the
|
||||
// skipHeartbeatWhenIdle gate (no task) — delivery never advances
|
||||
// lastHeartbeatAt, but the timer is provably firing. Span well past the
|
||||
// 2x-interval (4min) stale threshold.
|
||||
await vi.advanceTimersByTimeAsync(12 * 60_000);
|
||||
|
||||
// Idle-skip: onTimerTick returns before the callback, so no dispatch.
|
||||
expect(callback).not.toHaveBeenCalled();
|
||||
// The fix: a live timer is never treated as a zombie, so neither the
|
||||
// re-arm nor the escalation warning is ever emitted.
|
||||
expect(heartbeatLog.warn).not.toHaveBeenCalledWith(expect.stringContaining("zombie-timer-rearmed"));
|
||||
expect(heartbeatLog.warn).not.toHaveBeenCalledWith(expect.stringContaining("reason=heartbeat-rearm-nonadvancing-escalated"));
|
||||
// And the audit takes the explicit "leave live-but-skipping timer alone" path.
|
||||
expect(heartbeatLog.log).toHaveBeenCalledWith(expect.stringContaining("left live-but-skipping timer for agent-churn untouched"));
|
||||
expect((scheduler as any).nonAdvancingRearmState.has("agent-churn")).toBe(false);
|
||||
});
|
||||
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-15:40:
|
||||
* Production repro (idle "org" agents completing as `no_assignment_identity_run`,
|
||||
* plus over-budget / engine-paused skips): the timer fires and the run
|
||||
* completes, but the completion path does not record an "ok" heartbeat, so
|
||||
* `lastHeartbeatAt` stays frozen. Before the fix this drove the 60s audit to
|
||||
* re-arm every cycle and escalate for hours (observed: 3–63 consecutive
|
||||
* non-advancing re-arms across every permanent agent). The live-timer guard
|
||||
* must suppress that churn regardless of WHY delivery did not advance.
|
||||
*/
|
||||
it("does NOT escalate or churn when a live timer dispatches but delivery leaves lastHeartbeatAt frozen (budget/no-assignment skip)", async () => {
|
||||
vi.useFakeTimers();
|
||||
vi.setSystemTime(new Date("2026-01-01T00:00:00.000Z"));
|
||||
|
||||
const agents: Record<string, Agent> = {
|
||||
"agent-noadvance": buildAgent({ id: "agent-noadvance", heartbeatIntervalMs: 120_000 }),
|
||||
};
|
||||
vi.mocked(store.listAgents).mockImplementation(async () => Object.values(agents));
|
||||
vi.mocked(store.getAgent).mockImplementation(async (agentId: string) => agents[agentId] ?? null);
|
||||
vi.mocked(store.getActiveHeartbeatRun).mockResolvedValue(null);
|
||||
vi.mocked(store.updateAgent).mockImplementation(async (agentId: string, updates: Partial<Agent>) => {
|
||||
agents[agentId] = { ...agents[agentId], ...updates } as Agent;
|
||||
return agents[agentId];
|
||||
});
|
||||
// Callback runs (the run executes) but does NOT advance lastHeartbeatAt —
|
||||
// exactly the skipped/no-op-delivery completion shape.
|
||||
callback.mockResolvedValue(undefined);
|
||||
|
||||
scheduler = new HeartbeatTriggerScheduler(store, callback);
|
||||
scheduler.start();
|
||||
await vi.advanceTimersByTimeAsync(0);
|
||||
|
||||
callback.mockClear();
|
||||
vi.mocked(heartbeatLog.warn).mockClear();
|
||||
|
||||
await vi.advanceTimersByTimeAsync(12 * 60_000);
|
||||
|
||||
expect(callback).not.toHaveBeenCalled();
|
||||
expect(heartbeatLog.warn).toHaveBeenCalledWith(expect.stringContaining("reason=heartbeat-rearm-nonadvancing-escalated agentId=agent-churn"));
|
||||
expect((agents["agent-churn"].metadata as Record<string, any>).heartbeatTimerRepair).toEqual(
|
||||
expect.objectContaining({
|
||||
staleAtRepair: true,
|
||||
staleRepairReason: expect.stringContaining("heartbeat-rearm-nonadvancing-escalated"),
|
||||
}),
|
||||
);
|
||||
// The timer is alive: it dispatched on its own cadence (6 fires / 12min).
|
||||
expect(callback.mock.calls.filter((c) => c[0] === "agent-noadvance").length).toBeGreaterThanOrEqual(5);
|
||||
// Delivery never advanced lastHeartbeatAt...
|
||||
expect(agents["agent-noadvance"].lastHeartbeatAt).toBe("2026-01-01T00:00:00.000Z");
|
||||
// ...yet the audit must not misclassify the healthy timer as a zombie.
|
||||
expect(heartbeatLog.warn).not.toHaveBeenCalledWith(expect.stringContaining("zombie-timer-rearmed"));
|
||||
expect(heartbeatLog.warn).not.toHaveBeenCalledWith(expect.stringContaining("reason=heartbeat-rearm-nonadvancing-escalated"));
|
||||
expect((scheduler as any).nonAdvancingRearmState.has("agent-noadvance")).toBe(false);
|
||||
});
|
||||
});
|
||||
|
||||
|
||||
@@ -4144,6 +4144,19 @@ export class HeartbeatTriggerScheduler {
|
||||
private errorRecoveryLimit = MAX_HEARTBEAT_ERROR_RECOVERY_ATTEMPTS;
|
||||
private pendingAssignments: Map<string, PendingAssignment> = new Map();
|
||||
private registrationEpochs: Map<string, number> = new Map();
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-18:15:
|
||||
* Per-ARM identity for timer callbacks. Each applyTimerRegistration call takes
|
||||
* the next `timerArmSeq` value and records it as the agent's current arm. Timer
|
||||
* callbacks carry their armId; onTimerTick rejects a tick whose armId is no
|
||||
* longer current, and a phase-alignment timeout only transitions to its steady
|
||||
* interval while its arm is still current. This is finer-grained than
|
||||
* `registrationEpochs` (bumped once per registerAgent): the base arm and the
|
||||
* async settings-multiplier re-arm share a single epoch, so only a per-arm id
|
||||
* can distinguish a superseded base arm from the live multiplier arm.
|
||||
*/
|
||||
private timerArmSeq = 0;
|
||||
private currentTimerArm: Map<string, number> = new Map();
|
||||
private running = false;
|
||||
private assignedListener: ((agent: import("@fusion/core").Agent, taskId: string) => void) | null = null;
|
||||
private createdListener: ((agent: import("@fusion/core").Agent) => void) | null = null;
|
||||
@@ -4163,6 +4176,25 @@ export class HeartbeatTriggerScheduler {
|
||||
private timerAuditWatchdogHandle: ReturnType<typeof setInterval> | null = null;
|
||||
private lastAuditRanAtMs = 0;
|
||||
private nonAdvancingRearmState: Map<string, { lastHeartbeatAt: string | null; count: number }> = new Map();
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-15:40:
|
||||
* Wall-clock (ms) of the last moment we had positive evidence each agent's
|
||||
* CURRENT timer is alive: stamped both when the timer is (re-)armed
|
||||
* (applyTimerRegistration) and every time it PHYSICALLY FIRES (onTimerTick
|
||||
* entered), independent of whether that tick actually delivered a heartbeat.
|
||||
* The zombie-timer audit must key liveness off "is the interval firing" — NOT
|
||||
* off `lastHeartbeatAt` (which only advances on a successful "ok" delivery).
|
||||
* A timer whose delivery is intentionally skipped or no-op'd
|
||||
* (over-budget, engine/global pause, idle-skip, no-assignment idle-agent runs)
|
||||
* leaves `lastHeartbeatAt` frozen while the interval keeps firing perfectly.
|
||||
* Keying zombie detection off `lastHeartbeatAt` misclassified those live
|
||||
* timers as dead, re-armed them every 60s forever, and emitted escalating
|
||||
* `heartbeat-rearm-nonadvancing-escalated` warnings that could never recover
|
||||
* anything (re-arming a live timer is a no-op). This map lets the audit tell a
|
||||
* genuinely dead interval (no fire within the stale window) apart from a live
|
||||
* timer whose delivery is being skipped, and only re-arm the former.
|
||||
*/
|
||||
private lastTimerFireAtMs: Map<string, number> = new Map();
|
||||
/**
|
||||
* FNXC:AgentHeartbeat 2026-07-16-12:00:
|
||||
* FN-8184 caches the settings-derived multiplier for syncTimerForAgent,
|
||||
@@ -4279,6 +4311,12 @@ export class HeartbeatTriggerScheduler {
|
||||
}
|
||||
this.lastAuditRanAtMs = 0;
|
||||
this.nonAdvancingRearmState.clear();
|
||||
// FNXC:AgentHeartbeat 2026-07-17-15:40: clear fire-liveness markers on stop so
|
||||
// a subsequent start()/re-registration re-derives liveness from real ticks.
|
||||
this.lastTimerFireAtMs.clear();
|
||||
// FNXC:AgentHeartbeat 2026-07-17-18:15: clear per-arm ids so any callback
|
||||
// that outlives stop() is rejected by onTimerTick's arm guard.
|
||||
this.currentTimerArm.clear();
|
||||
|
||||
heartbeatLog.log("HeartbeatTriggerScheduler stopped");
|
||||
}
|
||||
@@ -4408,12 +4446,40 @@ export class HeartbeatTriggerScheduler {
|
||||
|
||||
this.clearAgentTimer(agentId);
|
||||
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-18:15:
|
||||
* Take this arm's unique identity and record it as the agent's current arm.
|
||||
* Every callback this arm schedules carries `armId`. onTimerTick rejects a
|
||||
* tick whose armId is no longer current (a superseded timer's already-queued
|
||||
* callback can then neither dispatch NOR record liveness for the replacement),
|
||||
* and the phase-alignment timeout below only transitions to its steady
|
||||
* interval while its arm is still current — otherwise a superseded timeout
|
||||
* would install an untracked interval over the live replacement in
|
||||
* `this.timers` and leak a duplicate-firing timer.
|
||||
*/
|
||||
const armId = ++this.timerArmSeq;
|
||||
this.currentTimerArm.set(agentId, armId);
|
||||
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-16:30:
|
||||
* Anchor the fire-liveness marker to the CURRENT timer at arm time. Arming a
|
||||
* fresh timer is itself positive evidence of liveness (setInterval/setTimeout
|
||||
* always schedule), so a just-registered timer is not a zombie even before
|
||||
* its first tick. Critically, re-stamping here OVERWRITES any marker left by
|
||||
* the previous timer: without this, a fire recorded under an old (shorter)
|
||||
* interval could vouch for a replacement timer against the new (larger) stale
|
||||
* window after an interval increase, masking a dead replacement until that
|
||||
* inflated window expired. Re-stamping restarts the staleness clock at every
|
||||
* (re-)registration, so liveness is only ever proven by the current timer.
|
||||
*/
|
||||
this.lastTimerFireAtMs.set(agentId, Date.now());
|
||||
|
||||
const armSteadyInterval = () => {
|
||||
// The setTimeout fired and was consumed; replace it with the long-lived
|
||||
// setInterval that drives every subsequent tick. Use the same
|
||||
// effectiveIntervalMs so the cadence remains correct.
|
||||
const intervalHandle = setInterval(() => {
|
||||
void this.onTimerTick(agentId, effectiveIntervalMs);
|
||||
void this.onTimerTick(agentId, effectiveIntervalMs, armId);
|
||||
}, effectiveIntervalMs);
|
||||
this.timers.set(agentId, {
|
||||
intervalMs: effectiveIntervalMs,
|
||||
@@ -4431,11 +4497,16 @@ export class HeartbeatTriggerScheduler {
|
||||
} else {
|
||||
const timeoutHandle = setTimeout(() => {
|
||||
// Fire the overdue/phase-aligned tick first, then transition to the
|
||||
// steady cadence. The tick fires regardless of whether the steady
|
||||
// interval install succeeds, so a missed tick can never silently
|
||||
// happen here.
|
||||
void this.onTimerTick(agentId, effectiveIntervalMs);
|
||||
armSteadyInterval();
|
||||
// steady cadence. The tick itself is armId-guarded inside onTimerTick.
|
||||
void this.onTimerTick(agentId, effectiveIntervalMs, armId);
|
||||
// FNXC:AgentHeartbeat 2026-07-17-18:15: only install the steady interval
|
||||
// if THIS arm is still current. A superseded timeout (its arm replaced by
|
||||
// a re-registration or the settings-multiplier re-arm) must not overwrite
|
||||
// the live replacement in this.timers, which would leak an untracked,
|
||||
// duplicate-firing interval that later clearAgentTimer never reaches.
|
||||
if (this.currentTimerArm.get(agentId) === armId) {
|
||||
armSteadyInterval();
|
||||
}
|
||||
}, initialDelayMs);
|
||||
this.timers.set(agentId, {
|
||||
intervalMs: effectiveIntervalMs,
|
||||
@@ -4490,6 +4561,12 @@ export class HeartbeatTriggerScheduler {
|
||||
this.registrationEpochs.set(agentId, (this.registrationEpochs.get(agentId) ?? 0) + 1);
|
||||
this.pendingAssignments.delete(agentId);
|
||||
this.nonAdvancingRearmState.delete(agentId);
|
||||
// FNXC:AgentHeartbeat 2026-07-17-15:40: drop the fire-liveness marker so it
|
||||
// cannot leak for deleted agents and a later re-registration starts fresh.
|
||||
this.lastTimerFireAtMs.delete(agentId);
|
||||
// FNXC:AgentHeartbeat 2026-07-17-18:15: clear the current-arm id so any
|
||||
// in-flight callback from this agent's last arm is rejected by onTimerTick.
|
||||
this.currentTimerArm.delete(agentId);
|
||||
if (this.timers.has(agentId)) {
|
||||
this.clearAgentTimer(agentId);
|
||||
heartbeatLog.log(`Unregistered timer for ${agentId}`);
|
||||
@@ -5022,6 +5099,38 @@ export class HeartbeatTriggerScheduler {
|
||||
continue;
|
||||
}
|
||||
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-15:40:
|
||||
* A present timer whose `lastHeartbeatAt` is stale is only a genuine
|
||||
* "zombie" (dead interval) when the interval has ALSO stopped firing.
|
||||
* Prior code inferred death solely from the frozen `lastHeartbeatAt`,
|
||||
* but that field advances only on a successful "ok" delivery — it stays
|
||||
* frozen whenever delivery is legitimately skipped or no-op'd
|
||||
* (over-budget, engine/global pause, idle-skip, or idle "org" agents
|
||||
* whose runs complete as `no_assignment_identity_run`). Those timers are
|
||||
* alive and firing on cadence; re-arming them every 60s recovers nothing
|
||||
* and only churns registrations while accruing phantom
|
||||
* `heartbeat-rearm-nonadvancing-escalated` warnings for hours.
|
||||
*
|
||||
* Fix the invariant: if the timer has PHYSICALLY FIRED within its stale
|
||||
* window (`lastTimerFireAtMs` newer than `staleThresholdMs`), it is not a
|
||||
* zombie — the frozen `lastHeartbeatAt` reflects intentionally-skipped
|
||||
* delivery, not a lost interval. Leave it alone and reset the
|
||||
* non-advancing counter. Only a present timer with NO recent fire (a
|
||||
* truly dead interval) falls through to the re-arm/escalation path below.
|
||||
*/
|
||||
const lastFireAtMs = this.lastTimerFireAtMs.get(agent.id);
|
||||
// Sample the clock once so the gate decision and the logged age agree.
|
||||
const sinceLastFireMs = typeof lastFireAtMs === "number" ? Date.now() - lastFireAtMs : Number.POSITIVE_INFINITY;
|
||||
const timerFiredWithinStaleWindow = sinceLastFireMs <= staleThresholdMs;
|
||||
if (hasTimerEntry && staleAtRepair && timerFiredWithinStaleWindow) {
|
||||
this.nonAdvancingRearmState.delete(agent.id);
|
||||
heartbeatLog.log(
|
||||
`Timer audit left live-but-skipping timer for ${agent.id} untouched (audit:${reason}): interval fired ${Math.round(sinceLastFireMs / 1000)}s ago; frozen lastHeartbeatAt reflects skipped/no-op delivery, not a dead timer`,
|
||||
);
|
||||
continue;
|
||||
}
|
||||
|
||||
const isZombieRearm = hasTimerEntry && staleAtRepair;
|
||||
|
||||
const activeRun = await this.store.getActiveHeartbeatRun(agent.id);
|
||||
@@ -5093,7 +5202,17 @@ export class HeartbeatTriggerScheduler {
|
||||
if (nonAdvancingEscalated) {
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-13-07:39:
|
||||
* FN-7939 — a zombie-timer re-arm that never restores delivery must become visible after a bounded count. Persistent skip/parallel guards can otherwise leave lastHeartbeatAt frozen while the audit rewrites `zombie-timer-rearmed` metadata forever, recreating multi-hour silent drift under a nominally active timer entry.
|
||||
* FN-7939 — a zombie-timer re-arm that never restores delivery must become visible after a bounded count.
|
||||
*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-15:40:
|
||||
* This escalation now fires ONLY for a genuinely dead interval: the
|
||||
* `timerFiredWithinStaleWindow` guard above short-circuits any present
|
||||
* timer that is still physically firing (its delivery merely skipped by
|
||||
* budget/pause/idle-skip/no-assignment), so a live-but-skipping timer no
|
||||
* longer reaches this path. Previously it did — the audit rewrote
|
||||
* `zombie-timer-rearmed` metadata every 60s for hours and emitted this
|
||||
* escalation for agents whose timers were perfectly healthy, because
|
||||
* `lastHeartbeatAt` (delivery) was conflated with interval liveness.
|
||||
*/
|
||||
heartbeatLog.warn(
|
||||
`Timer audit escalated non-advancing zombie re-arm reason=heartbeat-rearm-nonadvancing-escalated agentId=${agent.id} count=${consecutiveNonAdvancingRearms} threshold=${HeartbeatTriggerScheduler.NON_ADVANCING_REARM_ESCALATION_THRESHOLD} (audit:${reason}): ${staleRepairReason}`,
|
||||
@@ -5119,9 +5238,35 @@ export class HeartbeatTriggerScheduler {
|
||||
* Handle a timer tick for an agent.
|
||||
* Checks for active runs before invoking the callback.
|
||||
*/
|
||||
private async onTimerTick(agentId: string, intervalMs: number): Promise<void> {
|
||||
private async onTimerTick(agentId: string, intervalMs: number, armId?: number): Promise<void> {
|
||||
if (!this.running) return;
|
||||
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-18:15:
|
||||
* Reject superseded ticks BEFORE recording liveness or dispatching. Timer
|
||||
* callbacks carry the per-arm identity they were scheduled under
|
||||
* (applyTimerRegistration); any re-arm — a re-registration, an unregister, or
|
||||
* the settings-multiplier re-arm — advances the agent's current arm, so a
|
||||
* stale/already-queued callback from a replaced timer no longer matches.
|
||||
* Without this, that old callback could stamp `lastTimerFireAtMs` for the
|
||||
* CURRENT (possibly dead) timer and mask a needed repair for a full stale
|
||||
* window. Legacy/direct callers pass no armId and are unaffected.
|
||||
*/
|
||||
if (armId !== undefined && this.currentTimerArm.get(agentId) !== armId) {
|
||||
return;
|
||||
}
|
||||
|
||||
/*
|
||||
* FNXC:AgentHeartbeat 2026-07-17-15:40:
|
||||
* Stamp the physical fire BEFORE any gate. This records that the interval is
|
||||
* alive regardless of whether delivery proceeds below (skip guards, active
|
||||
* run, budget/pause). The audit's zombie detection consumes this so a live
|
||||
* timer whose delivery is intentionally skipped is never re-armed as a dead
|
||||
* "zombie". Stamped even on the paths that `return` early — a fired-but-
|
||||
* skipped tick is still proof of liveness.
|
||||
*/
|
||||
this.lastTimerFireAtMs.set(agentId, Date.now());
|
||||
|
||||
try {
|
||||
const agent = await this.store.getAgent(agentId);
|
||||
if (!agent) {
|
||||
|
||||
Reference in New Issue
Block a user