From a7ab3ccb49dc0ffc9667f90801305d4a34df11b6 Mon Sep 17 00:00:00 2001 From: gsxdsm Date: Fri, 17 Jul 2026 11:15:41 -0700 Subject: [PATCH] fix(heartbeat): stop zombie-timer audit churning live-but-skipping timers (#2271) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## 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) ## 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. --------- Co-authored-by: Claude Opus 4.8 --- .../src/__tests__/heartbeat-scheduler.test.ts | 229 +++++++++++++++++- packages/engine/src/agent-heartbeat.ts | 161 +++++++++++- 2 files changed, 371 insertions(+), 19 deletions(-) diff --git a/packages/engine/src/__tests__/heartbeat-scheduler.test.ts b/packages/engine/src/__tests__/heartbeat-scheduler.test.ts index 68a20b8e3b..bbd84bc62c 100644 --- a/packages/engine/src/__tests__/heartbeat-scheduler.test.ts +++ b/packages/engine/src/__tests__/heartbeat-scheduler.test.ts @@ -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 }).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).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 }).timers; + clearInterval(timers.get("agent-reReg")!.handle as ReturnType); + 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 }).currentTimerArm; + const fireMarkers = (scheduler as unknown as { lastTimerFireAtMs: Map }).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 }) + .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 }) + .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 }).timers; + const arms = (scheduler as unknown as { currentTimerArm: Map }).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 }).timers; - clearInterval(timers.get("agent-churn")!.handle as ReturnType); + 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 = { + "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) => { + 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).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); }); }); diff --git a/packages/engine/src/agent-heartbeat.ts b/packages/engine/src/agent-heartbeat.ts index 0f319bbe66..8e025a47bc 100644 --- a/packages/engine/src/agent-heartbeat.ts +++ b/packages/engine/src/agent-heartbeat.ts @@ -4144,6 +4144,19 @@ export class HeartbeatTriggerScheduler { private errorRecoveryLimit = MAX_HEARTBEAT_ERROR_RECOVERY_ATTEMPTS; private pendingAssignments: Map = new Map(); private registrationEpochs: Map = 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 = 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 | null = null; private lastAuditRanAtMs = 0; private nonAdvancingRearmState: Map = 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 = 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 { + private async onTimerTick(agentId: string, intervalMs: number, armId?: number): Promise { 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) {