diff --git a/src/lib/plugins/loader.ts b/src/lib/plugins/loader.ts index 4cbd26266c..d4bcd2739d 100644 --- a/src/lib/plugins/loader.ts +++ b/src/lib/plugins/loader.ts @@ -23,6 +23,16 @@ const log = logger("PLUGIN_LOADER"); const DEFAULT_HOOK_TIMEOUT = 10_000; const SIGKILL_GRACE_MS = 3_000; +// One-way notification hooks: no return value is consumed and they fire per-request +// (onStreamComplete fires once per completed stream). A timeout on one of these only +// DROPS the pending call — it must never kill the child process, because the +// kill-on-timeout path below has no respawn: one slow delivery (e.g. a plugin posting +// usage to a slow remote sink) would reject every in-flight hook call and leave the +// plugin dead-but-shown-active until a manual deactivate/activate. Blocking hooks +// (onRequest/onResponse/onError) and the rarely-fired lifecycle hooks keep the +// kill-on-timeout isolation semantics. +const NOTIFICATION_HOOKS: ReadonlySet = new Set(["onStreamComplete"]); + // #8395: stdout/stderr forwarding hygiene — cap how much of a plugin's own console // output we relay per stream, so a runaway/misbehaving plugin can't flood memory or // the log sink. Mirrors the per-plugin rate-limit hygiene already used for hooks @@ -46,6 +56,12 @@ export interface LoadedPlugin { cleanup: () => void; } +export interface LoadPluginOptions { + /** Per-call IPC hook timeout in ms. Defaults to DEFAULT_HOOK_TIMEOUT (10s); injectable + * so tests can exercise the timeout paths without waiting out the production value. */ + hookTimeoutMs?: number; +} + /** * #8395: forward a plugin child process's stdout/stderr to the parent's structured * logger, line-buffered. Without this, plugin console.log/console.error output is @@ -140,8 +156,10 @@ process.on("message", async (msg) => { */ export async function loadPlugin( entryPoint: string, - manifest: PluginManifestWithDefaults + manifest: PluginManifestWithDefaults, + options: LoadPluginOptions = {} ): Promise { + const hookTimeoutMs = options.hookTimeoutMs ?? DEFAULT_HOOK_TIMEOUT; // Integrity check: if the manifest declares an integrity field, verify the entry point. // Missing integrity is OK for backward compatibility; mismatched integrity is a fatal error. const integrityField = (manifest as unknown as Record).integrity; @@ -253,16 +271,26 @@ export async function loadPlugin( removeHostScript(hostScriptPath); }); - // Call a hook in the child process with timeout + SIGTERM + SIGKILL escalation - const callHook = ( - hook: string, - payload: unknown, - timeout = DEFAULT_HOOK_TIMEOUT - ): Promise => { + // Call a hook in the child process with a timeout. Blocking/lifecycle hooks escalate + // SIGTERM → SIGKILL on timeout; NOTIFICATION_HOOKS only drop the pending call. + const callHook = (hook: string, payload: unknown, timeout = hookTimeoutMs): Promise => { return new Promise((resolve, reject) => { const id = String(++callCounter); const timer = setTimeout(() => { pendingCalls.delete(id); + if (NOTIFICATION_HOOKS.has(hook)) { + // Fire-and-forget notification: drop this delivery, keep the process. A late + // "result" reply for this id is safely ignored by the message handler (the + // pending entry is gone and ids are monotonic, never reused), so it cannot + // reject unhandled or mis-match a later call. + log.warn("plugin.notification_hook_timeout_dropped", { + name: manifest.name, + hook, + timeout, + }); + resolve(undefined); + return; + } child.kill("SIGTERM"); // Escalate to SIGKILL if plugin ignores SIGTERM const killTimer = setTimeout(() => { diff --git a/tests/unit/plugins-onstreamcomplete-timeout-isolation.test.ts b/tests/unit/plugins-onstreamcomplete-timeout-isolation.test.ts new file mode 100644 index 0000000000..eb0fe9d3c0 --- /dev/null +++ b/tests/unit/plugins-onstreamcomplete-timeout-isolation.test.ts @@ -0,0 +1,214 @@ +// Regression test — a timed-out onStreamComplete delivery must NOT kill the plugin +// process. #11934 wired onStreamComplete (a fire-and-forget, one-way notification that +// fires once per completed stream) through loader.ts::callHook(), whose timeout path was +// designed for rarely-fired blocking/lifecycle hooks: it SIGTERM→SIGKILLs the child with +// no respawn anywhere. So a single slow delivery (e.g. a plugin posting usage to a slow +// remote sink past DEFAULT_HOOK_TIMEOUT) kills the plugin's child process, rejects every +// other in-flight hook call, and leaves the plugin dead-but-shown-active until a manual +// deactivate/activate. After the fix, a notification-hook timeout only DROPS the pending +// call (promise settles, warning logged) and the child keeps serving subsequent hooks. +// Blocking hooks (onRequest etc.) keep the pre-existing kill-on-timeout semantics. +import test from "node:test"; +import assert from "node:assert/strict"; +import { mkdtemp, rm, writeFile, readFile } from "node:fs/promises"; +import { existsSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; + +import { loadPlugin, type LoadedPlugin } from "../../src/lib/plugins/loader.ts"; +import type { PluginManifestWithDefaults } from "../../src/lib/plugins/manifest.ts"; +import type { PluginContext, PluginOnStreamCompletePayload } from "../../src/lib/plugins/hooks.ts"; + +// Short injectable timeout so the test doesn't wait out the 10s production default. +const HOOK_TIMEOUT_MS = 300; +// The slow handler sleeps far past the timeout AND past the production default, so the +// test fails for the documented reason (kill) on the unfixed code too, where the +// injected timeout is ignored and the 10s default applies. +const SLOW_HANDLER_MS = 12_000; + +function makeManifest( + name: string, + hooks: Partial +): PluginManifestWithDefaults { + return { + name, + version: "1.0.0", + license: "MIT", + main: "index.mjs", + source: "local", + tags: [], + requires: { permissions: [] }, + hooks: { + onRequest: false, + onResponse: false, + onError: false, + onInstall: false, + onActivate: false, + onDeactivate: false, + onUninstall: false, + onStreamComplete: false, + ...hooks, + }, + skills: [], + enabledByDefault: false, + configSchema: {}, + } as PluginManifestWithDefaults; +} + +async function waitFor(pred: () => boolean, timeoutMs: number): Promise { + const deadline = Date.now() + timeoutMs; + while (Date.now() < deadline && !pred()) { + await new Promise((r) => setTimeout(r, 25)); + } +} + +test( + "onStreamComplete timeout drops the call but keeps the plugin process alive", + { timeout: 60_000 }, + async (t) => { + const pluginDir = await mkdtemp(join(tmpdir(), "omniroute-plugin-sc-timeout-")); + const entryPoint = join(pluginDir, "index.mjs"); + let loaded: LoadedPlugin | undefined; + + t.after(async () => { + loaded?.cleanup(); + await rm(pluginDir, { recursive: true, force: true, maxRetries: 5, retryDelay: 100 }); + }); + + // The plugin runs in an isolated child process, so it reports each delivery it + // receives by writing ".json" into a directory baked into its source. + await writeFile( + entryPoint, + ` +import { writeFileSync } from "node:fs"; +import { join } from "node:path"; +const OUT_DIR = ${JSON.stringify(pluginDir)}; +export async function onStreamComplete(payload) { + if (payload.sleepMs) { + await new Promise((r) => setTimeout(r, payload.sleepMs)); + } + writeFileSync(join(OUT_DIR, payload.marker + ".json"), JSON.stringify(payload)); +} +`, + "utf-8" + ); + + loaded = await loadPlugin(entryPoint, makeManifest("sc-timeout-isolation", { + onStreamComplete: true, + }), { hookTimeoutMs: HOOK_TIMEOUT_MS }); + + // Capture the loader's warning (logger("PLUGIN_LOADER").warn → console.warn). + const originalWarn = console.warn; + let warned = ""; + console.warn = ((...args: unknown[]) => { + warned += args.map(String).join(" ") + "\n"; + originalWarn(...args); + }) as typeof console.warn; + t.after(() => { + console.warn = originalWarn; + }); + + // 1) One delivery exceeds the hook timeout. The promise must settle (fire-and-forget + // semantics — the call is dropped), not wait for the 12s handler. + const slowStart = Date.now(); + await loaded.plugin.onStreamComplete?.({ + marker: "slow", + sleepMs: SLOW_HANDLER_MS, + } as unknown as PluginOnStreamCompletePayload); + const elapsed = Date.now() - slowStart; + + // Give any (buggy) SIGTERM fired by the timeout path time to actually land, so the + // next delivery cannot slip in before the child dies and mask the kill. + await new Promise((r) => setTimeout(r, 750)); + + // 2) THE regression: the child must have survived the timed-out notification, so a + // subsequent delivery still reaches the plugin. On the unfixed code the timeout + // path SIGTERM→SIGKILLs the child (with no respawn), so this file never appears. + await loaded.plugin.onStreamComplete?.({ + marker: "fast", + } as unknown as PluginOnStreamCompletePayload); + const fastFile = join(pluginDir, "fast.json"); + await waitFor(() => existsSync(fastFile), 5_000); + assert.ok( + existsSync(fastFile), + "the plugin child process was killed by a timed-out onStreamComplete notification — " + + "subsequent deliveries no longer reach the plugin (dead-but-shown-active)" + ); + const fastPayload = JSON.parse(await readFile(fastFile, "utf-8")) as { marker: string }; + assert.equal(fastPayload.marker, "fast"); + + // 3) The timed-out call settled at the configured timeout, not the handler duration — + // i.e. the timeout is injectable and the drop is prompt. + assert.ok( + elapsed < SLOW_HANDLER_MS - 2_000, + `timed-out onStreamComplete should settle at ~hookTimeoutMs (${HOOK_TIMEOUT_MS}ms), ` + + `not wait for the handler; took ${elapsed}ms` + ); + + // 4) The drop is observable: a warning names the plugin and the hook. + assert.ok( + warned.includes("sc-timeout-isolation") && warned.includes("onStreamComplete"), + `expected a warning naming the plugin and hook when a notification delivery is ` + + `dropped on timeout; captured=${JSON.stringify(warned)}` + ); + } +); + +test( + "blocking-hook (onRequest) timeout still kills the plugin process (semantics unchanged)", + { timeout: 30_000 }, + async (t) => { + const pluginDir = await mkdtemp(join(tmpdir(), "omniroute-plugin-req-timeout-")); + const entryPoint = join(pluginDir, "index.mjs"); + let loaded: LoadedPlugin | undefined; + + t.after(async () => { + loaded?.cleanup(); + await rm(pluginDir, { recursive: true, force: true, maxRetries: 5, retryDelay: 100 }); + }); + + await writeFile( + entryPoint, + ` +import { writeFileSync } from "node:fs"; +import { join } from "node:path"; +const OUT_DIR = ${JSON.stringify(pluginDir)}; +export async function onRequest(ctx) { + if (ctx.metadata && ctx.metadata.sleepMs) { + await new Promise((r) => setTimeout(r, ctx.metadata.sleepMs)); + } + writeFileSync(join(OUT_DIR, ctx.requestId + ".json"), "{}"); + return {}; +} +`, + "utf-8" + ); + + loaded = await loadPlugin(entryPoint, makeManifest("req-timeout-kill", { + onRequest: true, + }), { hookTimeoutMs: HOOK_TIMEOUT_MS }); + + // A blocking hook exceeding the timeout: the pre-existing isolation semantics apply — + // the misbehaving plugin process is killed. + await loaded.plugin.onRequest?.({ + requestId: "req-slow", + body: {}, + metadata: { sleepMs: SLOW_HANDLER_MS }, + } as unknown as PluginContext); + + // Let the SIGTERM land before probing. + await new Promise((r) => setTimeout(r, 750)); + + await loaded.plugin.onRequest?.({ + requestId: "req-after-kill", + body: {}, + metadata: {}, + } as unknown as PluginContext); + await new Promise((r) => setTimeout(r, 1_200)); + assert.ok( + !existsSync(join(pluginDir, "req-after-kill.json")), + "a timed-out BLOCKING hook must still kill the plugin process — the kill-on-timeout " + + "semantics for onRequest must not be relaxed by the notification-hook fix" + ); + } +);