From 923bba70824b31a3fc75ba5b785fbb5cf3333f75 Mon Sep 17 00:00:00 2001 From: gsxdsm Date: Tue, 7 Jul 2026 13:53:28 -0700 Subject: [PATCH] FN-7645: force re-arm zombie heartbeat timers detected as stale during audit MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Fixes the heartbeat timer audit so it repairs not just missing timer registrations but also 'zombie' ones — timer entries that remain present in memory after their underlying interval silently stopped firing. Long-interval (~1h) agents were most affected since a single lost tick compounded into hours of staleness before self-healing noticed. - HeartbeatTriggerScheduler audit now computes staleness (elapsed vs repair-stale threshold) up front for every timer-eligible agent, not only for agents missing a timer entry - Present-but-stale timer entries are now treated as non-advancing and force cleared/re-registered via registerAgent() (which already clears any existing timer before re-arming) - Fresh (non-stale) present timers are left alone so healthy short-interval agents are never force-re-armed or double-ticked - Repair reason/log messages now distinguish zombie-timer-rearmed repairs from missing-registration repairs, and the summary log reports counts for each - Added heartbeat-scheduler tests covering the zombie-timer repair path - Added changeset and a docs/architecture.md note Files changed: .changeset/fn-7645-heartbeat-rearm.md | 7 + docs/architecture.md | 1 + .../src/__tests__/heartbeat-scheduler.test.ts | 223 +++++++++++++++++++++ packages/engine/src/agent-heartbeat.ts | 42 +++- 4 files changed, 266 insertions(+), 7 deletions(-) Fusion-Task-Id: FN-7645 Fusion-Task-Lineage: 652bc2eb-a660-4306-9f85-d2d5f9ca7e38 Co-authored-by: Fusion (runfusion.ai) --- .changeset/fn-7645-heartbeat-rearm.md | 7 + docs/architecture.md | 1 + .../src/__tests__/heartbeat-scheduler.test.ts | 223 ++++++++++++++++++ packages/engine/src/agent-heartbeat.ts | 42 +++- 4 files changed, 266 insertions(+), 7 deletions(-) create mode 100644 .changeset/fn-7645-heartbeat-rearm.md diff --git a/.changeset/fn-7645-heartbeat-rearm.md b/.changeset/fn-7645-heartbeat-rearm.md new file mode 100644 index 0000000000..fc812daf5a --- /dev/null +++ b/.changeset/fn-7645-heartbeat-rearm.md @@ -0,0 +1,7 @@ +--- +"@runfusion/fusion": patch +--- + +summary: Fix agents on long heartbeat intervals silently going stale for hours. +category: fix +dev: HeartbeatTriggerScheduler timer audit now re-arms non-advancing long-interval registrations (stale lastHeartbeatAt with a live timer entry), not just missing ones (FN-7645). diff --git a/docs/architecture.md b/docs/architecture.md index b878076706..729e520be2 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -1350,6 +1350,7 @@ Limits are controlled by project settings (`maxSpawnedAgentsPerParent`, `maxSpaw - task assignment - on-demand runs - Assignment triggers skipped because a heartbeat run is already active are deferred and re-fired from `HeartbeatMonitor.onRunCompleted`, preserving the existing completion recovery path while avoiding timer-dependent stalls. +- FN-7645: `HeartbeatTriggerScheduler.auditTimerRegistrations` (60s cadence) repairs both MISSING timer registrations and "zombie" ones — a timer map entry that stays present after its underlying `setInterval` silently stops firing. When a tickable, heartbeat-managed agent's `lastHeartbeatAt` exceeds the repair-stale threshold (`heartbeatIntervalMs * heartbeatRepairStaleMultiplier`, default 2x) even though a timer entry already exists, the audit clears and re-registers it (phase-aligned via `computeInitialDelayMs`), logging `reason=zombie-timer-rearmed`. This closes the gap where long-interval (~1h) agents could silently drift stale for hours because their sparse cadence meant a single lost tick was never re-armed by the previous missing-registration-only repair; short-interval agents were unaffected because their frequent ticks self-heal within minutes. All existing guards are preserved: pause suppression (`globalPause`/`enginePaused`) still gates dispatch in `onTimerTick`, FN-4119 stale active-run reaping still runs first for agents with a live run, ephemeral/task-worker agents stay excluded via `isTimerEligibleAgent`, and `registrationEpochs` staleness protection is untouched. ### Custom instructions `packages/engine/src/agent-instructions.ts` resolves per-agent instruction text/path with path-traversal and extension validation. diff --git a/packages/engine/src/__tests__/heartbeat-scheduler.test.ts b/packages/engine/src/__tests__/heartbeat-scheduler.test.ts index d57dccefb3..0e762b184f 100644 --- a/packages/engine/src/__tests__/heartbeat-scheduler.test.ts +++ b/packages/engine/src/__tests__/heartbeat-scheduler.test.ts @@ -471,6 +471,229 @@ describe("HeartbeatTriggerScheduler", () => { expect(store.endHeartbeatRun).not.toHaveBeenCalled(); expect(scheduler.getRegisteredAgents()).not.toContain("executor-FN-999"); }); + + describe("FN-7645: zombie long-interval timer re-arm", () => { + /** + * FNXC:AgentHeartbeat 2026-07-07-00:00: + * Regression coverage for FN-7645: a long-interval (~1h) agent whose + * live setInterval silently stops firing must self-heal within one 60s + * audit cycle once its lastHeartbeatAt goes stale beyond threshold, even + * though a timer map entry is still present (the audit previously + * short-circuited on `this.timers.has(agent.id)` and only repaired + * *missing* registrations). A parallel healthy short-interval agent must + * keep ticking on its own cadence, unaffected/undisturbed. + */ + function buildAgent(overrides: Partial & { id: string; heartbeatIntervalMs: number }): Agent { + const { heartbeatIntervalMs, ...rest } = overrides; + return { + name: rest.id, + role: "executor", + state: "active", + lastHeartbeatAt: "2026-01-01T00:00:00.000Z", + runtimeConfig: { enabled: true, heartbeatIntervalMs }, + createdAt: "2026-01-01T00:00:00.000Z", + updatedAt: "2026-01-01T00:00:00.000Z", + metadata: {}, + ...rest, + } as Agent; + } + + it("re-arms a present-but-non-advancing long-interval timer while leaving a healthy short-interval agent unaffected", async () => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-01-01T00:00:00.000Z")); + + const agents: Record = { + "agent-long": buildAgent({ id: "agent-long", heartbeatIntervalMs: 3_600_000 }), + "agent-short": buildAgent({ id: "agent-short", heartbeatIntervalMs: 300_000 }), + }; + vi.mocked(store.listAgents).mockImplementation(async () => Object.values(agents)); + vi.mocked(store.getActiveHeartbeatRun).mockResolvedValue(null); + + // Simulate production behavior: a dispatched timer tick advances the + // agent's lastHeartbeatAt (as a real heartbeat run completion would). + callback.mockImplementation(async (agentId: string) => { + agents[agentId] = { ...agents[agentId], lastHeartbeatAt: new Date().toISOString() }; + }); + + scheduler = new HeartbeatTriggerScheduler(store, callback); + scheduler.start(); + await vi.advanceTimersByTimeAsync(0); + + expect(scheduler.getRegisteredAgents()).toContain("agent-long"); + expect(scheduler.getRegisteredAgents()).toContain("agent-short"); + + // Kill the long-interval agent's live interval handle out from under the + // scheduler, simulating a silently-dead setInterval while its map entry + // (and therefore the audit's "already registered" short-circuit) remains + // present — the exact "zombie timer" signature this task fixes. + const timers = (scheduler as unknown as { timers: Map }).timers; + const longTimerEntry = timers.get("agent-long"); + expect(longTimerEntry?.kind).toBe("interval"); + clearInterval(longTimerEntry!.handle as ReturnType); + + callback.mockClear(); + + // Advance across many 60s audit cycles spanning several hours — the + // ~18h staleness signature from the original report, scaled down for + // test speed but well past the default 2x-interval (7.2M ms) threshold. + await vi.advanceTimersByTimeAsync(4 * 60 * 60 * 1000); // 4 hours + + // Assertion it is gone: the long-interval agent must have been + // re-armed and dispatched within one audit cycle of going stale. + expect(callback).toHaveBeenCalledWith("agent-long", "timer", expect.anything()); + expect(scheduler.getRegisteredAgents()).toContain("agent-long"); + expect(heartbeatLog.warn).toHaveBeenCalledWith(expect.stringContaining("zombie-timer-rearmed")); + + // The healthy short-interval agent ticks on its own normal cadence + // (4h / 300_000ms = 48 ticks) and must not be force re-armed or thrashed. + const shortTicks = callback.mock.calls.filter((call) => call[0] === "agent-short").length; + expect(shortTicks).toBe(48); + expect(heartbeatLog.warn).not.toHaveBeenCalledWith(expect.stringContaining("zombie-timer-rearmed agentId=agent-short")); + }); + + it("does not force re-arm a long-interval timer entry whose lastHeartbeatAt is fresh", async () => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-01-01T00:00:00.000Z")); + + const agent = buildAgent({ id: "agent-long", heartbeatIntervalMs: 3_600_000 }); + vi.mocked(store.listAgents).mockResolvedValue([agent]); + vi.mocked(store.getActiveHeartbeatRun).mockResolvedValue(null); + + scheduler = new HeartbeatTriggerScheduler(store, callback); + scheduler.start(); + await vi.advanceTimersByTimeAsync(0); + + callback.mockClear(); + vi.mocked(heartbeatLog.warn).mockClear(); + + // Well within the 2x-interval stale threshold (7.2M ms) — several audit + // cycles must not force a re-arm or dispatch. + await vi.advanceTimersByTimeAsync(30 * 60_000); // 30 minutes + + expect(callback).not.toHaveBeenCalled(); + expect(heartbeatLog.warn).not.toHaveBeenCalledWith(expect.stringContaining("zombie-timer-rearmed")); + }); + + it("does not force re-arm when lastHeartbeatAt is null/never-ticked even though a timer entry is present", async () => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-01-01T00:00:00.000Z")); + + const agent = buildAgent({ id: "agent-long", heartbeatIntervalMs: 3_600_000, lastHeartbeatAt: null as unknown as string }); + vi.mocked(store.listAgents).mockResolvedValue([agent]); + vi.mocked(store.getActiveHeartbeatRun).mockResolvedValue(null); + + scheduler = new HeartbeatTriggerScheduler(store, callback); + scheduler.start(); + await vi.advanceTimersByTimeAsync(0); + + callback.mockClear(); + vi.mocked(heartbeatLog.warn).mockClear(); + + // getHeartbeatAgeMs() returns NaN for a null lastHeartbeatAt, so the + // "stale beyond threshold" comparison must never be true — a never-ticked + // agent with a live timer entry must be left alone by the audit. + await vi.advanceTimersByTimeAsync(4 * 60 * 60 * 1000); + + expect(heartbeatLog.warn).not.toHaveBeenCalledWith(expect.stringContaining("zombie-timer-rearmed")); + }); + + it("only force re-arms once stale beyond threshold, not at a small multiple within it", async () => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-01-01T00:00:00.000Z")); + + // Default repair-stale multiplier is 2x, so threshold = 7_200_000ms (2h). + const agent = buildAgent({ id: "agent-long", heartbeatIntervalMs: 3_600_000 }); + vi.mocked(store.listAgents).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; + clearInterval(timers.get("agent-long")!.handle as ReturnType); + callback.mockClear(); + vi.mocked(heartbeatLog.warn).mockClear(); + + // Stale by a small multiple (1.1x interval = 3_960_000ms) — still under + // the 2x threshold, so the zombie repair must not fire yet. + await vi.advanceTimersByTimeAsync(3_960_000); + expect(heartbeatLog.warn).not.toHaveBeenCalledWith(expect.stringContaining("zombie-timer-rearmed")); + expect(callback).not.toHaveBeenCalled(); + + // Cross the 2x threshold (total elapsed now > 7_200_000ms) — the next + // audit cycle must repair it. Repair re-registers via a jittered + // (<=5s) catch-up timeout, so advance a little further to let that + // dispatch actually fire. + await vi.advanceTimersByTimeAsync(3_300_000); + await vi.advanceTimersByTimeAsync(5_000); + expect(heartbeatLog.warn).toHaveBeenCalledWith(expect.stringContaining("zombie-timer-rearmed")); + expect(callback).toHaveBeenCalledWith("agent-long", "timer", expect.anything()); + }); + + 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")); + + const agent = buildAgent({ id: "agent-long", heartbeatIntervalMs: 3_600_000 }); + vi.mocked(store.listAgents).mockResolvedValue([agent]); + vi.mocked(store.getActiveHeartbeatRun).mockResolvedValue(null); + + const taskStore = { + getSettings: vi.fn().mockResolvedValue({ globalPause: true, enginePaused: false }), + } as unknown as TaskStore; + + scheduler = new HeartbeatTriggerScheduler(store, callback, taskStore); + scheduler.start(); + await vi.advanceTimersByTimeAsync(0); + + const timers = (scheduler as unknown as { timers: Map }).timers; + clearInterval(timers.get("agent-long")!.handle as ReturnType); + callback.mockClear(); + + // The audit still re-registers the zombie timer (registration is not + // itself gated on pause), but the dispatched tick must be suppressed by + // onTimerTick's globalPause guard — the callback must never fire while + // globally paused, even for a freshly-repaired long-interval agent. + await vi.advanceTimersByTimeAsync(4 * 60 * 60 * 1000); + + expect(callback).not.toHaveBeenCalled(); + }); + + it("does not disturb a healthy active heartbeat run even when lastHeartbeatAt looks stale", async () => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-01-01T02:00:00.000Z")); + + // Active-run staleness (FN-4119) is judged against `heartbeatTimeoutMs`, + // independently from the timer-registration repair threshold (which is + // based on `heartbeatIntervalMs`). Use a long heartbeatTimeoutMs so the + // active run reads as healthy throughout the audit window even though + // lastHeartbeatAt (2h old) has already crossed the interval-based + // zombie-repair threshold. An agent with a genuinely live active run + // never gets a bare timer entry armed in the first place (audit skips + // re-arm while the run is healthy), so this proves the new zombie-stale + // check does not override the FN-4119 active-run guard. + const agent = buildAgent({ id: "agent-long", heartbeatIntervalMs: 3_600_000 }); + (agent.runtimeConfig as Record).heartbeatTimeoutMs = 24 * 60 * 60 * 1000; + vi.mocked(store.listAgents).mockResolvedValue([agent]); + vi.mocked(store.getActiveHeartbeatRun).mockResolvedValue({ id: "run-healthy", status: "active" } as any); + + scheduler = new HeartbeatTriggerScheduler(store, callback); + scheduler.start(); + await vi.advanceTimersByTimeAsync(0); + + expect(scheduler.getRegisteredAgents()).not.toContain("agent-long"); + callback.mockClear(); + vi.mocked(store.endHeartbeatRun).mockClear(); + + await vi.advanceTimersByTimeAsync(60_000); // one audit cycle + + expect(store.endHeartbeatRun).not.toHaveBeenCalled(); + expect(callback).not.toHaveBeenCalled(); + expect(scheduler.getRegisteredAgents()).not.toContain("agent-long"); + expect(heartbeatLog.log).toHaveBeenCalledWith("Timer audit skipped re-arm for agent-long (active run)"); + }); + }); }); describe("registerAgent", () => { diff --git a/packages/engine/src/agent-heartbeat.ts b/packages/engine/src/agent-heartbeat.ts index fbdc30fc6a..bd7faadd85 100644 --- a/packages/engine/src/agent-heartbeat.ts +++ b/packages/engine/src/agent-heartbeat.ts @@ -4616,9 +4616,32 @@ export class HeartbeatTriggerScheduler { const staleMultiplier = this.resolveRepairStaleMultiplier(settings); const agents = await this.store.listAgents(); let rearmedCount = 0; + let zombieRearmedCount = 0; for (const agent of agents) { if (!this.isTimerEligibleAgent(agent)) continue; - if (this.timers.has(agent.id)) continue; + + const hasTimerEntry = this.timers.has(agent.id); + const staleThresholdMs = this.getRepairStaleThresholdMs(agent, staleMultiplier); + const elapsedMs = getHeartbeatAgeMs(agent); + const staleAtRepair = Number.isFinite(elapsedMs) && elapsedMs > staleThresholdMs; + + /* + * FNXC:AgentHeartbeat 2026-07-07-00:00: + * FN-7645 — the audit previously short-circuited on `if (this.timers.has(agent.id)) continue;`, + * which only ever repaired MISSING registrations. A live setInterval can silently stop firing + * (dropped/garbage-collected interval, transient scheduling failure that doesn't throw) while its + * entry stays present in `this.timers` forever — a "zombie" registration. Long-interval (~1h) + * agents were the ones that actually suffered from this because their sparse cadence meant a + * single lost tick compounded into hours of silence before anyone noticed (short intervals + * self-heal within minutes just by virtue of ticking often). Fix: when a timer entry IS present + * but the agent's lastHeartbeatAt has gone stale beyond the same repair threshold used for + * missing-registration repair, treat it as non-advancing and force a clear+re-register — while a + * fresh (non-stale) present timer is left alone so healthy short-interval agents are never + * force-re-armed or double-ticked. + */ + if (hasTimerEntry && !staleAtRepair) continue; + + const isZombieRearm = hasTimerEntry && staleAtRepair; const activeRun = await this.store.getActiveHeartbeatRun(agent.id); const activeRunId = activeRun?.id ?? null; @@ -4640,25 +4663,30 @@ export class HeartbeatTriggerScheduler { } } + // registerAgent() clears any existing (including zombie) timer entry via + // clearAgentTimer() before re-arming, so a present-but-dead interval handle + // never leaks and the new registration phase-aligns via computeInitialDelayMs. this.registerAgent(agent.id, this.getAgentTimerConfig(agent), { lastHeartbeatAt: agent.lastHeartbeatAt, }); - const staleThresholdMs = this.getRepairStaleThresholdMs(agent, staleMultiplier); - const elapsedMs = getHeartbeatAgeMs(agent); - const staleAtRepair = Number.isFinite(elapsedMs) && elapsedMs > staleThresholdMs; const staleRepairReason = staleAtRepair - ? `No heartbeat for ${Math.round(elapsedMs / 1000)}s before timer audit repair (threshold ${Math.round(staleThresholdMs / 1000)}s)` + ? isZombieRearm + ? `zombie-timer-rearmed: no heartbeat for ${Math.round(elapsedMs / 1000)}s while a timer entry remained present (threshold ${Math.round(staleThresholdMs / 1000)}s)` + : `No heartbeat for ${Math.round(elapsedMs / 1000)}s before timer audit repair (threshold ${Math.round(staleThresholdMs / 1000)}s)` : undefined; await this.markRepairMetadata(agent, staleAtRepair, staleRepairReason); rearmedCount++; + if (isZombieRearm) zombieRearmedCount++; if (reapedActiveRun && activeRunId) { heartbeatLog.log( `Timer audit re-armed after stale-run reap reason=timer-audit-rearmed agentId=${agent.id} runId=${activeRunId} elapsedMs=${activeRunElapsedMs} thresholdMs=${activeRunThresholdMs}`, ); } - if (staleAtRepair) { + if (isZombieRearm) { + heartbeatLog.warn(`Timer audit force re-armed non-advancing agent ${agent.id} reason=zombie-timer-rearmed (audit:${reason}): ${staleRepairReason}`); + } else if (staleAtRepair) { heartbeatLog.warn(`Timer re-armed stale agent ${agent.id} (audit:${reason}): ${staleRepairReason ?? "heartbeat exceeded stale threshold before repair"}`); } else { heartbeatLog.log(`Timer re-armed for ${agent.id} (audit:${reason})`); @@ -4666,7 +4694,7 @@ export class HeartbeatTriggerScheduler { } if (rearmedCount > 0) { - heartbeatLog.log(`Timer audit repaired ${rearmedCount} missing registration(s) (${reason})`); + heartbeatLog.log(`Timer audit repaired ${rearmedCount} registration(s) (${zombieRearmedCount} zombie, ${rearmedCount - zombieRearmedCount} missing) (${reason})`); } } catch (error) { heartbeatLog.warn(`Timer audit failed (${reason}): ${error instanceof Error ? error.message : String(error)}`);