e439ee8 · c673daf · ec5e8b4 · ca5220e · 19b4e25
@@ -91,6 +91,13 @@
around it. None is advisory.
   line stays measured from `startedAt` and says `after the deploy
started`; a deploy no push asked for — a redeploy someone pressed, a
   boot reconcile — is worded the same way and never claims a push.
   Where that time went is in the log too, step by step
   (`apps/timing.ts`): a `timing:` line before the process starts splits
   the wait for a permit (`turn`), reading the manifest, the checkout, the
   data and the setup, and one after it answers says how long the process
   took and when it first said anything. A restart brings every app's
   production back before any preview, and a production deploy waiting
   for a permit goes ahead of the previews waiting for one.
5. **A private app answers only to someone the forge vouches for.** An app's
   `access` is `public` or `private` (defaulting to the repository's
   visibility), and it is set apart from the repository's own: the code can
@@ -17,6 +17,7 @@
import { forgeApiUrl } from "./token.ts";
import { isReservedAppEnvName } from "../core/app_env.ts";
import { err, ok, type Result } from "../kernel/result.ts";
import { stripForgeDirs } from "../runs/paths.ts";
import { seconds } from "./timing.ts";
export interface ProcessHandle {
  readonly pid: number;
@@ -314,6 +315,8 @@
export async function startProcess(
  const port = freePort();
  log(`$ ${manifest.run}  (PORT=${port})`);
  const spawnedAt = Date.now();
  let firstOutputAt: number | undefined;
  const proc = Bun.spawn(["/bin/sh", "-c", `exec ${manifest.run}`], {
    cwd: input.dir,
    env: appEnv({
@@ -335,6 +338,7 @@
export async function startProcess(
  // Output is pumped for the life of the process, not just the start.
  const recent: string[] = [];
  const remember = (raw: string): void => {
    firstOutputAt ??= Date.now();
    const line = stripForgeDirs([input.dir, input.dataDir], raw);
    recent.push(line);
    if (recent.length > 20) recent.shift();
@@ -381,6 +385,12 @@
export async function startProcess(
    });
  }
  log(`ready: ${input.url}`);
  // How the process's own share of the start divides: the time until it
  // first said anything (the runtime loading the app, the app's own boot
  // work) and the time until its health path answered.
  log(
    `timing: answered ${seconds(Date.now() - spawnedAt)} after the process was started${firstOutputAt === undefined ? "" : ` — its first output after ${seconds(firstOutputAt - spawnedAt)}`}`,
  );
  return ok({ handle, tested });
}
@@ -47,6 +47,7 @@
import { appendRunLog } from "../runs/log.ts";
import { primaryDomain } from "../core/domains.ts";
import { BUSY_WORDS, busyReason, type BusyReason } from "./busy.ts";
import { exportTree, readFileAt } from "./checkout.ts";
import { seconds, Stopwatch } from "./timing.ts";
import type { DomainResolver } from "./domains.ts";
import {
  appsRoot,
@@ -224,8 +225,7 @@
const PUSH_REASONS: readonly string[] = ["push", "opened", "merge"];
/** How long between two instants, in seconds to one decimal place: `3.4s`. */
function elapsedSeconds(fromIso: string, toIso: string): string {
  const ms = Math.max(0, Date.parse(toIso) - Date.parse(fromIso));
  return `${(ms / 1000).toFixed(1)}s`;
  return seconds(Date.parse(toIso) - Date.parse(fromIso));
}
/**
@@ -531,13 +531,20 @@
export class AppsRuntime {
        }),
      );
    });
    // Every app's production first, then every app's previews: deploys
    // take the gate in the order they are asked for, and the environment a
    // person actually visits must never come back behind someone's preview.
    const known = new Set<string>();
    const present: { record: AppRecord; repo: Repo }[] = [];
    for (const record of listApps(this.app.db)) {
      known.add(record.id);
      const repo = getRepoById(this.app.db, record.repoId);
      if (!repo) continue;
      await this.reconcileApp(record, repo, "boot");
      if (repo) present.push({ record, repo });
    }
    for (const { record, repo } of present)
      await this.reconcileApp(record, repo, "boot", "production");
    for (const { record, repo } of present)
      await this.reconcileApp(record, repo, "boot", "preview");
    this.pruneDirs(known);
    this.sweeper = setInterval(
      () => void this.sweep(),
@@ -591,8 +598,9 @@
export class AppsRuntime {
    })) {
      const env = previewEnv(pull.number);
      open.add(env);
      if (only === "production") continue;
      const head = await this.pullHead(dir, pull);
      if (head === undefined || only === "production") continue;
      if (head === undefined) continue;
      // A preview the forge built in an earlier life comes back asleep, not
      // deployed: nobody is looking at it this second, and the first who
      // does wakes it warm. Thirty previews starting at once is what a
@@ -859,10 +867,21 @@
export class AppsRuntime {
      `deploy ${state.env} of ${repo.ownerName}/${repo.name} at ${run.commitOid.slice(0, 7)} (${run.reason})`,
    );
    // The clock starts at the claim, the instant the log calls "the deploy
    // started"; the first lap is the wait for a permit. Production goes
    // ahead of previews waiting for one: it is the environment a person
    // actually visits.
    const clock = new Stopwatch();
    // A deploy that throws is a failed run, never a fallen forge: the chain
    // this runs on would otherwise reject unhandled and take the process.
    const outcome = await this.gate
      .run(() => this.bringUp(state, repo, run, write, abort.signal))
      .run(
        () => {
          clock.lap("turn");
          return this.bringUp(state, repo, run, write, abort.signal, clock);
        },
        { first: state.env === "production" },
      )
      .catch((error: unknown) => ({
        ok: false as const,
        error: `deploy failed: ${error instanceof Error ? error.message : String(error)}`,
@@ -994,6 +1013,7 @@
export class AppsRuntime {
    run: Run,
    write: (line: string) => void,
    signal: AbortSignal,
    clock: Stopwatch,
  ): Promise<
    | { ok: true; value: Live; tested: Promise<Result<void, string>> }
    | { ok: false; error: string }
@@ -1004,6 +1024,7 @@
export class AppsRuntime {
      readFileAt(bare, run.commitOid, "package.json"),
    ]);
    const manifest = parseManifest(forgeJson, packageJson);
    clock.lap("manifest");
    if (!manifest.ok) {
      return {
        ok: false,
@@ -1027,6 +1048,7 @@
export class AppsRuntime {
      const exported = await exportTree(bare, run.commitOid, dir);
      if (!exported.ok) return { ok: false, error: exported.error };
    }
    clock.lap(warm ? "checkout (warm)" : "checkout");
    const seeded = ensureEnvData(
      this.app.config.dataDir,
@@ -1043,6 +1065,7 @@
export class AppsRuntime {
      write(`data: ${seeded} from production`);
    else if (seeded === "empty" && state.env !== "production")
      write("data: starting empty");
    clock.lap("data");
    // The process's own credential; every way out of here without a
    // process to hold it revokes it.
@@ -1074,6 +1097,8 @@
export class AppsRuntime {
      log: write,
      warm,
    };
    clock.lap("setup");
    write(clock.line("starting the process"));
    const start = async (): ReturnType<typeof startProcess> => {
      try {
        return await startProcess({ ...startInput, signal });
@@ -0,0 +1,46 @@
/**
 * Where a deploy's time went, step by step, in the words its log uses.
 *
 * A deploy is a short line of steps — a turn at the gate, reading the
 * manifest, the checkout, the data, then the process — and the one number
 * the log used to print ("serving … 21.8s after the deploy started") cannot
 * say which of them held it. A stopwatch takes a lap at the end of each
 * step and prints them all on one `timing:` line, so a slow start is
 * attributed rather than guessed.
 */
/** Seconds to one decimal place: `3.4s`. */
export const seconds = (ms: number): string =>
  `${(Math.max(0, ms) / 1000).toFixed(1)}s`;
export class Stopwatch {
  private readonly from: number;
  private last: number;
  private readonly laps: { name: string; ms: number }[] = [];
  constructor(private readonly now: () => number = Date.now) {
    this.from = now();
    this.last = this.from;
  }
  /** End the step called `name`: it took the time since the previous lap. */
  lap(name: string): void {
    const at = this.now();
    this.laps.push({ name, ms: at - this.last });
    this.last = at;
  }
  /** Milliseconds since the stopwatch started. */
  elapsed(): number {
    return this.now() - this.from;
  }
  /**
   * `timing: <what> 0.4s after the deploy started — turn 0.0s · checkout
   * 0.3s · …`, every lap so far in the order it was taken.
   */
  line(what: string): string {
    const steps = this.laps.map((l) => `${l.name} ${seconds(l.ms)}`).join(" · ");
    return `timing: ${what} ${seconds(this.elapsed())} after the deploy started${steps === "" ? "" : ` — ${steps}`}`;
  }
}
@@ -87,16 +87,23 @@
export function trustedCaBundle(
 * FIFO on purpose: LIFO would be marginally better for cache locality and
 * catastrophically worse for fairness, which is the entire point — the
 * request that has waited longest goes next, so a burst degrades everyone's
 * latency a little rather than starving somebody forever.
 * latency a little rather than starving somebody forever. The one
 * exception is asked for by name (`first`), and is FIFO among itself.
 */
export class Gate {
  private active = 0;
  private readonly waiting: (() => void)[] = [];
  private readonly waiting: { wake: () => void; first: boolean }[] = [];
  private peak = 0;
  constructor(readonly limit: number) {}
  async acquire(): Promise<() => void> {
  /**
   * Take a permit, waiting for one if none is free. `first` waits ahead of
   * everyone who is not — still FIFO among its own kind, so it can jump a
   * queue but never starve another `first` — which is how a production
   * deploy gets the next permit while previews are waiting.
   */
  async acquire(options: { first?: boolean } = {}): Promise<() => void> {
    if (this.active < this.limit) {
      this.active++;
    } else {
@@ -105,7 +112,12 @@
export class Gate {
      // changes owner. Decrementing first would open a window in which a
      // caller arriving synchronously slips in ahead of the queue and the
      // limit is briefly exceeded — a semaphore that is only usually one.
      await new Promise<void>((resolve) => this.waiting.push(resolve));
      const first = options.first === true;
      await new Promise<void>((wake) => {
        const behind = first ? this.waiting.findIndex((w) => !w.first) : -1;
        if (behind === -1) this.waiting.push({ wake, first });
        else this.waiting.splice(behind, 0, { wake, first });
      });
    }
    if (this.active > this.peak) this.peak = this.active;
    let released = false;
@@ -115,14 +127,17 @@
export class Gate {
      if (released) return;
      released = true;
      const next = this.waiting.shift();
      if (next !== undefined) next();
      if (next !== undefined) next.wake();
      else this.active--;
    };
  }
  /** Run `work` holding one permit, released however it ends. */
  async run<T>(work: () => Promise<T>): Promise<T> {
    const release = await this.acquire();
  async run<T>(
    work: () => Promise<T>,
    options: { first?: boolean } = {},
  ): Promise<T> {
    const release = await this.acquire(options);
    try {
      return await work();
    } finally {
@@ -187,7 +187,7 @@
const elapsedTickJs = /* js */ `
`;
const logLineJs = /* js */ `
  var FORGE = /^(claude:|done:|failed:|paused|declined:|cloning |branch |forked |pushing |push refused|clone kept|nothing to propose|opened pull|updated pull|committed the|could not|checking out|deploy |data: |\\$ |session |the session|interrupted|passed in|install |test |start |ready |process )/;
  var FORGE = /^(claude:|done:|failed:|paused|declined:|cloning |branch |forked |pushing |push refused|clone kept|nothing to propose|opened pull|updated pull|committed the|could not|checking out|deploy |data: |\\$ |session |the session|interrupted|passed in|install |test |start |ready |process |timing: )/;
  function line(kind, speaker, fill) {
    var el = document.createElement('div');
    el.className = 'ln ln-' + kind;
@@ -114,7 +114,7 @@
export const costText = (usd: number): string => `$${usd.toFixed(2)}`;
export type LineKind = "tool" | "forge" | "say" | "you";
const FORGE_LINE =
  /^(claude:|done:|failed:|paused|declined:|cloning |branch |forked |pushing |push refused|clone kept|nothing to propose|opened pull|updated pull|committed the|could not|checking out|deploy |data: |\$ |session |the session|interrupted|passed in|install |test |start |ready |process )/;
  /^(claude:|done:|failed:|paused|declined:|cloning |branch |forked |pushing |push refused|clone kept|nothing to propose|opened pull|updated pull|committed the|could not|checking out|deploy |data: |\$ |session |the session|interrupted|passed in|install |test |start |ready |process |timing: )/;
export function lineKind(line: string): LineKind {
  if (line.startsWith("→ ")) return "tool";
@@ -837,6 +837,33 @@
describe("git process limits and timeouts", () => {
    expect(order).toEqual([1, 2, 3]);
  });
  test("a `first` waiter goes ahead of the others, and FIFO among its own kind", async () => {
    const gate = new Gate(1);
    const order: string[] = [];
    const held = await gate.acquire();
    const waiters = (
      [
        ["preview-1", false],
        ["production-a", true],
        ["preview-2", false],
        ["production-b", true],
      ] as const
    ).map(async ([name, first]) => {
      const release = await gate.acquire({ first });
      order.push(name);
      release();
    });
    held();
    await Promise.all(waiters);
    expect(order).toEqual([
      "production-a",
      "production-b",
      "preview-1",
      "preview-2",
    ]);
    expect(gate.stats().active).toBe(0);
  });
  test("concurrent git reads never exceed the process cap", async () => {
    const dataDir = await mkdtemp(join(tmpdir(), "forge-gate-"));
    try {
@@ -14,6 +14,7 @@
import { tmpdir } from "node:os";
import { join } from "node:path";
import { createApp, type App } from "../src/app.ts";
import { AppsRuntime } from "../src/apps/runtime.ts";
import { seconds, Stopwatch } from "../src/apps/timing.ts";
import { envDataDir, envDir, previewEnv } from "../src/apps/data.ts";
import { childEnv, runStep, startProcess } from "../src/apps/process.ts";
import type { AppManifest } from "../src/apps/manifest.ts";
@@ -528,7 +529,7 @@
describe("apps: production, previews, data, gates, crew", () => {
            {
              app: {
                run: "bun run src/server.ts",
                test: "sleep 3 && bun test",
                test: "sleep 8 && bun test",
                tty: "bun run src/tty.ts",
              },
            },
@@ -562,8 +563,9 @@
describe("apps: production, previews, data, gates, crew", () => {
      await Bun.sleep(50);
    }
    expect(answered).toBe(true);
    // It answered well inside the test step's own sleep.
    expect(Date.now() - start).toBeLessThan(3_000);
    // It answered well inside the test step's own sleep — with seconds to
    // spare, so a loaded machine cannot turn the margin into a race.
    expect(Date.now() - start).toBeLessThan(6_000);
    const status = runtime.envStatus(record, `pull-${opened.value.number}`);
    expect(status?.state).toBe("running");
@@ -2123,3 +2125,158 @@
Bun v1.3.14 (Linux x64 baseline)`;
    }
  }, 20_000);
});
// ---- the boot (issue #296) ----
/**
 * A restart brings production back first, and says where each deploy's
 * time went (issue #296): every app's production is reconciled before any
 * preview, and the log names the wait for a turn, the manifest, the
 * checkout, the data and the process's own start, each with its seconds.
 */
describe("the stopwatch a deploy's log reads from", () => {
  test("each lap is the time since the one before, in order, on one line", () => {
    let now = 1_000;
    const clock = new Stopwatch(() => now);
    now += 0; // no wait for a turn
    clock.lap("turn");
    now += 340;
    clock.lap("checkout");
    now += 20_060;
    clock.lap("data");
    expect(clock.elapsed()).toBe(20_400);
    expect(clock.line("starting the process")).toBe(
      "timing: starting the process 20.4s after the deploy started — turn 0.0s · checkout 0.3s · data 20.1s",
    );
  });
  test("seconds never go negative, and round to a tenth", () => {
    expect(seconds(-5)).toBe("0.0s");
    expect(seconds(1_250)).toBe("1.3s");
  });
});
describe("a restart brings every app's production up before any preview", () => {
  let dataDir: string;
  let app: App;
  let servers: Servers;
  let runtime: AppsRuntime;
  let alice: User;
  const DOMAIN = "boot.test";
  const repos: Repo[] = [];
  const previews: string[] = [];
  // No package.json, so a checkout is never warm and a preview is never
  // put back to sleep at boot: every environment deploys again.
  const FORGE_JSON = JSON.stringify({
    app: { run: "sh run.sh", install: "", health: "/", ready: 10 },
  });
  const RUN_SH = `exec bun -e "Bun.serve({port:Number(process.env.PORT),hostname:'127.0.0.1',fetch:()=>new Response('ok')})"\n`;
  const runtimeFor = (): AppsRuntime =>
    new AppsRuntime(app, {
      domain: DOMAIN,
      scheme: "http",
      publicPort: servers.port,
      forgeUrl: servers.url,
      // One permit: the order the gate hands them out is the order the
      // environments come up, and that order is the assertion.
      concurrency: 1,
    });
  async function settledAll(
    where: (run: Run) => boolean,
    count: number,
  ): Promise<Run[]> {
    const deadline = Date.now() + 60_000;
    while (Date.now() < deadline) {
      const runs = repos
        .flatMap((r) => listRuns(app.db, r.id, { kind: "deploy", limit: 50 }))
        .filter(where);
      if (
        runs.length >= count &&
        runs.every((r) => r.state === "ok" || r.state === "failed")
      )
        return runs;
      await Bun.sleep(50);
    }
    throw new Error("runs did not settle in time");
  }
  beforeAll(async () => {
    dataDir = await mkdtemp(join(tmpdir(), "forge-boot-"));
    app = createApp({ dataDir, port: 0 });
    servers = await serve(app);
    runtime = runtimeFor();
    await runtime.start();
    const created = await createUser(app.db, {
      username: "alice",
      email: "[email protected]",
      password: "a-good-passphrase",
      adminIfFirst: true,
    });
    if (!created.ok) throw new Error(created.error);
    alice = created.value;
    for (const name of ["first", "second"]) {
      const made = await createRepo(app, alice, {
        name,
        visibility: "public",
      });
      if (!made.ok) throw new Error(String(made.error));
      const repo = made.value;
      repos.push(repo);
      const committed = await commitToBranch(app, alice, repo, {
        message: "An app",
        files: [
          { path: "forge.json", content: FORGE_JSON },
          { path: "run.sh", content: RUN_SH },
        ],
      });
      if (!committed.ok) throw new Error(JSON.stringify(committed.error));
      const enabled = enableApp(app, alice, repo, {});
      if (!enabled.ok) throw new Error(String(enabled.error));
      const branch = await commitToBranch(app, alice, repo, {
        branch: "note",
        base: repo.defaultBranch,
        message: "A note",
        files: [{ path: "NOTE.md", content: "hi\n" }],
      });
      if (!branch.ok) throw new Error(JSON.stringify(branch.error));
      const opened = await openPull(app, alice, repo, {
        title: "A note",
        baseBranch: repo.defaultBranch,
        headBranch: "note",
      });
      if (!opened.ok) throw new Error(String(opened.error));
      previews.push(`pull-${opened.value.number}`);
    }
    await settledAll(() => true, 4);
  }, 90_000);
  afterAll(async () => {
    await runtime.stop();
    servers.stop();
    app.close();
    await rm(dataDir, { recursive: true, force: true });
  });
  test("both productions answer before either preview, and the log says where the time went", async () => {
    await runtime.stop();
    runtime = runtimeFor();
    await runtime.start();
    const boot = await settledAll((r) => r.reason === "boot", 4);
    expect(boot.every((r) => r.state === "ok")).toBe(true);
    const order = [...boot]
      .sort((a, b) => Date.parse(a.servingAt!) - Date.parse(b.servingAt!))
      .map((r) => (r.env === "production" ? "production" : "preview"));
    expect(order).toEqual(["production", "production", "preview", "preview"]);
    const production = boot.find((r) => r.env === "production")!;
    const text = readRunLog(dataDir, production.id).lines.join("\n");
    expect(text).toMatch(
      /timing: starting the process \d+\.\ds after the deploy started — turn \d+\.\ds · manifest \d+\.\ds · checkout \d+\.\ds · data \d+\.\ds · setup \d+\.\ds/,
    );
    expect(text).toMatch(
      /timing: answered \d+\.\ds after the process was started/,
    );
  }, 90_000);
});
@@ -428,25 +428,10 @@
describe("checks", () => {
  });
  test("when a slot frees, the newest of several queued checks runs first", async () => {
    // A slow check on its own environment holds the only slot.
    const held = await commitToBranch(app, alice, repo, {
      branch: "order-hold",
      message: "Hold the slot",
      files: [
        { path: "forge.json", content: checkJson("sleep 2 && test -f OK.md") },
      ],
    });
    if (!held.ok) throw new Error(JSON.stringify(held.error));
    const holder = await checks.request(
      repo,
      "order-hold",
      held.value.commitOid,
      "push",
    );
    expect(holder).toBeDefined();
    // Three more, on three environments so none supersedes another, queue
    // behind it — oldest requested first.
    // Three checks, on three environments so none supersedes another. Their
    // commits are written before the slot is taken: written after, on a
    // loaded machine they can outlast the holder, and the oldest then finds
    // the slot free instead of queueing.
    const oldest = await commitToBranch(app, alice, repo, {
      branch: "order-a",
      message: "A",
@@ -466,6 +451,24 @@
describe("checks", () => {
    });
    if (!newest.ok) throw new Error(JSON.stringify(newest.error));
    // A slow check on its own environment holds the only slot, and the
    // three queue behind it — oldest requested first.
    const held = await commitToBranch(app, alice, repo, {
      branch: "order-hold",
      message: "Hold the slot",
      files: [
        { path: "forge.json", content: checkJson("sleep 2 && test -f OK.md") },
      ],
    });
    if (!held.ok) throw new Error(JSON.stringify(held.error));
    const holder = await checks.request(
      repo,
      "order-hold",
      held.value.commitOid,
      "push",
    );
    expect(holder).toBeDefined();
    const oldestRun = await checks.request(
      repo,
      "order-a",
		@@ -91,6 +91,13 @@ around it. None is advisory.
91	91	line stays measured from `startedAt` and says `after the deploy
92	92	started`; a deploy no push asked for — a redeploy someone pressed, a
93	93	boot reconcile — is worded the same way and never claims a push.
	94	Where that time went is in the log too, step by step
	95	(`apps/timing.ts`): a `timing:` line before the process starts splits
	96	the wait for a permit (`turn`), reading the manifest, the checkout, the
	97	data and the setup, and one after it answers says how long the process
	98	took and when it first said anything. A restart brings every app's
	99	production back before any preview, and a production deploy waiting
	100	for a permit goes ahead of the previews waiting for one.
94	101	5. A private app answers only to someone the forge vouches for. An app's
95	102	`access` is `public` or `private` (defaulting to the repository's
96	103	visibility), and it is set apart from the repository's own: the code can
		@@ -17,6 +17,7 @@ import { forgeApiUrl } from "./token.ts";
17	17	import { isReservedAppEnvName } from "../core/app_env.ts";
18	18	import { err, ok, type Result } from "../kernel/result.ts";
19	19	import { stripForgeDirs } from "../runs/paths.ts";
	20	import { seconds } from "./timing.ts";
20	21
21	22	export interface ProcessHandle {
22	23	readonly pid: number;
		@@ -314,6 +315,8 @@ export async function startProcess(
314	315
315	316	const port = freePort();
316	317	log(`$ ${manifest.run} (PORT=${port})`);
	318	const spawnedAt = Date.now();
	319	let firstOutputAt: number \| undefined;
317	320	const proc = Bun.spawn(["/bin/sh", "-c", `exec ${manifest.run}`], {
318	321	cwd: input.dir,
319	322	env: appEnv({
		@@ -335,6 +338,7 @@ export async function startProcess(
335	338	// Output is pumped for the life of the process, not just the start.
336	339	const recent: string[] = [];
337	340	const remember = (raw: string): void => {
	341	firstOutputAt ??= Date.now();
338	342	const line = stripForgeDirs([input.dir, input.dataDir], raw);
339	343	recent.push(line);
340	344	if (recent.length > 20) recent.shift();
		@@ -381,6 +385,12 @@ export async function startProcess(
381	385	});
382	386	}
383	387	log(`ready: ${input.url}`);
	388	// How the process's own share of the start divides: the time until it
	389	// first said anything (the runtime loading the app, the app's own boot
	390	// work) and the time until its health path answered.
	391	log(
	392	`timing: answered ${seconds(Date.now() - spawnedAt)} after the process was started${firstOutputAt === undefined ? "" : ` — its first output after ${seconds(firstOutputAt - spawnedAt)}`}`,
	393	);
384	394	return ok({ handle, tested });
385	395	}
386	396
		@@ -47,6 +47,7 @@ import { appendRunLog } from "../runs/log.ts";
47	47	import { primaryDomain } from "../core/domains.ts";
48	48	import { BUSY_WORDS, busyReason, type BusyReason } from "./busy.ts";
49	49	import { exportTree, readFileAt } from "./checkout.ts";
	50	import { seconds, Stopwatch } from "./timing.ts";
50	51	import type { DomainResolver } from "./domains.ts";
51	52	import {
52	53	appsRoot,
		@@ -224,8 +225,7 @@ const PUSH_REASONS: readonly string[] = ["push", "opened", "merge"];
224	225
225	226	/** How long between two instants, in seconds to one decimal place: `3.4s`. */
226	227	function elapsedSeconds(fromIso: string, toIso: string): string {
227		const ms = Math.max(0, Date.parse(toIso) - Date.parse(fromIso));
228		return `${(ms / 1000).toFixed(1)}s`;
	228	return seconds(Date.parse(toIso) - Date.parse(fromIso));
229	229	}
230	230
231	231	/**
		@@ -531,13 +531,20 @@ export class AppsRuntime {
531	531	}),
532	532	);
533	533	});
	534	// Every app's production first, then every app's previews: deploys
	535	// take the gate in the order they are asked for, and the environment a
	536	// person actually visits must never come back behind someone's preview.
534	537	const known = new Set<string>();
	538	const present: { record: AppRecord; repo: Repo }[] = [];
535	539	for (const record of listApps(this.app.db)) {
536	540	known.add(record.id);
537	541	const repo = getRepoById(this.app.db, record.repoId);
538		if (!repo) continue;
539		await this.reconcileApp(record, repo, "boot");
	542	if (repo) present.push({ record, repo });
540	543	}
	544	for (const { record, repo } of present)
	545	await this.reconcileApp(record, repo, "boot", "production");
	546	for (const { record, repo } of present)
	547	await this.reconcileApp(record, repo, "boot", "preview");
541	548	this.pruneDirs(known);
542	549	this.sweeper = setInterval(
543	550	() => void this.sweep(),
		@@ -591,8 +598,9 @@ export class AppsRuntime {
591	598	})) {
592	599	const env = previewEnv(pull.number);
593	600	open.add(env);
	601	if (only === "production") continue;
594	602	const head = await this.pullHead(dir, pull);
595		if (head === undefined \|\| only === "production") continue;
	603	if (head === undefined) continue;
596	604	// A preview the forge built in an earlier life comes back asleep, not
597	605	// deployed: nobody is looking at it this second, and the first who
598	606	// does wakes it warm. Thirty previews starting at once is what a
		@@ -859,10 +867,21 @@ export class AppsRuntime {
859	867	`deploy ${state.env} of ${repo.ownerName}/${repo.name} at ${run.commitOid.slice(0, 7)} (${run.reason})`,
860	868	);
861	869
	870	// The clock starts at the claim, the instant the log calls "the deploy
	871	// started"; the first lap is the wait for a permit. Production goes
	872	// ahead of previews waiting for one: it is the environment a person
	873	// actually visits.
	874	const clock = new Stopwatch();
862	875	// A deploy that throws is a failed run, never a fallen forge: the chain
863	876	// this runs on would otherwise reject unhandled and take the process.
864	877	const outcome = await this.gate
865		.run(() => this.bringUp(state, repo, run, write, abort.signal))
	878	.run(
	879	() => {
	880	clock.lap("turn");
	881	return this.bringUp(state, repo, run, write, abort.signal, clock);
	882	},
	883	{ first: state.env === "production" },
	884	)
866	885	.catch((error: unknown) => ({
867	886	ok: false as const,
868	887	error: `deploy failed: ${error instanceof Error ? error.message : String(error)}`,
		@@ -994,6 +1013,7 @@ export class AppsRuntime {
994	1013	run: Run,
995	1014	write: (line: string) => void,
996	1015	signal: AbortSignal,
	1016	clock: Stopwatch,
997	1017	): Promise<
998	1018	\| { ok: true; value: Live; tested: Promise<Result<void, string>> }
999	1019	\| { ok: false; error: string }
		@@ -1004,6 +1024,7 @@ export class AppsRuntime {
1004	1024	readFileAt(bare, run.commitOid, "package.json"),
1005	1025	]);
1006	1026	const manifest = parseManifest(forgeJson, packageJson);
	1027	clock.lap("manifest");
1007	1028	if (!manifest.ok) {
1008	1029	return {
1009	1030	ok: false,
		@@ -1027,6 +1048,7 @@ export class AppsRuntime {
1027	1048	const exported = await exportTree(bare, run.commitOid, dir);
1028	1049	if (!exported.ok) return { ok: false, error: exported.error };
1029	1050	}
	1051	clock.lap(warm ? "checkout (warm)" : "checkout");
1030	1052
1031	1053	const seeded = ensureEnvData(
1032	1054	this.app.config.dataDir,
		@@ -1043,6 +1065,7 @@ export class AppsRuntime {
1043	1065	write(`data: ${seeded} from production`);
1044	1066	else if (seeded === "empty" && state.env !== "production")
1045	1067	write("data: starting empty");
	1068	clock.lap("data");
1046	1069
1047	1070	// The process's own credential; every way out of here without a
1048	1071	// process to hold it revokes it.
		@@ -1074,6 +1097,8 @@ export class AppsRuntime {
1074	1097	log: write,
1075	1098	warm,
1076	1099	};
	1100	clock.lap("setup");
	1101	write(clock.line("starting the process"));
1077	1102	const start = async (): ReturnType<typeof startProcess> => {
1078	1103	try {
1079	1104	return await startProcess({ ...startInput, signal });
		@@ -0,0 +1,46 @@
	1	/**
	2	* Where a deploy's time went, step by step, in the words its log uses.
	3	*
	4	* A deploy is a short line of steps — a turn at the gate, reading the
	5	* manifest, the checkout, the data, then the process — and the one number
	6	* the log used to print ("serving … 21.8s after the deploy started") cannot
	7	* say which of them held it. A stopwatch takes a lap at the end of each
	8	* step and prints them all on one `timing:` line, so a slow start is
	9	* attributed rather than guessed.
	10	*/
	11
	12	/** Seconds to one decimal place: `3.4s`. */
	13	export const seconds = (ms: number): string =>
	14	`${(Math.max(0, ms) / 1000).toFixed(1)}s`;
	15
	16	export class Stopwatch {
	17	private readonly from: number;
	18	private last: number;
	19	private readonly laps: { name: string; ms: number }[] = [];
	20
	21	constructor(private readonly now: () => number = Date.now) {
	22	this.from = now();
	23	this.last = this.from;
	24	}
	25
	26	/** End the step called `name`: it took the time since the previous lap. */
	27	lap(name: string): void {
	28	const at = this.now();
	29	this.laps.push({ name, ms: at - this.last });
	30	this.last = at;
	31	}
	32
	33	/** Milliseconds since the stopwatch started. */
	34	elapsed(): number {
	35	return this.now() - this.from;
	36	}
	37
	38	/**
	39	* `timing: <what> 0.4s after the deploy started — turn 0.0s · checkout
	40	* 0.3s · …`, every lap so far in the order it was taken.
	41	*/
	42	line(what: string): string {
	43	const steps = this.laps.map((l) => `${l.name} ${seconds(l.ms)}`).join(" · ");
	44	return `timing: ${what} ${seconds(this.elapsed())} after the deploy started${steps === "" ? "" : ` — ${steps}`}`;
	45	}
	46	}
		@@ -87,16 +87,23 @@ export function trustedCaBundle(
87	87	* FIFO on purpose: LIFO would be marginally better for cache locality and
88	88	* catastrophically worse for fairness, which is the entire point — the
89	89	* request that has waited longest goes next, so a burst degrades everyone's
90		* latency a little rather than starving somebody forever.
	90	* latency a little rather than starving somebody forever. The one
	91	* exception is asked for by name (`first`), and is FIFO among itself.
91	92	*/
92	93	export class Gate {
93	94	private active = 0;
94		private readonly waiting: (() => void)[] = [];
	95	private readonly waiting: { wake: () => void; first: boolean }[] = [];
95	96	private peak = 0;
96	97
97	98	constructor(readonly limit: number) {}
98	99
99		async acquire(): Promise<() => void> {
	100	/**
	101	* Take a permit, waiting for one if none is free. `first` waits ahead of
	102	* everyone who is not — still FIFO among its own kind, so it can jump a
	103	* queue but never starve another `first` — which is how a production
	104	* deploy gets the next permit while previews are waiting.
	105	*/
	106	async acquire(options: { first?: boolean } = {}): Promise<() => void> {
100	107	if (this.active < this.limit) {
101	108	this.active++;
102	109	} else {
		@@ -105,7 +112,12 @@ export class Gate {
105	112	// changes owner. Decrementing first would open a window in which a
106	113	// caller arriving synchronously slips in ahead of the queue and the
107	114	// limit is briefly exceeded — a semaphore that is only usually one.
108		await new Promise<void>((resolve) => this.waiting.push(resolve));
	115	const first = options.first === true;
	116	await new Promise<void>((wake) => {
	117	const behind = first ? this.waiting.findIndex((w) => !w.first) : -1;
	118	if (behind === -1) this.waiting.push({ wake, first });
	119	else this.waiting.splice(behind, 0, { wake, first });
	120	});
109	121	}
110	122	if (this.active > this.peak) this.peak = this.active;
111	123	let released = false;
		@@ -115,14 +127,17 @@ export class Gate {
115	127	if (released) return;
116	128	released = true;
117	129	const next = this.waiting.shift();
118		if (next !== undefined) next();
	130	if (next !== undefined) next.wake();
119	131	else this.active--;
120	132	};
121	133	}
122	134
123	135	/** Run `work` holding one permit, released however it ends. */
124		async run<T>(work: () => Promise<T>): Promise<T> {
125		const release = await this.acquire();
	136	async run<T>(
	137	work: () => Promise<T>,
	138	options: { first?: boolean } = {},
	139	): Promise<T> {
	140	const release = await this.acquire(options);
126	141	try {
127	142	return await work();
128	143	} finally {
		@@ -187,7 +187,7 @@ const elapsedTickJs = /* js */ `
187	187	`;
188	188
189	189	const logLineJs = /* js */ `
190		var FORGE = /^(claude:\|done:\|failed:\|paused\|declined:\|cloning \|branch \|forked \|pushing \|push refused\|clone kept\|nothing to propose\|opened pull\|updated pull\|committed the\|could not\|checking out\|deploy \|data: \|\\$ \|session \|the session\|interrupted\|passed in\|install \|test \|start \|ready \|process )/;
	190	var FORGE = /^(claude:\|done:\|failed:\|paused\|declined:\|cloning \|branch \|forked \|pushing \|push refused\|clone kept\|nothing to propose\|opened pull\|updated pull\|committed the\|could not\|checking out\|deploy \|data: \|\\$ \|session \|the session\|interrupted\|passed in\|install \|test \|start \|ready \|process \|timing: )/;
191	191	function line(kind, speaker, fill) {
192	192	var el = document.createElement('div');
193	193	el.className = 'ln ln-' + kind;
		@@ -114,7 +114,7 @@ export const costText = (usd: number): string => `$${usd.toFixed(2)}`;
114	114	export type LineKind = "tool" \| "forge" \| "say" \| "you";
115	115
116	116	const FORGE_LINE =
117		/^(claude:\|done:\|failed:\|paused\|declined:\|cloning \|branch \|forked \|pushing \|push refused\|clone kept\|nothing to propose\|opened pull\|updated pull\|committed the\|could not\|checking out\|deploy \|data: \|\$ \|session \|the session\|interrupted\|passed in\|install \|test \|start \|ready \|process )/;
	117	/^(claude:\|done:\|failed:\|paused\|declined:\|cloning \|branch \|forked \|pushing \|push refused\|clone kept\|nothing to propose\|opened pull\|updated pull\|committed the\|could not\|checking out\|deploy \|data: \|\$ \|session \|the session\|interrupted\|passed in\|install \|test \|start \|ready \|process \|timing: )/;
118	118
119	119	export function lineKind(line: string): LineKind {
120	120	if (line.startsWith("→ ")) return "tool";
		@@ -837,6 +837,33 @@ describe("git process limits and timeouts", () => {
837	837	expect(order).toEqual([1, 2, 3]);
838	838	});
839	839
	840	test("a `first` waiter goes ahead of the others, and FIFO among its own kind", async () => {
	841	const gate = new Gate(1);
	842	const order: string[] = [];
	843	const held = await gate.acquire();
	844	const waiters = (
	845	[
	846	["preview-1", false],
	847	["production-a", true],
	848	["preview-2", false],
	849	["production-b", true],
	850	] as const
	851	).map(async ([name, first]) => {
	852	const release = await gate.acquire({ first });
	853	order.push(name);
	854	release();
	855	});
	856	held();
	857	await Promise.all(waiters);
	858	expect(order).toEqual([
	859	"production-a",
	860	"production-b",
	861	"preview-1",
	862	"preview-2",
	863	]);
	864	expect(gate.stats().active).toBe(0);
	865	});
	866
840	867	test("concurrent git reads never exceed the process cap", async () => {
841	868	const dataDir = await mkdtemp(join(tmpdir(), "forge-gate-"));
842	869	try {
		@@ -14,6 +14,7 @@ import { tmpdir } from "node:os";
14	14	import { join } from "node:path";
15	15	import { createApp, type App } from "../src/app.ts";
16	16	import { AppsRuntime } from "../src/apps/runtime.ts";
	17	import { seconds, Stopwatch } from "../src/apps/timing.ts";
17	18	import { envDataDir, envDir, previewEnv } from "../src/apps/data.ts";
18	19	import { childEnv, runStep, startProcess } from "../src/apps/process.ts";
19	20	import type { AppManifest } from "../src/apps/manifest.ts";
		@@ -528,7 +529,7 @@ describe("apps: production, previews, data, gates, crew", () => {
528	529	{
529	530	app: {
530	531	run: "bun run src/server.ts",
531		test: "sleep 3 && bun test",
	532	test: "sleep 8 && bun test",
532	533	tty: "bun run src/tty.ts",
533	534	},
534	535	},
		@@ -562,8 +563,9 @@ describe("apps: production, previews, data, gates, crew", () => {
562	563	await Bun.sleep(50);
563	564	}
564	565	expect(answered).toBe(true);
565		// It answered well inside the test step's own sleep.
566		expect(Date.now() - start).toBeLessThan(3_000);
	566	// It answered well inside the test step's own sleep — with seconds to
	567	// spare, so a loaded machine cannot turn the margin into a race.
	568	expect(Date.now() - start).toBeLessThan(6_000);
567	569
568	570	const status = runtime.envStatus(record, `pull-${opened.value.number}`);
569	571	expect(status?.state).toBe("running");
		@@ -2123,3 +2125,158 @@ Bun v1.3.14 (Linux x64 baseline)`;
2123	2125	}
2124	2126	}, 20_000);
2125	2127	});
	2128
	2129	// ---- the boot (issue #296) ----
	2130	/**
	2131	* A restart brings production back first, and says where each deploy's
	2132	* time went (issue #296): every app's production is reconciled before any
	2133	* preview, and the log names the wait for a turn, the manifest, the
	2134	* checkout, the data and the process's own start, each with its seconds.
	2135	*/
	2136	describe("the stopwatch a deploy's log reads from", () => {
	2137	test("each lap is the time since the one before, in order, on one line", () => {
	2138	let now = 1_000;
	2139	const clock = new Stopwatch(() => now);
	2140	now += 0; // no wait for a turn
	2141	clock.lap("turn");
	2142	now += 340;
	2143	clock.lap("checkout");
	2144	now += 20_060;
	2145	clock.lap("data");
	2146	expect(clock.elapsed()).toBe(20_400);
	2147	expect(clock.line("starting the process")).toBe(
	2148	"timing: starting the process 20.4s after the deploy started — turn 0.0s · checkout 0.3s · data 20.1s",
	2149	);
	2150	});
	2151
	2152	test("seconds never go negative, and round to a tenth", () => {
	2153	expect(seconds(-5)).toBe("0.0s");
	2154	expect(seconds(1_250)).toBe("1.3s");
	2155	});
	2156	});
	2157
	2158	describe("a restart brings every app's production up before any preview", () => {
	2159	let dataDir: string;
	2160	let app: App;
	2161	let servers: Servers;
	2162	let runtime: AppsRuntime;
	2163	let alice: User;
	2164	const DOMAIN = "boot.test";
	2165	const repos: Repo[] = [];
	2166	const previews: string[] = [];
	2167
	2168	// No package.json, so a checkout is never warm and a preview is never
	2169	// put back to sleep at boot: every environment deploys again.
	2170	const FORGE_JSON = JSON.stringify({
	2171	app: { run: "sh run.sh", install: "", health: "/", ready: 10 },
	2172	});
	2173	const RUN_SH = `exec bun -e "Bun.serve({port:Number(process.env.PORT),hostname:'127.0.0.1',fetch:()=>new Response('ok')})"\n`;
	2174
	2175	const runtimeFor = (): AppsRuntime =>
	2176	new AppsRuntime(app, {
	2177	domain: DOMAIN,
	2178	scheme: "http",
	2179	publicPort: servers.port,
	2180	forgeUrl: servers.url,
	2181	// One permit: the order the gate hands them out is the order the
	2182	// environments come up, and that order is the assertion.
	2183	concurrency: 1,
	2184	});
	2185
	2186	async function settledAll(
	2187	where: (run: Run) => boolean,
	2188	count: number,
	2189	): Promise<Run[]> {
	2190	const deadline = Date.now() + 60_000;
	2191	while (Date.now() < deadline) {
	2192	const runs = repos
	2193	.flatMap((r) => listRuns(app.db, r.id, { kind: "deploy", limit: 50 }))
	2194	.filter(where);
	2195	if (
	2196	runs.length >= count &&
	2197	runs.every((r) => r.state === "ok" \|\| r.state === "failed")
	2198	)
	2199	return runs;
	2200	await Bun.sleep(50);
	2201	}
	2202	throw new Error("runs did not settle in time");
	2203	}
	2204
	2205	beforeAll(async () => {
	2206	dataDir = await mkdtemp(join(tmpdir(), "forge-boot-"));
	2207	app = createApp({ dataDir, port: 0 });
	2208	servers = await serve(app);
	2209	runtime = runtimeFor();
	2210	await runtime.start();
	2211	const created = await createUser(app.db, {
	2212	username: "alice",
	2213	email: "[email protected]",
	2214	password: "a-good-passphrase",
	2215	adminIfFirst: true,
	2216	});
	2217	if (!created.ok) throw new Error(created.error);
	2218	alice = created.value;
	2219	for (const name of ["first", "second"]) {
	2220	const made = await createRepo(app, alice, {
	2221	name,
	2222	visibility: "public",
	2223	});
	2224	if (!made.ok) throw new Error(String(made.error));
	2225	const repo = made.value;
	2226	repos.push(repo);
	2227	const committed = await commitToBranch(app, alice, repo, {
	2228	message: "An app",
	2229	files: [
	2230	{ path: "forge.json", content: FORGE_JSON },
	2231	{ path: "run.sh", content: RUN_SH },
	2232	],
	2233	});
	2234	if (!committed.ok) throw new Error(JSON.stringify(committed.error));
	2235	const enabled = enableApp(app, alice, repo, {});
	2236	if (!enabled.ok) throw new Error(String(enabled.error));
	2237	const branch = await commitToBranch(app, alice, repo, {
	2238	branch: "note",
	2239	base: repo.defaultBranch,
	2240	message: "A note",
	2241	files: [{ path: "NOTE.md", content: "hi\n" }],
	2242	});
	2243	if (!branch.ok) throw new Error(JSON.stringify(branch.error));
	2244	const opened = await openPull(app, alice, repo, {
	2245	title: "A note",
	2246	baseBranch: repo.defaultBranch,
	2247	headBranch: "note",
	2248	});
	2249	if (!opened.ok) throw new Error(String(opened.error));
	2250	previews.push(`pull-${opened.value.number}`);
	2251	}
	2252	await settledAll(() => true, 4);
	2253	}, 90_000);
	2254
	2255	afterAll(async () => {
	2256	await runtime.stop();
	2257	servers.stop();
	2258	app.close();
	2259	await rm(dataDir, { recursive: true, force: true });
	2260	});
	2261
	2262	test("both productions answer before either preview, and the log says where the time went", async () => {
	2263	await runtime.stop();
	2264	runtime = runtimeFor();
	2265	await runtime.start();
	2266	const boot = await settledAll((r) => r.reason === "boot", 4);
	2267	expect(boot.every((r) => r.state === "ok")).toBe(true);
	2268	const order = [...boot]
	2269	.sort((a, b) => Date.parse(a.servingAt!) - Date.parse(b.servingAt!))
	2270	.map((r) => (r.env === "production" ? "production" : "preview"));
	2271	expect(order).toEqual(["production", "production", "preview", "preview"]);
	2272
	2273	const production = boot.find((r) => r.env === "production")!;
	2274	const text = readRunLog(dataDir, production.id).lines.join("\n");
	2275	expect(text).toMatch(
	2276	/timing: starting the process \d+\.\ds after the deploy started — turn \d+\.\ds · manifest \d+\.\ds · checkout \d+\.\ds · data \d+\.\ds · setup \d+\.\ds/,
	2277	);
	2278	expect(text).toMatch(
	2279	/timing: answered \d+\.\ds after the process was started/,
	2280	);
	2281	}, 90_000);
	2282	});
		@@ -428,25 +428,10 @@ describe("checks", () => {
428	428	});
429	429
430	430	test("when a slot frees, the newest of several queued checks runs first", async () => {
431		// A slow check on its own environment holds the only slot.
432		const held = await commitToBranch(app, alice, repo, {
433		branch: "order-hold",
434		message: "Hold the slot",
435		files: [
436		{ path: "forge.json", content: checkJson("sleep 2 && test -f OK.md") },
437		],
438		});
439		if (!held.ok) throw new Error(JSON.stringify(held.error));
440		const holder = await checks.request(
441		repo,
442		"order-hold",
443		held.value.commitOid,
444		"push",
445		);
446		expect(holder).toBeDefined();
447
448		// Three more, on three environments so none supersedes another, queue
449		// behind it — oldest requested first.
	431	// Three checks, on three environments so none supersedes another. Their
	432	// commits are written before the slot is taken: written after, on a
	433	// loaded machine they can outlast the holder, and the oldest then finds
	434	// the slot free instead of queueing.
450	435	const oldest = await commitToBranch(app, alice, repo, {
451	436	branch: "order-a",
452	437	message: "A",
		@@ -466,6 +451,24 @@ describe("checks", () => {
466	451	});
467	452	if (!newest.ok) throw new Error(JSON.stringify(newest.error));
468	453
	454	// A slow check on its own environment holds the only slot, and the
	455	// three queue behind it — oldest requested first.
	456	const held = await commitToBranch(app, alice, repo, {
	457	branch: "order-hold",
	458	message: "Hold the slot",
	459	files: [
	460	{ path: "forge.json", content: checkJson("sleep 2 && test -f OK.md") },
	461	],
	462	});
	463	if (!held.ok) throw new Error(JSON.stringify(held.error));
	464	const holder = await checks.request(
	465	repo,
	466	"order-hold",
	467	held.value.commitOid,
	468	"push",
	469	);
	470	expect(holder).toBeDefined();
	471
469	472	const oldestRun = await checks.request(
470	473	repo,
471	474	"order-a",