feat(FN-2327): standardize dashboard runtime logging pipeline

- Add a shared runtime logger contract and dashboard runtime logger implementation for structured diagnostics
- Route dashboard CLI/runtime logs through the TUI sink and replace ad-hoc console diagnostics in server paths
- Update CLI and dashboard tests to assert structured runtime logging behavior across sync and error flows
- Document the structured logging architecture updates and include a changeset for @runfusion/fusion
This commit is contained in:
Fusion
2026-04-23 13:48:45 -07:00
committed by gsxdsm
parent 18b2c827a0
commit c01892dbd2
14 changed files with 436 additions and 113 deletions

View File

@@ -2615,3 +2615,61 @@ describe("runDashboard — merge stream sink routing", () => {
consoleLogSpy.mockRestore();
});
});
describe("runDashboard runtime logger wiring", () => {
it("injects a runtime logger into createServer and preserves non-TTY console fallback", async () => {
const { createServer } = await import("@fusion/dashboard");
const consoleLogSpy = vi.spyOn(console, "log").mockImplementation(() => {});
await runDashboard(0, { open: false, dev: true });
const createServerCall = (createServer as ReturnType<typeof vi.fn>).mock.calls.at(-1)!;
const serverOpts = createServerCall[1] as { runtimeLogger?: { info: (message: string, context?: Record<string, unknown>) => void } };
expect(serverOpts.runtimeLogger).toBeDefined();
serverOpts.runtimeLogger?.info("runtime diagnostic", { source: "test" });
expect(consoleLogSpy).toHaveBeenCalledWith(
'[dashboard] runtime diagnostic {"source":"test"}',
);
consoleLogSpy.mockRestore();
});
it("routes runtime logger output through DashboardLogSink in TTY mode", async () => {
const { createServer } = await import("@fusion/dashboard");
const { DashboardLogSink, DashboardTUI } = await import("./dashboard-tui.js");
const originalStdoutIsTTY = process.stdout.isTTY;
const originalStdinIsTTY = process.stdin.isTTY;
Object.defineProperty(process.stdout, "isTTY", { value: true, configurable: true });
Object.defineProperty(process.stdin, "isTTY", { value: true, configurable: true });
const tuiStartSpy = vi.spyOn(DashboardTUI.prototype, "start").mockResolvedValue(undefined);
const tuiStopSpy = vi.spyOn(DashboardTUI.prototype, "stop").mockResolvedValue(undefined);
const tuiLogSpy = vi.spyOn(DashboardTUI.prototype, "log").mockImplementation(() => {});
const captureConsoleSpy = vi.spyOn(DashboardLogSink.prototype, "captureConsole").mockImplementation(() => {});
try {
await runDashboard(0, { open: false, dev: true });
expect(captureConsoleSpy).toHaveBeenCalledTimes(1);
const createServerCall = (createServer as ReturnType<typeof vi.fn>).mock.calls.at(-1)!;
const serverOpts = createServerCall[1] as { runtimeLogger?: { info: (message: string, context?: Record<string, unknown>) => void } };
expect(serverOpts.runtimeLogger).toBeDefined();
serverOpts.runtimeLogger?.info("tty runtime diagnostic", { source: "test" });
expect(tuiLogSpy).toHaveBeenCalledWith('tty runtime diagnostic {"source":"test"}', "dashboard");
expect(tuiStartSpy).toHaveBeenCalled();
} finally {
Object.defineProperty(process.stdout, "isTTY", { value: originalStdoutIsTTY, configurable: true });
Object.defineProperty(process.stdin, "isTTY", { value: originalStdinIsTTY, configurable: true });
tuiStartSpy.mockRestore();
tuiStopSpy.mockRestore();
tuiLogSpy.mockRestore();
captureConsoleSpy.mockRestore();
}
});
});

View File

@@ -2,7 +2,14 @@ import type { AddressInfo } from "node:net";
import { randomBytes } from "node:crypto";
import { join } from "node:path";
import { TaskStore, AutomationStore, CentralCore, AgentStore, PluginStore, PluginLoader, getTaskMergeBlocker, getEnabledPiExtensionPaths, isEphemeralAgent } from "@fusion/core";
import { createServer, GitHubClient, createSkillsAdapter, getProjectSettingsPath, loadTlsCredentialsFromEnv } from "@fusion/dashboard";
import {
createServer,
GitHubClient,
createSkillsAdapter,
getProjectSettingsPath,
loadTlsCredentialsFromEnv,
type RuntimeLogger,
} from "@fusion/dashboard";
import { aiMergeTask, MissionAutopilot, MissionExecutionLoop, HeartbeatMonitor, HeartbeatTriggerScheduler, type WakeContext, ProjectEngineManager, PeerExchangeService } from "@fusion/engine";
import { AuthStorage, DefaultPackageManager, ModelRegistry, discoverAndLoadExtensions, createExtensionRuntime } from "@mariozechner/pi-coding-agent";
import {
@@ -28,6 +35,36 @@ let diagnosticStoreListenerCheck: (() => Record<string, number>) | null = null;
const STREAM_LOG_FLUSH_IDLE_MS = 100;
function formatRuntimeContext(context: Record<string, unknown> | undefined): string {
if (context === undefined) {
return "";
}
try {
return ` ${JSON.stringify(context)}`;
} catch {
return ` ${String(context)}`;
}
}
function createDashboardRuntimeLogger(logSink: DashboardLogSink, scope: string): RuntimeLogger {
return {
scope,
info(message, context) {
logSink.log(`${message}${formatRuntimeContext(context)}`, scope);
},
warn(message, context) {
logSink.warn(`${message}${formatRuntimeContext(context)}`, scope);
},
error(message, context) {
logSink.error(`${message}${formatRuntimeContext(context)}`, scope);
},
child(childScope) {
return createDashboardRuntimeLogger(logSink, `${scope}:${childScope}`);
},
};
}
export class StreamedLogBuffer {
private pending = "";
private flushTimer: ReturnType<typeof setTimeout> | null = null;
@@ -123,7 +160,7 @@ function formatUptime(ms: number): string {
* @param startTime - Process start timestamp
* @param dbHealthCheck - Optional function to check database health
*/
function logDiagnostics(prefix: string, startTime: number, dbHealthCheck?: () => boolean): void {
function logDiagnostics(logger: RuntimeLogger, prefix: string, startTime: number, dbHealthCheck?: () => boolean): void {
const mem = process.memoryUsage();
const uptime = Date.now() - startTime;
@@ -168,7 +205,7 @@ function logDiagnostics(prefix: string, startTime: number, dbHealthCheck?: () =>
`external=${formatBytes(mem.external)} arrayBuffers=${formatBytes(mem.arrayBuffers)} ` +
`handles=${handleCount} requests=${requestCount} db=${dbHealth}${listenerInfo}`;
console.log(logLine);
logger.info(logLine);
}
/**
@@ -176,7 +213,7 @@ function logDiagnostics(prefix: string, startTime: number, dbHealthCheck?: () =>
* Logs memory usage, handle counts, and uptime at startup and every 30 minutes.
* Also logs beforeExit and exit events for shutdown analysis.
*/
function ensureProcessDiagnostics(): void {
function ensureProcessDiagnostics(logger: RuntimeLogger): void {
if (processDiagnosticsRegistered) {
return;
}
@@ -185,11 +222,11 @@ function ensureProcessDiagnostics(): void {
diagnosticStartTime = Date.now();
// Log initial diagnostics at startup (before store is created)
logDiagnostics("dashboard", diagnosticStartTime);
logDiagnostics(logger, "dashboard", diagnosticStartTime);
// Register periodic diagnostics every 30 minutes
diagnosticIntervalHandle = setInterval(() => {
logDiagnostics("dashboard", diagnosticStartTime, diagnosticDbHealthCheck ?? undefined);
logDiagnostics(logger, "dashboard", diagnosticStartTime, diagnosticDbHealthCheck ?? undefined);
}, DIAGNOSTIC_INTERVAL_MS);
diagnosticIntervalHandle.unref?.(); // Don't prevent process exit
@@ -206,24 +243,24 @@ function ensureProcessDiagnostics(): void {
} catch {
// Ignore
}
console.log(`[dashboard] beforeExit code=${code} uptime=${formatUptime(uptime)} handles=${handleCount} requests=${requestCount}`);
logger.info(`[dashboard] beforeExit code=${code} uptime=${formatUptime(uptime)} handles=${handleCount} requests=${requestCount}`);
});
// Log exit event with exit code and uptime
process.on("exit", (code: number) => {
const uptime = Date.now() - diagnosticStartTime;
console.log(`[dashboard] exit code=${code} uptime=${formatUptime(uptime)}`);
logger.info(`[dashboard] exit code=${code} uptime=${formatUptime(uptime)}`);
});
// Log uncaught exceptions
process.on("uncaughtExceptionMonitor", (error: Error) => {
console.error(`[dashboard] uncaught exception pid=${process.pid}: ${error.stack || error.message}`);
logger.error(`[dashboard] uncaught exception pid=${process.pid}: ${error.stack || error.message}`);
});
// Log unhandled rejections
process.on("unhandledRejection", (reason: unknown) => {
const message = reason instanceof Error ? reason.stack || reason.message : String(reason);
console.error(`[dashboard] unhandled rejection pid=${process.pid}: ${message}`);
logger.error(`[dashboard] unhandled rejection pid=${process.pid}: ${message}`);
});
}
@@ -285,7 +322,11 @@ export async function runDashboard(port: number, opts: { paused?: boolean; dev?:
?? process.env.FUSION_DASHBOARD_TOKEN
?? process.env.FUSION_DAEMON_TOKEN
?? `fn_${randomBytes(16).toString("hex")}`;
ensureProcessDiagnostics();
// Single sink/logger pair for all dashboard command diagnostics.
// In TTY mode this routes to DashboardTUI; in non-TTY mode it falls back to console.*.
const logSink = new DashboardLogSink();
const runtimeLogger = createDashboardRuntimeLogger(logSink, "dashboard");
// Handle interactive port selection
let selectedPort = port;
@@ -320,9 +361,6 @@ export async function runDashboard(port: number, opts: { paused?: boolean; dev?:
let store: TaskStore | undefined;
let agentStore: AgentStore | undefined;
// Create a log sink that routes to TUI in TTY mode, or console otherwise
const logSink = new DashboardLogSink();
if (isTTY) {
tui = new DashboardTUI();
// Set up callbacks for utility actions
@@ -394,6 +432,10 @@ export async function runDashboard(port: number, opts: { paused?: boolean; dev?:
logSink.captureConsole();
}
// Register long-running process diagnostics after TTY sink wiring so
// startup/runtime lines flow into the TUI log buffer when interactive.
ensureProcessDiagnostics(runtimeLogger);
store = new TaskStore(cwd);
await store.init();
await store.watch();
@@ -925,6 +967,7 @@ export async function runDashboard(port: number, opts: { paused?: boolean; dev?:
https: loadTlsCredentialsFromEnv(),
daemon: dashboardAuthToken ? { token: dashboardAuthToken } : undefined,
noAuth: opts.noAuth,
runtimeLogger,
});
const shutdown = async (signal: NodeJS.Signals) => {
@@ -1112,6 +1155,7 @@ export async function runDashboard(port: number, opts: { paused?: boolean; dev?:
https: loadTlsCredentialsFromEnv(),
daemon: dashboardAuthToken ? { token: dashboardAuthToken } : undefined,
noAuth: opts.noAuth,
runtimeLogger,
});
}

View File

@@ -578,7 +578,7 @@ describe("Node settings sync routes", () => {
ok: true,
json: () => Promise.resolve({ success: true }),
});
const consoleSpy = vi.spyOn(console, "error").mockImplementation(() => {});
const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {});
await request(
app,
@@ -765,7 +765,7 @@ describe("Node settings sync routes", () => {
it("logs provider names but not credentials", async () => {
const localNode = createMockLocalNode();
mockListNodes.mockResolvedValue([localNode]);
const consoleSpy = vi.spyOn(console, "error").mockImplementation(() => {});
const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {});
await request(
app,

View File

@@ -203,7 +203,7 @@ describe("GET /api/projects/across-nodes", () => {
// Should have logged a warning
expect(consoleWarnSpy).toHaveBeenCalled();
expect(consoleWarnSpy.mock.calls[0][0]).toContain("[projects:across-nodes]");
expect(consoleWarnSpy.mock.calls[0][0]).toContain("projects:across-nodes]");
consoleWarnSpy.mockRestore();
});

View File

@@ -1,7 +1,7 @@
// @vitest-environment node
import type { NextFunction, Request, Response } from "express";
import { beforeEach, describe, expect, it, vi } from "vitest";
import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
import {
ApiError,
badRequest,
@@ -13,8 +13,14 @@ import {
sendErrorResponse,
unauthorized,
} from "./api-error.js";
import { resetRuntimeLogSink, setRuntimeLogSink } from "./runtime-logger.js";
const consoleErrorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined);
const runtimeLogEvents: Array<{
level: string;
scope: string;
message: string;
context?: Record<string, unknown>;
}> = [];
interface MockResponse {
res: Response;
@@ -49,6 +55,17 @@ function createMockResponse(overrides?: Partial<Response>, requestOverrides?: Pa
};
}
beforeEach(() => {
runtimeLogEvents.length = 0;
setRuntimeLogSink((level, scope, message, context) => {
runtimeLogEvents.push({ level, scope, message, context });
});
});
afterEach(() => {
resetRuntimeLogSink();
});
describe("ApiError", () => {
it("sets statusCode, message, and details", () => {
const details = { foo: "bar" };
@@ -67,9 +84,6 @@ describe("ApiError", () => {
});
describe("sendErrorResponse", () => {
beforeEach(() => {
consoleErrorSpy.mockClear();
});
it("sends standard { error: string } payload", () => {
const { res, statusMock, jsonMock } = createMockResponse();
@@ -102,11 +116,16 @@ describe("sendErrorResponse", () => {
sendErrorResponse(res, 500, "Internal issue");
expect(consoleErrorSpy).toHaveBeenCalledWith("[api:error]", {
method: "GET",
path: "/api/test?x=1",
statusCode: 500,
message: "Internal issue",
expect(runtimeLogEvents).toContainEqual({
level: "error",
scope: "api:error",
message: "Request failed",
context: {
method: "GET",
path: "/api/test?x=1",
statusCode: 500,
message: "Internal issue",
},
});
});
@@ -115,14 +134,11 @@ describe("sendErrorResponse", () => {
sendErrorResponse(res, 404, "Not found");
expect(consoleErrorSpy).not.toHaveBeenCalled();
expect(runtimeLogEvents).toHaveLength(0);
});
});
describe("catchHandler", () => {
beforeEach(() => {
consoleErrorSpy.mockClear();
});
it("catches ApiError and sends status/message/details", async () => {
const details = { field: "name" };
@@ -137,7 +153,7 @@ describe("catchHandler", () => {
expect(statusMock).toHaveBeenCalledWith(400);
expect(jsonMock).toHaveBeenCalledWith({ error: "Invalid input", details });
expect(next).not.toHaveBeenCalled();
expect(consoleErrorSpy).not.toHaveBeenCalled();
expect(runtimeLogEvents).toHaveLength(0);
});
it("catches generic Error and sends 500 with error message", async () => {
@@ -151,7 +167,17 @@ describe("catchHandler", () => {
expect(statusMock).toHaveBeenCalledWith(500);
expect(jsonMock).toHaveBeenCalledWith({ error: "boom" });
expect(consoleErrorSpy).toHaveBeenCalledTimes(1);
expect(runtimeLogEvents).toContainEqual(
expect.objectContaining({
level: "error",
scope: "api:error",
message: "Request failed",
context: expect.objectContaining({
statusCode: 500,
message: "boom",
}),
}),
);
});
it("calls next(err) when headers are already sent", async () => {

View File

@@ -1,4 +1,5 @@
import type { NextFunction, Request, RequestHandler, Response } from "express";
import { createRuntimeLogger, type RuntimeLogger } from "./runtime-logger.js";
export interface ApiErrorResponse {
error: string;
@@ -7,6 +8,7 @@ export interface ApiErrorResponse {
export interface SendErrorOptions {
details?: Record<string, unknown>;
logger?: RuntimeLogger;
}
export class ApiError extends Error {
@@ -31,7 +33,8 @@ export function sendErrorResponse(
): Response<ApiErrorResponse> {
if (statusCode >= 500) {
const request = res.req;
console.error("[api:error]", {
const logger = options?.logger ?? createRuntimeLogger("api:error");
logger.error("Request failed", {
method: request?.method,
path: request?.originalUrl ?? request?.path,
statusCode,

View File

@@ -1,4 +1,14 @@
export { createServer, loadTlsCredentialsFromEnv, type ServerOptions } from "./server.js";
export {
createRuntimeLogger,
getRuntimeLogSink,
resetRuntimeLogSink,
setRuntimeLogSink,
type RuntimeLogContext,
type RuntimeLogger,
type RuntimeLogLevel,
type RuntimeLogSink,
} from "./runtime-logger.js";
export { createSkillsAdapter, getProjectSettingsPath, type SkillsAdapter, type DiscoveredSkill, type CatalogEntry, type CatalogFetchResult, type ToggleSkillResult, type UpstreamError, type UpstreamErrorCode, type SkillContent, type SkillFileEntry } from "./skills-adapter.js";
export { GitHubClient, isPrMergeReady, type PrMergeStatus, type PrCheckStatus, type ReviewDecision, type MergePrParams, type FindPrParams } from "./github.js";
export { rateLimit, RATE_LIMITS, type RateLimitOptions } from "./rate-limit.js";

View File

@@ -24,6 +24,7 @@ import { SESSION_CLEANUP_DEFAULT_MAX_AGE_MS } from "./ai-session-store.js";
import * as projectStoreResolver from "./project-store-resolver.js";
import * as terminalServiceModule from "./terminal-service.js";
import { get as performGet, request as performRequest } from "./test-request.js";
import { resetRuntimeLogSink, setRuntimeLogSink } from "./runtime-logger.js";
// Mock @fusion/core for gh CLI auth checks
const mockCentralListProjects = vi.fn().mockResolvedValue([]);
@@ -354,25 +355,34 @@ describe("Standardized error responses", () => {
expect(res.body).toEqual({ error: expect.stringContaining("not found") });
});
it("returns 500 errors as { error } and logs to console.error", async () => {
const consoleErrorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined);
it("returns 500 errors as { error } and logs to the runtime logger", async () => {
const runtimeEvents: Array<{ level: string; scope: string; message: string; context?: Record<string, unknown> }> = [];
setRuntimeLogSink((level, scope, message, context) => {
runtimeEvents.push({ level, scope, message, context });
});
(store.getSettingsFast as ReturnType<typeof vi.fn>).mockRejectedValueOnce(new Error("Config read failed"));
const res = await GET(buildApp(), "/api/settings");
try {
const res = await GET(buildApp(), "/api/settings");
expect(res.status).toBe(500);
expect(res.body).toEqual({ error: "Config read failed" });
expect(consoleErrorSpy).toHaveBeenCalledWith(
"[api:error]",
expect.objectContaining({
method: "GET",
path: "/api/settings",
statusCode: 500,
message: "Config read failed",
}),
);
consoleErrorSpy.mockRestore();
expect(res.status).toBe(500);
expect(res.body).toEqual({ error: "Config read failed" });
expect(runtimeEvents).toContainEqual(
expect.objectContaining({
level: "error",
scope: "api:error",
message: "Request failed",
context: expect.objectContaining({
method: "GET",
path: "/api/settings",
statusCode: 500,
message: "Config read failed",
}),
}),
);
} finally {
resetRuntimeLogSink();
}
});
});

View File

@@ -75,6 +75,7 @@ import {
import { rateLimit, RATE_LIMITS } from "./rate-limit.js";
import { resolvePluginManifest } from "./plugin-routes.js";
import { getAuthFileCandidates, getFusionAuthPath, type StoredAuthProvider } from "./auth-paths.js";
import { createRuntimeLogger, type RuntimeLogger } from "./runtime-logger.js";
const TASK_DETAIL_ACTIVITY_LOG_LIMIT = 500;
@@ -1890,6 +1891,10 @@ function checkSessionLock(
export function createApiRoutes(store: TaskStore, options?: ServerOptions): Router {
const router = Router();
const runtimeLogger = options?.runtimeLogger?.child("routes") ?? createRuntimeLogger("routes");
const planningLogger = runtimeLogger.child("planning");
const proxyLogger = runtimeLogger.child("proxy");
const chatLogger = runtimeLogger.child("chat");
function prioritizeProjectsForCurrentDirectory<T extends { path: string }>(projects: T[]): T[] {
const cwd = resolve(process.cwd());
@@ -2030,7 +2035,7 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
nodeStream.on("error", (err: Error) => {
// Log but don't crash — stream may already be closing
console.error(`[proxy] Stream error for node ${nodeId}:`, err.message);
proxyLogger.error(`Stream error for node ${nodeId}`, { error: err.message });
if (!res.writableEnded) {
res.end();
}
@@ -2258,7 +2263,7 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
"POST /planning/create-tasks",
"GET /planning/:sessionId/stream",
];
console.debug("[planning:routes:registered]", planningRoutes);
planningLogger.info("routes registered", { planningRoutes });
}
const sessionFilesCache = new Map<string, { files: string[]; expiresAt: number }>();
const fileDiffsCache = new Map<
@@ -2465,7 +2470,9 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
await syncBackupRoutine(routineStoreForProject, settings);
} catch (err) {
// Log but don't fail the settings update if routine sync fails
console.error("Failed to sync backup routine:", err);
runtimeLogger.error("Failed to sync backup routine", {
error: err instanceof Error ? err.message : String(err),
});
}
}
@@ -3226,7 +3233,9 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
}
// Log without actual credentials
console.error(`[settings-sync] Auth credentials received: providers=${receivedProviders.join(",")}, source=${sourceNodeId}`);
runtimeLogger.child("settings-sync").info(
`Auth credentials received: providers=${receivedProviders.join(",")}, source=${sourceNodeId}`,
);
await central.close();
@@ -3750,7 +3759,7 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
});
// Models
registerModelsRoute(router, options?.modelRegistry, store);
registerModelsRoute(router, options?.modelRegistry, store, runtimeLogger.child("models"));
// List all tasks
router.get("/tasks", async (req, res) => {
@@ -3883,7 +3892,9 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
} catch (err) {
// Log the full error so server logs show what went wrong
const errorMessage = err instanceof Error ? err.message : String(err);
console.error(`[routes] Title summarization failed: ${errorMessage}`, err);
runtimeLogger.error(`Title summarization failed: ${errorMessage}`, {
error: errorMessage,
});
// Return null on error so task creation continues without title
return null;
}
@@ -4236,7 +4247,9 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
if (err instanceof ApiError) {
throw err;
}
console.error(`Failed to update task ${taskId}:`, err);
runtimeLogger.error(`Failed to update task ${taskId}`, {
error: err instanceof Error ? err.message : String(err),
});
const success = false;
return { success, taskId, error: err instanceof Error ? err.message : String(err) };
}
@@ -4258,7 +4271,7 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
// Log errors but don't fail the entire request
if (errors.length > 0) {
console.error(`[batch-update-models] ${errors.length} tasks failed to update:`, errors);
runtimeLogger.error(`${errors.length} tasks failed to update`, { errors });
}
res.json({ updated, count: updated.length });
@@ -4685,8 +4698,8 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
triggeringCommentIds: newCommentId ? [newCommentId] : undefined,
triggerDetail: "task-comment",
}).catch((error) => {
console.warn(
`[routes] failed to trigger task-comment heartbeat for ${task.id}: ${error instanceof Error ? error.message : String(error)}`,
runtimeLogger.warn(
`failed to trigger task-comment heartbeat for ${task.id}: ${error instanceof Error ? error.message : String(error)}`,
);
});
@@ -4947,8 +4960,8 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
triggeringCommentIds: newSteeringCommentId ? [newSteeringCommentId] : undefined,
triggerDetail: "steering-comment",
}).catch((error) => {
console.warn(
`[routes] failed to trigger steering-comment heartbeat for ${task.id}: ${error instanceof Error ? error.message : String(error)}`,
runtimeLogger.warn(
`failed to trigger steering-comment heartbeat for ${task.id}: ${error instanceof Error ? error.message : String(error)}`,
);
});
@@ -9758,7 +9771,9 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
normalizedProvider,
normalizedModelId,
).catch((err: Error) => {
console.error(`[chat:routes] Error in sendMessage:`, err);
chatLogger.error("Error in sendMessage", {
error: err.message,
});
chatStreamManager.broadcast(sessionId, {
type: "error",
data: err.message || "Failed to process message",
@@ -9846,7 +9861,7 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
"POST /chat/sessions/:id/cancel",
"DELETE /chat/sessions/:id/messages/:messageId",
];
console.debug("[chat:routes:registered]", chatRoutes);
chatLogger.info("routes registered", { chatRoutes });
}
/**
@@ -9952,7 +9967,9 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
// Debug logging
if (process.env.FUSION_DEBUG_AI) {
console.log(`[ai-summarize] Request from ${ip}, description length: ${description?.length || 0}`);
runtimeLogger.child("ai-summarize").info(
`Request from ${ip}, description length: ${description?.length || 0}`,
);
}
// Check rate limit first
@@ -9995,7 +10012,9 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
(settings.defaultProvider && settings.defaultModelId ? settings.defaultModelId : undefined);
if (process.env.FUSION_DEBUG_AI) {
console.log(`[ai-summarize] Resolved model: ${resolvedProvider || "auto"}/${resolvedModelId || "auto"}`);
runtimeLogger.child("ai-summarize").info(
`Resolved model: ${resolvedProvider || "auto"}/${resolvedModelId || "auto"}`,
);
}
// Process summarization
@@ -10018,7 +10037,9 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
} else if (err instanceof Error && err.name === "ValidationError") {
throw badRequest(err instanceof Error ? err.message : String(err));
} else {
console.error("[ai-summarize] Unexpected error:", err);
runtimeLogger.child("ai-summarize").error("Unexpected error", {
error: err instanceof Error ? err.message : String(err),
});
rethrowAsApiError(err, "Failed to generate title");
}
}
@@ -11772,7 +11793,7 @@ export function createApiRoutes(store: TaskStore, options?: ServerOptions): Rout
throw new Error("companies.sh request timed out");
}
// Log and include error in response so frontend can display it
console.warn(`[agents/companies] Failed to fetch catalog: ${message}`);
runtimeLogger.child("agents/companies").warn(`Failed to fetch catalog: ${message}`);
res.json({ companies, error: `Failed to fetch companies.sh catalog: ${message}` });
return;
}
@@ -14432,7 +14453,9 @@ async function persistImportedSkills(
if (err instanceof AgentGenerationRateLimitError) {
throw rateLimited(err.message);
}
console.error("[agent-generation] Error starting session:", err);
runtimeLogger.child("agent-generation").error("Error starting session", {
error: err instanceof Error ? err.message : String(err),
});
rethrowAsApiError(err, "Failed to start agent generation session");
}
});
@@ -14463,7 +14486,9 @@ async function persistImportedSkills(
if (err instanceof AgentGenerationSessionNotFoundError) {
throw notFound(err instanceof Error ? err.message : String(err));
}
console.error("[agent-generation] Error generating spec:", err);
runtimeLogger.child("agent-generation").error("Error generating spec", {
error: err instanceof Error ? err.message : String(err),
});
rethrowAsApiError(err, "Failed to generate agent specification");
}
});
@@ -14668,7 +14693,9 @@ async function persistImportedSkills(
await options.pluginLoader.loadPlugin(plugin.id);
} catch (loadErr) {
// Log but don't fail - plugin is registered, just not loaded
console.error(`[plugin-routes] Failed to load plugin ${plugin.id}:`, loadErr);
runtimeLogger.child("plugin-routes").error(`Failed to load plugin ${plugin.id}`, {
error: loadErr instanceof Error ? loadErr.message : String(loadErr),
});
}
}
@@ -14705,7 +14732,9 @@ async function persistImportedSkills(
try {
await options.pluginLoader.loadPlugin(plugin.id);
} catch (loadErr) {
console.error(`[plugin-routes] Failed to load plugin ${plugin.id}:`, loadErr);
runtimeLogger.child("plugin-routes").error(`Failed to load plugin ${plugin.id}`, {
error: loadErr instanceof Error ? loadErr.message : String(loadErr),
});
}
}
@@ -15330,7 +15359,9 @@ async function persistImportedSkills(
remoteProjectArrays.forEach((result, index) => {
if (result.status === "rejected") {
const node = remoteNodes[index];
console.warn(`[projects:across-nodes] Failed to fetch projects from node ${node?.id}: ${result.reason?.message ?? result.reason}`);
runtimeLogger.child("projects:across-nodes").warn(
`Failed to fetch projects from node ${node?.id}: ${result.reason?.message ?? result.reason}`,
);
}
});
@@ -16567,7 +16598,9 @@ async function persistImportedSkills(
// Log without actual credentials
const providerNames = Object.keys(apiKeyProviders);
console.error(`[settings-sync] Auth sync completed: direction=push, providers=${providerNames.join(",")}, targetNode=${node.id}`);
runtimeLogger.child("settings-sync").info(
`Auth sync completed: direction=push, providers=${providerNames.join(",")}, targetNode=${node.id}`,
);
res.json({ success: true, syncedProviders: providerNames });
} else {
@@ -16595,7 +16628,9 @@ async function persistImportedSkills(
await central.close();
// Log without actual credentials
console.error(`[settings-sync] Auth sync completed: direction=pull, providers=${syncedProviders.join(",")}, targetNode=${node.id}`);
runtimeLogger.child("settings-sync").info(
`Auth sync completed: direction=pull, providers=${syncedProviders.join(",")}, targetNode=${node.id}`,
);
res.json({ success: true, syncedProviders });
}
@@ -16745,12 +16780,11 @@ async function persistImportedSkills(
const applyResult = await central.applyRemoteSettings(remoteSettings);
if (applyResult.success) {
console.log(
`[mesh/sync] Applied remote settings from ${senderNodeId}: ` +
`global=${applyResult.globalCount}, projects=${applyResult.projectCount}, auth=${applyResult.authCount}`
runtimeLogger.child("mesh/sync").info(
`Applied remote settings from ${senderNodeId}: global=${applyResult.globalCount}, projects=${applyResult.projectCount}, auth=${applyResult.authCount}`,
);
} else {
console.warn(`[mesh/sync] Failed to apply remote settings: ${applyResult.error}`);
runtimeLogger.child("mesh/sync").warn(`Failed to apply remote settings: ${applyResult.error}`);
}
}
@@ -16758,7 +16792,9 @@ async function persistImportedSkills(
responseSettings = localPayload;
} catch (err) {
// Log but don't fail the sync - peers are more important
console.error("[mesh/sync] Settings sync error:", err);
runtimeLogger.child("mesh/sync").error("Settings sync error", {
error: err instanceof Error ? err.message : String(err),
});
}
}
@@ -18287,7 +18323,9 @@ async function persistImportedSkills(
nodeStream.on("error", (err: Error) => {
// Log but don't crash — stream may already be closing
console.error(`[proxy:sse] Stream error for node ${nodeId}:`, err.message);
runtimeLogger.child("proxy:sse").error(`Stream error for node ${nodeId}`, {
error: err.message,
});
if (!res.writableEnded) {
res.end();
}
@@ -18306,7 +18344,9 @@ async function persistImportedSkills(
res.end();
}
} else {
console.error(`[proxy:sse] Unexpected error for node ${nodeId}:`, err);
runtimeLogger.child("proxy:sse").error(`Unexpected error for node ${nodeId}`, {
error: err instanceof Error ? err.message : String(err),
});
if (!res.headersSent) {
if (err instanceof ApiError) {
throw err;
@@ -18430,7 +18470,9 @@ async function persistImportedSkills(
});
nodeStream.on("error", (err: Error) => {
console.error(`[proxy] Stream error for node ${nodeId}:`, err.message);
proxyLogger.error(`Stream error for node ${nodeId}`, {
error: err.message,
});
if (!res.writableEnded) {
res.end();
}
@@ -18447,7 +18489,9 @@ async function persistImportedSkills(
} else if (err instanceof TypeError) {
res.status(502).json({ error: "Bad Gateway" });
} else {
console.error(`[proxy] Unexpected error for node ${nodeId}:`, err);
proxyLogger.error(`Unexpected error for node ${nodeId}`, {
error: err instanceof Error ? err.message : String(err),
});
res.status(502).json({ error: "Bad Gateway" });
}
} finally {
@@ -18789,7 +18833,12 @@ async function refreshIssueInBackground(
* along with favoriteProviders for UI ordering.
* If no ModelRegistry is provided, returns an empty array.
*/
function registerModelsRoute(router: Router, modelRegistry?: ModelRegistryLike, store?: TaskStore): void {
function registerModelsRoute(
router: Router,
modelRegistry?: ModelRegistryLike,
store?: TaskStore,
runtimeLogger: RuntimeLogger = createRuntimeLogger("models"),
): void {
router.get("/models", async (_req, res) => {
// Always return 200 with empty array instead of 404 when no models available.
// This ensures the frontend can handle empty states gracefully.
@@ -18828,7 +18877,7 @@ function registerModelsRoute(router: Router, modelRegistry?: ModelRegistryLike,
throw err;
}
const message = err instanceof Error ? err.message : String(err);
console.log(`[models] Failed to load models: ${message}`);
runtimeLogger.warn(`Failed to load models: ${message}`);
res.json({ models: [], favoriteProviders: [], favoriteModels: [] });
}
});

View File

@@ -0,0 +1,82 @@
export type RuntimeLogLevel = "info" | "warn" | "error";
export interface RuntimeLogContext {
[key: string]: unknown;
}
export interface RuntimeLogSink {
(level: RuntimeLogLevel, scope: string, message: string, context?: RuntimeLogContext): void;
}
export interface RuntimeLogger {
readonly scope: string;
info(message: string, context?: RuntimeLogContext): void;
warn(message: string, context?: RuntimeLogContext): void;
error(message: string, context?: RuntimeLogContext): void;
child(scope: string): RuntimeLogger;
}
let sink: RuntimeLogSink = defaultRuntimeLogSink;
function defaultRuntimeLogSink(
level: RuntimeLogLevel,
scope: string,
message: string,
context?: RuntimeLogContext,
): void {
const line = `[${scope}] ${message}`;
const args = context === undefined ? [line] : [line, context];
try {
switch (level) {
case "info":
console.log(...args);
break;
case "warn":
console.warn(...args);
break;
case "error":
console.error(...args);
break;
}
} catch {
// Logging must never throw into runtime flows.
}
}
function emit(level: RuntimeLogLevel, scope: string, message: string, context?: RuntimeLogContext): void {
try {
sink(level, scope, message, context);
} catch {
// Logging must never throw into runtime flows.
}
}
export function createRuntimeLogger(scope: string): RuntimeLogger {
return {
scope,
info(message, context) {
emit("info", scope, message, context);
},
warn(message, context) {
emit("warn", scope, message, context);
},
error(message, context) {
emit("error", scope, message, context);
},
child(childScope) {
return createRuntimeLogger(`${scope}:${childScope}`);
},
};
}
export function setRuntimeLogSink(nextSink: RuntimeLogSink | null | undefined): void {
sink = nextSink ?? defaultRuntimeLogSink;
}
export function getRuntimeLogSink(): RuntimeLogSink {
return sink;
}
export function resetRuntimeLogSink(): void {
sink = defaultRuntimeLogSink;
}

View File

@@ -551,12 +551,13 @@ describe("Terminal stale-session eviction", () => {
expect(consoleErrorSpy).toHaveBeenCalled();
const failureCall = consoleErrorSpy.mock.calls.find(
(call) => typeof call[0] === "string" && call[0].includes("[terminal] Stale session eviction failed:"),
(call) => typeof call[0] === "string" && call[0].includes("[terminal] Stale session eviction failed"),
);
expect(failureCall).toBeDefined();
expect(failureCall?.[0]).toEqual(expect.stringContaining("[terminal] Stale session eviction failed:"));
expect(failureCall?.[1]).toBeInstanceOf(Error);
expect((failureCall?.[1] as Error).message).toContain("simulated eviction failure");
expect(failureCall?.[0]).toEqual(expect.stringContaining("[terminal] Stale session eviction failed"));
expect(failureCall?.[1]).toEqual(
expect.objectContaining({ error: "simulated eviction failure" }),
);
vi.advanceTimersByTime(60_000);
expect(mockTerminalService.evictStaleSessions).toHaveBeenCalledTimes(2);

View File

@@ -20,6 +20,7 @@ import { terminalSessionManager } from "./terminal.js";
import { WebSocketManager, type BadgeSnapshot } from "./websocket.js";
import type { BadgePubSub } from "./badge-pubsub.js";
import { createBadgePubSub, type BadgePubSubMessage } from "./badge-pubsub.js";
import { createRuntimeLogger, type RuntimeLogger } from "./runtime-logger.js";
import {
AiSessionStore,
SESSION_CLEANUP_DEFAULT_MAX_AGE_MS,
@@ -208,6 +209,9 @@ export interface ServerOptions {
* FUSION_DASHBOARD_TOKEN env vars. Used by `fn dashboard --no-auth` so a
* stale token in a project .env doesn't silently override the flag. */
noAuth?: boolean;
/** Optional runtime logger for server/routes diagnostics.
* Defaults to a console-backed logger scoped to `server` when omitted. */
runtimeLogger?: RuntimeLogger;
/** Optional TLS credentials. When provided, the server is served over HTTP/2
* with HTTP/1.1 fallback (allowHTTP1:true) — this lifts the browser's
* per-origin connection cap so long-lived SSE streams no longer starve
@@ -375,6 +379,7 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
}
const app = express();
const runtimeLogger = options?.runtimeLogger ?? createRuntimeLogger("server");
const mutationRateLimit = rateLimit(RATE_LIMITS.mutation);
const setupRateLimit = rateLimit(RATE_LIMITS.api);
const setupReadRateLimit = rateLimit(RATE_LIMITS.api);
@@ -649,8 +654,9 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
// Planning route diagnostics for production/runtime debugging. Disabled by default.
if (process.env.FUSION_DEBUG_PLANNING_ROUTES === "1") {
const planningLogger = runtimeLogger.child("planning");
app.use("/api/planning", (req, _res, next) => {
console.debug("[planning:request]", {
planningLogger.info("request", {
method: req.method,
path: req.path,
originalUrl: req.originalUrl,
@@ -675,8 +681,8 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
const totalRehydrated =
planningRehydratedCount + subtaskRehydratedCount + missionRehydratedCount + milestoneSliceRehydratedCount;
if (totalRehydrated > 0) {
console.log(
`[server] Rehydrated ${planningRehydratedCount} planning, ${subtaskRehydratedCount} subtask, ${missionRehydratedCount} mission, ${milestoneSliceRehydratedCount} milestone/slice sessions from SQLite`,
runtimeLogger.info(
`Rehydrated ${planningRehydratedCount} planning, ${subtaskRehydratedCount} subtask, ${missionRehydratedCount} mission, ${milestoneSliceRehydratedCount} milestone/slice sessions from SQLite`,
);
}
@@ -688,8 +694,8 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
const runAiSessionCleanup = (maxAgeMs: number, source: "initial" | "scheduled") => {
const result = aiSessionStore.cleanupStaleSessions(maxAgeMs);
console.log(
`[server] AI session cleanup (${source}): removed ${result.terminalDeleted} terminal, ${result.orphanedDeleted} orphaned sessions`,
runtimeLogger.info(
`AI session cleanup (${source}): removed ${result.terminalDeleted} terminal, ${result.orphanedDeleted} orphaned sessions`,
);
return result;
};
@@ -700,7 +706,9 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
try {
runAiSessionCleanup(maxAgeMs, "scheduled");
} catch (err) {
console.error("[server] Scheduled AI session cleanup failed", err);
runtimeLogger.error("Scheduled AI session cleanup failed", {
error: err instanceof Error ? err.message : String(err),
});
}
}, cleanupIntervalMs);
aiSessionCleanupIntervalHandle.unref?.();
@@ -728,18 +736,24 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
void Promise.resolve()
.then(() => runAiSessionCleanup(ttlMs, "initial"))
.catch((err) => {
console.error("[server] Initial AI session cleanup failed", err);
runtimeLogger.error("Initial AI session cleanup failed", {
error: err instanceof Error ? err.message : String(err),
});
});
scheduleAiSessionCleanup(cleanupIntervalMs, ttlMs);
})
.catch((err) => {
console.warn("[server] Failed to load settings for AI session cleanup; using defaults", err);
runtimeLogger.warn("Failed to load settings for AI session cleanup; using defaults", {
error: err instanceof Error ? err.message : String(err),
});
void Promise.resolve()
.then(() => runAiSessionCleanup(DEFAULT_AI_SESSION_TTL_MS, "initial"))
.catch((cleanupErr) => {
console.error("[server] Initial AI session cleanup failed", cleanupErr);
runtimeLogger.error("Initial AI session cleanup failed", {
error: cleanupErr instanceof Error ? cleanupErr.message : String(cleanupErr),
});
});
scheduleAiSessionCleanup(
@@ -751,7 +765,9 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
void Promise.resolve()
.then(() => runAiSessionCleanup(DEFAULT_AI_SESSION_TTL_MS, "initial"))
.catch((err) => {
console.error("[server] Initial AI session cleanup failed", err);
runtimeLogger.error("Initial AI session cleanup failed", {
error: err instanceof Error ? err.message : String(err),
});
});
scheduleAiSessionCleanup(
@@ -770,7 +786,14 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
});
// REST API
app.use("/api", createApiRoutes(store, { ...options, aiSessionStore, chatStore, chatManager, skillsAdapter: options?.skillsAdapter }));
app.use("/api", createApiRoutes(store, {
...options,
runtimeLogger,
aiSessionStore,
chatStore,
chatManager,
skillsAdapter: options?.skillsAdapter,
}));
// API 404 Handler - Return JSON for unmatched API routes (instead of falling through to SPA)
app.use("/api", (_req: express.Request, res: express.Response) => {
@@ -845,14 +868,15 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
aiSessionStore.stopScheduledCleanup();
void stopAllDevServers().catch((error) => {
const message = error instanceof Error ? error.message : String(error);
console.warn(`[server] Failed to shutdown dev-server managers: ${message}`);
runtimeLogger.warn(`Failed to shutdown dev-server managers: ${message}`);
});
});
if (!dashboardApp.__fnWebSocketsAttached) {
dashboardApp.__fnWebSocketsAttached = true;
setupTerminalWebSocket(dashboardApp, server as HttpServer, store, options);
setupBadgeWebSocket(dashboardApp, server as HttpServer, store, options);
const websocketOptions = { ...options, runtimeLogger };
setupTerminalWebSocket(dashboardApp, server as HttpServer, store, websocketOptions);
setupBadgeWebSocket(dashboardApp, server as HttpServer, store, websocketOptions);
}
return server as HttpServer;
@@ -878,6 +902,7 @@ export function setupTerminalWebSocket(
// Resolve the daemon token once so every upgrade picks up the same value.
const wsDaemonToken = getDaemonToken(options);
const terminalLogger = options?.runtimeLogger?.child("terminal") ?? createRuntimeLogger("terminal");
server.on("upgrade", (req, socket, head) => {
const pathname = new URL(req.url || "", `http://${req.headers.host}`).pathname;
@@ -930,7 +955,9 @@ export function setupTerminalWebSocket(
terminalService = getTerminalService(scopedRootDir);
}
} catch (err) {
console.error("[terminal] Failed to resolve project scope:", err);
terminalLogger.error("Failed to resolve project scope", {
error: err instanceof Error ? err.message : String(err),
});
ws.close(4510, "Failed to resolve project scope");
return;
}
@@ -944,7 +971,7 @@ export function setupTerminalWebSocket(
// Security check: reject sessions that don't belong to this project's root
// Session cwd must be within the resolved project root
if (!session.cwd.startsWith(scopedRootDir)) {
console.warn(`[terminal] Session ${sessionId} cwd ${session.cwd} does not belong to project root ${scopedRootDir}`);
terminalLogger.warn(`Session ${sessionId} cwd ${session.cwd} does not belong to project root ${scopedRootDir}`);
ws.close(4503, "Session does not belong to this project");
return;
}
@@ -960,8 +987,8 @@ export function setupTerminalWebSocket(
// Detect potentially stale sessions on reconnect
const idleMs = Date.now() - session.lastActivityAt.getTime();
if (idleMs > STALE_SESSION_THRESHOLD_MS) {
console.warn(
`[terminal] Session ${sessionId} reconnect after ${Math.round(idleMs / 1000)}s idle — PTY may be stale`
terminalLogger.warn(
`Session ${sessionId} reconnect after ${Math.round(idleMs / 1000)}s idle — PTY may be stale`,
);
}
@@ -995,7 +1022,7 @@ export function setupTerminalWebSocket(
try {
ws.send(JSON.stringify({ type: "exit", exitCode }));
const idleSec = id ? Math.round((Date.now() - (terminalService.getSession(id)?.lastActivityAt?.getTime() ?? Date.now())) / 1000) : 0;
console.info(`[terminal] Session ${id} exited with code ${exitCode} (was ${idleSec}s idle)`);
terminalLogger.info(`Session ${id} exited with code ${exitCode} (was ${idleSec}s idle)`);
} catch {
// WebSocket might be closing
}
@@ -1007,11 +1034,11 @@ export function setupTerminalWebSocket(
if (!isAlive) {
missedPongs++;
if (missedPongs >= MAX_MISSED_PONGS) {
console.warn(`[terminal] Connection dead after ${missedPongs} missed pongs, terminating`);
terminalLogger.warn(`Connection dead after ${missedPongs} missed pongs, terminating`);
ws.terminate();
return;
}
console.info(`[terminal] Missed pong #${missedPongs}, waiting for response...`);
terminalLogger.info(`Missed pong #${missedPongs}, waiting for response...`);
return;
}
isAlive = false;
@@ -1084,7 +1111,9 @@ export function setupTerminalWebSocket(
try {
defaultTerminalService.evictStaleSessions();
} catch (err) {
console.error("[terminal] Stale session eviction failed:", err);
terminalLogger.error("Stale session eviction failed", {
error: err instanceof Error ? err.message : String(err),
});
}
}, 60_000);
@@ -1093,7 +1122,7 @@ export function setupTerminalWebSocket(
clearInterval(staleEvictionInterval);
});
console.log("Terminal WebSocket server mounted at /api/terminal/ws");
terminalLogger.info("WebSocket server mounted at /api/terminal/ws");
}
export function setupBadgeWebSocket(