diff --git a/.changeset/quiet-scheduler-steady-state-logs.md b/.changeset/quiet-scheduler-steady-state-logs.md new file mode 100644 index 0000000000..bc3feb225f --- /dev/null +++ b/.changeset/quiet-scheduler-steady-state-logs.md @@ -0,0 +1,7 @@ +--- +"@runfusion/fusion": patch +--- + +summary: Quiet repetitive scheduler hold-release and task-routing lines that flooded the engine log pane. +category: fix +dev: Adds `Logger.debug()` in `packages/engine/src/logger.ts`, gated per subsystem by `FUSION_DEBUG` (`1`/`true`/`all`/`*`, or a comma-separated prefix list). Demotes `Hold release for deferred — no reservable slot` and local-only `Task routed to node=local` to debug; remote routing stays at info. See `docs/diagnostics.md`. diff --git a/docs/diagnostics.md b/docs/diagnostics.md index e381393d93..31c9b5c98c 100644 --- a/docs/diagnostics.md +++ b/docs/diagnostics.md @@ -1,5 +1,26 @@ # Diagnostics +## Debug-level engine logs (`FUSION_DEBUG`) + +Engine subsystem loggers (`createLogger` in `packages/engine/src/logger.ts`) expose a `debug()` level for steady-state per-poll chatter. It is **off by default** so the TUI log pane and engine stderr show state *changes* rather than the scheduler reprinting its resting state every poll. + +Opt in per subsystem with the logger prefix: + +```bash +FUSION_DEBUG=scheduler # one subsystem +FUSION_DEBUG=scheduler,merger # several +FUSION_DEBUG=1 # everything (also: true, all, *) +``` + +The variable is re-read per call, so it can be toggled on a long-lived process without recreating loggers. Debug lines emit under the `info` severity marker and render like any other info line. + +Currently debug-gated: + +- `Task routed to node=local (source=local)` — routing to a **remote** node stays at info; only the local default is demoted. +- `Hold release for deferred — no reservable slot for ` — being at capacity is the expected steady state, not an event. + +Guidance for new log sites: if a line repeats on every scheduler poll while nothing changed, it belongs at `debug()`. Anything reporting a transition, a rejection, or something needing operator action stays at `log()`/`warn()`/`error()`. + ## Goal injection diagnostics (`[goal-injection]`) Executor, heartbeat, and planning runs emit one goal-injection diagnostic with outcome `applied`, `no-goals`, or `disabled-or-failed`. diff --git a/packages/engine/src/__tests__/logger-debug-gating.test.ts b/packages/engine/src/__tests__/logger-debug-gating.test.ts new file mode 100644 index 0000000000..60568083ec --- /dev/null +++ b/packages/engine/src/__tests__/logger-debug-gating.test.ts @@ -0,0 +1,63 @@ +import { describe, it, expect, vi, afterEach } from "vitest"; +import { createLogger } from "../logger.js"; + +/* +FNXC:EngineDiagnostics 2026-07-15-12:55: +Guards the contract that keeps steady-state scheduler chatter out of the operator log pane: `debug()` is silent unless the subsystem opted in via `FUSION_DEBUG`, and `log()` is never gated. +A regression either way is invisible in normal use — it either re-floods the TUI or silently swallows real events — so it is asserted rather than eyeballed. +*/ +describe("createLogger debug gating", () => { + afterEach(() => { + delete process.env.FUSION_DEBUG; + vi.restoreAllMocks(); + }); + + it("suppresses debug output when FUSION_DEBUG is unset", () => { + const spy = vi.spyOn(console, "error").mockImplementation(() => {}); + createLogger("scheduler").debug("steady-state chatter"); + expect(spy).not.toHaveBeenCalled(); + }); + + it("emits debug output for a subsystem named in the FUSION_DEBUG list", () => { + process.env.FUSION_DEBUG = "scheduler,merger"; + const spy = vi.spyOn(console, "error").mockImplementation(() => {}); + createLogger("scheduler").debug("steady-state chatter"); + expect(spy).toHaveBeenCalledOnce(); + expect(spy.mock.calls[0]?.[0]).toContain("[scheduler] steady-state chatter"); + }); + + it("suppresses debug output for a subsystem absent from the FUSION_DEBUG list", () => { + process.env.FUSION_DEBUG = "merger"; + const spy = vi.spyOn(console, "error").mockImplementation(() => {}); + createLogger("scheduler").debug("steady-state chatter"); + expect(spy).not.toHaveBeenCalled(); + }); + + it.each(["1", "true", "all", "*"])("emits debug output for every subsystem when FUSION_DEBUG=%s", (value) => { + process.env.FUSION_DEBUG = value; + const spy = vi.spyOn(console, "error").mockImplementation(() => {}); + createLogger("scheduler").debug("steady-state chatter"); + expect(spy).toHaveBeenCalledOnce(); + }); + + it("re-reads FUSION_DEBUG per call so toggling does not require a new logger", () => { + const log = createLogger("scheduler"); + const spy = vi.spyOn(console, "error").mockImplementation(() => {}); + log.debug("first"); + expect(spy).not.toHaveBeenCalled(); + process.env.FUSION_DEBUG = "scheduler"; + log.debug("second"); + expect(spy).toHaveBeenCalledOnce(); + }); + + it("never gates log/warn/error on FUSION_DEBUG", () => { + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {}); + const log = createLogger("scheduler"); + log.log("real event"); + log.warn("real warning"); + log.error("real failure"); + expect(errorSpy).toHaveBeenCalledTimes(2); + expect(warnSpy).toHaveBeenCalledOnce(); + }); +}); diff --git a/packages/engine/src/hold-release.ts b/packages/engine/src/hold-release.ts index 9f3240f50b..b8790a5511 100644 --- a/packages/engine/src/hold-release.ts +++ b/packages/engine/src/hold-release.ts @@ -486,8 +486,13 @@ async function issueRelease( if (targetIsProcessing && deps.reserveSlot) { reservation = await deps.reserveSlot(task, target); if (!reservation) { - // Semaphore/worktree exhausted — reservation-first means no move at all. - schedulerLog.log(`Hold release for ${task.id} deferred — no reservable slot for ${target}`); + /* + Semaphore/worktree exhausted — reservation-first means no move at all. + + FNXC:WorkflowScheduling 2026-07-15-12:55: + A held card re-attempts release on every sweep, so a full board reprinted this line per task per poll and buried real scheduler events. Being at capacity is the expected steady state, not an event: debug-only (`FUSION_DEBUG=scheduler`). + */ + schedulerLog.debug(`Hold release for ${task.id} deferred — no reservable slot for ${target}`); return false; } } diff --git a/packages/engine/src/logger.ts b/packages/engine/src/logger.ts index d4f522aafb..3253d7b94a 100644 --- a/packages/engine/src/logger.ts +++ b/packages/engine/src/logger.ts @@ -18,6 +18,11 @@ export interface Logger { log(message: string, ...args: unknown[]): void; + /** + * Steady-state per-poll chatter. Suppressed unless the subsystem is opted in + * via `FUSION_DEBUG` (see `isDebugEnabled`). + */ + debug(message: string, ...args: unknown[]): void; warn(message: string, ...args: unknown[]): void; error(message: string, ...args: unknown[]): void; } @@ -29,6 +34,22 @@ function withSeverityMarker(level: "info" | "warn" | "error", payload: string): return `${LOG_LEVEL_MARKER_PREFIX}${level}${LOG_LEVEL_MARKER_SUFFIX}${payload}`; } +/* +FNXC:EngineDiagnostics 2026-07-15-12:55: +Operators read the TUI log pane to see what the engine is *doing*; per-poll steady-state chatter (routine node routing, capacity-deferred hold releases) drowned real events out — a 1000-line buffer held only a few seconds of scheduler polls. +Such lines move to `debug()`, off by default and opted in per subsystem via `FUSION_DEBUG` (`FUSION_DEBUG=1`/`all` for everything, or a comma-separated prefix list like `FUSION_DEBUG=scheduler,merger`). +Anything that reports a state *change* or needs operator action stays on `log()`/`warn()`/`error()`. +*/ +function isDebugEnabled(prefix: string): boolean { + const raw = process.env.FUSION_DEBUG?.trim(); + if (!raw) return false; + if (raw === "1" || raw === "true" || raw === "all" || raw === "*") return true; + return raw + .split(",") + .map((entry) => entry.trim()) + .includes(prefix); +} + /** * Create a structured logger that prefixes every message with `[prefix]`. * @@ -40,6 +61,11 @@ function withSeverityMarker(level: "info" | "warn" | "error", payload: string): * The logger prepends an internal control-character severity marker * so dashboard TUI console-capture can preserve info/warn/error * semantics even when `log()` is transported via `console.error`. + * + * `debug()` is gated on `FUSION_DEBUG` and re-reads the env var per + * call so tests and long-lived processes can toggle it without + * re-creating loggers. When enabled it emits under the `info` marker, + * so TUI console-capture needs no new severity to render it. */ export function createLogger(prefix: string): Logger { const tag = `[${prefix}]`; @@ -47,6 +73,10 @@ export function createLogger(prefix: string): Logger { log(message: string, ...args: unknown[]) { console.error(withSeverityMarker("info", `${tag} ${message}`), ...args); }, + debug(message: string, ...args: unknown[]) { + if (!isDebugEnabled(prefix)) return; + console.error(withSeverityMarker("info", `${tag} ${message}`), ...args); + }, warn(message: string, ...args: unknown[]) { console.warn(withSeverityMarker("warn", `${tag} ${message}`), ...args); }, diff --git a/packages/engine/src/scheduler.ts b/packages/engine/src/scheduler.ts index 3de1f96cfc..5bbeb38e5c 100644 --- a/packages/engine/src/scheduler.ts +++ b/packages/engine/src/scheduler.ts @@ -32,7 +32,7 @@ import { schedulerLog } from "./logger.js"; import { type PrMonitor, type PrComment } from "./pr-monitor.js"; import { reconcileMissionFeatureState } from "./mission-feature-sync.js"; import { evaluateSpecStaleness, getPromptPath } from "./spec-staleness.js"; -import { resolveEffectiveNode } from "./effective-node.js"; +import { resolveEffectiveNode, type EffectiveNode } from "./effective-node.js"; import { applyUnavailableNodePolicy, decideOwningNodeHandoff } from "./node-routing-policy.js"; import type { NodeDispatchValidationResult } from "./node-dispatch-validation.js"; import type { MeshLeaseManager } from "./mesh-lease-manager.js"; @@ -47,6 +47,20 @@ import { runHoldReleaseSweep, isUnplannedForExecution, type SlotReservation } fr import { moveTaskToReplanColumn } from "./replan-target.js"; import { evaluateParkedAgentTaskLink } from "./task-agent-sync.js"; +/* +FNXC:WorkflowScheduling 2026-07-15-12:55: +Every dispatch pass resolves a routing node, so logging each resolution at info level reprinted `routed to node=local (source=local)` for every task on every poll and buried real scheduler events in the TUI log pane. +Local routing is the default nobody needs told about: it is debug-only (`FUSION_DEBUG=scheduler`). Remote routing stays at info because it explains where work actually went and is what an operator reaches for when a task runs on the wrong host. +*/ +function logTaskRouting(taskId: string, node: EffectiveNode): void { + const message = `Task ${taskId} routed to node=${node.nodeId ?? "local"} (source=${node.source})`; + if (node.nodeId === undefined) { + schedulerLog.debug(message); + return; + } + schedulerLog.log(message); +} + function shouldRunWorkflowColumnScheduler(_settings: Settings): boolean { /* FNXC:WorkflowScheduling 2026-06-22-00:00: @@ -1902,7 +1916,7 @@ export class Scheduler { // Resolve effective node for routing let effectiveNode = resolveEffectiveNode(freshTask, settings); - schedulerLog.log(`Task ${task.id} routed to node=${effectiveNode.nodeId ?? "local"} (source=${effectiveNode.source})`); + logTaskRouting(task.id, effectiveNode); // Enforce dispatch configuration validation before node-health fallback logic. if (effectiveNode.nodeId !== undefined && this.options.validateNodeDispatch) { @@ -2426,7 +2440,7 @@ export class Scheduler { } let effectiveNode = resolveEffectiveNode(freshTask, settings); - schedulerLog.log(`Task ${task.id} routed to node=${effectiveNode.nodeId ?? "local"} (source=${effectiveNode.source})`); + logTaskRouting(task.id, effectiveNode); if (effectiveNode.nodeId !== undefined && this.options.validateNodeDispatch) { const nodeValidation = await this.options.validateNodeDispatch(effectiveNode.nodeId);