57efed7 · 80188ea · 8a005a4
@@ -18,6 +18,10 @@
green changes, and nothing waits on a person. [`docs/STUDIO.md`](docs/STUDIO.md)
git underneath is one click away — the switch in the top bar, or `?mode=dev` on
any URL — and it is the rest of this page.
Slow app? Its response's `Server-Timing` keeps the app's entries and adds the
forge's `forge-route`, `forge-wake`, `forge-upstream` and `forge-rewrite`
(milliseconds only; see `docs/APPS.md`).
A forge this one spawned (hosted) runs the apps it was given too: its `bakery`
answers at `bakery--<child>--<this forge's host>`, in this forge's lanes, on the
child's own data, and `/forges` says how many are running and why any is not. Each row also ends with the first step its person has not taken (`not claimed yet`, `no everyday account yet`, `no tell yet`, or `going: last tell <time>`; `has not reported yet` before the child's first beat), read from the child's heartbeat; the terminal's forges screen and the MCP `forges` tool (`nextStep`) say the same.
@@ -254,6 +254,20 @@
read the repository sees only the time, never a sha. The read is the `serving`
Server-Timing phase. The prefix was already the forge's, so an app's own
`/__forge/` path is not reachable.
**Reading a slow app's Server-Timing.** A response the proxy relays keeps the
app's own entries (`db`, `app`, …) and gains the forge's, each `forge-` named
and in milliseconds only: `forge-route` (finding the target and its grant),
`forge-wake` (waiting for a sleeping or starting environment; 0 when none),
`forge-upstream` (until the app's headers) and `forge-rewrite` (pill injection,
when it ran). Big `forge-wake` is a cold start, big `forge-upstream` is the
app; if all are small, the time went before the request reached the forge. The
"app stopped answering" page carries `route`, `wake` and `upstream` too; the
forge's own `/__forge/*` pages and the WebSocket upgrade name no forge- phases.
A refused answer (sign in, not found, not running) names none either: the wake
runs before the door is asked, so its time would tell a caller who may not read
the app whether it was asleep. The proxy has one writer for these
(`withPhases` over `notePhase`), which appends to the app's header.
**Tell the crew from the pill.** Signed in as someone who may direct the crew,
the panel also offers *Tell the crew* (`/__forge/crew` adds a `tell` link, only
for them; signed out there is no action). It opens the forge's own
@@ -47,7 +47,7 @@
import { clientBucket } from "../http/peer.ts";
import { DOOR_PULL_LIMIT, doorPage, type DoorPullLine } from "./door.ts";
import { checkWord } from "./check_word.ts";
import { openPulls } from "./door_pulls.ts";
import { takePhases, timePhase } from "../core/route_timing.ts";
import { notePhase, startedAt, takePhases, timePhase } from "../core/route_timing.ts";
import { readServing } from "./serving.ts";
import { notFound, securityFloor } from "../http/respond.ts";
import { appMeasure } from "./measure.ts";
@@ -390,17 +390,27 @@
function sealedPull(runtime: AppsRuntime, target: AppTarget): Issue | undefined
  return pull?.sealed === true ? pull : undefined;
}
/** The response with the phases the request named, as `Server-Timing`. */
/**
 * The response with the phases the request named, as `Server-Timing`: the
 * one writer for the proxy, on the forge's own `/__forge/*` pages and on a
 * relayed app answer alike. It appends, so an app's own entries stay first;
 * on an app answer the forge's phases are `forge-` named (`relayPhase`) so
 * none can collide with the app's or with the server's `route`.
 */
function withPhases(request: Request, res: Response): Response {
  const phases = takePhases(request);
  if (phases.length > 0)
    res.headers.set(
      "server-timing",
      phases.map((p) => `${p.name};dur=${p.ms.toFixed(1)}`).join(", "),
    );
  if (phases.length === 0) return res;
  const mine = phases.map((p) => `${p.name};dur=${p.ms.toFixed(1)}`).join(", ");
  const theirs = res.headers.get("server-timing");
  res.headers.set("server-timing", theirs === null || theirs === "" ? mine : `${theirs}, ${mine}`);
  return res;
}
/** Name one of the forge's phases of relaying an app answer. Durations only. */
function relayPhase(request: Request, name: "route" | "wake" | "upstream" | "rewrite", ms: number): void {
  notePhase(request, `forge-${name}`, ms);
}
/**
 * What the pill says: the app, the environment and, for a preview, the pull
 * and its title. The title goes only to a viewer who may read the pull.
@@ -1023,15 +1033,24 @@
export async function proxyApp(
  }
  // An environment asleep wakes for the request that wants it, and the
  // request waits the second that takes rather than seeing a closed door.
  if (runtime.envStatus(target.app, target.env)?.state === "asleep")
  let wakeMs = 0;
  if (runtime.envStatus(target.app, target.env)?.state === "asleep") {
    const woke = performance.now();
    await runtime.wake(target.app, target.env);
    wakeMs = performance.now() - woke;
  }
  const admitted = admit(runtime, request, target);
  // A refused answer names no phases: wake runs before `admit`, so its time
  // would tell a caller who may not read the app whether it was asleep.
  if (!admitted.ok)
    return url.pathname.startsWith("/__forge/")
      ? securityFloor(admitted.error)
      : admitted.error;
  const { status, port, grant: vouched } = admitted.value;
  runtime.touch(target.app, target.env);
  const began = performance.now();
  relayPhase(request, "route", Math.max(0, began - (startedAt(request) ?? began) - wakeMs));
  relayPhase(request, "wake", wakeMs);
  const upstream = new URL(url);
  upstream.protocol = "http:";
@@ -1082,6 +1101,7 @@
export async function proxyApp(
    portAnswered();
  };
  let response: Response;
  const sent = performance.now();
  try {
    response = await fetch(upstream, {
      method: request.method,
@@ -1097,8 +1117,10 @@
export async function proxyApp(
    } as RequestInit);
      
        junipercrew
        12d ago
        outdated
      
      The unavailable() return above carries no forge phases; add them or document.
    
  } catch {
    answered();
    return unavailable(runtime, target, status, "the app stopped answering");
    relayPhase(request, "upstream", performance.now() - sent);
    return withPhases(request, unavailable(runtime, target, status, "the app stopped answering"));
  }
  relayPhase(request, "upstream", performance.now() - sent);
  const out = new Headers(response.headers);
  for (const name of HOP_BY_HOP) out.delete(name);
  // Which app answered: a probe from outside (`spawn/reach.ts`) tells this
@@ -1130,6 +1152,7 @@
export async function proxyApp(
    (rewritable(out, response.status) ||
      (!out.has("content-length") && htmlAnswer(out, response.status)))
  ) {
    const rewriting = performance.now();
    let bytes: Uint8Array<ArrayBuffer>;
    try {
      if (out.has("content-length")) bytes = new Uint8Array(await response.arrayBuffer());
@@ -1138,15 +1161,18 @@
export async function proxyApp(
        // past that it goes on as it came, what was read first.
        const read = await readPage(response.body);
        if (!read.whole)
          return new Response(read.rest, {
            status: response.status,
            statusText: response.statusText,
            headers: out,
          });
          return withPhases(
            request,
            new Response(read.rest, {
              status: response.status,
              statusText: response.statusText,
              headers: out,
            }),
          );
        bytes = read.bytes;
      }
    } catch {
      return unavailable(runtime, target, status, "the app stopped answering");
      return withPhases(request, unavailable(runtime, target, status, "the app stopped answering"));
    }
    // A signed-in person's page load gets the panel's one-use proof, and so
    // is theirs alone: never stored or shared. A page the app's own script
@@ -1178,19 +1204,23 @@
export async function proxyApp(
    out.set("content-length", String(sent.length));
    out.delete("etag");
    out.delete("content-md5");
    return new Response(sent, {
      status: response.status,
      statusText: response.statusText,
      headers: out,
    });
    relayPhase(request, "rewrite", performance.now() - rewriting);
    return withPhases(
      request,
      new Response(sent, {
        status: response.status,
        statusText: response.statusText,
        headers: out,
      }),
    );
  }
  return new Response(
    body,
    {
  return withPhases(
    request,
    new Response(body, {
      status: response.status,
      statusText: response.statusText,
      headers: out,
    },
    }),
  );
}
@@ -296,6 +296,11 @@
export function noteStart(request: Request, at: number): void {
  startTimes.set(request, at);
}
/** When the server took the request (`noteStart`), if it did. */
export function startedAt(request: Request): number | undefined {
  return startTimes.get(request);
}
const framed = new WeakSet<Request>();
/**
@@ -0,0 +1,206 @@
/**
 * A proxied answer keeps the app's Server-Timing and appends the forge's own
 * phases, `forge-` named: where a slow request spent its time.
 */
import { afterAll, beforeAll, describe, expect, test } from "bun:test";
import { mkdtemp, rm } from "node:fs/promises";
import { tmpdir } from "node:os";
import { join } from "node:path";
import { createApp, type App } from "../src/app.ts";
import { AppsRuntime, type EnvStatus } from "../src/apps/runtime.ts";
import { newApp } from "../src/actions/apps.ts";
import { commitToBranch } from "../src/actions/repos.ts";
import type { Repo } from "../src/core/repos.ts";
import { createUser, type User } from "../src/core/users.ts";
import { serve, type Servers } from "../src/http/server.ts";
import { deploySettled } from "./helpers/apps-forge.ts";
const DOMAIN = "apps.test";
const SLOW = `const server = Bun.serve({
  port: Number(process.env.PORT),
  hostname: "127.0.0.1",
  async fetch(request) {
    if (new URL(request.url).pathname === "/healthz") {
      await Bun.sleep(300);
      return new Response("ok", { headers: { "server-timing": "db;dur=0.1, app;dur=1.1" } });
    }
    return new Response("<html><body><h1>hello</h1></body></html>", { headers: { "content-type": "text/html" } });
  },
});
`;
const dur = (header: string, name: string): number | undefined => {
  const m = new RegExp(`(?:^|, )${name};dur=([0-9.]+)`).exec(header);
  return m ? Number(m[1]) : undefined;
};
describe("a proxied answer's Server-Timing", () => {
  let dataDir: string;
  let app: App;
  let servers: Servers;
  let runtime: AppsRuntime;
  let alice: User;
  let repo: Repo;
  const viaHost = (path = "/") =>
    fetch(`${servers.url}${path}`, { headers: { host: `hello.${DOMAIN}`, accept: "text/html" }, redirect: "manual" });
  beforeAll(async () => {
    dataDir = await mkdtemp(join(tmpdir(), "forge-ptiming-"));
    app = createApp({ dataDir, port: 0 });
    servers = await serve(app);
    runtime = new AppsRuntime(app, {
      domain: DOMAIN,
      scheme: "http",
      publicPort: servers.port,
      forgeUrl: servers.url,
    });
    await runtime.start();
    const created = await createUser(app.db, { origin: "seed", trusted: true,
      username: "alice",
      email: "[email protected]",
      password: "a-good-passphrase",
      adminIfFirst: true,
    });
    if (!created.ok) throw new Error(created.error);
    alice = created.value;
    const made = await newApp(app, alice, { name: "hello", description: "d", visibility: "public" });
    if (!made.ok) throw new Error(String(made.error));
    repo = made.value.repo;
    const first = await deploySettled(app, repo.id, (r) => r.env === "production");
    expect(first.state).toBe("ok");
    const committed = await commitToBranch(app, alice, repo, {
      branch: repo.defaultBranch,
      base: repo.defaultBranch,
      message: "Slow healthz",
      files: [
        { path: "src/slow.ts", content: SLOW },
        {
          path: "forge.json",
          content: JSON.stringify({ app: { run: "bun run src/slow.ts", health: "/" } }),
        },
      ],
    });
    expect(committed.ok).toBe(true);
    const second = await deploySettled(app, repo.id, (r) => r.env === "production" && r.id !== first.id);
    expect(second.state).toBe("ok");
  }, 120_000);
  afterAll(async () => {
    await runtime.stop();
    servers.stop();
    app.close();
    await rm(dataDir, { recursive: true, force: true });
  });
  test("a slow upstream shows in forge-upstream, beside the app's own entries", async () => {
    const res = await viaHost("/healthz");
    expect(res.status).toBe(200);
    const header = res.headers.get("server-timing")!;
    expect(header.startsWith("db;dur=0.1, app;dur=1.1, ")).toBe(true);
    expect(dur(header, "forge-upstream")!).toBeGreaterThanOrEqual(250);
    expect(dur(header, "forge-route")).toBeDefined();
    expect(dur(header, "forge-wake")).toBe(0);
      
        junipercrew
        12d ago
        outdated
      
      Flake risk: sleep(300) can measure 299.x ms. Loosen the bound.
    
    // Durations only: nothing of the host or the app's name.
    expect(header).toMatch(/^[a-z0-9.;=, -]+$/);
    expect(header).not.toContain("hello");
  });
  test("a page the pill is written into names forge-rewrite", async () => {
    const res = await viaHost("/");
    const header = res.headers.get("server-timing")!;
    expect(dur(header, "forge-rewrite")).toBeDefined();
  });
  /** Make the next request find the environment asleep, and its wake take `ms`. */
  const asleepOnce = (ms: number, after: "awake" | "asleep") => {
    const status = runtime.envStatus.bind(runtime);
    const wake = runtime.wake.bind(runtime);
    let woke = false;
      
        junipercrew
        12d ago
        outdated
      
      Waits up to 20s on a real sleep sweeper; slow and timing-dependent. Prefer a direct test.
    
    runtime.envStatus = (record, env) =>
      woke && after === "awake" ? status(record, env) : ({ ...status(record, env)!, state: "asleep", port: undefined } as EnvStatus);
    runtime.wake = async () => {
      await Bun.sleep(ms);
      woke = true;
      return undefined;
    };
    return () => {
      runtime.envStatus = status;
      runtime.wake = wake;
    };
  };
  test("a request that wakes the environment names the wait in forge-wake", async () => {
    const restore = asleepOnce(150, "awake");
    try {
      const res = await viaHost("/healthz");
      expect(res.status).toBe(200);
      const header = res.headers.get("server-timing")!;
      expect(dur(header, "forge-wake")!).toBeGreaterThanOrEqual(140);
      expect(dur(header, "forge-upstream")!).toBeGreaterThanOrEqual(250);
    } finally {
      restore();
    }
  });
  test("a refused answer after a wake names no phases: the wait would say it was asleep", async () => {
    const restore = asleepOnce(50, "asleep");
    try {
      const res = await viaHost("/healthz");
      expect(res.status).toBeGreaterThanOrEqual(400);
      expect(res.headers.get("server-timing") ?? "").not.toContain("forge-");
    } finally {
      restore();
    }
  });
  /**
   * Point the next requests at a fake upstream on a raw socket that answers
   * `reply` to whatever it is sent and closes.
   */
  const fakeUpstream = (reply: string) => {
    const listener = Bun.listen({
      hostname: "127.0.0.1",
      port: 0,
      socket: {
        data(socket) {
          if (reply !== "") socket.write(reply);
          socket.end();
        },
      },
    });
    const status = runtime.envStatus.bind(runtime);
    runtime.envStatus = (record, env) => ({ ...status(record, env)!, port: listener.port }) as EnvStatus;
    return () => {
      runtime.envStatus = status;
      listener.stop(true);
    };
  };
  const stoppedAnswering = async (res: Response) => {
    expect(res.status).toBeGreaterThanOrEqual(500);
    expect(await res.text()).toContain("stopped answering");
    const header = res.headers.get("server-timing")!;
    for (const name of ["forge-route", "forge-wake", "forge-upstream"]) expect(dur(header, name)).toBeDefined();
  };
  test("an upstream that closes without answering: 'stopped answering' with the forge's phases", async () => {
    const restore = fakeUpstream("");
    try {
      await stoppedAnswering(await viaHost("/"));
    } finally {
      restore();
    }
  });
  test("a page that breaks off mid-body: 'stopped answering' with the forge's phases", async () => {
    const restore = fakeUpstream(
      "HTTP/1.1 200 OK\r\ncontent-type: text/html\r\ncontent-length: 1000\r\n\r\n<html><body>",
    );
    try {
      await stoppedAnswering(await viaHost("/"));
    } finally {
      restore();
    }
  });
});
		@@ -18,6 +18,10 @@ green changes, and nothing waits on a person. [`docs/STUDIO.md`](docs/STUDIO.md)
18	18	git underneath is one click away — the switch in the top bar, or `?mode=dev` on
19	19	any URL — and it is the rest of this page.
20	20
	21	Slow app? Its response's `Server-Timing` keeps the app's entries and adds the
	22	forge's `forge-route`, `forge-wake`, `forge-upstream` and `forge-rewrite`
	23	(milliseconds only; see `docs/APPS.md`).
	24
21	25	A forge this one spawned (hosted) runs the apps it was given too: its `bakery`
22	26	answers at `bakery--<child>--<this forge's host>`, in this forge's lanes, on the
23	27	child's own data, and `/forges` says how many are running and why any is not. Each row also ends with the first step its person has not taken (`not claimed yet`, `no everyday account yet`, `no tell yet`, or `going: last tell <time>`; `has not reported yet` before the child's first beat), read from the child's heartbeat; the terminal's forges screen and the MCP `forges` tool (`nextStep`) say the same.
		@@ -254,6 +254,20 @@ read the repository sees only the time, never a sha. The read is the `serving`
254	254	Server-Timing phase. The prefix was already the forge's, so an app's own
255	255	`/__forge/` path is not reachable.
256	256
	257	Reading a slow app's Server-Timing. A response the proxy relays keeps the
	258	app's own entries (`db`, `app`, …) and gains the forge's, each `forge-` named
	259	and in milliseconds only: `forge-route` (finding the target and its grant),
	260	`forge-wake` (waiting for a sleeping or starting environment; 0 when none),
	261	`forge-upstream` (until the app's headers) and `forge-rewrite` (pill injection,
	262	when it ran). Big `forge-wake` is a cold start, big `forge-upstream` is the
	263	app; if all are small, the time went before the request reached the forge. The
	264	"app stopped answering" page carries `route`, `wake` and `upstream` too; the
	265	forge's own `/__forge/*` pages and the WebSocket upgrade name no forge- phases.
	266	A refused answer (sign in, not found, not running) names none either: the wake
	267	runs before the door is asked, so its time would tell a caller who may not read
	268	the app whether it was asleep. The proxy has one writer for these
	269	(`withPhases` over `notePhase`), which appends to the app's header.
	270
257	271	Tell the crew from the pill. Signed in as someone who may direct the crew,
258	272	the panel also offers Tell the crew (`/__forge/crew` adds a `tell` link, only
259	273	for them; signed out there is no action). It opens the forge's own
		@@ -47,7 +47,7 @@ import { clientBucket } from "../http/peer.ts";
47	47	import { DOOR_PULL_LIMIT, doorPage, type DoorPullLine } from "./door.ts";
48	48	import { checkWord } from "./check_word.ts";
49	49	import { openPulls } from "./door_pulls.ts";
50		import { takePhases, timePhase } from "../core/route_timing.ts";
	50	import { notePhase, startedAt, takePhases, timePhase } from "../core/route_timing.ts";
51	51	import { readServing } from "./serving.ts";
52	52	import { notFound, securityFloor } from "../http/respond.ts";
53	53	import { appMeasure } from "./measure.ts";
		@@ -390,17 +390,27 @@ function sealedPull(runtime: AppsRuntime, target: AppTarget): Issue \| undefined
390	390	return pull?.sealed === true ? pull : undefined;
391	391	}
392	392
393		/** The response with the phases the request named, as `Server-Timing`. */
	393	/**
	394	* The response with the phases the request named, as `Server-Timing`: the
	395	* one writer for the proxy, on the forge's own `/__forge/*` pages and on a
	396	* relayed app answer alike. It appends, so an app's own entries stay first;
	397	* on an app answer the forge's phases are `forge-` named (`relayPhase`) so
	398	* none can collide with the app's or with the server's `route`.
	399	*/
394	400	function withPhases(request: Request, res: Response): Response {
395	401	const phases = takePhases(request);
396		if (phases.length > 0)
397		res.headers.set(
398		"server-timing",
399		phases.map((p) => `${p.name};dur=${p.ms.toFixed(1)}`).join(", "),
400		);
	402	if (phases.length === 0) return res;
	403	const mine = phases.map((p) => `${p.name};dur=${p.ms.toFixed(1)}`).join(", ");
	404	const theirs = res.headers.get("server-timing");
	405	res.headers.set("server-timing", theirs === null \|\| theirs === "" ? mine : `${theirs}, ${mine}`);
401	406	return res;
402	407	}
403	408
	409	/** Name one of the forge's phases of relaying an app answer. Durations only. */
	410	function relayPhase(request: Request, name: "route" \| "wake" \| "upstream" \| "rewrite", ms: number): void {
	411	notePhase(request, `forge-${name}`, ms);
	412	}
	413
404	414	/**
405	415	* What the pill says: the app, the environment and, for a preview, the pull
406	416	* and its title. The title goes only to a viewer who may read the pull.
		@@ -1023,15 +1033,24 @@ export async function proxyApp(
1023	1033	}
1024	1034	// An environment asleep wakes for the request that wants it, and the
1025	1035	// request waits the second that takes rather than seeing a closed door.
1026		if (runtime.envStatus(target.app, target.env)?.state === "asleep")
	1036	let wakeMs = 0;
	1037	if (runtime.envStatus(target.app, target.env)?.state === "asleep") {
	1038	const woke = performance.now();
1027	1039	await runtime.wake(target.app, target.env);
	1040	wakeMs = performance.now() - woke;
	1041	}
1028	1042	const admitted = admit(runtime, request, target);
	1043	// A refused answer names no phases: wake runs before `admit`, so its time
	1044	// would tell a caller who may not read the app whether it was asleep.
1029	1045	if (!admitted.ok)
1030	1046	return url.pathname.startsWith("/__forge/")
1031	1047	? securityFloor(admitted.error)
1032	1048	: admitted.error;
1033	1049	const { status, port, grant: vouched } = admitted.value;
1034	1050	runtime.touch(target.app, target.env);
	1051	const began = performance.now();
	1052	relayPhase(request, "route", Math.max(0, began - (startedAt(request) ?? began) - wakeMs));
	1053	relayPhase(request, "wake", wakeMs);
1035	1054
1036	1055	const upstream = new URL(url);
1037	1056	upstream.protocol = "http:";
		@@ -1082,6 +1101,7 @@ export async function proxyApp(
1082	1101	portAnswered();
1083	1102	};
1084	1103	let response: Response;
	1104	const sent = performance.now();
1085	1105	try {
1086	1106	response = await fetch(upstream, {
1087	1107	method: request.method,
		@@ -1097,8 +1117,10 @@ export async function proxyApp(
1097	1117	} as RequestInit);
		junipercrew 12d ago outdated The unavailable() return above carries no forge phases; add them or document.
1098	1118	} catch {
1099	1119	answered();
1100		return unavailable(runtime, target, status, "the app stopped answering");
	1120	relayPhase(request, "upstream", performance.now() - sent);
	1121	return withPhases(request, unavailable(runtime, target, status, "the app stopped answering"));
1101	1122	}
	1123	relayPhase(request, "upstream", performance.now() - sent);
1102	1124	const out = new Headers(response.headers);
1103	1125	for (const name of HOP_BY_HOP) out.delete(name);
1104	1126	// Which app answered: a probe from outside (`spawn/reach.ts`) tells this
		@@ -1130,6 +1152,7 @@ export async function proxyApp(
1130	1152	(rewritable(out, response.status) \|\|
1131	1153	(!out.has("content-length") && htmlAnswer(out, response.status)))
1132	1154	) {
	1155	const rewriting = performance.now();
1133	1156	let bytes: Uint8Array<ArrayBuffer>;
1134	1157	try {
1135	1158	if (out.has("content-length")) bytes = new Uint8Array(await response.arrayBuffer());
		@@ -1138,15 +1161,18 @@ export async function proxyApp(
1138	1161	// past that it goes on as it came, what was read first.
1139	1162	const read = await readPage(response.body);
1140	1163	if (!read.whole)
1141		return new Response(read.rest, {
1142		status: response.status,
1143		statusText: response.statusText,
1144		headers: out,
1145		});
	1164	return withPhases(
	1165	request,
	1166	new Response(read.rest, {
	1167	status: response.status,
	1168	statusText: response.statusText,
	1169	headers: out,
	1170	}),
	1171	);
1146	1172	bytes = read.bytes;
1147	1173	}
1148	1174	} catch {
1149		return unavailable(runtime, target, status, "the app stopped answering");
	1175	return withPhases(request, unavailable(runtime, target, status, "the app stopped answering"));
1150	1176	}
1151	1177	// A signed-in person's page load gets the panel's one-use proof, and so
1152	1178	// is theirs alone: never stored or shared. A page the app's own script
		@@ -1178,19 +1204,23 @@ export async function proxyApp(
1178	1204	out.set("content-length", String(sent.length));
1179	1205	out.delete("etag");
1180	1206	out.delete("content-md5");
1181		return new Response(sent, {
1182		status: response.status,
1183		statusText: response.statusText,
1184		headers: out,
1185		});
	1207	relayPhase(request, "rewrite", performance.now() - rewriting);
	1208	return withPhases(
	1209	request,
	1210	new Response(sent, {
	1211	status: response.status,
	1212	statusText: response.statusText,
	1213	headers: out,
	1214	}),
	1215	);
1186	1216	}
1187		return new Response(
1188		body,
1189		{
	1217	return withPhases(
	1218	request,
	1219	new Response(body, {
1190	1220	status: response.status,
1191	1221	statusText: response.statusText,
1192	1222	headers: out,
1193		},
	1223	}),
1194	1224	);
1195	1225	}
1196	1226
		@@ -296,6 +296,11 @@ export function noteStart(request: Request, at: number): void {
296	296	startTimes.set(request, at);
297	297	}
298	298
	299	/** When the server took the request (`noteStart`), if it did. */
	300	export function startedAt(request: Request): number \| undefined {
	301	return startTimes.get(request);
	302	}
	303
299	304	const framed = new WeakSet<Request>();
300	305
301	306	/**
		@@ -0,0 +1,206 @@
	1	/**
	2	* A proxied answer keeps the app's Server-Timing and appends the forge's own
	3	* phases, `forge-` named: where a slow request spent its time.
	4	*/
	5	import { afterAll, beforeAll, describe, expect, test } from "bun:test";
	6	import { mkdtemp, rm } from "node:fs/promises";
	7	import { tmpdir } from "node:os";
	8	import { join } from "node:path";
	9	import { createApp, type App } from "../src/app.ts";
	10	import { AppsRuntime, type EnvStatus } from "../src/apps/runtime.ts";
	11	import { newApp } from "../src/actions/apps.ts";
	12	import { commitToBranch } from "../src/actions/repos.ts";
	13	import type { Repo } from "../src/core/repos.ts";
	14	import { createUser, type User } from "../src/core/users.ts";
	15	import { serve, type Servers } from "../src/http/server.ts";
	16	import { deploySettled } from "./helpers/apps-forge.ts";
	17
	18	const DOMAIN = "apps.test";
	19	const SLOW = `const server = Bun.serve({
	20	port: Number(process.env.PORT),
	21	hostname: "127.0.0.1",
	22	async fetch(request) {
	23	if (new URL(request.url).pathname === "/healthz") {
	24	await Bun.sleep(300);
	25	return new Response("ok", { headers: { "server-timing": "db;dur=0.1, app;dur=1.1" } });
	26	}
	27	return new Response("<html><body><h1>hello</h1></body></html>", { headers: { "content-type": "text/html" } });
	28	},
	29	});
	30	`;
	31
	32	const dur = (header: string, name: string): number \| undefined => {
	33	const m = new RegExp(`(?:^\|, )${name};dur=([0-9.]+)`).exec(header);
	34	return m ? Number(m[1]) : undefined;
	35	};
	36
	37	describe("a proxied answer's Server-Timing", () => {
	38	let dataDir: string;
	39	let app: App;
	40	let servers: Servers;
	41	let runtime: AppsRuntime;
	42	let alice: User;
	43	let repo: Repo;
	44
	45	const viaHost = (path = "/") =>
	46	fetch(`${servers.url}${path}`, { headers: { host: `hello.${DOMAIN}`, accept: "text/html" }, redirect: "manual" });
	47
	48	beforeAll(async () => {
	49	dataDir = await mkdtemp(join(tmpdir(), "forge-ptiming-"));
	50	app = createApp({ dataDir, port: 0 });
	51	servers = await serve(app);
	52	runtime = new AppsRuntime(app, {
	53	domain: DOMAIN,
	54	scheme: "http",
	55	publicPort: servers.port,
	56	forgeUrl: servers.url,
	57	});
	58	await runtime.start();
	59	const created = await createUser(app.db, { origin: "seed", trusted: true,
	60	username: "alice",
	61	email: "[email protected]",
	62	password: "a-good-passphrase",
	63	adminIfFirst: true,
	64	});
	65	if (!created.ok) throw new Error(created.error);
	66	alice = created.value;
	67	const made = await newApp(app, alice, { name: "hello", description: "d", visibility: "public" });
	68	if (!made.ok) throw new Error(String(made.error));
	69	repo = made.value.repo;
	70	const first = await deploySettled(app, repo.id, (r) => r.env === "production");
	71	expect(first.state).toBe("ok");
	72	const committed = await commitToBranch(app, alice, repo, {
	73	branch: repo.defaultBranch,
	74	base: repo.defaultBranch,
	75	message: "Slow healthz",
	76	files: [
	77	{ path: "src/slow.ts", content: SLOW },
	78	{
	79	path: "forge.json",
	80	content: JSON.stringify({ app: { run: "bun run src/slow.ts", health: "/" } }),
	81	},
	82	],
	83	});
	84	expect(committed.ok).toBe(true);
	85	const second = await deploySettled(app, repo.id, (r) => r.env === "production" && r.id !== first.id);
	86	expect(second.state).toBe("ok");
	87	}, 120_000);
	88
	89	afterAll(async () => {
	90	await runtime.stop();
	91	servers.stop();
	92	app.close();
	93	await rm(dataDir, { recursive: true, force: true });
	94	});
	95
	96	test("a slow upstream shows in forge-upstream, beside the app's own entries", async () => {
	97	const res = await viaHost("/healthz");
	98	expect(res.status).toBe(200);
	99	const header = res.headers.get("server-timing")!;
	100	expect(header.startsWith("db;dur=0.1, app;dur=1.1, ")).toBe(true);
	101	expect(dur(header, "forge-upstream")!).toBeGreaterThanOrEqual(250);
	102	expect(dur(header, "forge-route")).toBeDefined();
	103	expect(dur(header, "forge-wake")).toBe(0);
		junipercrew 12d ago outdated Flake risk: sleep(300) can measure 299.x ms. Loosen the bound.
	104	// Durations only: nothing of the host or the app's name.
	105	expect(header).toMatch(/^[a-z0-9.;=, -]+$/);
	106	expect(header).not.toContain("hello");
	107	});
	108
	109	test("a page the pill is written into names forge-rewrite", async () => {
	110	const res = await viaHost("/");
	111	const header = res.headers.get("server-timing")!;
	112	expect(dur(header, "forge-rewrite")).toBeDefined();
	113	});
	114
	115	/** Make the next request find the environment asleep, and its wake take `ms`. */
	116	const asleepOnce = (ms: number, after: "awake" \| "asleep") => {
	117	const status = runtime.envStatus.bind(runtime);
	118	const wake = runtime.wake.bind(runtime);
	119	let woke = false;
		junipercrew 12d ago outdated Waits up to 20s on a real sleep sweeper; slow and timing-dependent. Prefer a direct test.
	120	runtime.envStatus = (record, env) =>
	121	woke && after === "awake" ? status(record, env) : ({ ...status(record, env)!, state: "asleep", port: undefined } as EnvStatus);
	122	runtime.wake = async () => {
	123	await Bun.sleep(ms);
	124	woke = true;
	125	return undefined;
	126	};
	127	return () => {
	128	runtime.envStatus = status;
	129	runtime.wake = wake;
	130	};
	131	};
	132
	133	test("a request that wakes the environment names the wait in forge-wake", async () => {
	134	const restore = asleepOnce(150, "awake");
	135	try {
	136	const res = await viaHost("/healthz");
	137	expect(res.status).toBe(200);
	138	const header = res.headers.get("server-timing")!;
	139	expect(dur(header, "forge-wake")!).toBeGreaterThanOrEqual(140);
	140	expect(dur(header, "forge-upstream")!).toBeGreaterThanOrEqual(250);
	141	} finally {
	142	restore();
	143	}
	144	});
	145
	146	test("a refused answer after a wake names no phases: the wait would say it was asleep", async () => {
	147	const restore = asleepOnce(50, "asleep");
	148	try {
	149	const res = await viaHost("/healthz");
	150	expect(res.status).toBeGreaterThanOrEqual(400);
	151	expect(res.headers.get("server-timing") ?? "").not.toContain("forge-");
	152	} finally {
	153	restore();
	154	}
	155	});
	156
	157	/**
	158	* Point the next requests at a fake upstream on a raw socket that answers
	159	* `reply` to whatever it is sent and closes.
	160	*/
	161	const fakeUpstream = (reply: string) => {
	162	const listener = Bun.listen({
	163	hostname: "127.0.0.1",
	164	port: 0,
	165	socket: {
	166	data(socket) {
	167	if (reply !== "") socket.write(reply);
	168	socket.end();
	169	},
	170	},
	171	});
	172	const status = runtime.envStatus.bind(runtime);
	173	runtime.envStatus = (record, env) => ({ ...status(record, env)!, port: listener.port }) as EnvStatus;
	174	return () => {
	175	runtime.envStatus = status;
	176	listener.stop(true);
	177	};
	178	};
	179
	180	const stoppedAnswering = async (res: Response) => {
	181	expect(res.status).toBeGreaterThanOrEqual(500);
	182	expect(await res.text()).toContain("stopped answering");
	183	const header = res.headers.get("server-timing")!;
	184	for (const name of ["forge-route", "forge-wake", "forge-upstream"]) expect(dur(header, name)).toBeDefined();
	185	};
	186
	187	test("an upstream that closes without answering: 'stopped answering' with the forge's phases", async () => {
	188	const restore = fakeUpstream("");
	189	try {
	190	await stoppedAnswering(await viaHost("/"));
	191	} finally {
	192	restore();
	193	}
	194	});
	195
	196	test("a page that breaks off mid-body: 'stopped answering' with the forge's phases", async () => {
	197	const restore = fakeUpstream(
	198	"HTTP/1.1 200 OK\r\ncontent-type: text/html\r\ncontent-length: 1000\r\n\r\n<html><body>",
	199	);
	200	try {
	201	await stoppedAnswering(await viaHost("/"));
	202	} finally {
	203	restore();
	204	}
	205	});
	206	});