From a2deae041ae2421083a0042db81a742b34439c76 Mon Sep 17 00:00:00 2001 From: gsxdsm Date: Mon, 10 Aug 2026 10:11:11 -0700 Subject: [PATCH] fix(engine): stop per-poll executor dispatch-blocked log spam The unmet-dependency and ephemeral-disabled pre-dispatch gates re-run on every dispatch attempt for a blocked task but only change state on the first, so every later pass re-logged the same line at default level and drowned the log pane. Route both through logDispatchBlockedOnce: 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. Co-Authored-By: Claude Opus 5 --- .../quiet-executor-dispatch-blocked-logs.md | 7 ++ .../__tests__/dispatch-block-log.test.ts | 77 +++++++++++++++++++ ...-outer-dispatch-when-ephemeral-disabled.ts | 23 +++++- .../src/executor/dependency-dispatch-gate.ts | 18 ++++- .../engine/src/executor/dispatch-block-log.ts | 39 ++++++++++ 5 files changed, 157 insertions(+), 7 deletions(-) create mode 100644 .changeset/quiet-executor-dispatch-blocked-logs.md create mode 100644 packages/engine/src/executor/__tests__/dispatch-block-log.test.ts create mode 100644 packages/engine/src/executor/dispatch-block-log.ts diff --git a/.changeset/quiet-executor-dispatch-blocked-logs.md b/.changeset/quiet-executor-dispatch-blocked-logs.md new file mode 100644 index 0000000000..d2b234a995 --- /dev/null +++ b/.changeset/quiet-executor-dispatch-blocked-logs.md @@ -0,0 +1,7 @@ +--- +"@runfusion/fusion": patch +--- + +summary: Stop the engine log from repeating "executor dispatch blocked" 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. diff --git a/packages/engine/src/executor/__tests__/dispatch-block-log.test.ts b/packages/engine/src/executor/__tests__/dispatch-block-log.test.ts new file mode 100644 index 0000000000..4c0b0e2fac --- /dev/null +++ b/packages/engine/src/executor/__tests__/dispatch-block-log.test.ts @@ -0,0 +1,77 @@ +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/block-outer-dispatch-when-ephemeral-disabled.ts b/packages/engine/src/executor/block-outer-dispatch-when-ephemeral-disabled.ts index 7c3aa5aacc..5aecb3370b 100644 --- a/packages/engine/src/executor/block-outer-dispatch-when-ephemeral-disabled.ts +++ b/packages/engine/src/executor/block-outer-dispatch-when-ephemeral-disabled.ts @@ -12,6 +12,7 @@ import { isEphemeralAgent } from "@fusion/core"; import type { EngineRunContext } from "../util/run-audit.js"; import { executorLog } from "../logger.js"; import { resolveReboundColumnFor } from "./lifecycle-columns.js"; +import { clearDispatchBlockedLogState, logDispatchBlockedOnce } from "./dispatch-block-log.js"; export type BlockOuterDispatchWhenEphemeralDisabledDeps = { store: TaskStore; @@ -24,7 +25,10 @@ export async function blockOuterDispatchWhenEphemeralDisabled( task: Task, ): Promise { const settings = await deps.store.getSettings(); - if (settings.ephemeralAgentsEnabled !== false) return false; + if (settings.ephemeralAgentsEnabled !== false) { + clearDispatchBlockedLogState(task.id); + return false; + } // A permanent (non-ephemeral) assignment is the sanctioned executor when // ephemeral workers are off. `assignedAgentId` is only ever set by permanent @@ -33,9 +37,15 @@ export async function blockOuterDispatchWhenEphemeralDisabled( // the run rather than starving a legitimately-assigned task. const assignedId = task.assignedAgentId?.trim(); if (assignedId) { - if (!deps.agentStore) return false; + if (!deps.agentStore) { + clearDispatchBlockedLogState(task.id); + return false; + } const agent = await deps.agentStore.getAgent(assignedId).catch(() => null); - if (agent && !isEphemeralAgent(agent)) return false; + if (agent && !isEphemeralAgent(agent)) { + clearDispatchBlockedLogState(task.id); + return false; + } } const liveTask = (await deps.store.getTask(task.id).catch(() => null)) ?? task; @@ -56,6 +66,11 @@ export async function blockOuterDispatchWhenEphemeralDisabled( "Executor pre-dispatch ephemeral gate blocked workflow/authoritative execution.", deps.getRunContextFor(liveTask.id), ); - executorLog.log(`${liveTask.id}: executor dispatch blocked — ephemeralAgentsEnabled=false and no permanent agent assigned`); + logDispatchBlockedOnce( + executorLog, + liveTask.id, + "ephemeral-disabled", + `${liveTask.id}: executor dispatch blocked — ephemeralAgentsEnabled=false and no permanent agent assigned`, + ); return true; } diff --git a/packages/engine/src/executor/dependency-dispatch-gate.ts b/packages/engine/src/executor/dependency-dispatch-gate.ts index 13686f8b0b..a16dd391d2 100644 --- a/packages/engine/src/executor/dependency-dispatch-gate.ts +++ b/packages/engine/src/executor/dependency-dispatch-gate.ts @@ -11,6 +11,7 @@ import { getUnmetSchedulingDependencies } from "../scheduler.js"; import { executorLog } from "../logger.js"; import type { EngineRunContext } from "../util/run-audit.js"; import { resolveReboundColumnFor } from "./lifecycle-columns.js"; +import { clearDispatchBlockedLogState, logDispatchBlockedOnce } from "./dispatch-block-log.js"; export type DependencyDispatchGateDeps = { store: TaskStore; @@ -21,7 +22,10 @@ export async function blockOuterDispatchWhenDependenciesUnmet( deps: DependencyDispatchGateDeps, task: Task, ): Promise { - if (!task.dependencies || task.dependencies.length === 0) return false; + if (!task.dependencies || task.dependencies.length === 0) { + clearDispatchBlockedLogState(task.id); + return false; + } const settings = await deps.store.getSettings(); const tasks = await deps.store.listTasks({ includeArchived: false, slim: true }); @@ -37,7 +41,10 @@ export async function blockOuterDispatchWhenDependenciesUnmet( tasks, settings.mergeRequestContractShadowEnabled === true ? { markerAcceptedByTaskId } : undefined, ); - if (unmetDeps.length === 0) return false; + if (unmetDeps.length === 0) { + clearDispatchBlockedLogState(liveTask.id); + return false; + } const reboundColumn = await resolveReboundColumnFor(deps.store, liveTask.id); if (liveTask.column !== reboundColumn) { @@ -73,6 +80,11 @@ export async function blockOuterDispatchWhenDependenciesUnmet( deps.getRunContextFor(liveTask.id), ); } - executorLog.log(`${liveTask.id}: executor dispatch blocked by unmet dependencies: ${unmetDeps.join(", ")}`); + logDispatchBlockedOnce( + executorLog, + liveTask.id, + `dependencies:${normalizedUnmetDeps.join(",")}`, + `${liveTask.id}: executor dispatch blocked by unmet dependencies: ${unmetDeps.join(", ")}`, + ); return true; } diff --git a/packages/engine/src/executor/dispatch-block-log.ts b/packages/engine/src/executor/dispatch-block-log.ts new file mode 100644 index 0000000000..f4d98a5319 --- /dev/null +++ b/packages/engine/src/executor/dispatch-block-log.ts @@ -0,0 +1,39 @@ +/** + * FNXC:EngineDiagnostics 2026-08-10-08:59: + * The executor pre-dispatch gates (unmet dependencies, ephemeral-agents-off) re-run on EVERY dispatch attempt for a + * blocked task, but they only change state on the first one — every later pass re-queues an already-queued task and + * re-logged the same line. On the default log level that is pure per-poll chatter: a single stuck dependency pushed a + * repeating "executor dispatch blocked" line into the TUI log pane until it drowned out real events (same failure mode + * the scheduler already avoids with its `wasNodeBlocked`/`wasNodeDispatchValidationBlocked` sets). + * + * So: log the block at `log()` level ONCE per task per distinct reason signature, and emit repeats under `debug()` + * (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. + */ +import type { Logger } from "../logger.js"; + +const lastLoggedBlockSignatureByTaskId = new Map(); + +/** + * 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); +} + +/** 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); +} + +/** Test-only: drop all remembered signatures. */ +export function resetDispatchBlockedLogState(): void { + lastLoggedBlockSignatureByTaskId.clear(); +}