test: report native job restart substages

tests/e2e/scenarios/native-compose-adoption-job-diagnostics.ts

@@ -0,0 +1,122 @@
+import { isRecord } from "../../../src/lib/guards.ts";
+import type { CliResult } from "../harness.ts";
+
+const STAGES = [
+  "prior-state",
+  "cli-result",
+  "fresh-state",
+  "fresh-exit",
+  "pending-clear",
+  "sql-ready",
+  "sql-counts",
+  "sibling-isolation",
+] as const;
+type Stage = (typeof STAGES)[number];
+const CODES = [
+  "E_CONFIG_INVALID",
+  "E_LIFECYCLE_FAILED",
+  "E_STATE",
+  "E_NATIVE_COMPOSE_ADOPTION",
+  "E_NATIVE_COMPOSE_OWNERSHIP",
+  "E_NATIVE_COMPOSE_PROBE",
+  "E_NATIVE_COMPOSE_PROBE_TIMEOUT",
+] as const;
+const MAX_REPLY_BYTES = 64 * 1024;
+
+function isStage(value: unknown): value is Stage {
+  return STAGES.some((stage) => stage === value);
+}
+
+function cliCode(stdout: string): string {
+  if (Buffer.byteLength(stdout) > MAX_REPLY_BYTES) {
+    return "unavailable";
+  }
+  try {
+    const value: unknown = JSON.parse(stdout);
+    if (!isRecord(value)) {
+      return "unavailable";
+    }
+    if (value.ok === true) {
+      return "none";
+    }
+    if (value.ok === false && isRecord(value.error)) {
+      const error = value.error;
+      return CODES.find((code) => code === error.code) ?? "unavailable";
+    }
+  } catch {
+    // A diagnostic cannot replace the original command outcome.
+  }
+  return "unavailable";
+}
+
+/**
+ * Record only closed start/restart substages and allowlisted CLI codes. No reply
+ * values, paths, argv, identifiers, arbitrary errors or elapsed-budget claims are
+ * emitted. Logging failure never replaces the original result or thrown error.
+ */
+export function createCompletedJobFixtureStartDiagnostics(opts: {
+  readonly log: (message: string) => void;
+  readonly operation: unknown;
+  readonly scope: unknown;
+}) {
+  const log = opts.log;
+  const operation =
+    opts.operation === "up" || opts.operation === "restart"
+      ? opts.operation
+      : "unavailable";
+  const scope =
+    opts.scope === "alpha" || opts.scope === "beta"
+      ? opts.scope
+      : "unavailable";
+  const prefix = `start-operation=${operation} worktree=${scope}`;
+  const emit = (message: string) => {
+    try {
+      log(`${prefix} ${message}`);
+    } catch {
+      // Diagnostics cannot skip cleanup or replace its original refusal.
+    }
+  };
+  return Object.freeze({
+    step: async <T>(
+      stage: unknown,
+      action: () => T | Promise<T>
+    ): Promise<T> => {
+      if (!isStage(stage)) {
+        return await action();
+      }
+      emit(`stage=${stage} status=begin`);
+      try {
+        const value = await action();
+        emit(`stage=${stage} status=end`);
+        return value;
+      } catch (error) {
+        emit(`stage=${stage} status=failed`);
+        throw error;
+      }
+    },
+    cliOutcome: (
+      result: Pick<CliResult, "exitCode" | "timedOut" | "stdout">
+    ) => {
+      try {
+        const exit = exitClass(result.exitCode);
+        const timeout = result.timedOut ? "yes" : "no";
+        emit(
+          `stage=cli-result exit=${exit} timed-out=${timeout} code=${cliCode(result.stdout)}`
+        );
+      } catch {
+        emit(
+          "stage=cli-result exit=unavailable timed-out=unavailable code=unavailable"
+        );
+      }
+    },
+  });
+}
+
+function exitClass(value: unknown): "zero" | "nonzero" | "unavailable" {
+  if (value === 0) {
+    return "zero";
+  }
+  return typeof value === "number" && Number.isSafeInteger(value)
+    ? "nonzero"
+    : "unavailable";
+}

tests/e2e/scenarios/native-compose-adoption-job-worktrees.ts

@@ -16,6 +16,7 @@ import {
   type Scenario,
   type ScenarioContext,
 } from "../harness.ts";
+import { createCompletedJobFixtureStartDiagnostics } from "./native-compose-adoption-job-diagnostics.ts";
 import { completedJobFixtureSources } from "./native-compose-adoption-job-inputs.ts";
 import {
   createAdoptionFixtureProbe,
@@ -752,30 +753,48 @@ function runtime(input: Awaited<ReturnType<typeof prepare>>) {
     expected: readonly number[],
     restart = false
   ) => {
-    const previous = await state(instance, "seed");
-    requireValue(typeof previous.startedAt === "string");
-    successful(
-      await cli(
+    const diagnostics = createCompletedJobFixtureStartDiagnostics({
+      log: ctx.log,
+      operation: restart ? "restart" : "up",
+      scope: instance === input.first ? "alpha" : "beta",
+    });
+    const previous = await diagnostics.step("prior-state", async () => {
+      const value = await state(instance, "seed");
+      requireValue(typeof value.startedAt === "string");
+      return value;
+    });
+    await diagnostics.step("cli-result", async () => {
+      const result = await cli(
         instance,
         restart ? ["restart", "--json"] : ["up", "--detach", "--json"]
-      )
+      );
+      diagnostics.cliOutcome(result);
+      successful(result);
+    });
+    const current = await diagnostics.step("fresh-state", () =>
+      state(instance, "seed")
     );
-    const current = await state(instance, "seed");
-    if (typeof previous.startedAt !== "string") {
-      refused();
-    }
-    completedJobFixtureFreshExit({
-      id: id(instance, "seed"),
-      priorStartedAt: previous.startedAt,
-      observed: current,
+    await diagnostics.step("fresh-exit", () => {
+      if (typeof previous.startedAt !== "string") {
+        refused();
+      }
+      completedJobFixtureFreshExit({
+        id: id(instance, "seed"),
+        priorStartedAt: previous.startedAt,
+        observed: current,
+      });
     });
-    await pending(instance, null);
-    await waitSql(
-      instance,
-      "SELECT count(*) FROM app_starts",
-      String(expected.length)
+    await diagnostics.step("pending-clear", () => pending(instance, null));
+    await diagnostics.step("sql-ready", () =>
+      waitSql(
+        instance,
+        "SELECT count(*) FROM app_starts",
+        String(expected.length)
+      )
+    );
+    await diagnostics.step("sql-counts", () =>
+      counts(instance, attempts, expected)
     );
-    await counts(instance, attempts, expected);
   };
   const control = async (
     instance: Instance,
@@ -1397,7 +1416,11 @@ export const nativeComposeAdoptionJobWorktreesScenario: Scenario = {
       await h.freshUp(first, 3, [1, 2, 3]);
       phases.mark("alpha-restart-4");
       await h.freshUp(first, 4, [1, 2, 3, 4], true);
-      await h.counts(second, 1, [1]);
+      await createCompletedJobFixtureStartDiagnostics({
+        log: ctx.log,
+        operation: "restart",
+        scope: "alpha",
+      }).step("sibling-isolation", () => h.counts(second, 1, [1]));
       phases.mark("alpha-nonzero-job-5");
       await h.control(first, "fail");
       await stop(h, first);

tests/native-compose-adoption-job-diagnostics.test.ts

@@ -0,0 +1,155 @@
+import { expect, test } from "bun:test";
+import { createCompletedJobFixtureStartDiagnostics } from "./e2e/scenarios/native-compose-adoption-job-diagnostics.ts";
+
+function diagnostics(messages: string[]) {
+  return createCompletedJobFixtureStartDiagnostics({
+    operation: "restart",
+    scope: "alpha",
+    log: (message) => messages.push(message),
+  });
+}
+
+test("completed-job start diagnostics distinguish CLI refusal from a later oracle", async () => {
+  for (const failureStage of ["cli-result", "fresh-exit"] as const) {
+    const messages: string[] = [];
+    const diagnostic = diagnostics(messages);
+    const original = new Error("private-original-refusal-canary");
+    const calls: string[] = [];
+    let observed: unknown;
+    try {
+      for (const stage of [
+        "cli-result",
+        "fresh-exit",
+        "pending-clear",
+      ] as const) {
+        await diagnostic.step(stage, () => {
+          calls.push(stage);
+          if (stage === failureStage) {
+            throw original;
+          }
+        });
+      }
+    } catch (error) {
+      observed = error;
+    }
+    expect(observed).toBe(original);
+    expect(calls).toEqual(
+      failureStage === "cli-result"
+        ? ["cli-result"]
+        : ["cli-result", "fresh-exit"]
+    );
+    expect(messages.at(-1)).toBe(
+      `start-operation=restart worktree=alpha stage=${failureStage} status=failed`
+    );
+    expect(messages.join("\n")).not.toContain("canary");
+    expect(messages.join("\n")).not.toContain("pending-clear");
+  }
+});
+
+test("completed-job start diagnostics preserve success order and callback results", async () => {
+  const messages: string[] = [];
+  const diagnostic = diagnostics(messages);
+  const value = { privateValue: "private-result-canary" };
+  for (const stage of [
+    "prior-state",
+    "cli-result",
+    "fresh-state",
+    "fresh-exit",
+    "pending-clear",
+    "sql-ready",
+    "sql-counts",
+    "sibling-isolation",
+  ]) {
+    expect(await diagnostic.step(stage, () => value)).toBe(value);
+    expect(messages.slice(-2)).toEqual([
+      `start-operation=restart worktree=alpha stage=${stage} status=begin`,
+      `start-operation=restart worktree=alpha stage=${stage} status=end`,
+    ]);
+  }
+  expect(messages).toHaveLength(16);
+  expect(messages.join("\n")).not.toContain("private-result-canary");
+});
+
+test("completed-job start diagnostics omit reply values and unknown codes or labels", async () => {
+  const messages: string[] = [];
+  const diagnostic = diagnostics(messages);
+  for (const code of ["E_CONFIG_INVALID", "private-code-canary"]) {
+    diagnostic.cliOutcome({
+      exitCode: 17,
+      timedOut: false,
+      stdout: JSON.stringify({
+        ok: false,
+        error: { code, message: "private-message-canary" },
+        env: "private-env-canary",
+        argv: ["private-argv-canary"],
+      }),
+    });
+  }
+  diagnostic.cliOutcome({
+    exitCode: 0,
+    timedOut: false,
+    stdout: "private-malformed-canary",
+  });
+  diagnostic.cliOutcome({
+    exitCode: 17,
+    timedOut: true,
+    stdout: "private-oversized-canary".repeat(10_000),
+  });
+  const unknown = createCompletedJobFixtureStartDiagnostics({
+    operation: "private-operation-canary",
+    scope: "private-scope-canary",
+    log: (message) => messages.push(message),
+  });
+  let calls = 0;
+  expect(await unknown.step("private-stage-canary", () => ++calls)).toBe(1);
+  await unknown.step("fresh-exit", () => ++calls);
+  expect(calls).toBe(2);
+  expect(messages[0]).toContain("code=E_CONFIG_INVALID");
+  expect(messages[1]).toContain("code=unavailable");
+  expect(messages[3]).toContain("timed-out=yes code=unavailable");
+  expect(messages.at(-1)).toBe(
+    "start-operation=unavailable worktree=unavailable stage=fresh-exit status=end"
+  );
+  expect(messages.join("\n")).not.toContain("canary");
+});
+
+test("completed-job start diagnostics cannot replace an outcome when the logger throws", async () => {
+  const diagnostic = createCompletedJobFixtureStartDiagnostics({
+    operation: "up",
+    scope: "beta",
+    log: () => {
+      throw new Error("private-logger-canary");
+    },
+  });
+  const original = new Error("private-original-canary");
+  expect(await diagnostic.step("prior-state", () => 42)).toBe(42);
+  let observed: unknown;
+  try {
+    await diagnostic.step("cli-result", () => {
+      diagnostic.cliOutcome({
+        exitCode: 17,
+        timedOut: false,
+        stdout: "private-reply-canary",
+      });
+      throw original;
+    });
+  } catch (error) {
+    observed = error;
+  }
+  expect(observed).toBe(original);
+});
+
+test("completed-job CLI diagnostics treat an unreadable reply as unavailable", () => {
+  const messages: string[] = [];
+  const diagnostic = diagnostics(messages);
+  const result = { exitCode: 1, timedOut: false, stdout: "" };
+  Object.defineProperty(result, "stdout", {
+    get: () => {
+      throw new Error("private-unreadable-reply-canary");
+    },
+  });
+  expect(() => diagnostic.cliOutcome(result)).not.toThrow();
+  expect(messages).toEqual([
+    "start-operation=restart worktree=alpha stage=cli-result exit=unavailable timed-out=unavailable code=unavailable",
+  ]);
+});