From cfa84781d6778531166e08eeef374bcc55286c08 Mon Sep 17 00:00:00 2001 From: gsxdsm Date: Sun, 26 Jul 2026 08:20:37 -0700 Subject: [PATCH] fix(engine): demote high-frequency TUI log spam to debug Route steady-state chatter (maintenance batch, skill listings, activity heartbeats, stuck polls, SSE connect/disconnect, heartbeat timer skips, cron/routine de-dupe skips, hold-release capacity races) through FUSION_DEBUG so the operator log pane keeps real state changes and failures. --- packages/dashboard/src/__tests__/sse.test.ts | 37 ++++++ packages/dashboard/src/sse.ts | 23 +++- .../src/__tests__/heartbeat-scheduler.test.ts | 14 ++- .../src/__tests__/heartbeat-test-helpers.ts | 1 + .../log-severity-spam-contract.test.ts | 112 ++++++++++++++++++ packages/engine/src/__tests__/pi.test.ts | 9 +- packages/engine/src/agent-heartbeat.ts | 35 +++--- packages/engine/src/cron-runner.ts | 7 +- packages/engine/src/hold-release.ts | 3 +- packages/engine/src/peer-exchange-service.ts | 5 +- packages/engine/src/pi.ts | 8 +- packages/engine/src/routine-scheduler.ts | 7 +- packages/engine/src/session-skill-context.ts | 6 +- packages/engine/src/skill-resolver.ts | 10 ++ packages/engine/src/stuck-task-detector.ts | 12 +- 15 files changed, 251 insertions(+), 38 deletions(-) create mode 100644 packages/engine/src/__tests__/log-severity-spam-contract.test.ts diff --git a/packages/dashboard/src/__tests__/sse.test.ts b/packages/dashboard/src/__tests__/sse.test.ts index f6620a115b..0f2be5aaf8 100644 --- a/packages/dashboard/src/__tests__/sse.test.ts +++ b/packages/dashboard/src/__tests__/sse.test.ts @@ -422,6 +422,43 @@ describe("automation store SSE events", () => { }); }); +describe("createSSE connection log severity", () => { + /* + FNXC:EngineDiagnostics 2026-07-26-08:17: + Connect/disconnect fires on every tab/reconnect. Must stay off the default TUI pane unless FUSION_DEBUG=sse. + */ + const originalDebug = process.env.FUSION_DEBUG; + + afterEach(() => { + if (originalDebug === undefined) delete process.env.FUSION_DEBUG; + else process.env.FUSION_DEBUG = originalDebug; + }); + + it("does not console.log +/- connection when FUSION_DEBUG is unset", () => { + delete process.env.FUSION_DEBUG; + const logSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + const connection = openSseConnection("client-severity-quiet"); + disconnectSSEClient("client-severity-quiet"); + const spam = logSpy.mock.calls + .map((call) => String(call[0] ?? "")) + .filter((line) => line.includes("[sse] + connection") || line.includes("[sse] - connection")); + expect(spam).toEqual([]); + logSpy.mockRestore(); + connection.req.emit("close"); + }); + + it("emits +/- connection when FUSION_DEBUG=sse", () => { + process.env.FUSION_DEBUG = "sse"; + const logSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + openSseConnection("client-severity-debug"); + disconnectSSEClient("client-severity-debug"); + const lines = logSpy.mock.calls.map((call) => String(call[0] ?? "")); + expect(lines.some((line) => line.includes("[sse] + connection"))).toBe(true); + expect(lines.some((line) => line.includes("[sse] - connection"))).toBe(true); + logSpy.mockRestore(); + }); +}); + describe("createSSE client cleanup", () => { it("disconnectSSEClient closes and unregisters the matching stream", () => { const baseline = getActiveSSEConnections(); diff --git a/packages/dashboard/src/sse.ts b/packages/dashboard/src/sse.ts index 03079f94a6..8df4975110 100644 --- a/packages/dashboard/src/sse.ts +++ b/packages/dashboard/src/sse.ts @@ -32,6 +32,25 @@ let activeConnections = 0; let highWaterMark = 0; let nextConnectionId = 1; +/* +FNXC:EngineDiagnostics 2026-07-26-08:15: +SSE open/close fires on every dashboard tab, reconnect, and focus flip. Logging each +/- connection at info filled the TUI log pane with steady-state transport chatter. Gate behind FUSION_DEBUG=sse (or FUSION_DEBUG=1/all/*). Keep backpressure and real failures on warn/error. +*/ +function isSseDebugEnabled(): 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("sse"); +} + +function sseDebug(message: string): void { + if (!isSseDebugEnabled()) return; + console.log(message); +} + const SSE_CLIENT_ID_MAX_LENGTH = 128; /* * FNXC:DashboardSSE 2026-06-23-15:08: @@ -534,7 +553,7 @@ export function createSSE( if (activeConnections > highWaterMark) { highWaterMark = activeConnections; } - console.log(`[sse] + connection (active=${activeConnections}, hwm=${highWaterMark})`); + sseDebug(`[sse] + connection (active=${activeConnections}, hwm=${highWaterMark})`); // Send initial heartbeat res.write(": connected\n\n"); @@ -905,7 +924,7 @@ export function createSSE( cleaned = true; unregisterManagedConnection(connectionId); activeConnections--; - console.log(`[sse] - connection (active=${activeConnections})`); + sseDebug(`[sse] - connection (active=${activeConnections})`); if (clientStaleTimer) clearTimeout(clientStaleTimer); clearInterval(heartbeat); store.off("task:created", onCreated); diff --git a/packages/engine/src/__tests__/heartbeat-scheduler.test.ts b/packages/engine/src/__tests__/heartbeat-scheduler.test.ts index 2f41277906..ff0b84e174 100644 --- a/packages/engine/src/__tests__/heartbeat-scheduler.test.ts +++ b/packages/engine/src/__tests__/heartbeat-scheduler.test.ts @@ -659,7 +659,7 @@ describe("HeartbeatTriggerScheduler", () => { expect(store.endHeartbeatRun).not.toHaveBeenCalled(); expect(scheduler.getRegisteredAgents()).not.toContain("agent-001"); - expect(heartbeatLog.log).toHaveBeenCalledWith("Timer audit skipped re-arm for agent-001 (active run)"); + expect(heartbeatLog.debug).toHaveBeenCalledWith("Timer audit skipped re-arm for agent-001 (active run)"); }); it("FN-4119 does not reap task-worker runs during audit", async () => { @@ -1043,7 +1043,7 @@ describe("HeartbeatTriggerScheduler", () => { expect(store.endHeartbeatRun).not.toHaveBeenCalled(); expect(callback).not.toHaveBeenCalled(); expect(scheduler.getRegisteredAgents()).not.toContain("agent-long"); - expect(heartbeatLog.log).toHaveBeenCalledWith("Timer audit skipped re-arm for agent-long (active run)"); + expect(heartbeatLog.debug).toHaveBeenCalledWith("Timer audit skipped re-arm for agent-long (active run)"); }); }); @@ -2078,7 +2078,9 @@ describe("HeartbeatTriggerScheduler", () => { expect(store.endHeartbeatRun).not.toHaveBeenCalled(); expect(callback).not.toHaveBeenCalled(); - expect(heartbeatLog.log).toHaveBeenCalledWith("Timer tick skipped for agent-001 (active run)"); + // Steady-state skip gates are debug-only so the TUI is not flooded per interval. + expect(heartbeatLog.debug).toHaveBeenCalledWith("Timer tick skipped for agent-001 (active run)"); + expect(heartbeatLog.log).not.toHaveBeenCalledWith("Timer tick skipped for agent-001 (active run)"); }); it.each([ @@ -2113,7 +2115,8 @@ describe("HeartbeatTriggerScheduler", () => { expect(store.getActiveHeartbeatRun).not.toHaveBeenCalled(); expect(store.endHeartbeatRun).not.toHaveBeenCalled(); expect(callback).not.toHaveBeenCalled(); - expect(heartbeatLog.log).toHaveBeenCalledWith(expectedLog); + expect(heartbeatLog.debug).toHaveBeenCalledWith(expectedLog); + expect(heartbeatLog.log).not.toHaveBeenCalledWith(expectedLog); }); it("skips timer dispatch when global pause is active", async () => { @@ -2128,7 +2131,8 @@ describe("HeartbeatTriggerScheduler", () => { await vi.advanceTimersByTimeAsync(5000); expect(callback).not.toHaveBeenCalled(); - expect(heartbeatLog.log).toHaveBeenCalledWith("Timer tick skipped for agent-001 (global pause active)"); + expect(heartbeatLog.debug).toHaveBeenCalledWith("Timer tick skipped for agent-001 (global pause active)"); + expect(heartbeatLog.log).not.toHaveBeenCalledWith("Timer tick skipped for agent-001 (global pause active)"); }); it("skips timer dispatch when engine pause is active", async () => { diff --git a/packages/engine/src/__tests__/heartbeat-test-helpers.ts b/packages/engine/src/__tests__/heartbeat-test-helpers.ts index 27f4040b90..f5bbeae351 100644 --- a/packages/engine/src/__tests__/heartbeat-test-helpers.ts +++ b/packages/engine/src/__tests__/heartbeat-test-helpers.ts @@ -60,6 +60,7 @@ export function createBudgetStatus(overrides: Partial = {}): export function createMockLogger() { return { log: vi.fn(), + debug: vi.fn(), warn: vi.fn(), error: vi.fn(), }; diff --git a/packages/engine/src/__tests__/log-severity-spam-contract.test.ts b/packages/engine/src/__tests__/log-severity-spam-contract.test.ts new file mode 100644 index 0000000000..1c354419da --- /dev/null +++ b/packages/engine/src/__tests__/log-severity-spam-contract.test.ts @@ -0,0 +1,112 @@ +/** + * FNXC:EngineDiagnostics 2026-07-26-08:17: + * Contract tests that high-frequency steady-state chatter stays on `debug()` / FUSION_DEBUG, + * so a reversion to info-level spam fails CI. Complements logger-debug-gating (framework) with + * shipped call-site severity for known TUI flood classes. + */ +import { describe, it, expect, vi, beforeEach, afterEach } from "vitest"; +import { readFileSync } from "node:fs"; +import { join } from "node:path"; +import { createLogger } from "../logger.js"; + +const engineSrc = join(__dirname, ".."); + +function readSrc(relative: string): string { + return readFileSync(join(engineSrc, relative), "utf8"); +} + +describe("log severity spam contract (source)", () => { + it("maintenance batch per-step success uses debug, not log", () => { + const src = readSrc("self-healing.ts"); + expect(src).toMatch(/log\.debug\(`Maintenance batch 1 step "\$\{fn\.name\}" succeeded`\)/); + expect(src).toMatch(/log\.debug\(`Maintenance batch 2 step "\$\{fn\.name\}" succeeded`\)/); + expect(src).not.toMatch(/log\.log\(`Maintenance batch [123] step "\$\{fn\.name\}" succeeded`\)/); + }); + + it("requested-skill listing diagnostics route to debug", () => { + const pi = readSrc("pi.ts"); + const resolver = readSrc("skill-resolver.ts"); + expect(pi).toMatch(/diag\.message\.startsWith\("Requested skill:"\)[\s\S]*piLog\.debug/); + expect(resolver).toMatch(/isRequestedSkillListingDiagnostic/); + expect(resolver).toMatch(/piLog\.debug\(msg\)/); + }); + + it("activity-recorded heartbeats and periodic stuck poll use debug", () => { + const src = readSrc("stuck-task-detector.ts"); + expect(src).toMatch(/stuckLog\.debug\(\s*`Activity recorded for/); + expect(src).toMatch(/stuckLog\.debug\("Running periodic stuck task check \(polling\)"\)/); + expect(src).not.toMatch(/stuckLog\.log\(\s*`Activity recorded for/); + expect(src).not.toMatch(/stuckLog\.log\("Running periodic stuck task check \(polling\)"\)/); + }); + + it("heartbeat timer skip gates use debug", () => { + const src = readSrc("agent-heartbeat.ts"); + expect(src).toMatch(/heartbeatLog\.debug\(`Timer tick skipped for \$\{agentId\} \(active run\)`\)/); + expect(src).toMatch(/heartbeatLog\.debug\(`Timer tick skipped for \$\{agentId\} \(global pause active\)`\)/); + expect(src).not.toMatch(/heartbeatLog\.log\(`Timer tick skipped for \$\{agentId\} \(active run\)`\)/); + }); + + it("cron multi-scope skip chatter uses debug; execute stays on log", () => { + const src = readSrc("cron-runner.ts"); + expect(src).toMatch(/log\.debug\(`Skipping \$\{schedule\.name\}[\s\S]*already executed from another scope/); + expect(src).toMatch(/log\.debug\(`Skipping \$\{schedule\.name\}[\s\S]*claim lost to another poller/); + expect(src).toMatch(/log\.log\(`Executing \$\{schedule\.name\}/); + }); + + it("plugin skill contribution/merge chatter uses debug", () => { + const src = readSrc("session-skill-context.ts"); + expect(src).toMatch(/piLog\.debug\(`\[skills\] Plugin \$\{pluginId\} contributes skill:/); + expect(src).toMatch(/piLog\.debug\(\s*`\[skills\] Merged \$\{appendedPluginNames\.length\}/); + }); + + it("hold-release capacity race uses debug like deferred-no-slot", () => { + const src = readSrc("hold-release.ts"); + expect(src).toMatch(/schedulerLog\.debug\(`Hold release for \$\{task\.id\} rejected on capacity/); + expect(src).toMatch(/schedulerLog\.debug\(`Hold release for \$\{task\.id\} deferred — no reservable slot/); + }); +}); + +describe("log severity spam contract (runtime gating)", () => { + const original = process.env.FUSION_DEBUG; + + beforeEach(() => { + delete process.env.FUSION_DEBUG; + }); + + afterEach(() => { + if (original === undefined) delete process.env.FUSION_DEBUG; + else process.env.FUSION_DEBUG = original; + }); + + it("createLogger debug is silent without FUSION_DEBUG and emits when opted in", () => { + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + const log = createLogger("stuck-detector"); + + log.debug("Activity recorded for FN-1 (sinceProgress=1)"); + expect(errorSpy).not.toHaveBeenCalled(); + + process.env.FUSION_DEBUG = "stuck-detector"; + log.debug("Activity recorded for FN-1 (sinceProgress=1)"); + expect(errorSpy).toHaveBeenCalled(); + const payload = String(errorSpy.mock.calls[0]![0]); + expect(payload).toContain("[stuck-detector]"); + expect(payload).toContain("Activity recorded"); + + errorSpy.mockRestore(); + }); + + it("log/warn/error remain ungated by FUSION_DEBUG", () => { + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {}); + const log = createLogger("heartbeat"); + + log.log("Executing heartbeat for agent-1 (source=timer)"); + log.warn("something needs attention"); + log.error("hard failure"); + + expect(errorSpy).toHaveBeenCalled(); + expect(warnSpy).toHaveBeenCalled(); + errorSpy.mockRestore(); + warnSpy.mockRestore(); + }); +}); diff --git a/packages/engine/src/__tests__/pi.test.ts b/packages/engine/src/__tests__/pi.test.ts index b5e49441ca..d1f9c9eb8e 100644 --- a/packages/engine/src/__tests__/pi.test.ts +++ b/packages/engine/src/__tests__/pi.test.ts @@ -433,6 +433,7 @@ describe("createFnAgent skills parameter", () => { }); it("skills auto-derivation logs the convenience parameter", async () => { + const piDebugSpy = vi.spyOn(piLog, "debug").mockImplementation(() => {}); const options: AgentOptions = { cwd: "/test/project", systemPrompt: "Test", @@ -441,10 +442,14 @@ describe("createFnAgent skills parameter", () => { await createFnAgent(options); - // Verify the log message includes the skill names - expect(piLogSpy).toHaveBeenCalledWith( + // Steady-state skill-request chatter is debug-gated so it does not fill the TUI. + expect(piDebugSpy).toHaveBeenCalledWith( expect.stringContaining("Using skills from convenience parameter: [review, fusion]") ); + expect(piLogSpy).not.toHaveBeenCalledWith( + expect.stringContaining("Using skills from convenience parameter: [review, fusion]") + ); + piDebugSpy.mockRestore(); }); it("resolves project root via resolvePiExtensionProjectRoot for non-worktree paths", async () => { diff --git a/packages/engine/src/agent-heartbeat.ts b/packages/engine/src/agent-heartbeat.ts index 4427e5b1f0..4166c1e5fc 100644 --- a/packages/engine/src/agent-heartbeat.ts +++ b/packages/engine/src/agent-heartbeat.ts @@ -2047,7 +2047,8 @@ export class HeartbeatMonitor { try { const budgetStatus = await this.store.getBudgetStatus(agentId); if (budgetStatus.isOverBudget) { - heartbeatLog.log(`Agent ${agentId} budget exhausted — heartbeat skipped`); + // FNXC:EngineDiagnostics 2026-07-26-08:17: timer-path skips complete a run record every interval; debug keeps TUI free of repeated budget/pause no-ops. + heartbeatLog.debug(`Agent ${agentId} budget exhausted — heartbeat skipped`); await this.completeRun(agentId, run.id, { status: "completed", resultJson: { reason: "budget_exhausted", budgetStatus }, @@ -2057,7 +2058,7 @@ export class HeartbeatMonitor { } // Above threshold: only allow critical triggers (assignment, on_demand) if (budgetStatus.isOverThreshold && source === "timer") { - heartbeatLog.log(`Agent ${agentId} over budget threshold (${budgetStatus.usagePercent}%) — timer heartbeat skipped`); + heartbeatLog.debug(`Agent ${agentId} over budget threshold (${budgetStatus.usagePercent}%) — timer heartbeat skipped`); await this.completeRun(agentId, run.id, { status: "completed", resultJson: { reason: "budget_threshold_exceeded", budgetStatus }, @@ -2076,7 +2077,7 @@ export class HeartbeatMonitor { heartbeatModelSettings = await taskStore.getSettings(); const settings = heartbeatModelSettings; if (settings.globalPause) { - heartbeatLog.log(`Agent ${agentId} heartbeat skipped — global pause active (source=${source})`); + heartbeatLog.debug(`Agent ${agentId} heartbeat skipped — global pause active (source=${source})`); await this.completeRun(agentId, run.id, { status: "completed", resultJson: { reason: "global_pause", source }, @@ -2085,7 +2086,7 @@ export class HeartbeatMonitor { return (await this.store.getRunDetail(agentId, run.id))!; } if (settings.enginePaused && source === "timer") { - heartbeatLog.log(`Agent ${agentId} timer heartbeat skipped — engine paused (soft pause)`); + heartbeatLog.debug(`Agent ${agentId} timer heartbeat skipped — engine paused (soft pause)`); await this.completeRun(agentId, run.id, { status: "completed", resultJson: { reason: "engine_paused", source }, @@ -4710,7 +4711,7 @@ export class HeartbeatTriggerScheduler { runtimeConfig.allowParallelExecution === false && (this.isTaskExecuting?.(taskId) || this.isAgentEffectivelyExecuting?.(agent.id)) ) { - heartbeatLog.log(`Assignment tick skipped for ${agent.id} (parallel execution disabled, task ${taskId} or column-bound session executing)`); + heartbeatLog.debug(`Assignment tick skipped for ${agent.id} (parallel execution disabled, task ${taskId} or column-bound session executing)`); return; } @@ -5228,7 +5229,7 @@ export class HeartbeatTriggerScheduler { if (activeRun) { if (settings?.globalPause || settings?.enginePaused) { this.nonAdvancingRearmState.delete(agent.id); - heartbeatLog.log(`Timer audit skipped re-arm for ${agent.id} (active run)`); + heartbeatLog.debug(`Timer audit skipped re-arm for ${agent.id} (active run)`); continue; } const reapResult = await this.maybeReapStaleActiveRun(agent, activeRun, "audit", staleMultiplier); @@ -5237,7 +5238,7 @@ export class HeartbeatTriggerScheduler { activeRunThresholdMs = reapResult.thresholdMs; if (!reapedActiveRun) { this.nonAdvancingRearmState.delete(agent.id); - heartbeatLog.log(`Timer audit skipped re-arm for ${agent.id} (active run)`); + heartbeatLog.debug(`Timer audit skipped re-arm for ${agent.id} (active run)`); continue; } } @@ -5356,13 +5357,17 @@ export class HeartbeatTriggerScheduler { try { const agent = await this.store.getAgent(agentId); + /* + FNXC:EngineDiagnostics 2026-07-26-08:17: + Timer skip reasons (pause, idle, active run, ineligible state) fire on every interval for every registered agent. That is steady-state gating, not a lifecycle event — demote to debug (FUSION_DEBUG=heartbeat). Keep reap/re-arm and actual executeHeartbeat start/complete on log/warn. + */ if (!agent) { - heartbeatLog.log(`Timer tick skipped for ${agentId} (agent missing)`); + heartbeatLog.debug(`Timer tick skipped for ${agentId} (agent missing)`); this.unregisterAgent(agentId); return; } if (!isHeartbeatManaged(agent) || (agent.state !== "error" && !isTickableState(agent.state))) { - heartbeatLog.log(`Timer tick skipped for ${agentId} (state=${agent.state})`); + heartbeatLog.debug(`Timer tick skipped for ${agentId} (state=${agent.state})`); this.unregisterAgent(agentId); return; } @@ -5370,7 +5375,7 @@ export class HeartbeatTriggerScheduler { const settings = this.taskStore ? await this.taskStore.getSettings() : null; const errorRecoveryLimit = this.updateErrorRecoveryLimit(settings); if (agent.state === "error" && !isErrorRecoveryEligible(agent, errorRecoveryLimit)) { - heartbeatLog.log(`Timer tick skipped for ${agentId} (state=${agent.state}, error recovery ineligible)`); + heartbeatLog.debug(`Timer tick skipped for ${agentId} (state=${agent.state}, error recovery ineligible)`); this.unregisterAgent(agentId); return; } @@ -5381,7 +5386,7 @@ export class HeartbeatTriggerScheduler { skipHeartbeatWhenIdle?: boolean; }; if (timerRc.skipHeartbeatWhenIdle === true && (!agent.taskId || agent.taskId.length === 0)) { - heartbeatLog.log(`Timer tick skipped for ${agentId} (skipHeartbeatWhenIdle, no task assigned)`); + heartbeatLog.debug(`Timer tick skipped for ${agentId} (skipHeartbeatWhenIdle, no task assigned)`); return; } @@ -5397,18 +5402,18 @@ export class HeartbeatTriggerScheduler { || this.isAgentEffectivelyExecuting?.(agentId) ) ) { - heartbeatLog.log(`Timer tick skipped for ${agentId} (parallel execution disabled, bound task ${agent.taskId ?? "—"} or column-bound session executing)`); + heartbeatLog.debug(`Timer tick skipped for ${agentId} (parallel execution disabled, bound task ${agent.taskId ?? "—"} or column-bound session executing)`); return; } // Global/engine pause guard: scheduler should not dispatch timer callbacks // while globally paused (hard stop) or engine paused (soft stop for timers). if (settings?.globalPause) { - heartbeatLog.log(`Timer tick skipped for ${agentId} (global pause active)`); + heartbeatLog.debug(`Timer tick skipped for ${agentId} (global pause active)`); return; } if (settings?.enginePaused) { - heartbeatLog.log(`Timer tick skipped for ${agentId} (engine paused)`); + heartbeatLog.debug(`Timer tick skipped for ${agentId} (engine paused)`); return; } @@ -5418,7 +5423,7 @@ export class HeartbeatTriggerScheduler { const staleMultiplier = this.resolveRepairStaleMultiplier(settings); const reapResult = await this.maybeReapStaleActiveRun(agent, activeRun, "timer", staleMultiplier); if (!reapResult.reaped) { - heartbeatLog.log(`Timer tick skipped for ${agentId} (active run)`); + heartbeatLog.debug(`Timer tick skipped for ${agentId} (active run)`); return; } heartbeatLog.log( diff --git a/packages/engine/src/cron-runner.ts b/packages/engine/src/cron-runner.ts index 0ed4c5e6fb..a57089f2b0 100644 --- a/packages/engine/src/cron-runner.ts +++ b/packages/engine/src/cron-runner.ts @@ -373,7 +373,8 @@ export class CronRunner { // Skip if already executed this tick (de-duplication across scopes) if (executedIds.has(schedule.id)) { - log.log(`Skipping ${schedule.name} (${schedule.id}) — already executed from another scope this tick`); + // FNXC:EngineDiagnostics 2026-07-26-08:17: multi-scope de-dupe/claim-loss skips are expected steady-state; keep executing lines at info. + log.debug(`Skipping ${schedule.name} (${schedule.id}) — already executed from another scope this tick`); continue; } executedIds.add(schedule.id); @@ -381,7 +382,7 @@ export class CronRunner { // Log which scope this schedule is from const scheduleScope = schedule.scope ?? "project"; if (scheduleScope !== this.scope && this.scope !== "all") { - log.log(`Skipping ${schedule.name} (${schedule.id}) — belongs to ${scheduleScope} scope, not polling`); + log.debug(`Skipping ${schedule.name} (${schedule.id}) — belongs to ${scheduleScope} scope, not polling`); continue; } @@ -406,7 +407,7 @@ export class CronRunner { */ const claimed = await this.automationStore.claimDueSchedule(schedule.id, schedule.nextRunAt); if (!claimed) { - log.log(`Skipping ${schedule.name} (${schedule.id}) — claim lost to another poller`); + log.debug(`Skipping ${schedule.name} (${schedule.id}) — claim lost to another poller`); continue; } diff --git a/packages/engine/src/hold-release.ts b/packages/engine/src/hold-release.ts index 252f7441d5..1cc437ff31 100644 --- a/packages/engine/src/hold-release.ts +++ b/packages/engine/src/hold-release.ts @@ -729,8 +729,9 @@ async function issueRelease( } catch (error) { if (error instanceof TransitionRejectionError && error.rejection.code === "capacity-exhausted") { // Lost the in-txn race for the slot — release the reservation, stay held. + // FNXC:EngineDiagnostics 2026-07-26-08:17: capacity races re-hit every sweep while full; same class as deferred-no-slot → debug. reservation?.release(); - schedulerLog.log(`Hold release for ${task.id} rejected on capacity for ${target} — staying held`); + schedulerLog.debug(`Hold release for ${task.id} rejected on capacity for ${target} — staying held`); return false; } // Any other failure: release the reservation and let the card stay held. diff --git a/packages/engine/src/peer-exchange-service.ts b/packages/engine/src/peer-exchange-service.ts index 39d409ea47..42b017379e 100644 --- a/packages/engine/src/peer-exchange-service.ts +++ b/packages/engine/src/peer-exchange-service.ts @@ -202,7 +202,8 @@ export class PeerExchangeService { async syncWithAllPeers(): Promise { // Single-flight: if a sync is already running, return that if (this.activeSync) { - peerExchangeLog.log("Sync already in progress, skipping"); + // FNXC:EngineDiagnostics 2026-07-26-08:17: overlapping sync ticks are expected under load — not operator-actionable. + peerExchangeLog.debug("Sync already in progress, skipping"); await this.activeSync; return []; } @@ -226,7 +227,7 @@ export class PeerExchangeService { ); if (onlineRemoteNodes.length === 0) { - peerExchangeLog.log("No online remote nodes to sync with"); + peerExchangeLog.debug("No online remote nodes to sync with"); return; } diff --git a/packages/engine/src/pi.ts b/packages/engine/src/pi.ts index 582fd74602..0b90dc0373 100644 --- a/packages/engine/src/pi.ts +++ b/packages/engine/src/pi.ts @@ -2329,7 +2329,11 @@ export async function createFnAgent(options: AgentOptions): Promise // Resolve skill selection: explicit skillSelection wins over convenience `skills` let effectiveSkillSelection: SkillSelectionContext | undefined = options.skillSelection; if (!effectiveSkillSelection && options.skills && options.skills.length > 0) { - piLog.log(`Using skills from convenience parameter: [${options.skills.join(", ")}]`); + /* + FNXC:EngineDiagnostics 2026-07-26-08:01: + Per-session "Using skills from convenience parameter" and "Requested skill: " lines fire on every agent start and filled the TUI log pane. Keep them on debug (FUSION_DEBUG=pi); missing/not-found and warn/error skill diagnostics stay visible. + */ + piLog.debug(`Using skills from convenience parameter: [${options.skills.join(", ")}]`); effectiveSkillSelection = { projectRootDir: resolvedProjectRoot, requestedSkillNames: options.skills, @@ -2348,6 +2352,8 @@ export async function createFnAgent(options: AgentOptions): Promise const msg = `[skills] [${purpose}] ${diag.type}: ${diag.message}`; if (diag.type === "error") piLog.error(msg); else if (diag.type === "warning") piLog.warn(msg); + // Steady-state listing of each requested name (not the 'not found' miss diagnostics). + else if (diag.type === "info" && diag.message.startsWith("Requested skill:")) piLog.debug(msg); else piLog.log(msg); } } diff --git a/packages/engine/src/routine-scheduler.ts b/packages/engine/src/routine-scheduler.ts index 635c31d25b..cc3221fde6 100644 --- a/packages/engine/src/routine-scheduler.ts +++ b/packages/engine/src/routine-scheduler.ts @@ -179,7 +179,8 @@ export class RoutineScheduler { for (const routine of dueRoutines) { // Skip if already executed this tick (de-duplication across scopes) if (executedIds.has(routine.id)) { - logger.log(`[${routine.id}] Skipped: already executed from another scope this tick`); + // FNXC:EngineDiagnostics 2026-07-26-08:17: multi-scope skip chatter is expected; processing/execute stays at info. + logger.debug(`[${routine.id}] Skipped: already executed from another scope this tick`); continue; } executedIds.add(routine.id); @@ -187,7 +188,7 @@ export class RoutineScheduler { // Log which scope this routine is from const routineScope = routine.scope ?? "project"; if (routineScope !== this.scope && this.scope !== "all") { - logger.log(`[${routine.id}] Skipped: belongs to ${routineScope} scope, not polling`); + logger.debug(`[${routine.id}] Skipped: belongs to ${routineScope} scope, not polling`); continue; } @@ -232,7 +233,7 @@ export class RoutineScheduler { // Skip if disabled if (!routine.enabled) { - logger.log(`[${routineId}] Skipped: routine is disabled`); + logger.debug(`[${routineId}] Skipped: routine is disabled`); return; } diff --git a/packages/engine/src/session-skill-context.ts b/packages/engine/src/session-skill-context.ts index 0e9860b63b..c54e1e46c7 100644 --- a/packages/engine/src/session-skill-context.ts +++ b/packages/engine/src/session-skill-context.ts @@ -190,7 +190,8 @@ export function collectPluginSkillNames( additionalSkillPathSet.add(dirname(bodyDir)); } - piLog.log(`[skills] Plugin ${pluginId} contributes skill: ${name}`); + // FNXC:EngineDiagnostics 2026-07-26-08:17: one line per plugin skill per session is steady-state discovery chatter. + piLog.debug(`[skills] Plugin ${pluginId} contributes skill: ${name}`); } return { @@ -366,7 +367,8 @@ function mergePluginSkills( } if (appendedPluginNames.length > 0) { - piLog.log( + // FNXC:EngineDiagnostics 2026-07-26-08:17: merge summary is expected every session that has plugin skills — debug-only. + piLog.debug( `[skills] Merged ${appendedPluginNames.length} plugin skill(s) into ${sessionPurpose} session: [${appendedPluginNames.join(", ")}]`, ); } diff --git a/packages/engine/src/skill-resolver.ts b/packages/engine/src/skill-resolver.ts index 1da7df736d..20c51f5403 100644 --- a/packages/engine/src/skill-resolver.ts +++ b/packages/engine/src/skill-resolver.ts @@ -386,6 +386,15 @@ function isMissingConfiguredPatternDiagnostic(diag: ResourceDiagnostic): boolean && diag.message.includes("' not found in discovered skills"); } +/* +FNXC:EngineDiagnostics 2026-07-26-08:01: +"Requested skill: " is a per-session listing diagnostic (not a miss). Emitting it at info filled the TUI with one line per skill on every session start. Keep the ResourceDiagnostic for programmatic consumers; mirror only to piLog.debug (FUSION_DEBUG=pi). Distinct from `Requested skill '…' not found…` miss diagnostics, which stay at info. +*/ +function isRequestedSkillListingDiagnostic(diag: ResourceDiagnostic): boolean { + const diagnosticType = diag.type as string; + return diagnosticType === "info" && diag.message.startsWith("Requested skill:"); +} + /** * Options for skills override filtering. * We track requested names here so we can validate against base.skills. @@ -538,6 +547,7 @@ export function createSkillsOverrideFromSelection( const msg = `[skills] ${diag.type}: ${diag.message}`; if (diag.type === "error") piLog.error(msg); else if (diag.type === "warning") piLog.warn(msg); + else if (isRequestedSkillListingDiagnostic(diag)) piLog.debug(msg); else piLog.log(msg); } } diff --git a/packages/engine/src/stuck-task-detector.ts b/packages/engine/src/stuck-task-detector.ts index 9826680f7b..4c22a11202 100644 --- a/packages/engine/src/stuck-task-detector.ts +++ b/packages/engine/src/stuck-task-detector.ts @@ -274,7 +274,11 @@ export class StuckTaskDetector { start(): void { if (this.interval) return; this.interval = setInterval(() => { - stuckLog.log("Running periodic stuck task check (polling)"); + /* + FNXC:EngineDiagnostics 2026-07-26-08:20: + The poll tick fires every pollIntervalMs with no state change. Logging it at info filled the TUI with steady-state "Running periodic stuck task check" lines. Keep on debug (FUSION_DEBUG=stuck-detector); real stuck detections and check errors stay on log/warn/error. + */ + stuckLog.debug("Running periodic stuck task check (polling)"); this.checkStuckTasks().catch((err) => { stuckLog.error("Error checking stuck tasks:", err); }); @@ -387,8 +391,12 @@ export class StuckTaskDetector { this.pushToolFingerprint(entry, fingerprint); } } + /* + FNXC:EngineDiagnostics 2026-07-26-08:14: + Text/tool heartbeats fire many times per session. These sampled "Activity recorded" lines are steady-state liveness chatter and filled the TUI log pane; keep them on debug (FUSION_DEBUG=stuck-detector). Real stuck detections and track/untrack state changes stay on log/warn/error. + */ if (entry.activitySinceProgress <= 3 || entry.activitySinceProgress % 50 === 0) { - stuckLog.log( + stuckLog.debug( `Activity recorded for ${taskId} (sinceProgress=${entry.activitySinceProgress}` + `${toolName ? `, tools=${entry.toolFingerprints.length}` : ""})`, );