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 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;
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -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;
|
||||||
}
|
}
|
||||||
|
|||||||
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