root/fusion
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fix(engine): stop per-poll symbol-lock renewal log and activityLog spam

Browse Source 
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 <noreply@anthropic.com>
This commit is contained in:
gsxdsm
2026-08-10 10:33:35 -07:00
parent a2deae041a
commit e6b6223d30
7 changed files with 254 additions and 92 deletions
Download Patch File Download Diff File Expand all files Collapse all files

4
.changeset/quiet-executor-dispatch-blocked-logs.md
View File

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

41
packages/engine/src/__tests__/scheduler-workflow-cutover.test.ts
View File

@@ -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",

77
packages/engine/src/executor/__tests__/dispatch-block-log.test.ts
View File

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

18
packages/engine/src/executor/dispatch-block-log.ts
View File

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

47
packages/engine/src/scheduler.ts
View File

@@ -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<string>();
/** Tracks dispatch-queued reason signatures to avoid per-tick log spam. */
private wasDispatchQueuedReasonLogged = new Set<string>();
/** 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<string, string>();
/** 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",
);
}
}
}

106
packages/engine/src/util/__tests__/repeat-suppressed-log.test.ts Normal file
View File

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

53
packages/engine/src/util/repeat-suppressed-log.ts Normal file
View File

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