FN-7645: force re-arm zombie heartbeat timers detected as stale during audit
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) <noreply@runfusion.ai>
This commit is contained in:
gsxdsm
7
.changeset/fn-7645-heartbeat-rearm.md
Normal file
7
.changeset/fn-7645-heartbeat-rearm.md
Normal file
@@ -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).
|
||||
@@ -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.
|
||||
|
||||
@@ -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<Agent> & { 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<string, Agent> = {
|
||||
"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<string, { handle: unknown; kind: string }> }).timers;
|
||||
const longTimerEntry = timers.get("agent-long");
|
||||
expect(longTimerEntry?.kind).toBe("interval");
|
||||
clearInterval(longTimerEntry!.handle as ReturnType<typeof setInterval>);
|
||||
|
||||
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<string, { handle: unknown; kind: string }> }).timers;
|
||||
clearInterval(timers.get("agent-long")!.handle as ReturnType<typeof setInterval>);
|
||||
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<string, { handle: unknown; kind: string }> }).timers;
|
||||
clearInterval(timers.get("agent-long")!.handle as ReturnType<typeof setInterval>);
|
||||
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<string, unknown>).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", () => {
|
||||
|
||||
@@ -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)}`);
|
||||
|
||||
Reference in New Issue
Block a user