feat(FN-2121): introduce structured logging in plugin loader

- Add a reusable createLogger utility in @fusion/core for prefixed log/warn/error output
- Replace plugin-loader console logging with structured logger calls across load, reload, stop, and hook paths
- Route plugin-scoped logger methods through createLogger, including debug gating on DEBUG=plugins
- Add regression tests that mock logger.js and verify key structured log emissions and error logging flows
This commit is contained in:
Fusion
2026-04-19 03:31:57 -07:00
committed by gsxdsm
parent eaaac2282a
commit 8e00867012
3 changed files with 374 additions and 26 deletions

View File

@@ -0,0 +1,47 @@
/**
* Lightweight structured logger for the `@fusion/core` package.
*
* Usage:
* ```ts
* import { createLogger } from "./logger.js";
* const log = createLogger("my-module");
* log.log("hello"); // → console.error("[my-module] hello")
* log.warn("oops"); // → console.warn("[my-module] oops")
* log.error("fail"); // → console.error("[my-module] fail")
* ```
*
* Core subsystems should use this utility rather than calling `console.*`
* directly so diagnostics stay consistent and easy to suppress/match in tests.
*/
export interface Logger {
log(message: string, ...args: unknown[]): void;
warn(message: string, ...args: unknown[]): void;
error(message: string, ...args: unknown[]): void;
}
/**
* Create a structured logger that prefixes every message with `[prefix]`.
*
* @param prefix - Short subsystem name, e.g. "plugin-loader".
* @returns A `Logger` whose output is prefixed and sent to stderr for normal
* logs and errors. Keeping logs off stdout prevents command/test
* output consumers from receiving Fusion execution chatter.
*/
export function createLogger(prefix: string): Logger {
const tag = `[${prefix}]`;
return {
log(message: string, ...args: unknown[]) {
console.error(`${tag} ${message}`, ...args);
},
warn(message: string, ...args: unknown[]) {
console.warn(`${tag} ${message}`, ...args);
},
error(message: string, ...args: unknown[]) {
console.error(`${tag} ${message}`, ...args);
},
};
}
/** Logger for the plugin loader subsystem. */
export const pluginLoaderLog = createLogger("plugin-loader");

View File

@@ -109,6 +109,36 @@ const mockTaskStore = {
logActivity: vi.fn(), logActivity: vi.fn(),
} as any; } as any;
type MockStructuredLogger = {
log: ReturnType<typeof vi.fn>;
warn: ReturnType<typeof vi.fn>;
error: ReturnType<typeof vi.fn>;
};
async function loadPluginLoaderWithMockedLogger() {
vi.resetModules();
const loggerMap = new Map<string, MockStructuredLogger>();
const createLoggerMock = vi.fn((prefix: string): MockStructuredLogger => {
const existing = loggerMap.get(prefix);
if (existing) return existing;
const logger: MockStructuredLogger = {
log: vi.fn(),
warn: vi.fn(),
error: vi.fn(),
};
loggerMap.set(prefix, logger);
return logger;
});
vi.doMock("./logger.js", () => ({
createLogger: createLoggerMock,
}));
const { PluginLoader: MockedPluginLoader } = await import("./plugin-loader.js");
return { MockedPluginLoader, createLoggerMock, loggerMap };
}
describe("PluginLoader", () => { describe("PluginLoader", () => {
let rootDir: string; let rootDir: string;
let pluginStore: PluginStore; let pluginStore: PluginStore;
@@ -691,6 +721,275 @@ describe("PluginLoader", () => {
}); });
}); });
// ── structured logging ──────────────────────────────────────────────
describe("structured logging", () => {
afterEach(() => {
vi.doUnmock("./logger.js");
});
it("logs when skipping a disabled plugin", async () => {
await pluginStore.init();
const plugin = makePlugin(makeManifest({ id: "disabled-log-test" }));
const pluginDir = join(rootDir, "plugins");
const pluginPath = await writePluginModule(pluginDir, "disabled-log.js", plugin);
await pluginStore.registerPlugin({
manifest: plugin.manifest,
path: pluginPath,
});
await pluginStore.disablePlugin("disabled-log-test");
const { MockedPluginLoader, loggerMap } = await loadPluginLoaderWithMockedLogger();
const loader = new MockedPluginLoader({ pluginStore, taskStore: mockTaskStore });
await expect(loader.loadPlugin("disabled-log-test")).rejects.toThrow("disabled");
expect(loggerMap.get("plugin-loader")?.log).toHaveBeenCalledWith(
"Skipping disabled plugin: disabled-log-test",
);
});
it("logs when plugin is already loaded", async () => {
await pluginStore.init();
const plugin = makePlugin(makeManifest({ id: "already-loaded-log" }));
const pluginDir = join(rootDir, "plugins");
const pluginPath = await writePluginModule(pluginDir, "already-loaded.js", plugin);
await pluginStore.registerPlugin({
manifest: plugin.manifest,
path: pluginPath,
});
const { MockedPluginLoader, loggerMap } = await loadPluginLoaderWithMockedLogger();
const loader = new MockedPluginLoader({ pluginStore, taskStore: mockTaskStore });
await loader.loadPlugin("already-loaded-log");
await loader.loadPlugin("already-loaded-log");
expect(loggerMap.get("plugin-loader")?.log).toHaveBeenCalledWith(
"Plugin already loaded: already-loaded-log",
);
});
it("logs when reloading a plugin", async () => {
await pluginStore.init();
const plugin = makePlugin(makeManifest({ id: "reload-log-test" }));
const pluginDir = join(rootDir, "plugins");
const pluginPath = await writePluginModule(pluginDir, "reload-log.js", plugin);
await pluginStore.registerPlugin({
manifest: plugin.manifest,
path: pluginPath,
});
const { MockedPluginLoader, loggerMap } = await loadPluginLoaderWithMockedLogger();
const loader = new MockedPluginLoader({ pluginStore, taskStore: mockTaskStore });
await loader.loadPlugin("reload-log-test");
await loader.reloadPlugin("reload-log-test");
expect(loggerMap.get("plugin-loader")?.log).toHaveBeenCalledWith(
"Reloading plugin: reload-log-test",
);
});
it("logs reload failures", async () => {
await pluginStore.init();
const pluginId = "reload-failure-log";
const pluginDir = join(rootDir, "plugins");
const pluginPath = join(pluginDir, "reload-failure.js");
await writePluginModule(pluginDir, "reload-failure.js", makePlugin(makeManifest({ id: pluginId })));
await pluginStore.registerPlugin({
manifest: makeManifest({ id: pluginId }),
path: pluginPath,
});
const { MockedPluginLoader, loggerMap } = await loadPluginLoaderWithMockedLogger();
const loader = new MockedPluginLoader({ pluginStore, taskStore: mockTaskStore });
await loader.loadPlugin(pluginId);
await writePluginWithHooks(
pluginDir,
"reload-failure.js",
{
onLoad: "(async () => { throw new Error('reload failed'); })",
},
makeManifest({ id: pluginId }),
);
await expect(loader.reloadPlugin(pluginId)).rejects.toThrow("reload failed");
expect(loggerMap.get("plugin-loader")?.error).toHaveBeenCalledWith(
`Reload failed for ${pluginId}, rolling back:`,
expect.any(Error),
);
});
it("logs rollback failures", async () => {
await pluginStore.init();
const pluginId = "rollback-failure-log";
const pluginDir = join(rootDir, "plugins");
const pluginPath = join(pluginDir, "rollback-failure.js");
await writePluginWithHooks(
pluginDir,
"rollback-failure.js",
{
onLoad: "((() => { let count = 0; return async () => { count += 1; if (count > 1) throw new Error('old onLoad failed on retry'); }; })())",
},
makeManifest({ id: pluginId }),
);
await pluginStore.registerPlugin({
manifest: makeManifest({ id: pluginId }),
path: pluginPath,
});
const { MockedPluginLoader, loggerMap } = await loadPluginLoaderWithMockedLogger();
const loader = new MockedPluginLoader({ pluginStore, taskStore: mockTaskStore });
await loader.loadPlugin(pluginId);
await writePluginWithHooks(
pluginDir,
"rollback-failure.js",
{
onLoad: "(async () => { throw new Error('new onLoad failed'); })",
},
makeManifest({ id: pluginId }),
);
await expect(loader.reloadPlugin(pluginId)).rejects.toThrow("new onLoad failed");
expect(loggerMap.get("plugin-loader")?.error).toHaveBeenCalledWith(
`Rollback failed for ${pluginId}, removing plugin:`,
expect.any(Error),
);
});
it("logs onUnload hook errors when stopping", async () => {
await pluginStore.init();
const pluginId = "stop-hook-log";
const pluginDir = join(rootDir, "plugins");
const pluginPath = await writePluginWithHooks(
pluginDir,
"stop-hook.js",
{
onUnload: "(() => { throw new Error('stop failed'); })",
},
makeManifest({ id: pluginId }),
);
await pluginStore.registerPlugin({
manifest: makeManifest({ id: pluginId }),
path: pluginPath,
});
const { MockedPluginLoader, loggerMap } = await loadPluginLoaderWithMockedLogger();
const loader = new MockedPluginLoader({ pluginStore, taskStore: mockTaskStore });
await loader.loadPlugin(pluginId);
await loader.stopPlugin(pluginId);
expect(loggerMap.get("plugin-loader")?.error).toHaveBeenCalledWith(
`Error in onUnload for ${pluginId}:`,
expect.any(Error),
);
});
it("logs loadAllPlugins failures", async () => {
await pluginStore.init();
const pluginDir = join(rootDir, "plugins");
const goodPlugin = makePlugin(makeManifest({ id: "good-load-all-log" }));
const goodPath = await writePluginModule(pluginDir, "good-load-all.js", goodPlugin);
const badPath = await writePluginWithHooks(
pluginDir,
"bad-load-all.js",
{
onLoad: "(async () => { throw new Error('load all failure'); })",
},
makeManifest({ id: "bad-load-all-log" }),
);
await pluginStore.registerPlugin({ manifest: goodPlugin.manifest, path: goodPath });
await pluginStore.registerPlugin({
manifest: makeManifest({ id: "bad-load-all-log" }),
path: badPath,
});
const { MockedPluginLoader, loggerMap } = await loadPluginLoaderWithMockedLogger();
const loader = new MockedPluginLoader({ pluginStore, taskStore: mockTaskStore });
await loader.loadAllPlugins();
expect(loggerMap.get("plugin-loader")?.error).toHaveBeenCalledWith(
"Failed to load plugin bad-load-all-log:",
expect.any(Error),
);
});
it("logs invokeHook failures", async () => {
await pluginStore.init();
const { MockedPluginLoader, loggerMap } = await loadPluginLoaderWithMockedLogger();
const loader = new MockedPluginLoader({ pluginStore, taskStore: mockTaskStore });
(loader as any).plugins.set("hook-error-log", {
manifest: makeManifest({ id: "hook-error-log" }),
state: "started",
hooks: {
onTaskCreated: () => {
throw new Error("hook failure");
},
},
tools: [],
routes: [],
} as FusionPlugin);
await loader.invokeHook("onTaskCreated", { id: "FN-123" } as any);
expect(loggerMap.get("plugin-loader")?.error).toHaveBeenCalledWith(
"Error in onTaskCreated hook for hook-error-log:",
expect.any(Error),
);
});
it("logs custom events from createContext through structured logger", async () => {
await pluginStore.init();
const pluginId = "custom-event-log";
const pluginDir = join(rootDir, "plugins");
const pluginPath = await writePluginWithHooks(
pluginDir,
"custom-event.js",
{
onLoad: "(async (ctx) => { ctx.emitEvent('custom-event', { payload: 'ok' }); })",
},
makeManifest({ id: pluginId }),
);
await pluginStore.registerPlugin({
manifest: makeManifest({ id: pluginId }),
path: pluginPath,
});
const { MockedPluginLoader, loggerMap } = await loadPluginLoaderWithMockedLogger();
const loader = new MockedPluginLoader({ pluginStore, taskStore: mockTaskStore });
await loader.loadPlugin(pluginId);
expect(loggerMap.get("plugin-loader")?.log).toHaveBeenCalledWith(
`[plugin:${pluginId}] Custom event: custom-event`,
{ payload: "ok" },
);
});
});
// ── getPluginTools ───────────────────────────────────────────────── // ── getPluginTools ─────────────────────────────────────────────────
describe("getPluginTools", () => { describe("getPluginTools", () => {

View File

@@ -24,9 +24,11 @@ import type {
PluginInstallation, PluginInstallation,
} from "./plugin-types.js"; } from "./plugin-types.js";
import { validatePluginManifest } from "./plugin-types.js"; import { validatePluginManifest } from "./plugin-types.js";
import { createLogger } from "./logger.js";
// Minimum Fusion version for plugin compatibility checks (can be expanded later) // Minimum Fusion version for plugin compatibility checks (can be expanded later)
const MINIMUM_FUSION_VERSION = "0.1.0"; const MINIMUM_FUSION_VERSION = "0.1.0";
const log = createLogger("plugin-loader");
export interface PluginLoaderOptions { export interface PluginLoaderOptions {
/** Plugin store for persistence */ /** Plugin store for persistence */
@@ -102,20 +104,20 @@ export class PluginLoader extends EventEmitter<{
emitEvent: (event: string, data: unknown) => { emitEvent: (event: string, data: unknown) => {
this.emit("plugin:error", { pluginId: plugin.manifest.id, error: new Error(`Custom event: ${event}`) }); this.emit("plugin:error", { pluginId: plugin.manifest.id, error: new Error(`Custom event: ${event}`) });
// Custom events are logged but not surfaced as errors // Custom events are logged but not surfaced as errors
console.log(`[plugin:${plugin.manifest.id}] Custom event: ${event}`, data); log.log(`[plugin:${plugin.manifest.id}] Custom event: ${event}`, data);
}, },
}; };
} }
private createLogger(pluginId: string): PluginLogger { private createLogger(pluginId: string): PluginLogger {
const prefix = `[plugin:${pluginId}]`; const pluginLog = createLogger(`plugin:${pluginId}`);
return { return {
info: (...args: unknown[]) => console.log(prefix, ...args), info: (message: string, ...args: unknown[]) => pluginLog.log(message, ...args),
warn: (...args: unknown[]) => console.warn(prefix, ...args), warn: (message: string, ...args: unknown[]) => pluginLog.warn(message, ...args),
error: (...args: unknown[]) => console.error(prefix, ...args), error: (message: string, ...args: unknown[]) => pluginLog.error(message, ...args),
debug: (...args: unknown[]) => { debug: (message: string, ...args: unknown[]) => {
if (process.env.DEBUG?.includes("plugins")) { if (process.env.DEBUG?.includes("plugins")) {
console.log(prefix, ...args); pluginLog.log(message, ...args);
} }
}, },
}; };
@@ -146,7 +148,7 @@ export class PluginLoader extends EventEmitter<{
// Skip disabled plugins // Skip disabled plugins
if (!installation.enabled) { if (!installation.enabled) {
console.log(`[plugin-loader] Skipping disabled plugin: ${pluginId}`); log.log(`Skipping disabled plugin: ${pluginId}`);
throw Object.assign(new Error(`Plugin "${pluginId}" is disabled`), { throw Object.assign(new Error(`Plugin "${pluginId}" is disabled`), {
code: "PLUGIN_DISABLED", code: "PLUGIN_DISABLED",
}); });
@@ -154,7 +156,7 @@ export class PluginLoader extends EventEmitter<{
// Skip already loaded plugins // Skip already loaded plugins
if (this.plugins.has(pluginId)) { if (this.plugins.has(pluginId)) {
console.log(`[plugin-loader] Plugin already loaded: ${pluginId}`); log.log(`Plugin already loaded: ${pluginId}`);
return this.plugins.get(pluginId)!; return this.plugins.get(pluginId)!;
} }
@@ -181,8 +183,8 @@ export class PluginLoader extends EventEmitter<{
plugin.manifest.fusionVersion, plugin.manifest.fusionVersion,
); );
if (!compatible) { if (!compatible) {
console.warn( log.warn(
`[plugin-loader] Plugin ${pluginId} requires Fusion ${plugin.manifest.fusionVersion}, minimum is ${MINIMUM_FUSION_VERSION}`, `Plugin ${pluginId} requires Fusion ${plugin.manifest.fusionVersion}, minimum is ${MINIMUM_FUSION_VERSION}`,
); );
} }
} }
@@ -284,7 +286,7 @@ export class PluginLoader extends EventEmitter<{
*/ */
private invalidateModuleCache(path: string): void { private invalidateModuleCache(path: string): void {
this.loadedModules.delete(path); this.loadedModules.delete(path);
console.log(`[plugin-loader] Module cache invalidated for: ${path}`); log.log(`Module cache invalidated for: ${path}`);
} }
/** /**
@@ -312,7 +314,7 @@ export class PluginLoader extends EventEmitter<{
const installation = await this.options.pluginStore.getPlugin(pluginId); const installation = await this.options.pluginStore.getPlugin(pluginId);
const pluginPath = this.resolvePluginPath(installation.path); const pluginPath = this.resolvePluginPath(installation.path);
console.log(`[plugin-loader] Reloading plugin: ${pluginId}`); log.log(`Reloading plugin: ${pluginId}`);
// Call onUnload with timeout // Call onUnload with timeout
try { try {
@@ -322,7 +324,7 @@ export class PluginLoader extends EventEmitter<{
`onUnload timeout for ${pluginId}`, `onUnload timeout for ${pluginId}`,
); );
} catch (err) { } catch (err) {
console.warn(`[plugin-loader] onUnload for ${pluginId} timed out or failed:`, err); log.warn(`onUnload for ${pluginId} timed out or failed:`, err);
// Continue with reload despite onUnload issues // Continue with reload despite onUnload issues
} }
@@ -362,13 +364,13 @@ export class PluginLoader extends EventEmitter<{
// State is already "started", no need to update store // State is already "started", no need to update store
// (avoiding started -> started transition which is disallowed) // (avoiding started -> started transition which is disallowed)
console.log(`[plugin-loader] Plugin ${pluginId} reloaded successfully`); log.log(`Plugin ${pluginId} reloaded successfully`);
this.emit("plugin:reloaded", { pluginId, plugin: newPlugin }); this.emit("plugin:reloaded", { pluginId, plugin: newPlugin });
return newPlugin; return newPlugin;
} catch (err) { } catch (err) {
// Rollback: restore old plugin // Rollback: restore old plugin
console.error(`[plugin-loader] Reload failed for ${pluginId}, rolling back:`, err); log.error(`Reload failed for ${pluginId}, rolling back:`, err);
try { try {
// Restore old plugin // Restore old plugin
@@ -385,12 +387,12 @@ export class PluginLoader extends EventEmitter<{
// Update store state back to started // Update store state back to started
await this.options.pluginStore.updatePluginState(pluginId, "started"); await this.options.pluginStore.updatePluginState(pluginId, "started");
console.warn(`[plugin-loader] Rollback successful for ${pluginId}`); log.warn(`Rollback successful for ${pluginId}`);
throw err; // Still throw the original error throw err; // Still throw the original error
} catch (rollbackErr) { } catch (rollbackErr) {
// Rollback also failed - remove plugin and set error state // Rollback also failed - remove plugin and set error state
console.error( log.error(
`[plugin-loader] Rollback failed for ${pluginId}, removing plugin:`, `Rollback failed for ${pluginId}, removing plugin:`,
rollbackErr, rollbackErr,
); );
@@ -520,8 +522,8 @@ export class PluginLoader extends EventEmitter<{
} catch (err) { } catch (err) {
if ((err as any).code !== "PLUGIN_DISABLED") { if ((err as any).code !== "PLUGIN_DISABLED") {
errors++; errors++;
console.error( log.error(
`[plugin-loader] Failed to load plugin ${installation.id}:`, `Failed to load plugin ${installation.id}:`,
err, err,
); );
} }
@@ -576,7 +578,7 @@ export class PluginLoader extends EventEmitter<{
async stopPlugin(pluginId: string): Promise<void> { async stopPlugin(pluginId: string): Promise<void> {
const plugin = this.plugins.get(pluginId); const plugin = this.plugins.get(pluginId);
if (!plugin) { if (!plugin) {
console.log(`[plugin-loader] Plugin not loaded: ${pluginId}`); log.log(`Plugin not loaded: ${pluginId}`);
return; return;
} }
@@ -588,7 +590,7 @@ export class PluginLoader extends EventEmitter<{
// Call onUnload hook // Call onUnload hook
await this.safeCallHook(plugin, "onUnload", []); await this.safeCallHook(plugin, "onUnload", []);
} catch (err) { } catch (err) {
console.error(`[plugin-loader] Error in onUnload for ${pluginId}:`, err); log.error(`Error in onUnload for ${pluginId}:`, err);
} }
// Update state // Update state
@@ -633,7 +635,7 @@ export class PluginLoader extends EventEmitter<{
try { try {
await this.stopPlugin(plugin.id); await this.stopPlugin(plugin.id);
} catch (err) { } catch (err) {
console.error(`[plugin-loader] Error stopping plugin ${plugin.id}:`, err); log.error(`Error stopping plugin ${plugin.id}:`, err);
} }
} }
} }
@@ -655,8 +657,8 @@ export class PluginLoader extends EventEmitter<{
try { try {
await this.safeCallHook(plugin, hookName, args); await this.safeCallHook(plugin, hookName, args);
} catch (err) { } catch (err) {
console.error( log.error(
`[plugin-loader] Error in ${hookName} hook for ${pluginId}:`, `Error in ${hookName} hook for ${pluginId}:`,
err, err,
); );