fix(FN-2371): preserve log severity in dashboard TUI capture

- Add severity control markers to core and engine structured loggers while keeping info logs on stderr transport
- Parse and strip internal severity markers in dashboard TUI console capture so logger.log entries render with info icons instead of error icons
- Expand dashboard TUI tests to cover captured console severity mapping and structured logger behavior, plus logger unit tests in core/engine
- Add a patch changeset for @runfusion/fusion describing the TUI log severity icon fix
This commit is contained in:
Fusion
2026-04-24 01:11:51 -07:00
committed by gsxdsm
parent ea079ef153
commit 31f021a03e
9 changed files with 229 additions and 41 deletions

View File

@@ -0,0 +1,5 @@
---
"@runfusion/fusion": patch
---
Fix dashboard TUI log severity rendering so structured `logger.log(...)` entries routed via `stderr` display with info severity/icon instead of being misclassified as errors.

View File

@@ -1,5 +1,5 @@
import { afterAll, beforeAll, describe, expect, it } from "vitest"; import { afterAll, beforeAll, describe, expect, it } from "vitest";
import { existsSync, renameSync } from "node:fs"; import { existsSync, renameSync, rmSync } from "node:fs";
import { join } from "node:path"; import { join } from "node:path";
import vitestConfig from "../../vitest.config"; import vitestConfig from "../../vitest.config";
@@ -17,6 +17,9 @@ function hideInternalPackageDistDirs() {
} }
const hiddenPath = `${distPath}.__fn2360-hidden-${process.pid}`; const hiddenPath = `${distPath}.__fn2360-hidden-${process.pid}`;
if (existsSync(hiddenPath)) {
rmSync(hiddenPath, { recursive: true, force: true });
}
renameSync(distPath, hiddenPath); renameSync(distPath, hiddenPath);
movedDistDirs.push({ from: distPath, to: hiddenPath }); movedDistDirs.push({ from: distPath, to: hiddenPath });
} }
@@ -26,6 +29,9 @@ function restoreInternalPackageDistDirs() {
for (let i = movedDistDirs.length - 1; i >= 0; i--) { for (let i = movedDistDirs.length - 1; i >= 0; i--) {
const { from, to } = movedDistDirs[i]; const { from, to } = movedDistDirs[i];
if (existsSync(to)) { if (existsSync(to)) {
if (existsSync(from)) {
rmSync(from, { recursive: true, force: true });
}
renameSync(to, from); renameSync(to, from);
} }
} }

View File

@@ -10,6 +10,7 @@ import {
type TaskStats, type TaskStats,
type SettingsValues, type SettingsValues,
} from "./dashboard-tui.js"; } from "./dashboard-tui.js";
import { createLogger } from "@fusion/engine";
// ── LogRingBuffer Tests ──────────────────────────────────────────────────── // ── LogRingBuffer Tests ────────────────────────────────────────────────────
@@ -197,7 +198,7 @@ describe("DashboardLogSink.captureConsole", () => {
sink.releaseConsole(); sink.releaseConsole();
}); });
it("routes console.error to sink.error", () => { it("keeps raw console.error lines as error", () => {
const tui = new DashboardTUI(); const tui = new DashboardTUI();
const sink = new DashboardLogSink(); const sink = new DashboardLogSink();
sink.setTUI(tui); sink.setTUI(tui);
@@ -215,6 +216,46 @@ describe("DashboardLogSink.captureConsole", () => {
sink.releaseConsole(); sink.releaseConsole();
}); });
it("treats structured logger.log routed via console.error as info", () => {
const tui = new DashboardTUI();
const sink = new DashboardLogSink();
sink.setTUI(tui);
sink.captureConsole();
const logger = createLogger("executor");
logger.log("task moved to in-progress");
const entries = (tui as unknown as {
logBuffer: LogRingBuffer;
}).logBuffer.getAll();
expect(entries).toHaveLength(1);
expect(entries[0].level).toBe("info");
expect(entries[0].prefix).toBe("executor");
expect(entries[0].message).toBe("task moved to in-progress");
sink.releaseConsole();
});
it("keeps structured logger.error as error", () => {
const tui = new DashboardTUI();
const sink = new DashboardLogSink();
sink.setTUI(tui);
sink.captureConsole();
const logger = createLogger("executor");
logger.error("task failed");
const entries = (tui as unknown as {
logBuffer: LogRingBuffer;
}).logBuffer.getAll();
expect(entries).toHaveLength(1);
expect(entries[0].level).toBe("error");
expect(entries[0].prefix).toBe("executor");
expect(entries[0].message).toBe("task failed");
sink.releaseConsole();
});
it("handles untagged messages without a prefix", () => { it("handles untagged messages without a prefix", () => {
const tui = new DashboardTUI(); const tui = new DashboardTUI();
const sink = new DashboardLogSink(); const sink = new DashboardLogSink();
@@ -255,21 +296,59 @@ describe("DashboardLogSink.captureConsole", () => {
}); });
}); });
describe("DashboardTUI log icon rendering", () => {
it("shows info icon (✓) instead of error icon (✗) for structured logger.log entries", () => {
const tui = new DashboardTUI();
const sink = new DashboardLogSink();
sink.setTUI(tui);
sink.captureConsole();
const stdoutWriteSpy = vi.spyOn(process.stdout, "write").mockImplementation(() => true);
(tui as any).activeSection = "logs";
(tui as any).isRunning = true;
try {
const logger = createLogger("executor");
logger.log("task moved to in-progress");
stdoutWriteSpy.mockClear();
(tui as any).renderLogsSection();
const rendered = stdoutWriteSpy.mock.calls.map(([chunk]) => String(chunk)).join("");
const stripped = rendered.replace(/\x1b\[[0-9;]*[a-zA-Z]/g, "");
expect(stripped).toContain("✓ [executor] task moved to in-progress");
expect(stripped).not.toContain("✗ [executor] task moved to in-progress");
} finally {
stdoutWriteSpy.mockRestore();
sink.releaseConsole();
}
});
});
// ── formatConsoleArgs helper ─────────────────────────────────────────────── // ── formatConsoleArgs helper ───────────────────────────────────────────────
describe("formatConsoleArgs", () => { describe("formatConsoleArgs", () => {
it("joins multiple args with a space", () => { it("joins multiple args with a space", () => {
const { message, prefix } = formatConsoleArgs(["hello", "world"]); const { message, prefix, level } = formatConsoleArgs(["hello", "world"]);
expect(prefix).toBeUndefined(); expect(prefix).toBeUndefined();
expect(level).toBe("info");
expect(message).toBe("hello world"); expect(message).toBe("hello world");
}); });
it("extracts a leading [prefix] tag", () => { it("extracts a leading [prefix] tag", () => {
const { message, prefix } = formatConsoleArgs(["[executor] starting task FN-123"]); const { message, prefix, level } = formatConsoleArgs(["[executor] starting task FN-123"], "warn");
expect(prefix).toBe("executor"); expect(prefix).toBe("executor");
expect(level).toBe("warn");
expect(message).toBe("starting task FN-123"); expect(message).toBe("starting task FN-123");
}); });
it("strips the internal severity marker and returns explicit level", () => {
const { message, prefix, level } = formatConsoleArgs(["\u0000fnlvl=error\u0000[executor] task failed"], "info");
expect(prefix).toBe("executor");
expect(level).toBe("error");
expect(message).toBe("task failed");
});
it("stringifies objects via JSON", () => { it("stringifies objects via JSON", () => {
const { message } = formatConsoleArgs(["result:", { ok: true, count: 3 }]); const { message } = formatConsoleArgs(["result:", { ok: true, count: 3 }]);
expect(message).toBe('result: {"ok":true,"count":3}'); expect(message).toBe('result: {"ok":true,"count":3}');

View File

@@ -1339,9 +1339,11 @@ export class DashboardLogSink {
/** /**
* Monkey-patch `console.log/warn/error` so everything (including the engine's * Monkey-patch `console.log/warn/error` so everything (including the engine's
* createLogger() output, which writes directly to console.error) surfaces in * createLogger() output, which writes directly to console.error) surfaces in
* the TUI's log ring buffer. Without this, most runtime logs render beneath * the TUI's log ring buffer. Structured logger calls carry an internal
* the alt-screen TUI and are immediately overwritten on the next render, * severity marker so `logger.log(...)` still lands as info even when routed
* leaving the Logs tab nearly empty. * through console.error transport. Without capture, most runtime logs render
* beneath the alt-screen TUI and are immediately overwritten on the next
* render, leaving the Logs tab nearly empty.
* *
* Messages that start with `[prefix] rest` are unpacked so the TUI stores * Messages that start with `[prefix] rest` are unpacked so the TUI stores
* `prefix="prefix"` and `message="rest"`. Idempotent; call `releaseConsole()` * `prefix="prefix"` and `message="rest"`. Idempotent; call `releaseConsole()`
@@ -1358,16 +1360,16 @@ export class DashboardLogSink {
error: console.error, error: console.error,
}; };
console.log = (...args: unknown[]) => { console.log = (...args: unknown[]) => {
const { message, prefix } = formatConsoleArgs(args); const { message, prefix, level } = formatConsoleArgs(args, "info");
this.log(message, prefix); this.writeCapturedConsoleLog(level, message, prefix);
}; };
console.warn = (...args: unknown[]) => { console.warn = (...args: unknown[]) => {
const { message, prefix } = formatConsoleArgs(args); const { message, prefix, level } = formatConsoleArgs(args, "warn");
this.warn(message, prefix); this.writeCapturedConsoleLog(level, message, prefix);
}; };
console.error = (...args: unknown[]) => { console.error = (...args: unknown[]) => {
const { message, prefix } = formatConsoleArgs(args); const { message, prefix, level } = formatConsoleArgs(args, "error");
this.error(message, prefix); this.writeCapturedConsoleLog(level, message, prefix);
}; };
} }
@@ -1379,15 +1381,33 @@ export class DashboardLogSink {
console.error = this.originalConsole.error; console.error = this.originalConsole.error;
this.originalConsole = null; this.originalConsole = null;
} }
private writeCapturedConsoleLog(level: LogEntry["level"], message: string, prefix?: string): void {
if (level === "error") {
this.error(message, prefix);
return;
}
if (level === "warn") {
this.warn(message, prefix);
return;
}
this.log(message, prefix);
}
} }
const LOG_LEVEL_MARKER_REGEX = /^\u0000fnlvl=(info|warn|error)\u0000\s*/;
/** /**
* Format heterogeneous console args into a single string, and extract a * Format heterogeneous console args into a single string, extracting a
* leading `[prefix]` if present. Mirrors `util.format` loosely without * leading internal severity marker and `[prefix]` tag when present.
* the dependency — objects are JSON-stringified (defensively, falling back * Mirrors `util.format` loosely without the dependency — objects are
* to String()), everything else is coerced via String(). * JSON-stringified (defensively, falling back to String()), everything
* else is coerced via String().
*/ */
export function formatConsoleArgs(args: unknown[]): { message: string; prefix?: string } { export function formatConsoleArgs(
args: unknown[],
fallbackLevel: LogEntry["level"] = "info",
): { message: string; prefix?: string; level: LogEntry["level"] } {
const stringified = args.map((arg) => { const stringified = args.map((arg) => {
if (typeof arg === "string") return arg; if (typeof arg === "string") return arg;
if (arg instanceof Error) return arg.stack ?? arg.message; if (arg instanceof Error) return arg.stack ?? arg.message;
@@ -1398,11 +1418,15 @@ export function formatConsoleArgs(args: unknown[]): { message: string; prefix?:
return String(arg); return String(arg);
}).join(" "); }).join(" ");
const match = stringified.match(/^\[([^\]]+)\]\s*(.*)$/s); const markerMatch = stringified.match(LOG_LEVEL_MARKER_REGEX);
const level = markerMatch?.[1] as LogEntry["level"] | undefined;
const withoutMarker = markerMatch ? stringified.replace(LOG_LEVEL_MARKER_REGEX, "") : stringified;
const match = withoutMarker.match(/^\[([^\]]+)\]\s*(.*)$/s);
if (match) { if (match) {
return { prefix: match[1], message: match[2] }; return { prefix: match[1], message: match[2], level: level ?? fallbackLevel };
} }
return { message: stringified }; return { message: withoutMarker, level: level ?? fallbackLevel };
} }
// ── String Helpers ──────────────────────────────────────────────────────────── // ── String Helpers ────────────────────────────────────────────────────────────

View File

@@ -0,0 +1,43 @@
import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
import { createLogger } from "./logger.js";
describe("core createLogger", () => {
let logSpy: ReturnType<typeof vi.spyOn>;
let warnSpy: ReturnType<typeof vi.spyOn>;
let errorSpy: ReturnType<typeof vi.spyOn>;
beforeEach(() => {
logSpy = vi.spyOn(console, "log").mockImplementation(() => {});
warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {});
errorSpy = vi.spyOn(console, "error").mockImplementation(() => {});
});
afterEach(() => {
logSpy.mockRestore();
warnSpy.mockRestore();
errorSpy.mockRestore();
});
it("emits info logs to stderr with an info severity marker", () => {
const logger = createLogger("core-test");
logger.log("hello");
expect(logSpy).not.toHaveBeenCalled();
expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=info\u0000[core-test] hello");
});
it("emits warn logs with a warn severity marker", () => {
const logger = createLogger("core-test");
logger.warn("careful");
expect(warnSpy).toHaveBeenCalledWith("\u0000fnlvl=warn\u0000[core-test] careful");
});
it("emits error logs with an error severity marker", () => {
const logger = createLogger("core-test");
const err = new Error("boom");
logger.error("broken", err);
expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=error\u0000[core-test] broken", err);
});
});

View File

@@ -20,6 +20,13 @@ export interface Logger {
error(message: string, ...args: unknown[]): void; error(message: string, ...args: unknown[]): void;
} }
const LOG_LEVEL_MARKER_PREFIX = "\u0000fnlvl=";
const LOG_LEVEL_MARKER_SUFFIX = "\u0000";
function withSeverityMarker(level: "info" | "warn" | "error", payload: string): string {
return `${LOG_LEVEL_MARKER_PREFIX}${level}${LOG_LEVEL_MARKER_SUFFIX}${payload}`;
}
/** /**
* Create a structured logger that prefixes every message with `[prefix]`. * Create a structured logger that prefixes every message with `[prefix]`.
* *
@@ -27,18 +34,22 @@ export interface Logger {
* @returns A `Logger` whose output is prefixed and sent to stderr for normal * @returns A `Logger` whose output is prefixed and sent to stderr for normal
* logs and errors. Keeping logs off stdout prevents command/test * logs and errors. Keeping logs off stdout prevents command/test
* output consumers from receiving Fusion execution chatter. * output consumers from receiving Fusion execution chatter.
*
* 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`.
*/ */
export function createLogger(prefix: string): Logger { export function createLogger(prefix: string): Logger {
const tag = `[${prefix}]`; const tag = `[${prefix}]`;
return { return {
log(message: string, ...args: unknown[]) { log(message: string, ...args: unknown[]) {
console.error(`${tag} ${message}`, ...args); console.error(withSeverityMarker("info", `${tag} ${message}`), ...args);
}, },
warn(message: string, ...args: unknown[]) { warn(message: string, ...args: unknown[]) {
console.warn(`${tag} ${message}`, ...args); console.warn(withSeverityMarker("warn", `${tag} ${message}`), ...args);
}, },
error(message: string, ...args: unknown[]) { error(message: string, ...args: unknown[]) {
console.error(`${tag} ${message}`, ...args); console.error(withSeverityMarker("error", `${tag} ${message}`), ...args);
}, },
}; };
} }

View File

@@ -17,6 +17,11 @@
* of control for filtering, suppressing (e.g. in tests), or redirecting * of control for filtering, suppressing (e.g. in tests), or redirecting
* engine log output in the future. * engine log output in the future.
*/ */
const LOG_LEVEL_MARKER_PREFIX = "\0fnlvl=";
const LOG_LEVEL_MARKER_SUFFIX = "\0";
function withSeverityMarker(level, payload) {
return `${LOG_LEVEL_MARKER_PREFIX}${level}${LOG_LEVEL_MARKER_SUFFIX}${payload}`;
}
/** /**
* Create a structured logger that prefixes every message with `[prefix]`. * Create a structured logger that prefixes every message with `[prefix]`.
* *
@@ -24,18 +29,22 @@
* @returns A `Logger` whose output is prefixed and sent to stderr. Keeping * @returns A `Logger` whose output is prefixed and sent to stderr. Keeping
* engine logs off stdout prevents command/test output consumers from * engine logs off stdout prevents command/test output consumers from
* receiving Fusion execution chatter. * receiving Fusion execution chatter.
*
* 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`.
*/ */
export function createLogger(prefix) { export function createLogger(prefix) {
const tag = `[${prefix}]`; const tag = `[${prefix}]`;
return { return {
log(message, ...args) { log(message, ...args) {
globalThis.console.error(`${tag} ${message}`, ...args); globalThis.console.error(withSeverityMarker("info", `${tag} ${message}`), ...args);
}, },
warn(message, ...args) { warn(message, ...args) {
globalThis.console.warn(`${tag} ${message}`, ...args); globalThis.console.warn(withSeverityMarker("warn", `${tag} ${message}`), ...args);
}, },
error(message, ...args) { error(message, ...args) {
globalThis.console.error(`${tag} ${message}`, ...args); globalThis.console.error(withSeverityMarker("error", `${tag} ${message}`), ...args);
}, },
}; };
} }

View File

@@ -31,26 +31,26 @@ describe("createLogger", () => {
const logger = createLogger("test"); const logger = createLogger("test");
logger.log("hello world"); logger.log("hello world");
expect(logSpy).not.toHaveBeenCalled(); expect(logSpy).not.toHaveBeenCalled();
expect(errorSpy).toHaveBeenCalledWith("[test] hello world"); expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=info\u0000[test] hello world");
}); });
it("formats warn output as [prefix] message", () => { it("formats warn output as [prefix] message", () => {
const logger = createLogger("test"); const logger = createLogger("test");
logger.warn("something happened"); logger.warn("something happened");
expect(warnSpy).toHaveBeenCalledWith("[test] something happened"); expect(warnSpy).toHaveBeenCalledWith("\u0000fnlvl=warn\u0000[test] something happened");
}); });
it("formats error output as [prefix] message", () => { it("formats error output as [prefix] message", () => {
const logger = createLogger("test"); const logger = createLogger("test");
logger.error("failure"); logger.error("failure");
expect(errorSpy).toHaveBeenCalledWith("[test] failure"); expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=error\u0000[test] failure");
}); });
it("passes extra arguments through", () => { it("passes extra arguments through", () => {
const logger = createLogger("test"); const logger = createLogger("test");
const err = new Error("boom"); const err = new Error("boom");
logger.error("failed:", err); logger.error("failed:", err);
expect(errorSpy).toHaveBeenCalledWith("[test] failed:", err); expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=error\u0000[test] failed:", err);
}); });
it("keeps log output off stdout", () => { it("keeps log output off stdout", () => {
@@ -65,24 +65,24 @@ describe("createLogger", () => {
it("pre-built instances use correct prefixes", () => { it("pre-built instances use correct prefixes", () => {
schedulerLog.log("tick"); schedulerLog.log("tick");
expect(errorSpy).toHaveBeenCalledWith("[scheduler] tick"); expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=info\u0000[scheduler] tick");
executorLog.log("run"); executorLog.log("run");
expect(errorSpy).toHaveBeenCalledWith("[executor] run"); expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=info\u0000[executor] run");
triageLog.log("spec"); triageLog.log("spec");
expect(errorSpy).toHaveBeenCalledWith("[triage] spec"); expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=info\u0000[triage] spec");
mergerLog.log("merge"); mergerLog.log("merge");
expect(errorSpy).toHaveBeenCalledWith("[merger] merge"); expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=info\u0000[merger] merge");
worktreePoolLog.log("prune"); worktreePoolLog.log("prune");
expect(errorSpy).toHaveBeenCalledWith("[worktree-pool] prune"); expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=info\u0000[worktree-pool] prune");
reviewerLog.log("review"); reviewerLog.log("review");
expect(errorSpy).toHaveBeenCalledWith("[reviewer] review"); expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=info\u0000[reviewer] review");
remoteNodeLog.log("stream"); remoteNodeLog.log("stream");
expect(errorSpy).toHaveBeenCalledWith("[remote-node] stream"); expect(errorSpy).toHaveBeenCalledWith("\u0000fnlvl=info\u0000[remote-node] stream");
}); });
}); });

View File

@@ -22,6 +22,13 @@ export interface Logger {
error(message: string, ...args: unknown[]): void; error(message: string, ...args: unknown[]): void;
} }
const LOG_LEVEL_MARKER_PREFIX = "\u0000fnlvl=";
const LOG_LEVEL_MARKER_SUFFIX = "\u0000";
function withSeverityMarker(level: "info" | "warn" | "error", payload: string): string {
return `${LOG_LEVEL_MARKER_PREFIX}${level}${LOG_LEVEL_MARKER_SUFFIX}${payload}`;
}
/** /**
* Create a structured logger that prefixes every message with `[prefix]`. * Create a structured logger that prefixes every message with `[prefix]`.
* *
@@ -29,18 +36,22 @@ export interface Logger {
* @returns A `Logger` whose output is prefixed and sent to stderr. Keeping * @returns A `Logger` whose output is prefixed and sent to stderr. Keeping
* engine logs off stdout prevents command/test output consumers from * engine logs off stdout prevents command/test output consumers from
* receiving Fusion execution chatter. * receiving Fusion execution chatter.
*
* 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`.
*/ */
export function createLogger(prefix: string): Logger { export function createLogger(prefix: string): Logger {
const tag = `[${prefix}]`; const tag = `[${prefix}]`;
return { return {
log(message: string, ...args: unknown[]) { log(message: string, ...args: unknown[]) {
console.error(`${tag} ${message}`, ...args); console.error(withSeverityMarker("info", `${tag} ${message}`), ...args);
}, },
warn(message: string, ...args: unknown[]) { warn(message: string, ...args: unknown[]) {
console.warn(`${tag} ${message}`, ...args); console.warn(withSeverityMarker("warn", `${tag} ${message}`), ...args);
}, },
error(message: string, ...args: unknown[]) { error(message: string, ...args: unknown[]) {
console.error(`${tag} ${message}`, ...args); console.error(withSeverityMarker("error", `${tag} ${message}`), ...args);
}, },
}; };
} }