test: diagnose restart startup cascades

tests/audit-integrity.test.ts

@@ -491,64 +491,85 @@ describe("audit journal integrity", () => {
   });
 
   it("restores the prior integrity ledger when checkpoint replacement fails during compaction", async () => {
-    const directory = await mkdtemp(join(tmpdir(), "miftah-audit-integrity-compaction-rollback-"));
-    const path = join(directory, "audit.jsonl");
-    const logger = new AuditLogger(path, {
-      integrity: { algorithm: "sha256-chain" },
-      rotation: { maxBytes: 1, retainFiles: 2 }
-    });
-    await logger.log({
-      wrapper: "github",
-      profile: "work",
-      operation: "tools/call",
-      name: "durable-before-compaction-checkpoint-failure",
-      status: "success",
-      durationMs: 1
-    });
-
-    const probe = await open(path, "r");
-    const fileHandlePrototype = Object.getPrototypeOf(probe) as { write: BufferWrite };
-    const originalWrite = probe.write as BufferWrite;
-    await probe.close();
+    let stage = "creating fixture";
     let writes = 0;
-    const writeSpy = vi.spyOn(fileHandlePrototype, "write").mockImplementation(async function (
-      this: FileHandle,
-      buffer: Uint8Array,
-      offset: number,
-      length: number,
-      position: number | null
-    ) {
-      writes += 1;
-      if (writes === 2) throw Object.assign(new Error("simulated full disk"), { code: "ENOSPC" });
-      return originalWrite.call(this, buffer, offset, length, position);
-    });
+    const timeoutDiagnostic = setTimeout(() => {
+      process.stderr.write(
+        `MIFTAH_AUDIT_INTEGRITY_TIMEOUT_DIAGNOSTIC: stage=${stage}; interceptedWrites=${writes}\n`
+      );
+    }, 4_500);
+    timeoutDiagnostic.unref();
+
     try {
+      const directory = await mkdtemp(join(tmpdir(), "miftah-audit-integrity-compaction-rollback-"));
+      const path = join(directory, "audit.jsonl");
+      const logger = new AuditLogger(path, {
+        integrity: { algorithm: "sha256-chain" },
+        rotation: { maxBytes: 1, retainFiles: 2 }
+      });
+      stage = "writing initial record";
+      await logger.log({
+        wrapper: "github",
+        profile: "work",
+        operation: "tools/call",
+        name: "durable-before-compaction-checkpoint-failure",
+        status: "success",
+        durationMs: 1
+      });
+
+      stage = "opening write probe";
+      const probe = await open(path, "r");
+      const fileHandlePrototype = Object.getPrototypeOf(probe) as { write: BufferWrite };
+      const originalWrite = probe.write as BufferWrite;
+      stage = "closing write probe";
+      await probe.close();
+      stage = "installing write spy";
+      const writeSpy = vi.spyOn(fileHandlePrototype, "write").mockImplementation(async function (
+        this: FileHandle,
+        buffer: Uint8Array,
+        offset: number,
+        length: number,
+        position: number | null
+      ) {
+        writes += 1;
+        if (writes === 2) throw Object.assign(new Error("simulated full disk"), { code: "ENOSPC" });
+        return originalWrite.call(this, buffer, offset, length, position);
+      });
+      try {
+        stage = "writing replacement checkpoint";
+        await expect(
+          logger.log({
+            wrapper: "github",
+            profile: "work",
+            operation: "tools/call",
+            name: "must-not-leave-a-new-ledger-with-an-old-checkpoint",
+            status: "success",
+            durationMs: 2
+          })
+        ).rejects.toMatchObject({ code: "AUDIT_WRITE_FAILED" });
+      } finally {
+        stage = "restoring write spy";
+        writeSpy.mockRestore();
+      }
+
+      stage = "verifying rollback";
+      expect(await verifyAuditJournal(path)).toEqual({ ok: true });
+      stage = "writing recovery record";
       await expect(
         logger.log({
           wrapper: "github",
           profile: "work",
           operation: "tools/call",
-          name: "must-not-leave-a-new-ledger-with-an-old-checkpoint",
+          name: "succeeds-after-compaction-checkpoint-rollback",
           status: "success",
-          durationMs: 2
+          durationMs: 3
         })
-      ).rejects.toMatchObject({ code: "AUDIT_WRITE_FAILED" });
+      ).resolves.toBeUndefined();
+      stage = "verifying recovery";
+      expect(await verifyAuditJournal(path)).toEqual({ ok: true });
     } finally {
-      writeSpy.mockRestore();
+      clearTimeout(timeoutDiagnostic);
     }
-
-    expect(await verifyAuditJournal(path)).toEqual({ ok: true });
-    await expect(
-      logger.log({
-        wrapper: "github",
-        profile: "work",
-        operation: "tools/call",
-        name: "succeeds-after-compaction-checkpoint-rollback",
-        status: "success",
-        durationMs: 3
-      })
-    ).resolves.toBeUndefined();
-    expect(await verifyAuditJournal(path)).toEqual({ ok: true });
   });
 
   it("rejects an oversized integrity record before changing the retained journal", async () => {

tests/audit-outcomes.test.ts

@@ -12,6 +12,7 @@ import { validateConfig } from "../src/config/validate-config.js";
 import { MiftahServer } from "../src/mcp/server/miftah-server.js";
 import { ProfileManager } from "../src/profiles/profile-manager.js";
 import { UpstreamProcessManager } from "../src/upstream/upstream-process-manager.js";
+import { countFixtureStarts, diagnosticFailure, summarizeUpstreamHealth } from "./helpers/upstream-diagnostics.js";
 
 const fixture = join(dirname(fileURLToPath(import.meta.url)), "fixtures", "fake-upstream.mjs");
 
@@ -119,12 +120,25 @@ describe("audit outcomes", () => {
   it("records wrapper and lazy upstream lifecycle outcomes", async () => {
     const directory = await mkdtemp(join(tmpdir(), "miftah-audit-lifecycle-"));
     const auditPath = join(directory, "audit.jsonl");
+    const initializedPath = join(directory, "upstream-initialized");
+    const listToolsStartedPath = join(directory, "upstream-list-tools-started");
+    const startCountPath = join(directory, "upstream-start-count");
+    await writeFile(startCountPath, "");
     const config = validateConfig({
       version: "1",
       name: "accounts",
       defaultProfile: "work",
       upstream: { transport: "stdio", command: process.execPath, args: [fixture] },
-      profiles: { work: { env: { TEST_ACCOUNT_NAME: "work" } } },
+      profiles: {
+        work: {
+          env: {
+            TEST_ACCOUNT_NAME: "work",
+            TEST_INITIALIZED_PATH: initializedPath,
+            TEST_LIST_TOOLS_STARTED_PATH: listToolsStartedPath,
+            TEST_START_COUNT_PATH: startCountPath
+          }
+        }
+      },
       audit: { path: auditPath }
     });
     const manager = new UpstreamProcessManager(config.upstream!, config.profiles, { startupTimeoutMs: 1_000 });
@@ -134,7 +148,30 @@ describe("audit outcomes", () => {
 
     try {
       await Promise.all([wrapper.connect(serverTransport), client.connect(clientTransport)]);
-      await client.listTools();
+      const startsBeforeDiscovery = await countFixtureStarts(startCountPath);
+      await Promise.all([
+        writeFile(initializedPath, "before-discovery"),
+        writeFile(listToolsStartedPath, "before-discovery")
+      ]);
+      try {
+        await client.listTools();
+      } catch (error) {
+        const [starts, initialized, listToolsStarted] = await Promise.all([
+          countFixtureStarts(startCountPath),
+          readFile(initializedPath, "utf8"),
+          readFile(listToolsStartedPath, "utf8")
+        ]);
+        throw diagnosticFailure(
+          "Lazy upstream discovery failed",
+          {
+            startDelta: starts - startsBeforeDiscovery,
+            initialized,
+            listToolsStarted,
+            health: summarizeUpstreamHealth(manager.listHealth())
+          },
+          error
+        );
+      }
       await client.close();
       await wrapper.close();
 

tests/helpers/upstream-diagnostics.test.ts

@@ -0,0 +1,63 @@
+import { mkdtemp, rm, writeFile } from "node:fs/promises";
+import { tmpdir } from "node:os";
+import { join } from "node:path";
+import { afterEach, describe, expect, it } from "vitest";
+import { countFixtureStarts, diagnosticFailure, summarizeUpstreamHealth } from "./upstream-diagnostics.js";
+
+const directories: string[] = [];
+
+afterEach(async () => {
+  await Promise.all(directories.splice(0).map(async (directory) => rm(directory, { recursive: true, force: true })));
+});
+
+describe("upstream test diagnostics", () => {
+  it("counts fixture starts and emits only the safe health fields", async () => {
+    const directory = await mkdtemp(join(tmpdir(), "miftah-upstream-diagnostics-"));
+    directories.push(directory);
+    const starts = join(directory, "starts");
+    await writeFile(starts, "one\n\ntwo\n");
+
+    await expect(countFixtureStarts(starts)).resolves.toBe(2);
+    expect(
+      summarizeUpstreamHealth([
+        {
+          profile: "work",
+          upstreamName: "remote",
+          state: "failed",
+          processState: "failed",
+          restartCount: 1,
+          lastStopReason: "shutdown-timeout",
+          restartLimitReached: false,
+          capabilities: {
+            tools: { state: "failed", lastTransition: "2026-01-01T00:00:00.000Z", error: "sensitive tool failure" },
+            resources: { state: "unknown", lastTransition: "2026-01-01T00:00:00.000Z" },
+            prompts: { state: "available", lastTransition: "2026-01-01T00:00:00.000Z" }
+          },
+          status: "failed",
+          lastTransition: "2026-01-01T00:00:00.000Z",
+          error: "sensitive manager error"
+        }
+      ])
+    ).toEqual([
+      {
+        profile: "work",
+        upstreamName: "remote",
+        state: "failed",
+        processState: "failed",
+        restartCount: 1,
+        lastStopReason: "shutdown-timeout",
+        restartLimitReached: false,
+        capabilities: { tools: "failed", resources: "unknown", prompts: "available" }
+      }
+    ]);
+  });
+
+  it("keeps a captured failure as the cause without putting it in the safe diagnostic message", () => {
+    const cause = new Error("sensitive upstream failure");
+    const error = diagnosticFailure("Upstream marker diagnostic", { startDelta: 0 }, cause);
+
+    expect(error.message).toBe('Upstream marker diagnostic: {"startDelta":0}');
+    expect(error.message).not.toContain("sensitive upstream failure");
+    expect(error.cause).toBe(cause);
+  });
+});

tests/helpers/upstream-diagnostics.ts

@@ -0,0 +1,48 @@
+import { readFile } from "node:fs/promises";
+
+interface DiagnosticCapabilityHealth {
+  readonly state: string;
+  readonly lastTransition: string;
+  readonly error?: string;
+}
+
+interface DiagnosticUpstreamHealth {
+  readonly profile: string;
+  readonly upstreamName: string;
+  readonly status?: string;
+  readonly state: string;
+  readonly processState: string;
+  readonly lastTransition?: string;
+  readonly restartCount: number;
+  readonly lastStopReason?: string;
+  readonly restartLimitReached?: boolean;
+  readonly error?: string;
+  readonly capabilities: Record<string, DiagnosticCapabilityHealth>;
+}
+
+/** Counts fixture process entries without reporting any fixture output. */
+export async function countFixtureStarts(path: string): Promise<number> {
+  const contents = await readFile(path, "utf8");
+  return contents.split("\n").filter(Boolean).length;
+}
+
+/** Restricts failure diagnostics to lifecycle metadata that cannot contain upstream output or secrets. */
+export function summarizeUpstreamHealth(health: readonly DiagnosticUpstreamHealth[]): Array<Record<string, unknown>> {
+  return health.map((entry) => ({
+    profile: entry.profile,
+    upstreamName: entry.upstreamName,
+    state: entry.state,
+    processState: entry.processState,
+    restartCount: entry.restartCount,
+    lastStopReason: entry.lastStopReason,
+    restartLimitReached: entry.restartLimitReached,
+    capabilities: Object.fromEntries(
+      Object.entries(entry.capabilities).map(([capability, capabilityHealth]) => [capability, capabilityHealth.state])
+    )
+  }));
+}
+
+/** Keeps the original test failure in Error.cause while emitting a safe, allowlisted diagnostic message. */
+export function diagnosticFailure(message: string, details: Record<string, unknown>, cause: unknown): Error {
+  return new Error(`${message}: ${JSON.stringify(details)}`, { cause });
+}