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:
7
.changeset/quiet-executor-dispatch-blocked-logs.md
Normal file
7
.changeset/quiet-executor-dispatch-blocked-logs.md
Normal 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.
|
||||
@@ -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);
|
||||
});
|
||||
});
|
||||
@@ -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<boolean> {
|
||||
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;
|
||||
}
|
||||
|
||||
@@ -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<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 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;
|
||||
}
|
||||
|
||||
39
packages/engine/src/executor/dispatch-block-log.ts
Normal file
39
packages/engine/src/executor/dispatch-block-log.ts
Normal 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();
|
||||
}
|
||||
Reference in New Issue
Block a user