fd95908 · 0b78a28 · 3a569be · 54e4cf5
@@ -273,7 +273,11 @@
clock, so a loop busy with something else lands in it), `forge-body` (reading a
`forge-rewrite` (pill injection with that read, when it ran). Big `forge-wake`
is a cold start, big `forge-ttfb` is the app or its listener — unless
`forge-lag` is more than half of `forge-ttfb`, when the wait was the forge's,
not the app's (`forgeWaited` in `src/perf/loop_worst.ts`) — big `forge-body`
not the app's (`forgeWaited` in `src/perf/loop_worst.ts`), and a signed-in
forge admin also gets `forge-stall;desc="<pattern>";dur=<ms>`, up to three, naming
the route pattern or `job:<name>` that held the loop, longest first (that copy is
`cache-control: private, no-store`; nobody else gets `forge-stall`;
`docs/features/app-slowest-wait.md`) — big `forge-body`
is an app slow to finish its page; if all are small, the time went before the
request reached the forge. The forge opens no second socket to time the
connect: it would take a backlog slot in the very case it is meant to find.
@@ -22,7 +22,9 @@
Slow app? Its response's `Server-Timing` keeps the app's entries and adds the
forge's `forge-route`, `forge-wake`, `forge-upstream`, `forge-ttfb`,
`forge-lag`, `forge-body` and `forge-rewrite` (milliseconds only; see
`docs/APPS.md`). When `forge-lag` is more than half of `forge-ttfb`, the wait
was the forge's, not the app's.
was the forge's, not the app's; a signed-in forge admin then also gets
`forge-stall;desc="<pattern>";dur=<ms>` naming the route or `job:<name>` that held
the loop (sent `private, no-store`; nobody else gets it).
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
@@ -2,10 +2,16 @@
An app's production speed card says the slowest wait the forge relayed to it in the last 10 minutes, and whether the forge or the app spent it. When the forge's own event-loop lag (`forge-lag`) is more than half the time to the app's headers (`forge-ttfb`), the wait is the forge's (`forgeWaited`, `src/perf/loop_worst.ts`), and the card says so instead of calling the app slow.
- Page: Settings → App → **Visitors and speed**, a **Slowest wait, 10 min** row beside the p75 figures: `the forge was busy: 600 ms of the 820 ms wait`, or `820 ms, the app's own`. No row when nothing was relayed in the window.
- Terminal: the deploys screen's visitors line ends `· slowest wait, 10 min: the forge was busy: 600 ms of the 820 ms wait`.
- API: `GET /api/v1/repos/:owner/:name/app`, for the app's admins, carries `vitals.wait: {ttfbMs, lagMs, at, forge}`; absent with no wait in the window.
- Page: Settings → App → **Visitors and speed**, a **Slowest wait, 10 min** row beside the p75 figures: `the forge was busy: 600 ms of the 820 ms wait, held by job:sweep-runs (600 ms)`, or `820 ms, the app's own`. No row when nothing was relayed in the window.
- Terminal: the deploys screen's visitors line ends `· slowest wait, 10 min: the forge was busy: 600 ms of the 820 ms wait, held by job:sweep-runs (600 ms)`.
- API: `GET /api/v1/repos/:owner/:name/app`, for the app's admins, carries `vitals.wait: {ttfbMs, lagMs, at, forge, held}`; absent with no wait in the window. `held` is `[{name, ms}]`, empty unless `forge`.
## What held it (#11000)
When the wait was the forge's, the forge names what blocked its loop in the lag's 10 s window: the stalls the loop watch (`src/perf/loop.ts`) noted, each by the route patterns that ran across it, else the background jobs as `job:<name>`. Longest stall first, each name once, at most three. A name is only ever a pattern — a path pattern such as `/:owner/:name`, `job:<name>` or `(unmatched)` — never a path's ids or query (`isStallPattern`, `src/apps/relay_wait.ts`); a stall nothing named ran across is left out. The card and terminal line add `, held by <name> (<ms>)…`; no `held by` when the wait was the app's own.
A signed-in forge admin (active, not an agent) also gets the names on the relayed answer itself, beside `forge-lag`: `Server-Timing: forge-stall;desc="job:sweep-runs";dur=600.0`, one entry per name. That copy is sent `cache-control: private, no-store` (and without `etag`), so no shared cache keeps the forge's route names; visitors and everyone else never get `forge-stall`.
Production only; previews are not counted. Held in the forge's memory (at most 2,000 apps), so a restart forgets it.
Try it: hold a production app's answer behind a busy forge (a long synchronous task on the forge, then load the app), then open its repository's Settings → App within 10 minutes.
Try it: hold a production app's answer behind a busy forge (a long synchronous task on the forge, then load the app), then open its repository's Settings → App within 10 minutes. Signed in as a forge admin, the app's own response carries `forge-stall` too.
@@ -65,8 +65,9 @@
import { notFound, securityFloor } from "../http/respond.ts";
import { appMeasure } from "./measure.ts";
import { holdPortRequest, holdPortSocket } from "./handoff.ts";
import { secureFor } from "../http/cookie_secure.ts";
import { currentLoopLag } from "../perf/loop_worst.ts";
import { noteRelayWait } from "./relay_wait.ts";
import { currentLoopLag, forgeWaited, LAG_WINDOW_MS } from "../perf/loop_worst.ts";
import { loopWatch } from "../perf/live.ts";
import { heldBy, noteRelayWait, stallTiming } from "./relay_wait.ts";
import { cspNonce, htmlAnswer, readPage, rewritable, TOOLBAR_ASSET_PATH, TOOLBAR_ASSET_PREFIX, toolbarResponse, withToolbar, type PillWhere } from "./toolbar.ts";
const proxySecure = (request: Request, url: URL, forgeUrl: string): boolean =>
@@ -430,8 +431,17 @@
function sealedPull(runtime: AppsRuntime, target: AppTarget): Issue | undefined
 */
function withPhases(request: Request, res: Response): Response {
  const phases = takePhases(request);
  if (phases.length === 0) return res;
  const mine = phases.map((p) => `${p.name};dur=${p.ms.toFixed(1)}`).join(", ");
  const stall = stallFor.get(request);
  if (stall !== undefined) {
    stallFor.delete(request);
    // An admin's copy names internal routes: never one a shared cache may keep.
    res.headers.set("cache-control", "private, no-store");
    res.headers.delete("etag");
  }
  if (phases.length === 0 && stall === undefined) return res;
  const named = phases.map((p) => `${p.name};dur=${p.ms.toFixed(1)}`);
  if (stall !== undefined) named.push(stall);
  const mine = named.join(", ");
  const theirs = res.headers.get("server-timing");
  res.headers.set("server-timing", theirs === null || theirs === "" ? mine : `${theirs}, ${mine}`);
  return res;
@@ -460,13 +470,38 @@
function relayPhase(request: Request, name: RelayPhase, ms: number): void {
 * so a loop blocked by something else lands in it while the app sat idle;
 * `forgeWaited` (the one place the rule lives) says when the wait was the forge's.
 */
function relayUpstream(request: Request, target: AppTarget, headersMs: number): void {
function relayUpstream(
  runtime: AppsRuntime,
  request: Request,
  target: AppTarget,
  headersMs: number,
  who: GrantWho | undefined,
): void {
  const lag = currentLoopLag();
  relayPhase(request, "ttfb", headersMs);
  relayPhase(request, "lag", lag);
  relayPhase(request, "upstream", headersMs);
  // What held a wait that was the forge's (#11000): the stalls of the lag's
  // window, read only then — at most 40 of them, so the common relay pays nothing.
  const now = performance.now();
  const held = forgeWaited(lag, headersMs) ? heldBy(loopWatch.within(now - LAG_WINDOW_MS, now)) : [];
  // Production's slowest wait, for the app's speed card (`apps/relay_wait.ts`).
  if (target.env === "production") noteRelayWait(target.app.id, headersMs, lag);
  if (target.env === "production") noteRelayWait(target.app.id, headersMs, lag, Date.now(), held);
  if (held.length > 0 && forgeAdmin(runtime, who)) stallFor.set(request, stallTiming(held));
}
/**
 * The `forge-stall` entries a relayed answer carries, by request, until
 * `withPhases` writes them. Set only for a forge admin: route patterns are
 * the forge's own, so nobody else sees them.
 */
const stallFor = new WeakMap<Request, string>();
/** Whether the grant names an active person who administers the forge (an agent never does). */
function forgeAdmin(runtime: AppsRuntime, who: GrantWho | undefined): boolean {
  if (who === undefined) return false;
  const user = getUserById(runtime.app.db, who.id);
  return user !== undefined && isActive(user) && user.isAdmin && user.kind !== "agent";
}
/**
@@ -1223,10 +1258,10 @@
export async function proxyApp(
    } as RequestInit);
  } catch {
    answered();
    relayUpstream(request, target, performance.now() - sent);
    relayUpstream(runtime, request, target, performance.now() - sent, vouched?.who);
    return withPhases(request, unavailable(runtime, target, status, "the app stopped answering"));
  }
  relayUpstream(request, target, performance.now() - sent);
  relayUpstream(runtime, request, target, performance.now() - sent, vouched?.who);
  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
@@ -7,16 +7,61 @@
 * half the wait (`forgeWaited`, the one place the rule lives), the words
 * say the forge was busy, not the app.
 *
 * When the wait was the forge's, it also says what held it (#11000): the
 * stalls the loop watch named (`perf/loop.ts`) in the lag's window, as route
 * patterns or `job:<name>`, the longest stall first. Patterns only — a name
 * that is not one (`isStallPattern`) is never told — and only to the app's
 * owners, on the speed card and the terminal line; a signed-in forge admin
 * also gets them on the relayed answer as `forge-stall` (`stallTiming`).
 *
 * Process memory, not the database: one O(1) compare per relay, at most
 * `KEEP_APPS` apps (the oldest reading goes first), gone on restart.
 * `KEEP_APPS` apps (the oldest reading goes first), gone on restart. The
 * stalls are read only when the forge waited, and at most `HELD_NAMES` kept.
 */
import { blamed, NO_REQUEST, type Stall } from "../perf/loop.ts";
import { forgeWaited } from "../perf/loop_worst.ts";
/** How long a slowest wait stays told, ms. */
export const WAIT_WINDOW_MS = 10 * 60 * 1000;
/** The most apps held; past it the stalest reading is dropped. */
export const KEEP_APPS = 2_000;
/** The most stall names told for one wait. */
export const HELD_NAMES = 3;
/** One stall that held a wait: what ran across it, and how long it blocked, ms. */
export interface HeldBy {
  readonly name: string;
  readonly ms: number;
}
/**
 * Whether `name` is a route pattern or a job's name, and so safe to tell: a
 * path pattern (`/:owner/:name`), `job:<name>`, or the unmatched bucket. No
 * query, no quote, no space, nothing a header's quoted string would need
 * escaped, at most 120 characters.
 */
export function isStallPattern(name: string): boolean {
  return name.length <= 120 && /^(?:\/[A-Za-z0-9_:.\/*#-]*|job:[A-Za-z0-9_.:-]+|\(unmatched\))$/.test(name);
}
/**
 * What held a wait, from the stalls of its window: each stall's names
 * (routes, else jobs), the longest stall first, each name once, the
 * unnamed (`NO_REQUEST`) and anything not a pattern dropped, at most `HELD_NAMES`.
 */
export function heldBy(stalls: readonly Stall[]): HeldBy[] {
  const out: HeldBy[] = [];
  const seen = new Set<string>();
  for (const s of [...stalls].sort((a, b) => b.lateMs - a.lateMs))
    for (const name of blamed(s)) {
      if (out.length >= HELD_NAMES) return out;
      if (name === NO_REQUEST || seen.has(name) || !isStallPattern(name)) continue;
      seen.add(name);
      out.push({ name, ms: s.lateMs });
    }
  return out;
}
export interface RelayWait {
  /** Time to the app's headers, on the forge's clock, ms. */
@@ -27,22 +72,34 @@
export interface RelayWait {
  readonly at: number;
  /** True when the forge's lag explains most of the wait (`forgeWaited`). */
  readonly forge: boolean;
  /** What held it, longest first; empty unless `forge`. */
  readonly held: readonly HeldBy[];
}
const slowest = new Map<string, RelayWait>();
/** Note one relayed wait for `appId`; it is kept when it is the window's slowest. */
export function noteRelayWait(appId: string, ttfbMs: number, lagMs: number, at: number = Date.now()): void {
/**
 * Note one relayed wait for `appId`; it is kept when it is the window's
 * slowest. `held` is what held it (`heldBy`), kept only when the forge waited.
 */
export function noteRelayWait(
  appId: string,
  ttfbMs: number,
  lagMs: number,
  at: number = Date.now(),
  held: readonly HeldBy[] = [],
): void {
  if (!Number.isFinite(ttfbMs) || ttfbMs < 0 || !Number.isFinite(lagMs) || lagMs < 0) return;
  const held = slowest.get(appId);
  if (held !== undefined && at - held.at < WAIT_WINDOW_MS && held.ttfbMs >= ttfbMs) return;
  if (held === undefined && slowest.size >= KEEP_APPS) {
  const kept = slowest.get(appId);
  if (kept !== undefined && at - kept.at < WAIT_WINDOW_MS && kept.ttfbMs >= ttfbMs) return;
  if (kept === undefined && slowest.size >= KEEP_APPS) {
    // Maps keep insertion order and a replacement re-inserts, so the first is the stalest.
    const first = slowest.keys().next().value;
    if (first !== undefined) slowest.delete(first);
  }
  slowest.delete(appId);
  slowest.set(appId, { ttfbMs, lagMs, at, forge: forgeWaited(lagMs, ttfbMs) });
  const forge = forgeWaited(lagMs, ttfbMs);
  slowest.set(appId, { ttfbMs, lagMs, at, forge, held: forge ? held : [] });
}
/** The slowest wait of the window ending at `at`, or undefined with none. */
@@ -60,8 +117,23 @@
const msText = (v: number): string => (v < 1000 ? `${Math.round(v)} ms` : `${(v
/**
 * The reading in one plain sentence, whose wait first: "the forge was busy:
 * 600 ms of the 820 ms wait" or "820 ms, the app's own". Plain text; callers escape.
 * 600 ms of the 820 ms wait, held by job:sweep (600 ms)" or "820 ms, the
 * app's own". Plain text; callers escape.
 */
export function relayWaitWords(w: RelayWait): string {
  return w.forge ? `the forge was busy: ${msText(w.lagMs)} of the ${msText(w.ttfbMs)} wait` : `${msText(w.ttfbMs)}, the app's own`;
  if (!w.forge) return `${msText(w.ttfbMs)}, the app's own`;
  const busy = `the forge was busy: ${msText(w.lagMs)} of the ${msText(w.ttfbMs)} wait`;
  return w.held.length === 0 ? busy : `${busy}, held by ${w.held.map((h) => `${h.name} (${msText(h.ms)})`).join(", ")}`;
}
/**
 * What held a wait as `Server-Timing` entries, for a forge admin's eyes only:
 * `forge-stall;desc="/explore";dur=1226.8`, one per name. Names are checked
 * again here (`isStallPattern`), so nothing that needs escaping is written.
 */
export function stallTiming(held: readonly HeldBy[]): string {
  return held
    .filter((h) => isStallPattern(h.name) && Number.isFinite(h.ms) && h.ms >= 0)
    .map((h) => `forge-stall;desc="${h.name}";dur=${h.ms.toFixed(1)}`)
    .join(", ");
}
@@ -57,12 +57,18 @@
export interface LoopWatch {
  stalled(lateMs: number, at: number): Stall | null;
  /** The stalls so far by route, the hour ending at `now` (same clock as `at`). */
  tally(now: number): StallTally;
  /**
   * The stalls noted at `from`..`to` (same clock as `at`), newest first. Read
   * from the end, so it costs the stalls in the window: at most one per
   * `LIMIT_MS`, 40 in a 10 s window (#11000).
   */
  within(from: number, to: number): readonly Stall[];
  /** Forget every request and stall noted so far; a test sharing the process's watch starts from nothing. */
  clear(): void;
}
/** What a stall is counted against: its routes, else its jobs, else `NO_REQUEST`. */
const blamed = (s: Stall): readonly string[] =>
export const blamed = (s: Stall): readonly string[] =>
  s.routes.length > 0 ? s.routes : s.jobs.length > 0 ? s.jobs.map((j) => JOB_PREFIX + j) : [NO_REQUEST];
function byRoute(stalls: Iterable<Stall>): RouteStall[] {
@@ -121,6 +127,15 @@
export function createLoopWatch(limitMs = LIMIT_MS, jobsAcross: JobsAcross = ()
        hour: byRoute(hour.filter((s) => s.at <= now)).sort((a, b) => b.ms - a.ms || (a.route < b.route ? -1 : 1)),
      };
    },
    within(from, to) {
      const out: Stall[] = [];
      for (let i = hour.length - 1; i >= 0; i--) {
        const s = hour[i]!;
        if (s.at < from) break;
        if (s.at <= to) out.push(s);
      }
      return out;
    },
  };
}
@@ -0,0 +1,209 @@
/**
 * A relayed wait the forge held says what held it (#11000): the stall's
 * route pattern or `job:<name>`, the longest first, on the app's speed card
 * and terminal line; a signed-in forge admin also gets `forge-stall` on the
 * relayed answer, and nobody else does.
 */
import { afterAll, beforeAll, beforeEach, 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 } from "../src/apps/runtime.ts";
import { appVisitors, newApp } from "../src/actions/apps.ts";
import { signGrant } from "../src/apps/proxy.ts";
import {
  clearRelayWaits,
  heldBy,
  HELD_NAMES,
  isStallPattern,
  noteRelayWait,
  relayWait,
  relayWaitWords,
  stallTiming,
} from "../src/apps/relay_wait.ts";
import { visitorsLine, type AppVitals } from "../src/apps/vitals.ts";
import { appVisitorsView } from "../src/web/pages/settings.ts";
import { getAppByRepo } from "../src/core/apps.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";
      
        sentinelcrew
        7h ago
        
      
      Duplicate import from the same module: merge createJobWatch and jobWatch into one line.
    
import { createJobWatch, jobWatch } from "../src/perf/jobs.ts";
import { loopWatch } from "../src/perf/live.ts";
import { createLoopWatch, type Stall } from "../src/perf/loop.ts";
import { loopWorst } from "../src/perf/loop_worst.ts";
import { deploySettled } from "./helpers/apps-forge.ts";
const NOW = Date.parse("2026-11-10T12:00:00Z");
const none: AppVitals = { today: 0, week: 0, ttfbP75: undefined, loadP75: undefined, lcpP75: undefined, inpP75: undefined, clsP75: undefined, loadDays: [] };
const stall = (lateMs: number, routes: string[], jobs: string[] = []): Stall => ({ at: 0, lateMs, routes, jobs });
beforeEach(() => clearRelayWaits());
describe("what held a wait", () => {
  test("a synthetic stall attributed to a job names it, on the card and the terminal line", () => {
    // A clock the test steps: the job's synchronous slice runs 0..600, the wake sees it at 600.
    let t = 0;
    const jobs = createJobWatch(() => t);
    const watch = createLoopWatch(250, jobs.across);
    jobs.during("sweep-runs", () => {
      t = 600;
    });
    const s = watch.stalled(600, 600)!;
    expect(s.jobs).toEqual(["sweep-runs"]);
    // The window the relay reads: the lag's 10 s before it.
    const held = heldBy(watch.within(600 - 10_000, 600));
    expect(held).toEqual([{ name: "job:sweep-runs", ms: 600 }]);
    // 820 ms to headers, 600 of it the forge's: the wait was the forge's, held by the job.
    noteRelayWait("a1", 820, 600, NOW, held);
    const wait = relayWait("a1", NOW)!;
    expect(wait.forge).toBe(true);
    const words = "the forge was busy: 600 ms of the 820 ms wait, held by job:sweep-runs (600 ms)";
    expect(relayWaitWords(wait)).toBe(words);
    expect(visitorsLine({ ...none, wait })).toEndWith(` · slowest wait, 10 min: ${words}`);
    expect(String(appVisitorsView({ ...none, wait }))).toContain(`<dd>${words}</dd>`);
  });
  test("nothing is named when the wait was the app's own", () => {
    // 1.5 s to headers, 40 ms lag: forgeWaited is false, so a stall handed in is dropped.
    noteRelayWait("a1", 1500, 40, NOW, [{ name: "/explore", ms: 300 }]);
    const wait = relayWait("a1", NOW)!;
    expect(wait.forge).toBe(false);
    expect(wait.held).toEqual([]);
    expect(relayWaitWords(wait)).toBe("1.5 s, the app's own");
    expect(visitorsLine({ ...none, wait })).not.toContain("held by");
  });
  test("the longest stall first, each name once, at most HELD_NAMES, the unnamed dropped", () => {
    const held = heldBy([
      stall(300, ["/explore"]),
      stall(900, ["/:owner/:name", "/explore"]),
      stall(400, [], []),
      stall(500, [], ["backup"]),
      stall(350, ["/robots.txt"]),
    ]);
    expect(held).toEqual([
      { name: "/:owner/:name", ms: 900 },
      { name: "/explore", ms: 900 },
      { name: "job:backup", ms: 500 },
    ]);
    expect(held.length).toBe(HELD_NAMES);
    expect(heldBy([stall(400, [], [])])).toEqual([]);
  });
  test("desc is always a pattern: no ids, no query, nothing to escape", () => {
    for (const ok of ["/", "/explore", "/:owner/:name/*", "/explore#read", "job:sweep-runs", "(unmatched)"])
      expect(isStallPattern(ok)).toBe(true);
    for (const bad of ["/explore?q=secret", 'job:"x"', "/a b", "/a;dur=1", "/a,b", "none", "", "alice/repo", `/${"a".repeat(200)}`, "/a\\b"])
      expect(isStallPattern(bad)).toBe(false);
    // A name that is not a pattern is never held, so never told.
    expect(heldBy([stall(900, ["/issues?id=01HXYZ", "/explore"])])).toEqual([{ name: "/explore", ms: 900 }]);
    expect(stallTiming([{ name: "/explore", ms: 1226.84 }, { name: "job:sweep", ms: 300 }])).toBe(
      'forge-stall;desc="/explore";dur=1226.8, forge-stall;desc="job:sweep";dur=300.0',
    );
    expect(stallTiming([{ name: "/x?y", ms: 1 }])).toBe("");
  });
  test("within reads the window's stalls, newest first", () => {
    const watch = createLoopWatch(250);
    watch.stalled(300, 1_000);
    watch.stalled(400, 5_000);
    watch.stalled(500, 12_000);
    expect(watch.within(2_000, 12_000).map((s) => s.at)).toEqual([12_000, 5_000]);
    expect(watch.within(13_000, 20_000)).toEqual([]);
  });
});
describe("forge-stall on the relayed answer", () => {
  const DOMAIN = "apps.test";
  let dataDir: string;
  let app: App;
  let servers: Servers;
  let runtime: AppsRuntime;
  let alice: User;
  let bob: User;
  let repo: Repo;
  beforeAll(async () => {
    dataDir = await mkdtemp(join(tmpdir(), "forge-stallname-"));
    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 a = await createUser(app.db, { origin: "seed", trusted: true, username: "alice", email: "[email protected]", password: "a-good-passphrase", adminIfFirst: true });
    if (!a.ok) throw new Error(a.error);
    alice = a.value;
    const b = await createUser(app.db, { origin: "seed", trusted: true, username: "bob", email: "[email protected]", password: "a-good-passphrase" });
    if (!b.ok) throw new Error(b.error);
    bob = b.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;
    expect((await deploySettled(app, repo.id, (r) => r.env === "production")).state).toBe("ok");
  }, 120_000);
  afterAll(async () => {
    await runtime.stop();
    servers.stop();
    app.close();
    await rm(dataDir, { recursive: true, force: true });
  });
  /** A request to the app as `who` (a grant cookie), or as a visitor with none. */
      
        sentinelcrew
        7h ago
        outdated
      
      A 1 s synchronous busy-wait blocks the whole test process and depends on other suites' leftover stalls. Make it shorter or isolate the window (e.g. clear the loop watch's hour first) so it is fast and deterministic.
    
  const asViewer = (who: User | undefined) => {
    const record = getAppByRepo(app.db, repo.id)!;
    const headers: Record<string, string> = { host: `hello.${DOMAIN}`, accept: "text/plain" };
    if (who !== undefined) {
      const grant = signGrant(app.config.dataDir, { app: record, env: "production" }, 60_000, Date.now(), {
        id: who.id,
        name: who.username,
        role: who.isAdmin ? "admin" : "user",
      });
      headers.cookie = `forge_grant_${record.id.slice(-8)}=${grant}`;
    }
    return fetch(`${servers.url}/`, { headers, redirect: "manual" });
  };
  /**
   * A synthetic stall of `ms` as job `name`, noted where a real one lands:
   * the lag window (`forge-lag`) and the loop watch the relay reads. Nothing
   * blocks the loop, so the test takes no time and the stall is exactly `ms`.
   */
  const stallAsJob = (name: string, ms: number) => {
    jobWatch.during(name, () => {});
    const now = performance.now();
    loopWorst.note(ms, now);
    const s = loopWatch.stalled(ms, now)!;
    // A route that ran across it outranks the job (setup's requests often do);
    // the job's own naming is pinned above, with a stepped clock.
    return heldBy([s])[0]!.name;
  };
  test("a forge admin sees the stall's pattern; a visitor and a signed-in non-admin do not", async () => {
    // 1 s: longer than any stall another suite in this process leaves in the window.
    const name = stallAsJob("stall-name-test", 1_000);
    expect(isStallPattern(name)).toBe(true);
    {
      const admin = await asViewer(alice);
      expect(admin.status).toBe(200);
      const timing = admin.headers.get("server-timing")!;
      expect(timing).toContain(`forge-stall;desc="${name}";dur=1000.0`);
      // Every desc a pattern, never a path's id or query.
      for (const m of timing.matchAll(/forge-stall;desc="([^"]*)"/g)) expect(isStallPattern(m[1]!)).toBe(true);
      // An admin's copy is never kept by a shared cache.
      expect(admin.headers.get("cache-control")).toBe("private, no-store");
      // The speed card names it too.
      expect(visitorsLine(appVisitors(app, alice, repo)!)).toContain(`${name} (1.0 s)`);
      for (const who of [undefined, bob]) {
        const res = await asViewer(who);
        expect(res.status).toBe(200);
        const header = res.headers.get("server-timing") ?? "";
        // The wait was the forge's (forge-lag is there) but the stall is not told.
        expect(header).toContain("forge-lag;dur=");
        expect(header).not.toContain("forge-stall");
        expect(header).not.toContain("job:");
      }
    }
  });
});
		@@ -273,7 +273,11 @@ clock, so a loop busy with something else lands in it), `forge-body` (reading a
273	273	`forge-rewrite` (pill injection with that read, when it ran). Big `forge-wake`
274	274	is a cold start, big `forge-ttfb` is the app or its listener — unless
275	275	`forge-lag` is more than half of `forge-ttfb`, when the wait was the forge's,
276		not the app's (`forgeWaited` in `src/perf/loop_worst.ts`) — big `forge-body`
	276	not the app's (`forgeWaited` in `src/perf/loop_worst.ts`), and a signed-in
	277	forge admin also gets `forge-stall;desc="<pattern>";dur=<ms>`, up to three, naming
	278	the route pattern or `job:<name>` that held the loop, longest first (that copy is
	279	`cache-control: private, no-store`; nobody else gets `forge-stall`;
	280	`docs/features/app-slowest-wait.md`) — big `forge-body`
277	281	is an app slow to finish its page; if all are small, the time went before the
278	282	request reached the forge. The forge opens no second socket to time the
279	283	connect: it would take a backlog slot in the very case it is meant to find.
		@@ -22,7 +22,9 @@ Slow app? Its response's `Server-Timing` keeps the app's entries and adds the
22	22	forge's `forge-route`, `forge-wake`, `forge-upstream`, `forge-ttfb`,
23	23	`forge-lag`, `forge-body` and `forge-rewrite` (milliseconds only; see
24	24	`docs/APPS.md`). When `forge-lag` is more than half of `forge-ttfb`, the wait
25		was the forge's, not the app's.
	25	was the forge's, not the app's; a signed-in forge admin then also gets
	26	`forge-stall;desc="<pattern>";dur=<ms>` naming the route or `job:<name>` that held
	27	the loop (sent `private, no-store`; nobody else gets it).
26	28
27	29	A forge this one spawned (hosted) runs the apps it was given too: its `bakery`
28	30	answers at `bakery--<child>--<this forge's host>`, in this forge's lanes, on the
		@@ -2,10 +2,16 @@
2	2
3	3	An app's production speed card says the slowest wait the forge relayed to it in the last 10 minutes, and whether the forge or the app spent it. When the forge's own event-loop lag (`forge-lag`) is more than half the time to the app's headers (`forge-ttfb`), the wait is the forge's (`forgeWaited`, `src/perf/loop_worst.ts`), and the card says so instead of calling the app slow.
4	4
5		- Page: Settings → App → Visitors and speed, a Slowest wait, 10 min row beside the p75 figures: `the forge was busy: 600 ms of the 820 ms wait`, or `820 ms, the app's own`. No row when nothing was relayed in the window.
6		- Terminal: the deploys screen's visitors line ends `· slowest wait, 10 min: the forge was busy: 600 ms of the 820 ms wait`.
7		- API: `GET /api/v1/repos/:owner/:name/app`, for the app's admins, carries `vitals.wait: {ttfbMs, lagMs, at, forge}`; absent with no wait in the window.
	5	- Page: Settings → App → Visitors and speed, a Slowest wait, 10 min row beside the p75 figures: `the forge was busy: 600 ms of the 820 ms wait, held by job:sweep-runs (600 ms)`, or `820 ms, the app's own`. No row when nothing was relayed in the window.
	6	- Terminal: the deploys screen's visitors line ends `· slowest wait, 10 min: the forge was busy: 600 ms of the 820 ms wait, held by job:sweep-runs (600 ms)`.
	7	- API: `GET /api/v1/repos/:owner/:name/app`, for the app's admins, carries `vitals.wait: {ttfbMs, lagMs, at, forge, held}`; absent with no wait in the window. `held` is `[{name, ms}]`, empty unless `forge`.
	8
	9	## What held it (#11000)
	10
	11	When the wait was the forge's, the forge names what blocked its loop in the lag's 10 s window: the stalls the loop watch (`src/perf/loop.ts`) noted, each by the route patterns that ran across it, else the background jobs as `job:<name>`. Longest stall first, each name once, at most three. A name is only ever a pattern — a path pattern such as `/:owner/:name`, `job:<name>` or `(unmatched)` — never a path's ids or query (`isStallPattern`, `src/apps/relay_wait.ts`); a stall nothing named ran across is left out. The card and terminal line add `, held by <name> (<ms>)…`; no `held by` when the wait was the app's own.
	12
	13	A signed-in forge admin (active, not an agent) also gets the names on the relayed answer itself, beside `forge-lag`: `Server-Timing: forge-stall;desc="job:sweep-runs";dur=600.0`, one entry per name. That copy is sent `cache-control: private, no-store` (and without `etag`), so no shared cache keeps the forge's route names; visitors and everyone else never get `forge-stall`.
8	14
9	15	Production only; previews are not counted. Held in the forge's memory (at most 2,000 apps), so a restart forgets it.
10	16
11		Try it: hold a production app's answer behind a busy forge (a long synchronous task on the forge, then load the app), then open its repository's Settings → App within 10 minutes.
	17	Try it: hold a production app's answer behind a busy forge (a long synchronous task on the forge, then load the app), then open its repository's Settings → App within 10 minutes. Signed in as a forge admin, the app's own response carries `forge-stall` too.
		@@ -65,8 +65,9 @@ import { notFound, securityFloor } from "../http/respond.ts";
65	65	import { appMeasure } from "./measure.ts";
66	66	import { holdPortRequest, holdPortSocket } from "./handoff.ts";
67	67	import { secureFor } from "../http/cookie_secure.ts";
68		import { currentLoopLag } from "../perf/loop_worst.ts";
69		import { noteRelayWait } from "./relay_wait.ts";
	68	import { currentLoopLag, forgeWaited, LAG_WINDOW_MS } from "../perf/loop_worst.ts";
	69	import { loopWatch } from "../perf/live.ts";
	70	import { heldBy, noteRelayWait, stallTiming } from "./relay_wait.ts";
70	71	import { cspNonce, htmlAnswer, readPage, rewritable, TOOLBAR_ASSET_PATH, TOOLBAR_ASSET_PREFIX, toolbarResponse, withToolbar, type PillWhere } from "./toolbar.ts";
71	72
72	73	const proxySecure = (request: Request, url: URL, forgeUrl: string): boolean =>
		@@ -430,8 +431,17 @@ function sealedPull(runtime: AppsRuntime, target: AppTarget): Issue \| undefined
430	431	*/
431	432	function withPhases(request: Request, res: Response): Response {
432	433	const phases = takePhases(request);
433		if (phases.length === 0) return res;
434		const mine = phases.map((p) => `${p.name};dur=${p.ms.toFixed(1)}`).join(", ");
	434	const stall = stallFor.get(request);
	435	if (stall !== undefined) {
	436	stallFor.delete(request);
	437	// An admin's copy names internal routes: never one a shared cache may keep.
	438	res.headers.set("cache-control", "private, no-store");
	439	res.headers.delete("etag");
	440	}
	441	if (phases.length === 0 && stall === undefined) return res;
	442	const named = phases.map((p) => `${p.name};dur=${p.ms.toFixed(1)}`);
	443	if (stall !== undefined) named.push(stall);
	444	const mine = named.join(", ");
435	445	const theirs = res.headers.get("server-timing");
436	446	res.headers.set("server-timing", theirs === null \|\| theirs === "" ? mine : `${theirs}, ${mine}`);
437	447	return res;
		@@ -460,13 +470,38 @@ function relayPhase(request: Request, name: RelayPhase, ms: number): void {
460	470	* so a loop blocked by something else lands in it while the app sat idle;
461	471	* `forgeWaited` (the one place the rule lives) says when the wait was the forge's.
462	472	*/
463		function relayUpstream(request: Request, target: AppTarget, headersMs: number): void {
	473	function relayUpstream(
	474	runtime: AppsRuntime,
	475	request: Request,
	476	target: AppTarget,
	477	headersMs: number,
	478	who: GrantWho \| undefined,
	479	): void {
464	480	const lag = currentLoopLag();
465	481	relayPhase(request, "ttfb", headersMs);
466	482	relayPhase(request, "lag", lag);
467	483	relayPhase(request, "upstream", headersMs);
	484	// What held a wait that was the forge's (#11000): the stalls of the lag's
	485	// window, read only then — at most 40 of them, so the common relay pays nothing.
	486	const now = performance.now();
	487	const held = forgeWaited(lag, headersMs) ? heldBy(loopWatch.within(now - LAG_WINDOW_MS, now)) : [];
468	488	// Production's slowest wait, for the app's speed card (`apps/relay_wait.ts`).
469		if (target.env === "production") noteRelayWait(target.app.id, headersMs, lag);
	489	if (target.env === "production") noteRelayWait(target.app.id, headersMs, lag, Date.now(), held);
	490	if (held.length > 0 && forgeAdmin(runtime, who)) stallFor.set(request, stallTiming(held));
	491	}
	492
	493	/**
	494	* The `forge-stall` entries a relayed answer carries, by request, until
	495	* `withPhases` writes them. Set only for a forge admin: route patterns are
	496	* the forge's own, so nobody else sees them.
	497	*/
	498	const stallFor = new WeakMap<Request, string>();
	499
	500	/** Whether the grant names an active person who administers the forge (an agent never does). */
	501	function forgeAdmin(runtime: AppsRuntime, who: GrantWho \| undefined): boolean {
	502	if (who === undefined) return false;
	503	const user = getUserById(runtime.app.db, who.id);
	504	return user !== undefined && isActive(user) && user.isAdmin && user.kind !== "agent";
470	505	}
471	506
472	507	/**
		@@ -1223,10 +1258,10 @@ export async function proxyApp(
1223	1258	} as RequestInit);
1224	1259	} catch {
1225	1260	answered();
1226		relayUpstream(request, target, performance.now() - sent);
	1261	relayUpstream(runtime, request, target, performance.now() - sent, vouched?.who);
1227	1262	return withPhases(request, unavailable(runtime, target, status, "the app stopped answering"));
1228	1263	}
1229		relayUpstream(request, target, performance.now() - sent);
	1264	relayUpstream(runtime, request, target, performance.now() - sent, vouched?.who);
1230	1265	const out = new Headers(response.headers);
1231	1266	for (const name of HOP_BY_HOP) out.delete(name);
1232	1267	// Which app answered: a probe from outside (`spawn/reach.ts`) tells this
		@@ -7,16 +7,61 @@
7	7	* half the wait (`forgeWaited`, the one place the rule lives), the words
8	8	* say the forge was busy, not the app.
9	9	*
	10	* When the wait was the forge's, it also says what held it (#11000): the
	11	* stalls the loop watch named (`perf/loop.ts`) in the lag's window, as route
	12	* patterns or `job:<name>`, the longest stall first. Patterns only — a name
	13	* that is not one (`isStallPattern`) is never told — and only to the app's
	14	* owners, on the speed card and the terminal line; a signed-in forge admin
	15	* also gets them on the relayed answer as `forge-stall` (`stallTiming`).
	16	*
10	17	* Process memory, not the database: one O(1) compare per relay, at most
11		* `KEEP_APPS` apps (the oldest reading goes first), gone on restart.
	18	* `KEEP_APPS` apps (the oldest reading goes first), gone on restart. The
	19	* stalls are read only when the forge waited, and at most `HELD_NAMES` kept.
12	20	*/
13	21
	22	import { blamed, NO_REQUEST, type Stall } from "../perf/loop.ts";
14	23	import { forgeWaited } from "../perf/loop_worst.ts";
15	24
16	25	/** How long a slowest wait stays told, ms. */
17	26	export const WAIT_WINDOW_MS = 10 * 60 * 1000;
18	27	/** The most apps held; past it the stalest reading is dropped. */
19	28	export const KEEP_APPS = 2_000;
	29	/** The most stall names told for one wait. */
	30	export const HELD_NAMES = 3;
	31
	32	/** One stall that held a wait: what ran across it, and how long it blocked, ms. */
	33	export interface HeldBy {
	34	readonly name: string;
	35	readonly ms: number;
	36	}
	37
	38	/**
	39	* Whether `name` is a route pattern or a job's name, and so safe to tell: a
	40	* path pattern (`/:owner/:name`), `job:<name>`, or the unmatched bucket. No
	41	* query, no quote, no space, nothing a header's quoted string would need
	42	* escaped, at most 120 characters.
	43	*/
	44	export function isStallPattern(name: string): boolean {
	45	return name.length <= 120 && /^(?:\/[A-Za-z0-9_:.\/#-]\|job:[A-Za-z0-9_.:-]+\|\(unmatched\))$/.test(name);
	46	}
	47
	48	/**
	49	* What held a wait, from the stalls of its window: each stall's names
	50	* (routes, else jobs), the longest stall first, each name once, the
	51	* unnamed (`NO_REQUEST`) and anything not a pattern dropped, at most `HELD_NAMES`.
	52	*/
	53	export function heldBy(stalls: readonly Stall[]): HeldBy[] {
	54	const out: HeldBy[] = [];
	55	const seen = new Set<string>();
	56	for (const s of [...stalls].sort((a, b) => b.lateMs - a.lateMs))
	57	for (const name of blamed(s)) {
	58	if (out.length >= HELD_NAMES) return out;
	59	if (name === NO_REQUEST \|\| seen.has(name) \|\| !isStallPattern(name)) continue;
	60	seen.add(name);
	61	out.push({ name, ms: s.lateMs });
	62	}
	63	return out;
	64	}
20	65
21	66	export interface RelayWait {
22	67	/** Time to the app's headers, on the forge's clock, ms. */
		@@ -27,22 +72,34 @@ export interface RelayWait {
27	72	readonly at: number;
28	73	/** True when the forge's lag explains most of the wait (`forgeWaited`). */
29	74	readonly forge: boolean;
	75	/** What held it, longest first; empty unless `forge`. */
	76	readonly held: readonly HeldBy[];
30	77	}
31	78
32	79	const slowest = new Map<string, RelayWait>();
33	80
34		/** Note one relayed wait for `appId`; it is kept when it is the window's slowest. */
35		export function noteRelayWait(appId: string, ttfbMs: number, lagMs: number, at: number = Date.now()): void {
	81	/**
	82	* Note one relayed wait for `appId`; it is kept when it is the window's
	83	* slowest. `held` is what held it (`heldBy`), kept only when the forge waited.
	84	*/
	85	export function noteRelayWait(
	86	appId: string,
	87	ttfbMs: number,
	88	lagMs: number,
	89	at: number = Date.now(),
	90	held: readonly HeldBy[] = [],
	91	): void {
36	92	if (!Number.isFinite(ttfbMs) \|\| ttfbMs < 0 \|\| !Number.isFinite(lagMs) \|\| lagMs < 0) return;
37		const held = slowest.get(appId);
38		if (held !== undefined && at - held.at < WAIT_WINDOW_MS && held.ttfbMs >= ttfbMs) return;
39		if (held === undefined && slowest.size >= KEEP_APPS) {
	93	const kept = slowest.get(appId);
	94	if (kept !== undefined && at - kept.at < WAIT_WINDOW_MS && kept.ttfbMs >= ttfbMs) return;
	95	if (kept === undefined && slowest.size >= KEEP_APPS) {
40	96	// Maps keep insertion order and a replacement re-inserts, so the first is the stalest.
41	97	const first = slowest.keys().next().value;
42	98	if (first !== undefined) slowest.delete(first);
43	99	}
44	100	slowest.delete(appId);
45		slowest.set(appId, { ttfbMs, lagMs, at, forge: forgeWaited(lagMs, ttfbMs) });
	101	const forge = forgeWaited(lagMs, ttfbMs);
	102	slowest.set(appId, { ttfbMs, lagMs, at, forge, held: forge ? held : [] });
46	103	}
47	104
48	105	/** The slowest wait of the window ending at `at`, or undefined with none. */
		@@ -60,8 +117,23 @@ const msText = (v: number): string => (v < 1000 ? `${Math.round(v)} ms` : `${(v
60	117
61	118	/**
62	119	* The reading in one plain sentence, whose wait first: "the forge was busy:
63		* 600 ms of the 820 ms wait" or "820 ms, the app's own". Plain text; callers escape.
	120	* 600 ms of the 820 ms wait, held by job:sweep (600 ms)" or "820 ms, the
	121	* app's own". Plain text; callers escape.
64	122	*/
65	123	export function relayWaitWords(w: RelayWait): string {
66		return w.forge ? `the forge was busy: ${msText(w.lagMs)} of the ${msText(w.ttfbMs)} wait` : `${msText(w.ttfbMs)}, the app's own`;
	124	if (!w.forge) return `${msText(w.ttfbMs)}, the app's own`;
	125	const busy = `the forge was busy: ${msText(w.lagMs)} of the ${msText(w.ttfbMs)} wait`;
	126	return w.held.length === 0 ? busy : `${busy}, held by ${w.held.map((h) => `${h.name} (${msText(h.ms)})`).join(", ")}`;
	127	}
	128
	129	/**
	130	* What held a wait as `Server-Timing` entries, for a forge admin's eyes only:
	131	* `forge-stall;desc="/explore";dur=1226.8`, one per name. Names are checked
	132	* again here (`isStallPattern`), so nothing that needs escaping is written.
	133	*/
	134	export function stallTiming(held: readonly HeldBy[]): string {
	135	return held
	136	.filter((h) => isStallPattern(h.name) && Number.isFinite(h.ms) && h.ms >= 0)
	137	.map((h) => `forge-stall;desc="${h.name}";dur=${h.ms.toFixed(1)}`)
	138	.join(", ");
67	139	}
		@@ -57,12 +57,18 @@ export interface LoopWatch {
57	57	stalled(lateMs: number, at: number): Stall \| null;
58	58	/** The stalls so far by route, the hour ending at `now` (same clock as `at`). */
59	59	tally(now: number): StallTally;
	60	/**
	61	* The stalls noted at `from`..`to` (same clock as `at`), newest first. Read
	62	* from the end, so it costs the stalls in the window: at most one per
	63	* `LIMIT_MS`, 40 in a 10 s window (#11000).
	64	*/
	65	within(from: number, to: number): readonly Stall[];
60	66	/** Forget every request and stall noted so far; a test sharing the process's watch starts from nothing. */
61	67	clear(): void;
62	68	}
63	69
64	70	/** What a stall is counted against: its routes, else its jobs, else `NO_REQUEST`. */
65		const blamed = (s: Stall): readonly string[] =>
	71	export const blamed = (s: Stall): readonly string[] =>
66	72	s.routes.length > 0 ? s.routes : s.jobs.length > 0 ? s.jobs.map((j) => JOB_PREFIX + j) : [NO_REQUEST];
67	73
68	74	function byRoute(stalls: Iterable<Stall>): RouteStall[] {
		@@ -121,6 +127,15 @@ export function createLoopWatch(limitMs = LIMIT_MS, jobsAcross: JobsAcross = ()
121	127	hour: byRoute(hour.filter((s) => s.at <= now)).sort((a, b) => b.ms - a.ms \|\| (a.route < b.route ? -1 : 1)),
122	128	};
123	129	},
	130	within(from, to) {
	131	const out: Stall[] = [];
	132	for (let i = hour.length - 1; i >= 0; i--) {
	133	const s = hour[i]!;
	134	if (s.at < from) break;
	135	if (s.at <= to) out.push(s);
	136	}
	137	return out;
	138	},
124	139	};
125	140	}
126	141
		@@ -0,0 +1,209 @@
	1	/**
	2	* A relayed wait the forge held says what held it (#11000): the stall's
	3	* route pattern or `job:<name>`, the longest first, on the app's speed card
	4	* and terminal line; a signed-in forge admin also gets `forge-stall` on the
	5	* relayed answer, and nobody else does.
	6	*/
	7	import { afterAll, beforeAll, beforeEach, describe, expect, test } from "bun:test";
	8	import { mkdtemp, rm } from "node:fs/promises";
	9	import { tmpdir } from "node:os";
	10	import { join } from "node:path";
	11	import { createApp, type App } from "../src/app.ts";
	12	import { AppsRuntime } from "../src/apps/runtime.ts";
	13	import { appVisitors, newApp } from "../src/actions/apps.ts";
	14	import { signGrant } from "../src/apps/proxy.ts";
	15	import {
	16	clearRelayWaits,
	17	heldBy,
	18	HELD_NAMES,
	19	isStallPattern,
	20	noteRelayWait,
	21	relayWait,
	22	relayWaitWords,
	23	stallTiming,
	24	} from "../src/apps/relay_wait.ts";
	25	import { visitorsLine, type AppVitals } from "../src/apps/vitals.ts";
	26	import { appVisitorsView } from "../src/web/pages/settings.ts";
	27	import { getAppByRepo } from "../src/core/apps.ts";
	28	import type { Repo } from "../src/core/repos.ts";
	29	import { createUser, type User } from "../src/core/users.ts";
	30	import { serve, type Servers } from "../src/http/server.ts";
		sentinelcrew 7h ago Duplicate import from the same module: merge `createJobWatch` and `jobWatch` into one line.
	31	import { createJobWatch, jobWatch } from "../src/perf/jobs.ts";
	32	import { loopWatch } from "../src/perf/live.ts";
	33	import { createLoopWatch, type Stall } from "../src/perf/loop.ts";
	34	import { loopWorst } from "../src/perf/loop_worst.ts";
	35	import { deploySettled } from "./helpers/apps-forge.ts";
	36
	37	const NOW = Date.parse("2026-11-10T12:00:00Z");
	38	const none: AppVitals = { today: 0, week: 0, ttfbP75: undefined, loadP75: undefined, lcpP75: undefined, inpP75: undefined, clsP75: undefined, loadDays: [] };
	39	const stall = (lateMs: number, routes: string[], jobs: string[] = []): Stall => ({ at: 0, lateMs, routes, jobs });
	40
	41	beforeEach(() => clearRelayWaits());
	42
	43	describe("what held a wait", () => {
	44	test("a synthetic stall attributed to a job names it, on the card and the terminal line", () => {
	45	// A clock the test steps: the job's synchronous slice runs 0..600, the wake sees it at 600.
	46	let t = 0;
	47	const jobs = createJobWatch(() => t);
	48	const watch = createLoopWatch(250, jobs.across);
	49	jobs.during("sweep-runs", () => {
	50	t = 600;
	51	});
	52	const s = watch.stalled(600, 600)!;
	53	expect(s.jobs).toEqual(["sweep-runs"]);
	54	// The window the relay reads: the lag's 10 s before it.
	55	const held = heldBy(watch.within(600 - 10_000, 600));
	56	expect(held).toEqual([{ name: "job:sweep-runs", ms: 600 }]);
	57	// 820 ms to headers, 600 of it the forge's: the wait was the forge's, held by the job.
	58	noteRelayWait("a1", 820, 600, NOW, held);
	59	const wait = relayWait("a1", NOW)!;
	60	expect(wait.forge).toBe(true);
	61	const words = "the forge was busy: 600 ms of the 820 ms wait, held by job:sweep-runs (600 ms)";
	62	expect(relayWaitWords(wait)).toBe(words);
	63	expect(visitorsLine({ ...none, wait })).toEndWith(` · slowest wait, 10 min: ${words}`);
	64	expect(String(appVisitorsView({ ...none, wait }))).toContain(`<dd>${words}</dd>`);
	65	});
	66
	67	test("nothing is named when the wait was the app's own", () => {
	68	// 1.5 s to headers, 40 ms lag: forgeWaited is false, so a stall handed in is dropped.
	69	noteRelayWait("a1", 1500, 40, NOW, [{ name: "/explore", ms: 300 }]);
	70	const wait = relayWait("a1", NOW)!;
	71	expect(wait.forge).toBe(false);
	72	expect(wait.held).toEqual([]);
	73	expect(relayWaitWords(wait)).toBe("1.5 s, the app's own");
	74	expect(visitorsLine({ ...none, wait })).not.toContain("held by");
	75	});
	76
	77	test("the longest stall first, each name once, at most HELD_NAMES, the unnamed dropped", () => {
	78	const held = heldBy([
	79	stall(300, ["/explore"]),
	80	stall(900, ["/:owner/:name", "/explore"]),
	81	stall(400, [], []),
	82	stall(500, [], ["backup"]),
	83	stall(350, ["/robots.txt"]),
	84	]);
	85	expect(held).toEqual([
	86	{ name: "/:owner/:name", ms: 900 },
	87	{ name: "/explore", ms: 900 },
	88	{ name: "job:backup", ms: 500 },
	89	]);
	90	expect(held.length).toBe(HELD_NAMES);
	91	expect(heldBy([stall(400, [], [])])).toEqual([]);
	92	});
	93
	94	test("desc is always a pattern: no ids, no query, nothing to escape", () => {
	95	for (const ok of ["/", "/explore", "/:owner/:name/*", "/explore#read", "job:sweep-runs", "(unmatched)"])
	96	expect(isStallPattern(ok)).toBe(true);
	97	for (const bad of ["/explore?q=secret", 'job:"x"', "/a b", "/a;dur=1", "/a,b", "none", "", "alice/repo", `/${"a".repeat(200)}`, "/a\\b"])
	98	expect(isStallPattern(bad)).toBe(false);
	99	// A name that is not a pattern is never held, so never told.
	100	expect(heldBy([stall(900, ["/issues?id=01HXYZ", "/explore"])])).toEqual([{ name: "/explore", ms: 900 }]);
	101	expect(stallTiming([{ name: "/explore", ms: 1226.84 }, { name: "job:sweep", ms: 300 }])).toBe(
	102	'forge-stall;desc="/explore";dur=1226.8, forge-stall;desc="job:sweep";dur=300.0',
	103	);
	104	expect(stallTiming([{ name: "/x?y", ms: 1 }])).toBe("");
	105	});
	106
	107	test("within reads the window's stalls, newest first", () => {
	108	const watch = createLoopWatch(250);
	109	watch.stalled(300, 1_000);
	110	watch.stalled(400, 5_000);
	111	watch.stalled(500, 12_000);
	112	expect(watch.within(2_000, 12_000).map((s) => s.at)).toEqual([12_000, 5_000]);
	113	expect(watch.within(13_000, 20_000)).toEqual([]);
	114	});
	115	});
	116
	117	describe("forge-stall on the relayed answer", () => {
	118	const DOMAIN = "apps.test";
	119	let dataDir: string;
	120	let app: App;
	121	let servers: Servers;
	122	let runtime: AppsRuntime;
	123	let alice: User;
	124	let bob: User;
	125	let repo: Repo;
	126
	127	beforeAll(async () => {
	128	dataDir = await mkdtemp(join(tmpdir(), "forge-stallname-"));
	129	app = createApp({ dataDir, port: 0 });
	130	servers = await serve(app);
	131	runtime = new AppsRuntime(app, { domain: DOMAIN, scheme: "http", publicPort: servers.port, forgeUrl: servers.url });
	132	await runtime.start();
	133	const a = await createUser(app.db, { origin: "seed", trusted: true, username: "alice", email: "[email protected]", password: "a-good-passphrase", adminIfFirst: true });
	134	if (!a.ok) throw new Error(a.error);
	135	alice = a.value;
	136	const b = await createUser(app.db, { origin: "seed", trusted: true, username: "bob", email: "[email protected]", password: "a-good-passphrase" });
	137	if (!b.ok) throw new Error(b.error);
	138	bob = b.value;
	139	const made = await newApp(app, alice, { name: "hello", description: "d", visibility: "public" });
	140	if (!made.ok) throw new Error(String(made.error));
	141	repo = made.value.repo;
	142	expect((await deploySettled(app, repo.id, (r) => r.env === "production")).state).toBe("ok");
	143	}, 120_000);
	144
	145	afterAll(async () => {
	146	await runtime.stop();
	147	servers.stop();
	148	app.close();
	149	await rm(dataDir, { recursive: true, force: true });
	150	});
	151
	152	/** A request to the app as `who` (a grant cookie), or as a visitor with none. */
		sentinelcrew 7h ago outdated A 1 s synchronous busy-wait blocks the whole test process and depends on other suites' leftover stalls. Make it shorter or isolate the window (e.g. clear the loop watch's hour first) so it is fast and deterministic.
	153	const asViewer = (who: User \| undefined) => {
	154	const record = getAppByRepo(app.db, repo.id)!;
	155	const headers: Record<string, string> = { host: `hello.${DOMAIN}`, accept: "text/plain" };
	156	if (who !== undefined) {
	157	const grant = signGrant(app.config.dataDir, { app: record, env: "production" }, 60_000, Date.now(), {
	158	id: who.id,
	159	name: who.username,
	160	role: who.isAdmin ? "admin" : "user",
	161	});
	162	headers.cookie = `forge_grant_${record.id.slice(-8)}=${grant}`;
	163	}
	164	return fetch(`${servers.url}/`, { headers, redirect: "manual" });
	165	};
	166
	167	/**
	168	* A synthetic stall of `ms` as job `name`, noted where a real one lands:
	169	* the lag window (`forge-lag`) and the loop watch the relay reads. Nothing
	170	* blocks the loop, so the test takes no time and the stall is exactly `ms`.
	171	*/
	172	const stallAsJob = (name: string, ms: number) => {
	173	jobWatch.during(name, () => {});
	174	const now = performance.now();
	175	loopWorst.note(ms, now);
	176	const s = loopWatch.stalled(ms, now)!;
	177	// A route that ran across it outranks the job (setup's requests often do);
	178	// the job's own naming is pinned above, with a stepped clock.
	179	return heldBy([s])[0]!.name;
	180	};
	181
	182	test("a forge admin sees the stall's pattern; a visitor and a signed-in non-admin do not", async () => {
	183	// 1 s: longer than any stall another suite in this process leaves in the window.
	184	const name = stallAsJob("stall-name-test", 1_000);
	185	expect(isStallPattern(name)).toBe(true);
	186	{
	187	const admin = await asViewer(alice);
	188	expect(admin.status).toBe(200);
	189	const timing = admin.headers.get("server-timing")!;
	190	expect(timing).toContain(`forge-stall;desc="${name}";dur=1000.0`);
	191	// Every desc a pattern, never a path's id or query.
	192	for (const m of timing.matchAll(/forge-stall;desc="([^"]*)"/g)) expect(isStallPattern(m[1]!)).toBe(true);
	193	// An admin's copy is never kept by a shared cache.
	194	expect(admin.headers.get("cache-control")).toBe("private, no-store");
	195	// The speed card names it too.
	196	expect(visitorsLine(appVisitors(app, alice, repo)!)).toContain(`${name} (1.0 s)`);
	197
	198	for (const who of [undefined, bob]) {
	199	const res = await asViewer(who);
	200	expect(res.status).toBe(200);
	201	const header = res.headers.get("server-timing") ?? "";
	202	// The wait was the forge's (forge-lag is there) but the stall is not told.
	203	expect(header).toContain("forge-lag;dur=");
	204	expect(header).not.toContain("forge-stall");
	205	expect(header).not.toContain("job:");
	206	}
	207	}
	208	});
	209	});