From e6b6223d30357d71582ce9dc24c74ef04e61e27f Mon Sep 17 00:00:00 2001 From: gsxdsm Date: Mon, 10 Aug 2026 10:33:35 -0700 Subject: [PATCH] fix(engine): stop per-poll symbol-lock renewal log and activityLog spam MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Renewal runs every poll for every implementation-column task with declared symbols, and a lost lock never recovers by renewing — renewSymbolLocks reports the same lost set on each pass, so the warning and its store.logEntry companion repeated forever: log-pane spam plus unbounded activityLog growth for a stuck task. The two error paths had the same shape on any persistent failure. Extract the executor's suppression into a shared createRepeatSuppressedLog and use it in both: first occurrence per task/signature logs at full level, repeats drop to debug(), a changed lost set or error message logs again, and a clean renewal clears the memo. The logEntry write is gated on the same decision. Co-Authored-By: Claude Opus 5 --- .../quiet-executor-dispatch-blocked-logs.md | 4 +- .../scheduler-workflow-cutover.test.ts | 41 +++++++ .../__tests__/dispatch-block-log.test.ts | 77 ------------- .../engine/src/executor/dispatch-block-log.ts | 18 +-- packages/engine/src/scheduler.ts | 47 +++++++- .../__tests__/repeat-suppressed-log.test.ts | 106 ++++++++++++++++++ .../engine/src/util/repeat-suppressed-log.ts | 53 +++++++++ 7 files changed, 254 insertions(+), 92 deletions(-) delete mode 100644 packages/engine/src/executor/__tests__/dispatch-block-log.test.ts create mode 100644 packages/engine/src/util/__tests__/repeat-suppressed-log.test.ts create mode 100644 packages/engine/src/util/repeat-suppressed-log.ts diff --git a/.changeset/quiet-executor-dispatch-blocked-logs.md b/.changeset/quiet-executor-dispatch-blocked-logs.md index d2b234a995..93286df121 100644 --- a/.changeset/quiet-executor-dispatch-blocked-logs.md +++ b/.changeset/quiet-executor-dispatch-blocked-logs.md @@ -2,6 +2,6 @@ "@runfusion/fusion": patch --- -summary: Stop the engine log from repeating "executor dispatch blocked" every poll for a stuck task. +summary: Stop the engine log repeating dispatch-blocked and symbol-lock-loss lines every poll for a stuck task. category: fix -dev: The unmet-dependency and ephemeral-disabled pre-dispatch gates now route through `logDispatchBlockedOnce` (packages/engine/src/executor/dispatch-block-log.ts): first block per task/reason logs at `log()`, identical repeats drop to `debug()` (`FUSION_DEBUG=executor`), a changed reason logs again, and the marker clears when the gate passes. +dev: Shared `createRepeatSuppressedLog` (packages/engine/src/util/repeat-suppressed-log.ts) backs the executor's unmet-dependency/ephemeral-disabled pre-dispatch gates and the scheduler's symbol-lock renewal: first occurrence per task/signature logs at full level, identical repeats drop to `debug()` (`FUSION_DEBUG=executor,scheduler`), a changed signature logs again, and the memo clears when the condition resolves. Symbol-lock loss also gated its per-poll `store.logEntry` append on the same decision. diff --git a/packages/engine/src/__tests__/scheduler-workflow-cutover.test.ts b/packages/engine/src/__tests__/scheduler-workflow-cutover.test.ts index fcc6fd3e12..ddf6132cba 100644 --- a/packages/engine/src/__tests__/scheduler-workflow-cutover.test.ts +++ b/packages/engine/src/__tests__/scheduler-workflow-cutover.test.ts @@ -169,6 +169,47 @@ describe("Scheduler workflow cutover", () => { expect(store.renewSymbolLocks).toHaveBeenCalledWith(["pkg/a.ts#A"], "FN-symbol-owner", 10 * 60_000); }); + /* + FNXC:EngineDiagnostics 2026-08-10-17:13: + Renewal runs every poll, and a LOST lock never recovers by renewing — the same `lost` set comes back on every + subsequent pass. Reporting it per poll spammed the log pane AND appended an identical activityLog row forever for a + stuck task. Assert the transition contract: report once per distinct lost set, again when the set CHANGES, and once + more after a clean renewal clears the memo — with the `logEntry` write gated on the same decision. + */ + it("reports a persistently lost symbol lock once per distinct loss, not once per poll", async () => { + const active = task({ + id: "FN-symbol-owner", + column: "in-progress", + missionId: "M-1", + sliceId: "SL-1", + declaredSymbols: ["pkg/a.ts#A"], + }); + const store = storeWith([active]); + vi.mocked(store.renewSymbolLocks).mockResolvedValue({ renewed: [], lost: ["pkg/a.ts#A"] } as any); + const scheduler = new Scheduler(store); + (scheduler as unknown as { running: boolean }).running = true; + + await scheduler.schedule(); + await scheduler.schedule(); + await scheduler.schedule(); + + const lossEntries = () => vi.mocked(store.logEntry).mock.calls.filter((call) => String(call[1]).startsWith("symbol-lock renewal lost")); + expect(lossEntries()).toHaveLength(1); + + // A different lost set is a real transition and reports again. + vi.mocked(store.renewSymbolLocks).mockResolvedValue({ renewed: [], lost: ["pkg/a.ts#A", "pkg/b.ts#B"] } as any); + await scheduler.schedule(); + await scheduler.schedule(); + expect(lossEntries()).toHaveLength(2); + + // A clean renewal clears the memo, so a later loss is reported afresh. + vi.mocked(store.renewSymbolLocks).mockResolvedValue({ renewed: ["pkg/a.ts#A"], lost: [] } as any); + await scheduler.schedule(); + vi.mocked(store.renewSymbolLocks).mockResolvedValue({ renewed: [], lost: ["pkg/a.ts#A", "pkg/b.ts#B"] } as any); + await scheduler.schedule(); + expect(lossEntries()).toHaveLength(3); + }); + it("renews locks in a custom workflow WIP column", async () => { const active = task({ id: "FN-custom-symbol-owner", diff --git a/packages/engine/src/executor/__tests__/dispatch-block-log.test.ts b/packages/engine/src/executor/__tests__/dispatch-block-log.test.ts deleted file mode 100644 index 4c0b0e2fac..0000000000 --- a/packages/engine/src/executor/__tests__/dispatch-block-log.test.ts +++ /dev/null @@ -1,77 +0,0 @@ -import { beforeEach, describe, expect, it, vi } from "vitest"; -import type { Logger } from "../../logger.js"; -import { - clearDispatchBlockedLogState, - logDispatchBlockedOnce, - resetDispatchBlockedLogState, -} from "../dispatch-block-log.js"; - -/* -FNXC:EngineDiagnostics 2026-08-10-08:59: -The executor's pre-dispatch gates re-run on every dispatch attempt for a blocked task and used to re-log the same -"executor dispatch blocked" line each pass, flooding the default-level TUI log pane. The invariant asserted here is -per-signature, not per-call-site: the FIRST block logs at `log()`, identical repeats drop to `debug()`, a CHANGED reason -logs again (operators must still see transitions), and clearing the state after the gate passes restores `log()` for the -next block. Both gates (unmet dependencies, ephemeral-agents-off) route through this helper. -*/ -function createFakeLogger(): Logger & { log: ReturnType; debug: ReturnType } { - return { - log: vi.fn(), - debug: vi.fn(), - warn: vi.fn(), - error: vi.fn(), - } as unknown as Logger & { log: ReturnType; debug: ReturnType }; -} - -describe("logDispatchBlockedOnce", () => { - beforeEach(() => { - resetDispatchBlockedLogState(); - }); - - it("logs the first block and demotes identical repeats to debug", () => { - const logger = createFakeLogger(); - - for (let i = 0; i < 5; i++) { - logDispatchBlockedOnce(logger, "FN-1", "dependencies:FN-PARENT", "FN-1: blocked"); - } - - expect(logger.log).toHaveBeenCalledTimes(1); - expect(logger.log).toHaveBeenCalledWith("FN-1: blocked"); - expect(logger.debug).toHaveBeenCalledTimes(4); - }); - - it("logs again when the block reason changes", () => { - const logger = createFakeLogger(); - - logDispatchBlockedOnce(logger, "FN-1", "dependencies:FN-A", "FN-1: blocked by FN-A"); - logDispatchBlockedOnce(logger, "FN-1", "dependencies:FN-A", "FN-1: blocked by FN-A"); - logDispatchBlockedOnce(logger, "FN-1", "dependencies:FN-B", "FN-1: blocked by FN-B"); - - expect(logger.log.mock.calls.map((call) => call[0])).toEqual([ - "FN-1: blocked by FN-A", - "FN-1: blocked by FN-B", - ]); - }); - - it("keeps signatures per task so one blocked task does not silence another", () => { - const logger = createFakeLogger(); - - logDispatchBlockedOnce(logger, "FN-1", "ephemeral-disabled", "FN-1: blocked"); - logDispatchBlockedOnce(logger, "FN-2", "ephemeral-disabled", "FN-2: blocked"); - - expect(logger.log).toHaveBeenCalledTimes(2); - expect(logger.debug).not.toHaveBeenCalled(); - }); - - it("logs at default level again after the gate passes and clears the state", () => { - const logger = createFakeLogger(); - - logDispatchBlockedOnce(logger, "FN-1", "ephemeral-disabled", "FN-1: blocked"); - logDispatchBlockedOnce(logger, "FN-1", "ephemeral-disabled", "FN-1: blocked"); - clearDispatchBlockedLogState("FN-1"); - logDispatchBlockedOnce(logger, "FN-1", "ephemeral-disabled", "FN-1: blocked"); - - expect(logger.log).toHaveBeenCalledTimes(2); - expect(logger.debug).toHaveBeenCalledTimes(1); - }); -}); diff --git a/packages/engine/src/executor/dispatch-block-log.ts b/packages/engine/src/executor/dispatch-block-log.ts index f4d98a5319..152972a3c5 100644 --- a/packages/engine/src/executor/dispatch-block-log.ts +++ b/packages/engine/src/executor/dispatch-block-log.ts @@ -10,30 +10,30 @@ * (opt in with `FUSION_DEBUG=executor`). A changed reason — e.g. a different unmet dependency — is a new signature and * logs again, so operators still see the transition. Callers clear the marker when the gate passes so the next block of * the same task is reported afresh; the map is keyed by task id and is bounded by the set of currently-blocked tasks. + * + * FNXC:EngineDiagnostics 2026-08-10-17:13: + * The suppression itself is now the shared `createRepeatSuppressedLog` primitive — the scheduler's symbol-lock renewal + * needed the identical behaviour, so the mechanism lives in one place while this module stays the executor's instance. */ import type { Logger } from "../logger.js"; +import { createRepeatSuppressedLog } from "../util/repeat-suppressed-log.js"; -const lastLoggedBlockSignatureByTaskId = new Map(); +const dispatchBlockLog = createRepeatSuppressedLog(); /** * Log a dispatch-block message at `log()` level only when `signature` differs from the last one logged for `taskId`; * otherwise emit it at `debug()` level. */ export function logDispatchBlockedOnce(logger: Logger, taskId: string, signature: string, message: string): void { - if (lastLoggedBlockSignatureByTaskId.get(taskId) === signature) { - logger.debug(message); - return; - } - lastLoggedBlockSignatureByTaskId.set(taskId, signature); - logger.log(message); + dispatchBlockLog.logOnce(logger, taskId, signature, message); } /** Forget a task's last-logged block signature so its next block is reported at `log()` level again. */ export function clearDispatchBlockedLogState(taskId: string): void { - lastLoggedBlockSignatureByTaskId.delete(taskId); + dispatchBlockLog.clear(taskId); } /** Test-only: drop all remembered signatures. */ export function resetDispatchBlockedLogState(): void { - lastLoggedBlockSignatureByTaskId.clear(); + dispatchBlockLog.reset(); } diff --git a/packages/engine/src/scheduler.ts b/packages/engine/src/scheduler.ts index 52dc779c37..24b94cc36d 100644 --- a/packages/engine/src/scheduler.ts +++ b/packages/engine/src/scheduler.ts @@ -28,6 +28,7 @@ import { } from "./concurrency/concurrency.js"; import { planTaskWorktreePath, resolveTaskWorkingBranch } from "./worktree/worktree-names.js"; import { schedulerLog } from "./logger.js"; +import { createRepeatSuppressedLog } from "./util/repeat-suppressed-log.js"; import { type PrMonitor, type PrComment } from "./merge/pr-monitor.js"; import { reconcileMissionFeatureState } from "./missions/mission-feature-sync.js"; import { resolveDedicatedPlannerColumnsForTask, resolvePlannerLanesForTask } from "./planner-lane-resolution.js"; @@ -953,6 +954,8 @@ export class Scheduler { private wasPermanentAgentUnavailable = new Set(); /** Tracks dispatch-queued reason signatures to avoid per-tick log spam. */ private wasDispatchQueuedReasonLogged = new Set(); + /** Tracks per-task symbol-lock renewal outcomes so a persistent loss/error reports once, not once per poll. */ + private readonly symbolLockRenewalLog = createRepeatSuppressedLog(); /** Tracks per-task candidacy fingerprints for task:updated auto-claim invalidation gating. */ private lastAutoClaimFingerprint = new Map(); /** Tracks recent engine-sourced in-progress → todo requeues to prevent immediate re-dispatch races. */ @@ -1624,6 +1627,7 @@ export class Scheduler { this.wasNodeDispatchValidationBlocked.clear(); this.wasPermanentAgentUnavailable.clear(); this.wasDispatchQueuedReasonLogged.clear(); + this.symbolLockRenewalLog.reset(); schedulerLog.log("Stopped"); } @@ -2170,22 +2174,57 @@ export class Scheduler { try { missionLinked = Boolean(await this.options.missionStore.getFeatureByTaskId(task.id)); } catch (error) { - schedulerLog.warn(`Symbol-lock renewal lineage lookup failed for ${task.id}:`, error); + const message = error instanceof Error ? error.message : String(error); + this.symbolLockRenewalLog.logOnce( + schedulerLog, + task.id, + `lineage-lookup-failed:${message}`, + `Symbol-lock renewal lineage lookup failed for ${task.id}: ${message}`, + "warn", + ); continue; } } if (!missionLinked) continue; + /* + FNXC:EngineDiagnostics 2026-08-10-17:13: + Renewal re-runs every poll for every implementation-column task that declares symbols, and a LOST lock never + recovers by renewing — `renewSymbolLocks` reports the same `lost` set on every subsequent pass, so the warning and + its `logEntry` companion repeated forever: log-pane spam plus an unbounded activityLog append for a stuck task. + Report a lost set (and a persistent renewal error) once per task per distinct signature — a changed set of lost + symbols or a new error message is a real transition and reports again — and clear the memo on a clean renewal so a + later loss is reported afresh. The `logEntry` write is gated on the SAME first-occurrence decision, so the task's + activity log records the transition rather than one row per poll. + */ try { const result = await this.store.renewSymbolLocks(symbols, task.id, SYMBOL_LOCK_LEASE_MS); if (result.lost.length > 0) { - schedulerLog.warn(`Symbol-lock renewal lost ownership for ${task.id}: ${result.lost.join(", ")}`); - await this.store.logEntry(task.id, `symbol-lock renewal lost: ${result.lost.join(", ")}`); + const lost = [...result.lost].sort(); + const appended = this.symbolLockRenewalLog.logOnce( + schedulerLog, + task.id, + `lost:${lost.join(",")}`, + `Symbol-lock renewal lost ownership for ${task.id}: ${result.lost.join(", ")}`, + "warn", + ); + if (appended) { + await this.store.logEntry(task.id, `symbol-lock renewal lost: ${result.lost.join(", ")}`); + } + } else { + this.symbolLockRenewalLog.clear(task.id); } } catch (error) { // Do not abort capacity admission for unrelated tasks; the durable expiry // and self-healing reconciliation remain the crash-safe backstop. - schedulerLog.warn(`Symbol-lock renewal failed for ${task.id}:`, error); + const message = error instanceof Error ? error.message : String(error); + this.symbolLockRenewalLog.logOnce( + schedulerLog, + task.id, + `renewal-failed:${message}`, + `Symbol-lock renewal failed for ${task.id}: ${message}`, + "warn", + ); } } } diff --git a/packages/engine/src/util/__tests__/repeat-suppressed-log.test.ts b/packages/engine/src/util/__tests__/repeat-suppressed-log.test.ts new file mode 100644 index 0000000000..2836b81ba8 --- /dev/null +++ b/packages/engine/src/util/__tests__/repeat-suppressed-log.test.ts @@ -0,0 +1,106 @@ +import { describe, expect, it, vi } from "vitest"; +import type { Logger } from "../../logger.js"; +import { createRepeatSuppressedLog } from "../repeat-suppressed-log.js"; +import { + clearDispatchBlockedLogState, + logDispatchBlockedOnce, + resetDispatchBlockedLogState, +} from "../../executor/dispatch-block-log.js"; + +/* +FNXC:EngineDiagnostics 2026-08-10-08:59: +The executor's pre-dispatch gates re-run on every dispatch attempt for a blocked task and used to re-log the same +"executor dispatch blocked" line each pass, flooding the default-level TUI log pane. The invariant asserted here is +per-signature, not per-call-site: the FIRST occurrence logs at `log()`/`warn()`, identical repeats drop to `debug()`, a +CHANGED reason logs again (operators must still see transitions), and clearing the state after the condition resolves +restores full level for the next occurrence. + +FNXC:EngineDiagnostics 2026-08-10-17:13: +Same mechanism now backs the scheduler's symbol-lock renewal, where a persistent loss also drove a per-poll +`store.logEntry` append — hence the `logOnce` return value, which callers use to gate that companion write. +*/ +function createFakeLogger(): Logger & Record<"log" | "debug" | "warn" | "error", ReturnType> { + return { + log: vi.fn(), + debug: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + } as unknown as Logger & Record<"log" | "debug" | "warn" | "error", ReturnType>; +} + +describe("createRepeatSuppressedLog", () => { + it("logs the first occurrence and demotes identical repeats to debug", () => { + const suppressed = createRepeatSuppressedLog(); + const logger = createFakeLogger(); + + const appended = [...Array(5)].map(() => suppressed.logOnce(logger, "FN-1", "dependencies:FN-PARENT", "FN-1: blocked")); + + expect(appended).toEqual([true, false, false, false, false]); + expect(logger.log).toHaveBeenCalledTimes(1); + expect(logger.log).toHaveBeenCalledWith("FN-1: blocked"); + expect(logger.debug).toHaveBeenCalledTimes(4); + }); + + it("logs again when the signature changes", () => { + const suppressed = createRepeatSuppressedLog(); + const logger = createFakeLogger(); + + suppressed.logOnce(logger, "FN-1", "lost:a", "FN-1: lost a", "warn"); + suppressed.logOnce(logger, "FN-1", "lost:a", "FN-1: lost a", "warn"); + suppressed.logOnce(logger, "FN-1", "lost:a,b", "FN-1: lost a, b", "warn"); + + expect(logger.warn.mock.calls.map((call) => call[0])).toEqual(["FN-1: lost a", "FN-1: lost a, b"]); + expect(logger.log).not.toHaveBeenCalled(); + }); + + it("keeps signatures per key so one stuck task does not silence another", () => { + const suppressed = createRepeatSuppressedLog(); + const logger = createFakeLogger(); + + suppressed.logOnce(logger, "FN-1", "ephemeral-disabled", "FN-1: blocked"); + suppressed.logOnce(logger, "FN-2", "ephemeral-disabled", "FN-2: blocked"); + + expect(logger.log).toHaveBeenCalledTimes(2); + expect(logger.debug).not.toHaveBeenCalled(); + }); + + it("reports at full level again after the condition resolves and the key is cleared", () => { + const suppressed = createRepeatSuppressedLog(); + const logger = createFakeLogger(); + + suppressed.logOnce(logger, "FN-1", "ephemeral-disabled", "FN-1: blocked"); + suppressed.logOnce(logger, "FN-1", "ephemeral-disabled", "FN-1: blocked"); + suppressed.clear("FN-1"); + const appended = suppressed.logOnce(logger, "FN-1", "ephemeral-disabled", "FN-1: blocked"); + + expect(appended).toBe(true); + expect(logger.log).toHaveBeenCalledTimes(2); + expect(logger.debug).toHaveBeenCalledTimes(1); + }); + + it("keeps instances independent so subsystems cannot collide on the same key", () => { + const executorSuppressed = createRepeatSuppressedLog(); + const schedulerSuppressed = createRepeatSuppressedLog(); + const logger = createFakeLogger(); + + executorSuppressed.logOnce(logger, "FN-1", "blocked", "executor"); + schedulerSuppressed.logOnce(logger, "FN-1", "blocked", "scheduler"); + + expect(logger.log).toHaveBeenCalledTimes(2); + }); +}); + +describe("executor dispatch-block log instance", () => { + it("suppresses repeats and re-reports after the gate passes", () => { + resetDispatchBlockedLogState(); + const logger = createFakeLogger(); + + logDispatchBlockedOnce(logger, "FN-1", "dependencies:FN-PARENT", "FN-1: blocked"); + logDispatchBlockedOnce(logger, "FN-1", "dependencies:FN-PARENT", "FN-1: blocked"); + clearDispatchBlockedLogState("FN-1"); + logDispatchBlockedOnce(logger, "FN-1", "dependencies:FN-PARENT", "FN-1: blocked"); + + expect(logger.log).toHaveBeenCalledTimes(2); + expect(logger.debug).toHaveBeenCalledTimes(1); + }); +}); diff --git a/packages/engine/src/util/repeat-suppressed-log.ts b/packages/engine/src/util/repeat-suppressed-log.ts new file mode 100644 index 0000000000..6ff9a799a2 --- /dev/null +++ b/packages/engine/src/util/repeat-suppressed-log.ts @@ -0,0 +1,53 @@ +/** + * FNXC:EngineDiagnostics 2026-08-10-17:13: + * Shared primitive for "this condition is re-evaluated every poll but only the TRANSITION is news". + * Engine sweeps (scheduler poll, executor pre-dispatch gates) re-run the same checks on every pass, so a condition that + * persists — an unmet dependency, a lost symbol lock, a failing lookup — used to reprint an identical line at default + * level forever and bury real events in the TUI log pane (the same failure mode the 2026-07-15 routing/capacity sweep + * fixed by hand with per-subsystem `was*Blocked` sets). + * + * `logOnce` logs at `log()`/`warn()` the first time a key is seen with a given signature, and drops identical repeats to + * `debug()` (opt in per subsystem via `FUSION_DEBUG`). A CHANGED signature is a real transition and logs at full level + * again. It returns whether it logged at full level, so callers can gate a companion side effect — a `store.logEntry` + * write that would otherwise append the same row every poll — on the same first-occurrence decision. + * + * The logger is passed per call rather than captured, so a shared instance stays usable from call sites that log through + * different subsystem loggers. Each call site builds its own instance, so keyspaces (task ids) cannot collide across + * subsystems, and callers clear a key when the condition resolves so its next occurrence is reported afresh. State is + * bounded by the set of keys currently in the condition. + */ +import type { Logger } from "../logger.js"; + +export type RepeatSuppressedLog = { + /** + * Emit `message` at `level` when `signature` differs from the last one logged for `key`; otherwise emit at `debug()`. + * + * @returns `true` when the message was logged at `level` (i.e. this is a new or changed condition). + */ + logOnce(logger: Logger, key: string, signature: string, message: string, level?: "log" | "warn"): boolean; + /** Forget a key so its next occurrence logs at full level again. */ + clear(key: string): void; + /** Drop all remembered signatures (engine stop / tests). */ + reset(): void; +}; + +export function createRepeatSuppressedLog(): RepeatSuppressedLog { + const lastSignatureByKey = new Map(); + return { + logOnce(logger, key, signature, message, level = "log") { + if (lastSignatureByKey.get(key) === signature) { + logger.debug(message); + return false; + } + lastSignatureByKey.set(key, signature); + logger[level](message); + return true; + }, + clear(key) { + lastSignatureByKey.delete(key); + }, + reset() { + lastSignatureByKey.clear(); + }, + }; +}