fix(FN-2117): log swallowed engine runtime errors

- Add structured warning logs in silent catch paths for IPC worker shutdown, plugin unregistration cleanup, child runtime metrics polling, and merger build rollback reset - Improve merger rollback warning context to make build-verification reset and retry failures easier to diagnose - Add regression tests covering each new warning path to ensure errors are surfaced without changing existing control flow - Add StepSessionExecutor test coverage for cherry-pick abort logging when conflict cleanup fails
2026-04-19 02:55:04 -07:00
parent f947b7dc49
commit 11c5791622
9 changed files with 196 additions and 11 deletions
--- a/packages/engine/src/ipc/ipc-worker.test.ts
+++ b/packages/engine/src/ipc/ipc-worker.test.ts
@@ -15,6 +15,7 @@
 */
 import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
 import { PING, PONG, OK, ERROR, TASK_CREATED, ERROR_EVENT } from "./ipc-protocol.js";
+import { ipcLog } from "../logger.js";

 // ── Mock logger to suppress console output ──────────────────────────────
 vi.mock("../logger.js", () => ({
@@ -408,6 +409,23 @@ describe("IpcWorker", () => {
      worker.removeAllListeners();
    });

+    it("logs warning when process.send throws during shutdown", () => {
+      const { worker, sendFn } = createWorker();
+      vi.mocked(ipcLog.warn).mockClear();
+
+      sendFn.mockImplementation(() => {
+        throw new Error("channel closed");
+      });
+
+      worker.shutdown();
+
+      expect(vi.mocked(ipcLog.warn)).toHaveBeenCalledWith(
+        expect.stringContaining("Failed to send SHUTDOWN message to parent: channel closed"),
+      );
+      expect(worker.isShuttingDown()).toBe(true);
+      worker.removeAllListeners();
+    });
+
    it('emits "shutdown" event on the IpcWorker instance', () => {
      const { worker } = createWorker();
      const handler = vi.fn();
--- a/packages/engine/src/ipc/ipc-worker.ts
+++ b/packages/engine/src/ipc/ipc-worker.ts
@@ -278,8 +278,9 @@ export class IpcWorker extends EventEmitter {
    // Notify parent we're shutting down
    try {
      process.send?.({ type: "SHUTDOWN", id: generateCorrelationId(), payload: {} });
-    } catch {
-      // Ignore errors during shutdown
+    } catch (sendErr: unknown) {
+      const msg = sendErr instanceof Error ? sendErr.message : String(sendErr);
+      ipcLog.warn(`Failed to send SHUTDOWN message to parent: ${msg}`);
    }
  }

--- a/packages/engine/src/merger.test.ts
+++ b/packages/engine/src/merger.test.ts
@@ -2560,6 +2560,60 @@ describe("aiMergeTask — build verification", () => {
    );
  });

+  it("logs warning when git reset --merge fails during build-verification rollback", async () => {
+    const store = createMockStore(
+      { id: "FN-099", worktree: "/tmp/root/.worktrees/KB-099" },
+      [{ id: "FN-099", worktree: "/tmp/root/.worktrees/KB-099", column: "in-review" } as Task],
+    );
+    (store.getSettings as ReturnType<typeof vi.fn>).mockResolvedValue({
+      ...DEFAULT_SETTINGS,
+      buildCommand: "pnpm build",
+      verificationFixRetries: 0,
+    });
+
+    const warnSpy = vi.spyOn(mergerLog, "warn");
+    const resetFailureMessage = "reset failed: dirty working tree";
+
+    mockedCreateHaiAgent.mockImplementation(async (opts: any) => {
+      const reportTool = opts.customTools?.find((t: any) => t.name === "report_build_failure");
+      return {
+        session: {
+          prompt: vi.fn().mockImplementation(async () => {
+            await reportTool?.execute("tool-call-1", {
+              message: "Type error in src/utils.ts",
+            });
+          }),
+          dispose: vi.fn(),
+        },
+      } as any;
+    });
+
+    mockedExecSync.mockImplementation((cmd: any) => {
+      const cmdStr = String(cmd);
+      if (cmdStr.includes("rev-parse --verify")) return Buffer.from("abc123");
+      if (cmdStr.includes("git log")) return "- feat: something";
+      if (cmdStr.includes("merge-base")) return Buffer.from("abc123");
+      if (cmdStr.includes("git diff") && cmdStr.includes("--stat")) return "1 file changed";
+      if (cmdStr.includes("merge --squash")) return Buffer.from("");
+      if (cmdStr.includes("diff --cached --quiet")) return "1";
+      if (cmdStr.includes("git reset --merge")) throw new Error(resetFailureMessage);
+      if (cmdStr.includes("branch -d") || cmdStr.includes("branch -D")) return Buffer.from("");
+      if (cmdStr.includes("worktree remove")) return Buffer.from("");
+      return Buffer.from("");
+    });
+
+    await expect(aiMergeTask(store, "/tmp/root", "FN-099")).rejects.toThrow(
+      "Build verification failed for FN-099: Type error in src/utils.ts",
+    );
+
+    expect(warnSpy).toHaveBeenCalledWith(
+      expect.stringContaining("FN-099: git reset --merge cleanup failed during build-verification rollback"),
+    );
+    expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining(resetFailureMessage));
+
+    warnSpy.mockRestore();
+  });
+
  it("merge proceeds normally when no build command is configured", async () => {
    mockedCreateHaiAgent.mockResolvedValue({
      session: {
--- a/packages/engine/src/merger.ts
+++ b/packages/engine/src/merger.ts
@@ -2103,9 +2103,11 @@ async function executeMergeAttempt(
      // Reset staged changes to abort the merge
      try {
        execSync("git reset --merge", { cwd: rootDir, stdio: "pipe" });
-      } catch (err: unknown) {
-        const msg = err instanceof Error ? err.message : String(err);
-        mergerLog.warn(`${taskId}: git reset --merge cleanup failed (build-verification reset): ${msg}`);
+      } catch (resetErr: unknown) {
+        const msg = resetErr instanceof Error ? resetErr.message : String(resetErr);
+        mergerLog.warn(
+          `${taskId}: git reset --merge cleanup failed during build-verification rollback (build-verification reset, build-retry): ${msg}`,
+        );
      }

      throw new Error(`Build verification failed for ${taskId}: ${errorMessage}`);
--- a/packages/engine/src/plugin-runner.test.ts
+++ b/packages/engine/src/plugin-runner.test.ts
@@ -9,14 +9,15 @@ import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
 import { PluginRunner, type PluginRunnerOptions } from "./plugin-runner.js";
 import type { PluginLoader, PluginStore, PluginInstallation } from "@fusion/core";
 import type { FusionPlugin, PluginToolDefinition } from "@fusion/core";
+import { createLogger } from "./logger.js";

 // Mock the logger to suppress output during tests
 vi.mock("./logger.js", () => ({
-  createLogger: () => ({
+  createLogger: vi.fn(() => ({
    log: vi.fn(),
    warn: vi.fn(),
    error: vi.fn(),
-  }),
+  })),
  executorLog: {
    log: vi.fn(),
    warn: vi.fn(),
@@ -63,6 +64,18 @@ describe("PluginRunner", () => {
    ...overrides,
  });

+  const getPluginRunnerLogger = () => {
+    const logger = vi.mocked(createLogger).mock.results.at(-1)?.value as {
+      log: ReturnType<typeof vi.fn>;
+      warn: ReturnType<typeof vi.fn>;
+      error: ReturnType<typeof vi.fn>;
+    } | undefined;
+    if (!logger) {
+      throw new Error("Expected plugin-runner logger to be initialized");
+    }
+    return logger;
+  };
+
  beforeEach(() => {
    // Create fresh mocks for each test
    mockPluginLoader = {
@@ -655,6 +668,37 @@ describe("PluginRunner", () => {
      expect(true).toBe(true); // Handler exists and doesn't throw
    });

+    it("logs warning when stopPlugin fails during plugin:unregistered handler", async () => {
+      mockPluginLoader.stopPlugin.mockRejectedValue(new Error("stop failed"));
+      await pluginRunner.init();
+
+      const unregisteredHandler = mockPluginStore.on.mock.calls.find(
+        call => call[0] === "plugin:unregistered"
+      )?.[1];
+      const logger = getPluginRunnerLogger();
+      logger.warn.mockClear();
+      expect(unregisteredHandler).toBeTypeOf("function");
+
+      const plugin = {
+        id: "broken-plugin",
+        name: "Broken Plugin",
+        version: "1.0.0",
+        path: "/test/path",
+        enabled: false,
+        state: "stopped" as const,
+        settings: {},
+        createdAt: "2024-01-01T00:00:00.000Z",
+        updatedAt: "2024-01-01T00:00:00.000Z",
+      };
+
+      await expect(unregisteredHandler?.(plugin)).resolves.toBeUndefined();
+
+      expect(mockPluginLoader.stopPlugin).toHaveBeenCalledWith("broken-plugin");
+      expect(logger.warn).toHaveBeenCalledWith(
+        expect.stringContaining("Failed to stop unregistered plugin broken-plugin: stop failed"),
+      );
+    });
+
    it("should handle plugin:stateChanged event", async () => {
      await pluginRunner.init();
      
--- a/packages/engine/src/plugin-runner.ts
+++ b/packages/engine/src/plugin-runner.ts
@@ -285,8 +285,9 @@ export class PluginRunner {
    try {
      executorLog.log(`Stopping unregistered plugin: ${plugin.id}`);
      await this.options.pluginLoader.stopPlugin(plugin.id);
-    } catch (err) {
-      this.log.warn(`Failed to stop unregistered plugin ${plugin.id}: ${err instanceof Error ? err.message : String(err)}`);
+    } catch (err: unknown) {
+      const msg = err instanceof Error ? err.message : String(err);
+      this.log.warn(`Failed to stop unregistered plugin ${plugin.id}: ${msg} (plugin '${plugin.id}')`);
    }
  }

--- a/packages/engine/src/runtimes/child-process-runtime.test.ts
+++ b/packages/engine/src/runtimes/child-process-runtime.test.ts
@@ -6,6 +6,7 @@ import type {
  RuntimeMetrics,
  RuntimeStatus,
 } from "../project-runtime.js";
+import { runtimeLog } from "../logger.js";
 import {
  START_RUNTIME,
  STOP_RUNTIME,
@@ -673,6 +674,36 @@ describe("ChildProcessRuntime", () => {
      });
    });

+    it("logs warning when GET_METRICS IPC query fails", async () => {
+      const warnSpy = vi.spyOn(runtimeLog, "warn").mockImplementation(() => {});
+
+      queueChild({
+        sendCallbackErrors: {
+          [GET_METRICS]: new Error("metrics unavailable"),
+        },
+      });
+      await runtime.start();
+
+      runtimeAny.lastMetrics = {
+        inFlightTasks: 1,
+        activeAgents: 0,
+        lastActivityAt: "2026-04-08T04:00:00.000Z",
+      };
+
+      const metrics = runtime.getMetrics();
+      expect(metrics.inFlightTasks).toBe(1);
+      expect(metrics.activeAgents).toBe(0);
+
+      await vi.waitFor(() => {
+        expect(warnSpy).toHaveBeenCalledWith(
+          expect.stringContaining("GET_METRICS IPC query failed, using cached value"),
+        );
+      });
+      expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining("metrics unavailable"));
+
+      warnSpy.mockRestore();
+    });
+
    it("getTaskStore() always throws not accessible error", () => {
      expect(() => runtime.getTaskStore()).toThrow("not accessible in ChildProcessRuntime");
    });
--- a/packages/engine/src/runtimes/child-process-runtime.ts
+++ b/packages/engine/src/runtimes/child-process-runtime.ts
@@ -450,8 +450,9 @@ export class ChildProcessRuntime
        .then((metrics: unknown) => {
          this.lastMetrics = metrics as RuntimeMetrics;
        })
-        .catch(() => {
-          // Ignore errors, use cached value
+        .catch((err: unknown) => {
+          const msg = err instanceof Error ? err.message : String(err);
+          runtimeLog.warn(`GET_METRICS IPC query failed, using cached value: ${msg}`);
        });
    }

--- a/packages/engine/src/step-session-executor.test.ts
+++ b/packages/engine/src/step-session-executor.test.ts
@@ -1130,6 +1130,39 @@ describe("StepSessionExecutor", () => {
      );
    });

+    it("logs warning when cherry-pick --abort fails after conflict and still throws conflict", async () => {
+      const task = makeTaskDetail({
+        prompt: makeStepPrompt("FN-001", 2),
+      });
+      const executor = new StepSessionExecutor({
+        taskDetail: task,
+        worktreePath: "/project/.worktrees/main",
+        rootDir: "/project",
+        settings: makeSettings({ maxParallelSteps: 2 }),
+      });
+
+      mockedExecSync.mockImplementation((cmd: string) => {
+        if (cmd.includes("git log")) {
+          return "abc123";
+        }
+        if (cmd.includes("git cherry-pick") && cmd.includes("--abort")) {
+          throw new Error("abort failed");
+        }
+        if (cmd.includes("git cherry-pick")) {
+          throw new Error("Merge conflict");
+        }
+        return "";
+      });
+
+      await expect(
+        (executor as any).cherryPickCommits(1, "/project/.worktrees/step-1"),
+      ).rejects.toThrow("Cherry-pick conflict for commit abc123 in step 1: Merge conflict");
+
+      expect(getStepSessionLogger().warn).toHaveBeenCalledWith(
+        "Cherry-pick --abort failed for step 1: abort failed",
+      );
+    });
+
    it("semaphore integration: parallel steps acquire/release", async () => {
      const prompt = `# Task: FN-001