e2e: invert the stale launchd repro to guard the fast, self-healing boot

The repro pinned the broken behavior (stale plist forces a >=14s dead wait). Flip it to guard the fix: the startup window must appear within a few seconds, the kickstart failure must be followed by a self-heal-or-fallback log line rather than a dead wait, boot-to-ready must stay under the fast budget and close to the clean control, and recovery must either repair launchd or fall back cleanly to managed spawn without attaching to the stale plist port. The E2E_RECORD recording now captures the fixed fast boot.

Rhys Sullivan committed 4 months ago

Commit 12e7d751 parent a1b7f3a3 files · +112 −52Browse files

Unified · Split

3 files

e2e/desktop-packaged/stale-launchd-registration.test.ts +114 −54
e2e/recordings/stale-launchd-fast-boot.mp4 +0 −0
e2e/recordings/stale-launchd-slow-boot.mp4 +0 −0

e2e/desktop-packaged/stale-launchd-registration.test.ts+114−54

 const execFileAsync = promisify(execFile);
 const SERVICE_LABEL = "sh.executor.daemon";
 const SCENARIO_NAME =
-  "Desktop packaged supervised attach: stale launchd registration pins the 15s dead boot wait";
+  "Desktop packaged supervised attach: stale launchd registration self-heals without a dead boot wait";
-const RECORDING_FILE = resolve("recordings/stale-launchd-slow-boot.mp4");
+const RECORDING_FILE = resolve("recordings/stale-launchd-fast-boot.mp4");
 const RECORDING_WIDTH = 1280;
 const RECORDING_HEIGHT = 720;
 const STALE_PLIST_PORT = 58_251;
 interface BootResult {
   readonly pageCdpMs: number;
+  readonly startupWindowMs: number;
   readonly sidecarReadyMs: number;
   readonly connectionKind: string;
   readonly origin: string;
   readonly manifestKind: string;
   readonly manifestPid: number;
-  readonly matchedLogLine: string | null;
+  readonly kickstartFailureLine: string | null;
+  readonly recoveryLogLine: string | null;
+  readonly launchdPrintSucceeded: boolean;
 }
 declare global {
   }
 };
+const launchctlPrintService = async (): Promise<string | null> => {
+  try {
+    const { stdout, stderr } = await execFileAsync("launchctl", ["print", serviceTarget()], {
+      encoding: "utf8",
+    });
+    return `${stdout}${stderr}`.trim();
+  } catch {
+    return null;
+  }
+};
 const captureLaunchdService = (): LaunchdServiceSnapshot | null => {
   if (process.platform !== "darwin") return null;
   const path = launchAgentPath();
   return JSON.parse(readFileSync(manifestPath, "utf8")) as ServerManifest;
 };
-const readKickstartFailureLine = (home: string): string | null => {
+interface StaleRecoveryLog {
+  readonly kickstartFailureLine: string | null;
+  readonly recoveryLogLine: string | null;
+}
+// The desktop's own classification line for a stale registration; electron-log
+// appends the launchctl error on the same line. Production launchctl fails the
+// kickstart with exit 113 ("Could not find service"); a tart guest's
+// `launchctl asuser` session fails it with exit 125 ("Domain does not support
+// specified action"). Same stale state, same self-heal branch, so match the
+// kickstart failure without pinning the environment-specific exit code.
+const isKickstartFailureLine = (line: string): boolean =>
+  line.includes("Failed to restart registered supervised service; reinstalling") &&
+  line.includes("launchctl kickstart failed");
+const isRecoveryLogLine = (line: string): boolean =>
+  line.includes("installed supervised service via bundled executor") ||
+  line.includes("Failed to install supervised service after registered service restart failure") ||
+  line.includes("using managed sidecar");
+const readStaleRecoveryLog = (home: string): StaleRecoveryLog => {
   const logPath = join(home, "Library", "Logs", "Executor", "main.log");
-  if (!existsSync(logPath)) return null;
+  if (!existsSync(logPath)) return { kickstartFailureLine: null, recoveryLogLine: null };
-  return (
+  const lines = readFileSync(logPath, "utf8").split("\n");
-    readFileSync(logPath, "utf8")
+  const kickstartIndex = lines.findIndex(isKickstartFailureLine);
-      .split("\n")
+  if (kickstartIndex < 0) return { kickstartFailureLine: null, recoveryLogLine: null };
-      .find(
+  const recoveryLogLine =
-        (line) =>
+    lines.slice(kickstartIndex + 1).find((line) => isRecoveryLogLine(line)) ?? null;
-          line.includes("launchctl kickstart failed (exit 113)") &&
+  return {
-          line.includes('Could not find service "sh.executor.daemon"'),
+    kickstartFailureLine: lines[kickstartIndex] ?? null,
-      ) ?? null
+    recoveryLogLine,
-  );
+  };
 };
-const waitForKickstartFailureLine = async (home: string): Promise<string> => {
+const waitForStaleRecoveryLog = async (home: string): Promise<StaleRecoveryLog> => {
   const deadline = Date.now() + 30_000;
   for (;;) {
-    const line = readKickstartFailureLine(home);
+    const lines = readStaleRecoveryLog(home);
-    if (line) return line;
+    if (lines.kickstartFailureLine && lines.recoveryLogLine) return lines;
     if (Date.now() >= deadline) {
       const logPath = join(home, "Library", "Logs", "Executor", "main.log");
       const tail = existsSync(logPath)
         ? readFileSync(logPath, "utf8").split("\n").slice(-20).join("\n")
         : "<main.log missing>";
-      throw new Error(`Timed out waiting for kickstart failure log line\n${tail}`);
+      throw new Error(`Timed out waiting for stale launchd recovery log lines\n${tail}`);
     }
     await new Promise((resolveWait) => setTimeout(resolveWait, 250));
   }
   readonly home: string;
   readonly env: NodeJS.ProcessEnv;
   readonly recorder: BootRecorder | null;
-  readonly expectKickstartFailure: boolean;
+  readonly expectStartupWindow: boolean;
+  readonly expectStaleRecoveryLog: boolean;
 }): Promise<BootResult> => {
   let app: PackagedApp | undefined;
   const startedAt = Date.now();
     const launched = await launchPackaged(input.env, input.recorder);
     app = launched.app;
     const page = app.cdp;
+    const startupWindowVisible = await page
+      .waitForText("Starting Executor", 5_000)
+      .then(() => true)
+      .catch(() => false);
+    const startupWindowMs = startupWindowVisible ? Date.now() - startedAt : launched.pageCdpMs;
+    expect(
+      !input.expectStartupWindow || startupWindowVisible,
+      "startup window shows before service recovery finishes when required",
+    ).toBe(true);
     await page.waitForText("Settings", 120_000);
     const sidecarReadyMs = Date.now() - startedAt;
     await input.recorder?.captureReadyFrame();
     } | null>("window.executor.getServerConnection()");
     expect(connection, "the app eventually exposes a server connection").not.toBeNull();
     const manifest = readServerManifest(input.home);
-    const matchedLogLine = input.expectKickstartFailure
+    const recoveryLog = input.expectStaleRecoveryLog
-      ? await waitForKickstartFailureLine(input.home)
+      ? await waitForStaleRecoveryLog(input.home)
-      : readKickstartFailureLine(input.home);
+      : readStaleRecoveryLog(input.home);
+    const launchdPrintSucceeded = (await launchctlPrintService()) !== null;
     return {
       pageCdpMs: launched.pageCdpMs,
+      startupWindowMs,
       sidecarReadyMs,
       connectionKind: connection!.kind,
       origin: connection!.origin,
       manifestKind: manifest.kind,
       manifestPid: manifest.pid,
-      matchedLogLine,
+      kickstartFailureLine: recoveryLog.kickstartFailureLine,
+      recoveryLogLine: recoveryLog.recoveryLogLine,
+      launchdPrintSucceeded,
     };
   } finally {
     await input.recorder?.stop();
   static create = (runDir: string): BootRecorder | null => {
     if (process.env.E2E_RECORD !== "1") return null;
-    const frameDir = join(runDir, "stale-launchd-slow-boot-frames");
+    const frameDir = join(runDir, "stale-launchd-fast-boot-frames");
     rmSync(frameDir, { recursive: true, force: true });
     mkdirSync(frameDir, { recursive: true });
     mkdirSync(dirname(RECORDING_FILE), { recursive: true });
   captureReadyFrame = async (): Promise<void> => {
     if (!this.enabled) return;
-    this.enqueueFrame("managed sidecar ready", this.page);
+    this.enqueueFrame("executor ready", this.page);
     await this.queue;
   };
       home: cleanHome,
       env: cleanBootEnv(cleanHome),
       recorder: null,
-      expectKickstartFailure: false,
+      expectStartupWindow: false,
+      expectStaleRecoveryLog: false,
     });
     writeStaleLaunchAgentPlist(staleHome);
       home: staleHome,
       env: packagedAppEnv(staleHome),
       recorder: staleRecorder,
-      expectKickstartFailure: true,
+      expectStartupWindow: true,
+      expectStaleRecoveryLog: true,
     });
     /*
-     * Regression pin for the current broken behavior:
+     * Regression guard for the production incident:
-     * a stale plist makes `service status` report registered even though launchd
+     * a stale plist makes `service status` report registered while launchd cannot
-     * cannot find the label. The packaged app logs the kickstart failure, then
+     * find the label. The app must show a window immediately, then repair or
-     * still pays the full 15s wait before falling back to managed-spawn.
+     * bypass that stale service without paying the old dead 15s wait.
-     *
-     * When the fix lands, invert the >=14s stale assertions. The desired
-     * behavior is a fast-fail to managed-spawn, close to the clean control.
      */
-    expect(stale.matchedLogLine, "stale boot logs the launchd kickstart failure").toContain(
+    expect(stale.kickstartFailureLine, "stale boot logs the launchd kickstart failure").toContain(
-      "launchctl kickstart failed (exit 113)",
+      "launchctl kickstart failed",
-    );
-    expect(stale.matchedLogLine, "stale boot says launchd cannot find the label").toContain(
-      'Could not find service "sh.executor.daemon"',
     );
+    expect(
+      stale.kickstartFailureLine,
+      "the failed kickstart is classified as a stale registration to repair",
+    ).toContain("Failed to restart registered supervised service; reinstalling");
+    expect(
+      stale.recoveryLogLine,
+      "kickstart failure is followed by self-heal or fallback logging",
+    ).not.toBeNull();
     expect(
       stale.pageCdpMs,
-      "window/CDP is not reachable until the dead wait is paid",
+      "the Electron page target is reachable before service recovery finishes",
-    ).toBeGreaterThanOrEqual(14_000);
+    ).toBeLessThan(3_000);
     expect(
-      stale.sidecarReadyMs,
+      stale.startupWindowMs,
-      "managed sidecar readiness is delayed by the dead wait",
+      "the startup window appears promptly in the stale launchd case",
-    ).toBeGreaterThanOrEqual(14_000);
+    ).toBeLessThan(3_000);
-    expect(stale.connectionKind, "the app eventually recovers through managed-spawn").toBe(
+    expect(new URL(stale.origin).port, "recovery must not attach to the stale plist port").not.toBe(
-      "desktop-sidecar",
+      String(STALE_PLIST_PORT),
     );
-    expect(
-      new URL(stale.origin).port,
-      "managed recovery must not be a launchd attach to the stale plist port",
-    ).not.toBe(String(STALE_PLIST_PORT));
     expect(
       clean.sidecarReadyMs,
       "the clean control skips supervision and boots quickly",
     ).toBeLessThan(10_000);
     expect(
       stale.sidecarReadyMs,
-      "the stale launchd path is dramatically slower than the clean control",
+      "stale launchd recovery stays within the fast boot budget",
-    ).toBeGreaterThan(clean.sidecarReadyMs + 5_000);
+    ).toBeLessThan(10_000);
+    expect(
+      stale.sidecarReadyMs,
+      "the stale launchd path stays close to the clean control",
+    ).toBeLessThan(clean.sidecarReadyMs + 7_500);
+    const repairedLaunchd = stale.launchdPrintSucceeded && stale.manifestKind === "cli-daemon";
+    const managedFallback =
+      !stale.launchdPrintSucceeded && stale.manifestKind === "desktop-sidecar";
+    expect(
+      repairedLaunchd || managedFallback,
+      "stale state is either repaired into launchd or cleanly falls back to managed spawn",
+    ).toBe(true);
     const recording = staleRecorder?.recordingStats();
     emitEvidence(
-      `[stale-launchd-repro] clean=${clean.sidecarReadyMs}ms stale=${stale.sidecarReadyMs}ms stalePageCdp=${stale.pageCdpMs}ms cleanOrigin=${clean.origin} staleOrigin=${stale.origin} staleConnectionKind=${stale.connectionKind} staleManifestKind=${stale.manifestKind} stalePid=${stale.manifestPid}`,
+      `[stale-launchd-repro] clean=${clean.sidecarReadyMs}ms stale=${stale.sidecarReadyMs}ms staleStartup=${stale.startupWindowMs}ms stalePageCdp=${stale.pageCdpMs}ms cleanOrigin=${clean.origin} staleOrigin=${stale.origin} staleConnectionKind=${stale.connectionKind} staleManifestKind=${stale.manifestKind} stalePid=${stale.manifestPid} launchdPrintAfterBoot=${stale.launchdPrintSucceeded}`,
     );
-    emitEvidence(`[stale-launchd-repro] matchedLogLine=${stale.matchedLogLine}`);
+    emitEvidence(`[stale-launchd-repro] kickstartFailureLine=${stale.kickstartFailureLine}`);
+    emitEvidence(`[stale-launchd-repro] recoveryLogLine=${stale.recoveryLogLine}`);
     if (recording) {
       emitEvidence(
         `[stale-launchd-repro] recording=${recording.path} frames=${recording.frames} size=${recording.size}`,

e2e/recordings/stale-launchd-fast-boot.mp4+0−0

Binary file not shown.

e2e/recordings/stale-launchd-slow-boot.mp4+0−0

Binary file not shown.