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 <noreply@anthropic.com>
This commit is contained in:
gsxdsm
2026-08-10 10:11:11 -07:00
parent 936dd1ea96
commit a2deae041a
5 changed files with 157 additions and 7 deletions

View File

@@ -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.

View File

@@ -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<typeof vi.fn>; debug: ReturnType<typeof vi.fn> } {
return {
log: vi.fn(),
debug: vi.fn(),
warn: vi.fn(),
error: vi.fn(),
} as unknown as Logger & { log: ReturnType<typeof vi.fn>; debug: ReturnType<typeof vi.fn> };
}
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);
});
});

View File

@@ -12,6 +12,7 @@ import { isEphemeralAgent } from "@fusion/core";
import type { EngineRunContext } from "../util/run-audit.js"; import type { EngineRunContext } from "../util/run-audit.js";
import { executorLog } from "../logger.js"; import { executorLog } from "../logger.js";
import { resolveReboundColumnFor } from "./lifecycle-columns.js"; import { resolveReboundColumnFor } from "./lifecycle-columns.js";
import { clearDispatchBlockedLogState, logDispatchBlockedOnce } from "./dispatch-block-log.js";
export type BlockOuterDispatchWhenEphemeralDisabledDeps = { export type BlockOuterDispatchWhenEphemeralDisabledDeps = {
store: TaskStore; store: TaskStore;
@@ -24,7 +25,10 @@ export async function blockOuterDispatchWhenEphemeralDisabled(
task: Task, task: Task,
): Promise<boolean> { ): Promise<boolean> {
const settings = await deps.store.getSettings(); 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 // A permanent (non-ephemeral) assignment is the sanctioned executor when
// ephemeral workers are off. `assignedAgentId` is only ever set by permanent // 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. // the run rather than starving a legitimately-assigned task.
const assignedId = task.assignedAgentId?.trim(); const assignedId = task.assignedAgentId?.trim();
if (assignedId) { if (assignedId) {
if (!deps.agentStore) return false; if (!deps.agentStore) {
clearDispatchBlockedLogState(task.id);
return false;
}
const agent = await deps.agentStore.getAgent(assignedId).catch(() => null); 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; 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.", "Executor pre-dispatch ephemeral gate blocked workflow/authoritative execution.",
deps.getRunContextFor(liveTask.id), 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; return true;
} }

View File

@@ -11,6 +11,7 @@ import { getUnmetSchedulingDependencies } from "../scheduler.js";
import { executorLog } from "../logger.js"; import { executorLog } from "../logger.js";
import type { EngineRunContext } from "../util/run-audit.js"; import type { EngineRunContext } from "../util/run-audit.js";
import { resolveReboundColumnFor } from "./lifecycle-columns.js"; import { resolveReboundColumnFor } from "./lifecycle-columns.js";
import { clearDispatchBlockedLogState, logDispatchBlockedOnce } from "./dispatch-block-log.js";
export type DependencyDispatchGateDeps = { export type DependencyDispatchGateDeps = {
store: TaskStore; store: TaskStore;
@@ -21,7 +22,10 @@ export async function blockOuterDispatchWhenDependenciesUnmet(
deps: DependencyDispatchGateDeps, deps: DependencyDispatchGateDeps,
task: Task, task: Task,
): Promise<boolean> { ): Promise<boolean> {
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 settings = await deps.store.getSettings();
const tasks = await deps.store.listTasks({ includeArchived: false, slim: true }); const tasks = await deps.store.listTasks({ includeArchived: false, slim: true });
@@ -37,7 +41,10 @@ export async function blockOuterDispatchWhenDependenciesUnmet(
tasks, tasks,
settings.mergeRequestContractShadowEnabled === true ? { markerAcceptedByTaskId } : undefined, 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); const reboundColumn = await resolveReboundColumnFor(deps.store, liveTask.id);
if (liveTask.column !== reboundColumn) { if (liveTask.column !== reboundColumn) {
@@ -73,6 +80,11 @@ export async function blockOuterDispatchWhenDependenciesUnmet(
deps.getRunContextFor(liveTask.id), 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; return true;
} }

View File

@@ -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<string, string>();
/**
* 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();
}