fix(plugins): do not kill the plugin process when a fire-and-forget hook times out (#12116)

Corrige o kill do processo inteiro do plugin quando um handler fire-and-forget de `onStreamComplete` demora >10s — hook documentado como fire-and-forget não deveria derrubar o processo a cada stream completo. Finding 5 do #12113. Teste próprio (214 linhas). Validado no worktree combinado. Obrigado!

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<string> = 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<LoadedPlugin> {
+  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<string, unknown>).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<unknown> => {
+  // 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<unknown> => {
     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(() => {

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["hooks"]>
+): 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<void> {
+  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 "<marker>.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"
+    );
+  }
+);