Recovery: roll back an install that does not come up, and a hand-back runbook

apps/server/src/factory/installScripts.test.ts

@@ -1,17 +1,19 @@
-// @effect-diagnostics nodeBuiltinImport:off
+// @effect-diagnostics nodeBuiltinImport:off globalTimers:off
 import * as NodeChildProcess from "node:child_process";
 import * as NodeFS from "node:fs";
+import * as NodeNet from "node:net";
 import * as NodeOS from "node:os";
 import * as NodePath from "node:path";
 
-import { afterAll, beforeAll, describe, expect, it } from "vite-plus/test";
+import { afterAll, afterEach, beforeAll, describe, expect, it } from "vite-plus/test";
 
 const scripts = NodePath.resolve(import.meta.dirname, "../../../../factory/scripts");
 const label = "io.github.rawphp.t3fac";
 const uid = process.getuid?.() ?? 0;
 
 const v1 = "0.0.1-test+fac.aaaaaaa";
 const v2 = "0.0.2-test+fac.bbbbbbb";
+const v3 = "0.0.3-test+fac.ccccccc";
 
 let tmp: string;
 let home: string;
@@ -21,22 +23,42 @@ let launchctlLoaded: string;
 let launchctlDrain: string;
 const archives: Record<string, string> = {};
 
+// One listener shared by every test: the scripts check this port instead of 3876.
+let listener: NodeNet.Server;
+let healthPort = 0;
+
+beforeAll(async () => {
+  listener = NodeNet.createServer((socket) => socket.destroy());
+  await new Promise<void>((resolve) => listener.listen(0, "127.0.0.1", resolve));
+  healthPort = (listener.address() as NodeNet.AddressInfo).port;
+});
+
+afterAll(async () => {
+  await new Promise<void>((resolve) => listener.close(() => resolve()));
+});
+
 const plistPath = () => NodePath.join(home, "Library/LaunchAgents", `${label}.plist`);
 const root = () => NodePath.join(home, ".local/share/t3fac");
+const logPath = () => NodePath.join(home, "Library/Logs/t3fac/t3fac.log");
 
 const run = (script: string, ...args: Array<string>) => runWith({}, script, ...args);
 
+const scriptEnv = (extraEnv: Record<string, string>) => ({
+  HOME: home,
+  PATH: `${bin}:/usr/bin:/bin`,
+  LAUNCHCTL_LOG: launchctlLog,
+  LAUNCHCTL_LOADED: launchctlLoaded,
+  LAUNCHCTL_DRAIN: launchctlDrain,
+  T3FAC_PORT: String(healthPort),
+  T3FAC_HEALTH_WAIT: "2",
+  LAUNCHCTL_HEALTHY: `versions/${v1} versions/${v2} versions/${v3}`,
+  ...extraEnv,
+});
+
 const runWith = (extraEnv: Record<string, string>, script: string, ...args: Array<string>) => {
   NodeFS.writeFileSync(launchctlLog, "");
   const result = NodeChildProcess.spawnSync("bash", [NodePath.join(scripts, script), ...args], {
-    env: {
-      HOME: home,
-      PATH: `${bin}:/usr/bin:/bin`,
-      LAUNCHCTL_LOG: launchctlLog,
-      LAUNCHCTL_LOADED: launchctlLoaded,
-      LAUNCHCTL_DRAIN: launchctlDrain,
-      ...extraEnv,
-    },
+    env: scriptEnv(extraEnv),
     encoding: "utf8",
   });
   const calls = NodeFS.readFileSync(launchctlLog, "utf8").split("\n").filter(Boolean);
@@ -71,7 +93,11 @@ const makeArchive = (version: string, options: { binary?: boolean; label?: strin
 
 // A little launchd-like: bootout leaves the job loaded for two more `print` polls (or
 // LAUNCHCTL_BOOTOUT_DRAIN), and bootstrap fails with EIO while it is still loaded (or when
-// LAUNCHCTL_BOOTSTRAP_FAIL is set).
+// LAUNCHCTL_BOOTSTRAP_FAIL is set). A bootstrap writes "factory started" to the log when
+// LAUNCHCTL_HEALTHY (space-separated `current` targets) lists the version `current` points at
+// (LAUNCHCTL_HEALTHY_LINE writes another line instead, LAUNCHCTL_HEALTHY_DELAY writes it that many
+// seconds later, as a server still starting would); LAUNCHCTL_TRUNCATE_LOG empties the log first,
+// as a rotation would.
 const setupSandbox = () => {
   tmp = NodeFS.realpathSync(NodeFS.mkdtempSync(NodePath.join(NodeOS.tmpdir(), "t3fac-install-")));
   home = NodePath.join(tmp, "home");
@@ -101,7 +127,22 @@ const setupSandbox = () => {
       '      echo "Bootstrap failed: 5: Input/output error" >&2',
       "      exit 5",
       "    fi",
-      '    touch "$LAUNCHCTL_LOADED" ;;',
+      '    touch "$LAUNCHCTL_LOADED"',
+      '    if [ -n "${LAUNCHCTL_HEALTHY+x}" ]; then',
+      '      target=$(readlink "$HOME/.local/share/t3fac/current")',
+      "      for entry in $LAUNCHCTL_HEALTHY; do",
+      '        if [ "$entry" = "$target" ]; then',
+      '          mkdir -p "$HOME/Library/Logs/t3fac"',
+      '          if [ -n "$LAUNCHCTL_TRUNCATE_LOG" ]; then : > "$HOME/Library/Logs/t3fac/t3fac.log"; fi',
+      '          line="${LAUNCHCTL_HEALTHY_LINE:-factory started}"',
+      '          if [ -n "$LAUNCHCTL_HEALTHY_DELAY" ]; then',
+      '            (sleep "$LAUNCHCTL_HEALTHY_DELAY"; echo "$line" >> "$HOME/Library/Logs/t3fac/t3fac.log") > /dev/null 2>&1 &',
+      "          else",
+      '            echo "$line" >> "$HOME/Library/Logs/t3fac/t3fac.log"',
+      "          fi",
+      "        fi",
+      "      done",
+      "    fi ;;",
       '  bootout) echo "${LAUNCHCTL_BOOTOUT_DRAIN:-2}" > "$LAUNCHCTL_DRAIN" ;;',
       "esac",
       "exit 0",
@@ -295,6 +336,33 @@ describe("rollback.sh when the previous version is gone from disk", () => {
   });
 });
 
+describe("rollback.sh when current is missing", () => {
+  beforeAll(() => {
+    setupInstalledSandbox();
+  });
+
+  afterAll(() => {
+    NodeFS.rmSync(tmp, { recursive: true, force: true });
+  });
+
+  it("still restores previous", () => {
+    NodeFS.rmSync(NodePath.join(root(), "current"));
+    const result = run("rollback.sh");
+    expect(result.status).toBe(0);
+    expect(result.output).toContain(`rolled back to ${v1}`);
+    expect(NodeFS.readlinkSync(NodePath.join(root(), "current"))).toBe(`versions/${v1}`);
+    expect(NodeFS.existsSync(NodePath.join(root(), "previous"))).toBe(false);
+  });
+
+  it("names only the restored version when its health check fails", () => {
+    setupInstalledSandbox();
+    NodeFS.rmSync(NodePath.join(root(), "current"));
+    const result = runWith({ LAUNCHCTL_HEALTHY: "" }, "rollback.sh");
+    expect(result.status).toBe(1);
+    expect(result.stderr).toContain(`rollback to ${v1} failed its health check`);
+  });
+});
+
 describe("install.sh and rollback.sh when the job never unloads", () => {
   const stuck = { LAUNCHCTL_BOOTOUT_DRAIN: "1000", T3FAC_UNLOAD_WAIT: "1" };
 
@@ -320,6 +388,181 @@ describe("install.sh and rollback.sh when the job never unloads", () => {
   });
 });
 
+describe("install.sh and rollback.sh health check", () => {
+  const installV1 = () => {
+    setupSandbox();
+    for (const version of [v1, v2, v3]) archives[version] = makeArchive(version);
+    expect(run("install.sh", archives[v1]!).status).toBe(0);
+  };
+
+  const installV1ThenV2 = () => {
+    installV1();
+    expect(run("install.sh", archives[v2]!).status).toBe(0);
+  };
+
+  const seedLog = (content: string) => {
+    NodeFS.mkdirSync(NodePath.dirname(logPath()), { recursive: true });
+    NodeFS.writeFileSync(logPath(), content);
+  };
+
+  const link = (name: string) => NodeFS.readlinkSync(NodePath.join(root(), name));
+  const bootstraps = (calls: Array<string>) => calls.filter((c) => c.startsWith("bootstrap"));
+
+  afterEach(() => {
+    NodeFS.rmSync(tmp, { recursive: true, force: true });
+  });
+
+  it("keeps a healthy install", () => {
+    installV1();
+    const result = run("install.sh", archives[v2]!);
+    expect(result.status).toBe(0);
+    expect(result.output).toContain(`installed ${v2}`);
+    expect(link("current")).toBe(`versions/${v2}`);
+    expect(link("previous")).toBe(`versions/${v1}`);
+    expect(bootstraps(result.calls)).toHaveLength(1);
+  });
+
+  it("rolls back an install whose server never logs that it started", () => {
+    installV1();
+    const lines = Array.from({ length: 60 }, (_, i) => `boot line ${i + 1}`);
+    seedLog(lines.join("\n") + "\n");
+    const result = runWith({ LAUNCHCTL_HEALTHY: `versions/${v1}` }, "install.sh", archives[v2]!);
+    expect(result.status).toBe(1);
+    expect(result.stderr).toContain(
+      `install of ${v2} failed its health check; rolled back to ${v1}`,
+    );
+    // The last 50 lines: line 11 is the oldest shown, line 10 is cut.
+    expect(result.stderr).toContain("boot line 60");
+    expect(result.stderr).toContain("boot line 11\n");
+    expect(result.stderr).not.toContain("boot line 10\n");
+    expect(link("current")).toBe(`versions/${v1}`);
+    expect(NodeFS.existsSync(NodePath.join(root(), "previous"))).toBe(false);
+    expect(bootstraps(result.calls)).toHaveLength(2);
+  });
+
+  it("keeps an install whose server logs that it started only after the first check", () => {
+    installV1();
+    const result = runWith(
+      { LAUNCHCTL_HEALTHY_DELAY: "1", T3FAC_HEALTH_WAIT: "3" },
+      "install.sh",
+      archives[v2]!,
+    );
+    expect(result.status).toBe(0);
+    expect(link("current")).toBe(`versions/${v2}`);
+    expect(bootstraps(result.calls)).toHaveLength(1);
+  });
+
+  it("keeps an install whose port accepts connections only after the first check", async () => {
+    installV1();
+    const late = NodeNet.createServer((socket) => socket.destroy());
+    await new Promise<void>((resolve) => late.listen(0, "127.0.0.1", resolve));
+    const port = (late.address() as NodeNet.AddressInfo).port;
+    await new Promise<void>((resolve) => late.close(() => resolve()));
+    NodeFS.writeFileSync(launchctlLog, "");
+    const child = NodeChildProcess.spawn(
+      "bash",
+      [NodePath.join(scripts, "install.sh"), archives[v2]!],
+      {
+        env: scriptEnv({ T3FAC_PORT: String(port), T3FAC_HEALTH_WAIT: "5" }),
+        stdio: "ignore",
+      },
+    );
+    const exited = new Promise<number | null>((resolve) => child.on("exit", resolve));
+    // Open the port a poll after the bootstrap, so the first check finds it closed and only a
+    // later one can pass.
+    while (!NodeFS.readFileSync(launchctlLog, "utf8").includes("bootstrap")) {
+      await new Promise((resolve) => setTimeout(resolve, 20));
+    }
+    await new Promise((resolve) => setTimeout(resolve, 600));
+    await new Promise<void>((resolve) => late.listen(port, "127.0.0.1", resolve));
+    try {
+      expect(await exited).toBe(0);
+    } finally {
+      await new Promise<void>((resolve) => late.close(() => resolve()));
+    }
+    expect(link("current")).toBe(`versions/${v2}`);
+  });
+
+  it("keeps an install whose server logs that it has no factory config", () => {
+    installV1();
+    const result = runWith(
+      { LAUNCHCTL_HEALTHY_LINE: "no factory config" },
+      "install.sh",
+      archives[v2]!,
+    );
+    expect(result.status).toBe(0);
+    expect(link("current")).toBe(`versions/${v2}`);
+    expect(bootstraps(result.calls)).toHaveLength(1);
+  });
+
+  it("rolls back an install whose port does not accept connections", async () => {
+    installV1();
+    const closed = NodeNet.createServer();
+    await new Promise<void>((resolve) => closed.listen(0, "127.0.0.1", resolve));
+    const port = (closed.address() as NodeNet.AddressInfo).port;
+    await new Promise<void>((resolve) => closed.close(() => resolve()));
+    // The port stays closed for the rollback's own check too, so that one fails as well.
+    const result = runWith({ T3FAC_PORT: String(port) }, "install.sh", archives[v2]!);
+    expect(result.status).toBe(1);
+    expect(result.stderr).toContain(`port ${port} does not accept connections`);
+    expect(result.stderr).toContain(`install of ${v2} failed its health check; rollback`);
+    expect(link("current")).toBe(`versions/${v1}`);
+    expect(bootstraps(result.calls)).toHaveLength(2);
+  });
+
+  it("does not count a factory started line that was there before the restart", () => {
+    installV1();
+    seedLog("factory started\n");
+    const result = runWith({ LAUNCHCTL_HEALTHY: `versions/${v1}` }, "install.sh", archives[v2]!);
+    expect(result.status).toBe(1);
+    expect(result.stderr).toContain(
+      `install of ${v2} failed its health check; rolled back to ${v1}`,
+    );
+    expect(link("current")).toBe(`versions/${v1}`);
+  });
+
+  it("counts a line written after the log was truncated to a size below the noted one", () => {
+    installV1();
+    seedLog("older log content\n".repeat(10));
+    const result = runWith({ LAUNCHCTL_TRUNCATE_LOG: "1" }, "install.sh", archives[v2]!);
+    expect(result.status).toBe(0);
+    expect(link("current")).toBe(`versions/${v2}`);
+  });
+
+  it("exits 1 and says so when an unhealthy first install has nothing to roll back to", () => {
+    setupSandbox();
+    archives[v1] = makeArchive(v1);
+    const result = runWith({ LAUNCHCTL_HEALTHY: "" }, "install.sh", archives[v1]!);
+    expect(result.status).toBe(1);
+    expect(result.stderr).toContain(
+      `install of ${v1} failed its health check; no earlier version to roll back to`,
+    );
+    expect(link("current")).toBe(`versions/${v1}`);
+    expect(NodeFS.existsSync(NodePath.join(root(), "previous"))).toBe(false);
+    expect(bootstraps(result.calls)).toHaveLength(1);
+  });
+
+  it("rollback.sh exits 1 naming both versions when the restored version is unhealthy too", () => {
+    installV1ThenV2();
+    const result = runWith({ LAUNCHCTL_HEALTHY: "" }, "rollback.sh");
+    expect(result.status).toBe(1);
+    expect(result.stderr).toContain(`rollback to ${v1} from ${v2} failed its health check`);
+    expect(link("current")).toBe(`versions/${v1}`);
+    expect(NodeFS.existsSync(NodePath.join(root(), "previous"))).toBe(false);
+  });
+
+  it("install.sh reports when the rollback fails its health check as well", () => {
+    installV1();
+    const result = runWith({ LAUNCHCTL_HEALTHY: "" }, "install.sh", archives[v3]!);
+    expect(result.status).toBe(1);
+    expect(result.stderr).toContain(`rollback to ${v1} from ${v3} failed its health check`);
+    expect(result.stderr).toContain(
+      `install of ${v3} failed its health check; rollback to ${v1} failed too`,
+    );
+    expect(link("current")).toBe(`versions/${v1}`);
+  });
+});
+
 describe("build.sh --print-version", () => {
   let repo: string;
 

factory/README.md

@@ -30,10 +30,46 @@ Build, install and roll back the darwin-arm64 binary (LaunchAgent `io.github.raw
 
 ```sh
 factory/scripts/build.sh                      # clean tree only: build, smoke test, then -> release/t3fac-<version>-darwin-arm64.tar.gz
-factory/scripts/install.sh <archive>          # unpack, point `current` at it, restart the job
-factory/scripts/rollback.sh                   # point `current` at the previous version, restart the job
+factory/scripts/install.sh <archive>          # unpack, point `current` at it, restart the job, wait for it to come up, roll back if it does not
+factory/scripts/rollback.sh                   # point `current` at the previous version, restart the job and check it comes up
 ```
 
+## Recovery
+
+`install.sh` and `rollback.sh` check that the job came up. After the restart they wait up to `T3FAC_HEALTH_WAIT` seconds (default 90) for the server to accept connections on port 3876 and for a `factory started` or `no factory config` line to be written to `~/Library/Logs/t3fac/t3fac.log` after the restart. Lines from before the restart do not count. If either is missing, the script prints the last 50 log lines. A failed `install.sh` then runs `rollback.sh` and exits 1 with `install of <version> failed its health check; rolled back to <previous>`. With no earlier version it exits 1 and says so.
+
+### Telling the fork is down
+
+```sh
+launchctl print gui/$(id -u)/io.github.rawphp.t3fac
+tail -n 50 ~/Library/Logs/t3fac/t3fac.log
+```
+
+A non-zero exit from `launchctl print`, or output with no `pid` line, means the job is not running. A `last exit code` other than 0 together with a changing `runs` count is a crash loop. In the log, look for `factory started` or `no factory config` after the last start. Neither means the server never got as far as the factory, or the factory found an error in `~/.config/t3fac/factory/config.yml`: it logs each error as `<file>: <field>: <message>` and stays idle. A config error fails the health check too, so `install.sh` rolls back a good archive until the config is fixed.
+
+### Rolling back by hand
+
+```sh
+factory/scripts/rollback.sh
+```
+
+It points `current` at `previous`, restarts the job, removes `previous` and runs the same health check on the restored version. It exits 1 with `rollback to <previous> from <current> failed its health check` when that check fails too. When there is no `previous`, install an older archive from `release/` with `factory/scripts/install.sh <archive>`.
+
+### Handing this repo back to the Rust factory
+
+Do this when every installed version has a bug that stops the fork from building its own fix. It is the reverse of the #21 switch.
+
+1. Check that no run of either factory holds an issue for this repo: `softfac runs list` for the Rust factory, `softfac runs list --data-dir ~/.config/t3fac/factory` for the fork, and `gh issue list --repo original-solutions/t3code-factory --label factory:building` and `--label factory:triage` both come back empty.
+2. Remove `original-solutions/t3code-factory` from `repos` in `~/.config/t3fac/factory/config.yml`. When it is the only repo there, move `config.yml` aside instead (`mv ~/.config/t3fac/factory/config.yml ~/.config/t3fac/factory/config.yml.off`): an empty `repos` is a config error, which fails every later health check, while a missing config logs `no factory config` and passes.
+3. Add it to `repos` in `~/.config/softfac/config.yml` with `repo`, `path` and `user`.
+4. Restart each factory so it rereads its config.
+
+The Rust factory then builds the fix.
+
+### Moving it back
+
+Once `install.sh` has installed a fixed archive and it passed its health check, repeat the steps above in reverse: check that no run holds an issue, remove the repo from `~/.config/softfac/config.yml`, add it to `repos` in `~/.config/t3fac/factory/config.yml` (or move `config.yml.off` back to `config.yml`), and restart each factory.
+
 ## Syncing with upstream
 
 `factory/scripts/sync.sh` merges upstream's newest `v*-nightly.*` tag into `main` through a pull request. `.github/workflows/factory-sync.yml` runs it daily at 03:17 UTC and on `workflow_dispatch`, as two jobs:

factory/launchd/io.github.rawphp.t3fac.plist

@@ -1,6 +1,7 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
 <plist version="1.0">
+<!-- The --port and log path below are repeated in factory/scripts/lib/t3fac.sh for the health check. -->
 <dict>
 	<key>Label</key>
 	<string>io.github.rawphp.t3fac</string>