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.
This commit is contained in:
@@ -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();
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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 () => {
|
||||
|
||||
@@ -60,6 +60,7 @@ export function createBudgetStatus(overrides: Partial<AgentBudgetStatus> = {}):
|
||||
export function createMockLogger() {
|
||||
return {
|
||||
log: vi.fn(),
|
||||
debug: vi.fn(),
|
||||
warn: vi.fn(),
|
||||
error: vi.fn(),
|
||||
};
|
||||
|
||||
112
packages/engine/src/__tests__/log-severity-spam-contract.test.ts
Normal file
112
packages/engine/src/__tests__/log-severity-spam-contract.test.ts
Normal file
@@ -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();
|
||||
});
|
||||
});
|
||||
@@ -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 () => {
|
||||
|
||||
@@ -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(
|
||||
|
||||
@@ -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;
|
||||
}
|
||||
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -202,7 +202,8 @@ export class PeerExchangeService {
|
||||
async syncWithAllPeers(): Promise<SyncResult[]> {
|
||||
// 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;
|
||||
}
|
||||
|
||||
|
||||
@@ -2329,7 +2329,11 @@ export async function createFnAgent(options: AgentOptions): Promise<AgentResult>
|
||||
// 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: <name>" 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<AgentResult>
|
||||
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);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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;
|
||||
}
|
||||
|
||||
|
||||
@@ -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(", ")}]`,
|
||||
);
|
||||
}
|
||||
|
||||
@@ -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: <name>" 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);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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}` : ""})`,
|
||||
);
|
||||
|
||||
Reference in New Issue
Block a user