b4afca2
@@ -1985,6 +1985,7 @@
export function serve(options: ServeOptions) {
    // own error page, which carries source and paths, and never without
    // the headers. The detail goes to the log, where it belongs.
    error(error) {
      // Inside the generated app, which has no forge log module.
      console.error(error);
      return html("<h1>Something went wrong</h1>", 500);
    },
@@ -3304,6 +3305,7 @@
export function lint(root: string): string[] {
if (import.meta.main) {
  const problems = lint(join(import.meta.dir, ".."));
  // Generated app's lint CLI: stderr is its output.
  for (const problem of problems) console.error(problem);
  process.exit(problems.length === 0 ? 0 : 1);
}
@@ -3390,6 +3392,7 @@
export function record(db: Database, attempt: Attempt): void {
      Number(lastInsertRowid) - KEEP,
    );
  } catch (error) {
    // Generated app: one JSON line to stderr, its own log.
    console.error(
      JSON.stringify({
        audit: row,
@@ -4220,6 +4223,7 @@
test("contract/openapi.json is what the routes say now (else: bun run contract:e
  const now = JSON.parse(emit());
  const stale = !Bun.deepEquals(JSON.parse(committed), now);
  if (stale)
    // Generated app's contract CLI: stderr is its output.
    console.error(
      "contract/openapi.json is stale: run \`bun run contract:emit\` and commit it",
    );
@@ -10,6 +10,7 @@
import { isHookName, runHookClient } from "./hooks.ts";
const name = process.argv[process.argv.length - 1];
if (!isHookName(name)) {
  // Git relays a hook's stderr to the pusher; it must be stderr.
  console.error(`forge: unknown hook ${name}`);
  process.exit(1);
}
@@ -84,6 +84,7 @@
export const HOOK_RELAY_TIMEOUT_MS = 120_000;
export async function runHookClient(hook: HookName): Promise<never> {
  const socket = process.env.FORGE_SOCKET;
  if (!socket) {
    // Hook stderr is shown to the pusher by git; it must be stderr.
    console.error("forge hook: FORGE_SOCKET unset");
    process.exit(1);
  }
@@ -115,10 +116,12 @@
export async function runHookClient(hook: HookName): Promise<never> {
      }),
    });
    const text = await response.text();
    // The relayed refusal text, for the pusher to read.
    if (text !== "") console.error(text);
    process.exit(response.ok ? 0 : 1);
  } catch (error) {
    // pre-receive fails closed: an unreachable forge must not admit a push.
    // Hook stderr is shown to the pusher by git.
    console.error(`forge: hook relay failed (${String(error)})`);
    process.exit(hook === "pre-receive" ? 1 : 0);
  }
@@ -47,6 +47,62 @@
export function logLevel(): LogLevel {
  return threshold;
}
/** The most recent error lines kept in memory; older ones fall off. */
export const ERROR_RING = 100;
const HOUR_MS = 3_600_000;
const MINUTE_MS = 60_000;
export interface ErrorLine {
  readonly at: string;
  readonly scope: string;
  readonly message: string;
}
const ring: ErrorLine[] = [];
/** scope → minute bucket → count: an hour of counts in at most 61 buckets per scope. */
const buckets = new Map<string, Map<number, number>>();
function prune(now: number): void {
  const floor = Math.floor((now - HOUR_MS) / MINUTE_MS);
  for (const [scope, minutes] of buckets) {
    for (const minute of minutes.keys()) if (minute <= floor) minutes.delete(minute);
    if (minutes.size === 0) buckets.delete(scope);
  }
}
function record(scope: string, message: string, now: number): void {
  ring.push({ at: new Date(now).toISOString(), scope, message });
  if (ring.length > ERROR_RING) ring.splice(0, ring.length - ERROR_RING);
  prune(now);
  const minutes = buckets.get(scope) ?? new Map<number, number>();
  const minute = Math.floor(now / MINUTE_MS);
  minutes.set(minute, (minutes.get(minute) ?? 0) + 1);
  buckets.set(scope, minutes);
}
/** Errors in the last hour, in total and per scope, and the newest lines first. */
export function recentErrors(
  limit = 5,
  now = Date.now(),
): { lastHour: number; byScope: Record<string, number>; latest: ErrorLine[] } {
  prune(now);
  const byScope: Record<string, number> = {};
  let lastHour = 0;
  for (const [scope, minutes] of buckets) {
    let n = 0;
    for (const c of minutes.values()) n += c;
    byScope[scope] = n;
    lastHour += n;
  }
  return { lastHour, byScope, latest: ring.slice(-limit).reverse() };
}
/** Forget everything kept. For tests. */
export function clearErrors(): void {
  ring.length = 0;
  buckets.clear();
}
export function createLog(scope: string): Log {
  const emit = (level: LogLevel, message: string, fields?: LogFields) => {
    if (order[level] < order[threshold]) return;
@@ -59,6 +115,10 @@
export function createLog(scope: string): Log {
      }
    }
    line = redactSecrets(line);
    if (level === "error") {
      const body = line.slice(line.indexOf(`[${scope}] `) + scope.length + 3);
      record(scope, body, Date.now());
    }
    console[level === "debug" ? "log" : level](line);
  };
  return {
@@ -9,11 +9,14 @@
import type { Database } from "bun:sqlite";
import { statfsSync } from "node:fs";
import { freemem, totalmem } from "node:os";
import { recentErrors, type ErrorLine } from "./log.ts";
import { leaseLapsed, listRunning, queueDepth } from "../core/runs.ts";
import { STALE_AFTER_MS } from "../runs/lease.ts";
/** Free disk under this share of the volume is something to say. */
export const DISK_FREE_MIN = 0.1;
/** This many error lines in an hour is a burst worth saying. */
export const ERROR_BURST = 20;
/** A run still running this long after it started is stuck even if it breathes. */
export const NO_PROGRESS_MS = 6 * 3_600_000;
/** A run that has waited this long to start is a queue that is not moving. */
@@ -41,6 +44,7 @@
export interface Vitals {
    since: string;
  }[];
  readonly apps: { serving: number; asleep: number; previews: number };
  readonly errors: { lastHour: number; latest: ErrorLine[] };
  readonly at: string;
}
@@ -99,6 +103,12 @@
export function vitals(input: VitalsInput): Vitals {
    else if (e.state === "running") apps.serving++;
  }
  const seen = recentErrors(5, now);
  if (seen.lastHour >= ERROR_BURST)
    needs.push(
      `${seen.lastHour} errors in the last hour (${ERROR_BURST} or more is a burst).`,
    );
  return {
    ok: needs.length === 0,
    needs,
@@ -111,6 +121,7 @@
export function vitals(input: VitalsInput): Vitals {
    queue,
    stuck,
    apps,
    errors: { lastHour: seen.lastHour, latest: seen.latest },
    at: new Date(now).toISOString(),
  };
}
@@ -34,6 +34,7 @@
import { pruneTokens } from "./core/tokens.ts";
if (process.argv[2] === "hook") {
  const name = process.argv[3];
  if (!isHookName(name)) {
    // CLI message on stderr for the person at the terminal.
    console.error(`forge: unknown hook ${name}`);
    process.exit(1);
  }
@@ -95,6 +95,7 @@
export async function restoreSnapshot(
if (import.meta.main) {
  const [name, dataDir] = process.argv.slice(2);
  if (!name || !dataDir) {
    // CLI usage on stderr for the person at the terminal, not a forge event.
    console.error(
      "usage: bun run src/snapshot/restore.ts <snapshot-name> <data-dir>",
    );
@@ -104,6 +105,7 @@
if (import.meta.main) {
  const s3 = s3FromEnv();
  const store = dir ? dirStore(dir) : s3 ? s3Store(s3) : undefined;
  if (store === undefined) {
    // CLI message on stderr for the person at the terminal.
    console.error(
      "no store: set S3_* as the forge has them, or FORGE_SNAPSHOT_DIR",
    );
@@ -40,6 +40,7 @@
const username = flag("user");
const user =
  username === undefined ? undefined : getUserByName(forge.db, username);
if (username !== undefined && user === undefined) {
  // CLI message on stderr for the person at the terminal.
  console.error(`forge: no such user: ${username}`);
  process.exit(1);
}
@@ -267,6 +267,7 @@
export class TerminalSession {
    const fatal = (e: unknown): void => {
      this.leave();
      // The terminal is restored; now let the error be seen normally.
      // Terminal is restored; the crash goes to the user's own stderr.
      console.error(e);
      process.exit(1);
    };
@@ -78,7 +78,7 @@
test("a site admin with a read-only token gets the shape; others get a 404", asy
  expect(res.status).toBe(200);
  const v = (await res.json()) as Record<string, any>;
  expect(Object.keys(v).sort()).toEqual(
    ["apps", "at", "disk", "memory", "needs", "ok", "queue", "stuck"].sort(),
    ["apps", "at", "disk", "errors", "memory", "needs", "ok", "queue", "stuck"].sort(),
  );
  expect(v.disk.totalBytes).toBeGreaterThan(0);
  expect(v.memory.rssBytes).toBeGreaterThan(0);
@@ -139,3 +139,35 @@
test("the number of queries does not grow with runs", () => {
  expect(count()).toBe(before);
  expect(before).toBe(2);
});
test("errors are counted, bounded, redacted, and a burst is said", async () => {
  const { createLog, clearErrors, recentErrors, ERROR_RING } = await import(
    "../src/kernel/log.ts"
  );
  const { ERROR_BURST } = await import("../src/kernel/vitals.ts");
  const orig = console.error;
  console.error = () => {};
  try {
    clearErrors();
    const log = createLog("probe");
    log.error("upstream refused", { token: "ghp_abcdefghijklmnop1234567890" });
    const v = (await (await health(admin)).json()) as ReturnType<typeof vitals>;
    expect(v.errors.lastHour).toBe(1);
    expect(v.errors.latest[0]!.scope).toBe("probe");
    const text = JSON.stringify(v);
    expect(text).toContain("[redacted]");
    expect(text).not.toContain("ghp_abcdefghijklmnop1234567890");
    expect(v.needs.some((n) => n.includes("errors in the last hour"))).toBe(false);
    for (let i = 0; i < ERROR_RING + 50; i++) log.error(`boom ${i}`);
    const seen = recentErrors(1000);
    expect(seen.latest.length).toBe(ERROR_RING);
    expect(seen.lastHour).toBe(ERROR_RING + 51);
    expect(seen.lastHour).toBeGreaterThanOrEqual(ERROR_BURST);
    expect(vitals({ db: app.db, dataDir }).needs.some((n) => n.includes("errors in the last hour"))).toBe(true);
    expect(vitals({ db: app.db, dataDir, now: Date.now() + 2 * 3_600_000 }).errors.lastHour).toBe(0);
  } finally {
    console.error = orig;
    clearErrors();
  }
});
		@@ -1985,6 +1985,7 @@ export function serve(options: ServeOptions) {
1985	1985	// own error page, which carries source and paths, and never without
1986	1986	// the headers. The detail goes to the log, where it belongs.
1987	1987	error(error) {
	1988	// Inside the generated app, which has no forge log module.
1988	1989	console.error(error);
1989	1990	return html("<h1>Something went wrong</h1>", 500);
1990	1991	},
		@@ -3304,6 +3305,7 @@ export function lint(root: string): string[] {
3304	3305
3305	3306	if (import.meta.main) {
3306	3307	const problems = lint(join(import.meta.dir, ".."));
	3308	// Generated app's lint CLI: stderr is its output.
3307	3309	for (const problem of problems) console.error(problem);
3308	3310	process.exit(problems.length === 0 ? 0 : 1);
3309	3311	}
		@@ -3390,6 +3392,7 @@ export function record(db: Database, attempt: Attempt): void {
3390	3392	Number(lastInsertRowid) - KEEP,
3391	3393	);
3392	3394	} catch (error) {
	3395	// Generated app: one JSON line to stderr, its own log.
3393	3396	console.error(
3394	3397	JSON.stringify({
3395	3398	audit: row,
		@@ -4220,6 +4223,7 @@ test("contract/openapi.json is what the routes say now (else: bun run contract:e
4220	4223	const now = JSON.parse(emit());
4221	4224	const stale = !Bun.deepEquals(JSON.parse(committed), now);
4222	4225	if (stale)
	4226	// Generated app's contract CLI: stderr is its output.
4223	4227	console.error(
4224	4228	"contract/openapi.json is stale: run \`bun run contract:emit\` and commit it",
4225	4229	);
		@@ -10,6 +10,7 @@ import { isHookName, runHookClient } from "./hooks.ts";
10	10
11	11	const name = process.argv[process.argv.length - 1];
12	12	if (!isHookName(name)) {
	13	// Git relays a hook's stderr to the pusher; it must be stderr.
13	14	console.error(`forge: unknown hook ${name}`);
14	15	process.exit(1);
15	16	}
		@@ -84,6 +84,7 @@ export const HOOK_RELAY_TIMEOUT_MS = 120_000;
84	84	export async function runHookClient(hook: HookName): Promise<never> {
85	85	const socket = process.env.FORGE_SOCKET;
86	86	if (!socket) {
	87	// Hook stderr is shown to the pusher by git; it must be stderr.
87	88	console.error("forge hook: FORGE_SOCKET unset");
88	89	process.exit(1);
89	90	}
		@@ -115,10 +116,12 @@ export async function runHookClient(hook: HookName): Promise<never> {
115	116	}),
116	117	});
117	118	const text = await response.text();
	119	// The relayed refusal text, for the pusher to read.
118	120	if (text !== "") console.error(text);
119	121	process.exit(response.ok ? 0 : 1);
120	122	} catch (error) {
121	123	// pre-receive fails closed: an unreachable forge must not admit a push.
	124	// Hook stderr is shown to the pusher by git.
122	125	console.error(`forge: hook relay failed (${String(error)})`);
123	126	process.exit(hook === "pre-receive" ? 1 : 0);
124	127	}
		@@ -47,6 +47,62 @@ export function logLevel(): LogLevel {
47	47	return threshold;
48	48	}
49	49
	50	/** The most recent error lines kept in memory; older ones fall off. */
	51	export const ERROR_RING = 100;
	52	const HOUR_MS = 3_600_000;
	53	const MINUTE_MS = 60_000;
	54
	55	export interface ErrorLine {
	56	readonly at: string;
	57	readonly scope: string;
	58	readonly message: string;
	59	}
	60
	61	const ring: ErrorLine[] = [];
	62	/** scope → minute bucket → count: an hour of counts in at most 61 buckets per scope. */
	63	const buckets = new Map<string, Map<number, number>>();
	64
	65	function prune(now: number): void {
	66	const floor = Math.floor((now - HOUR_MS) / MINUTE_MS);
	67	for (const [scope, minutes] of buckets) {
	68	for (const minute of minutes.keys()) if (minute <= floor) minutes.delete(minute);
	69	if (minutes.size === 0) buckets.delete(scope);
	70	}
	71	}
	72
	73	function record(scope: string, message: string, now: number): void {
	74	ring.push({ at: new Date(now).toISOString(), scope, message });
	75	if (ring.length > ERROR_RING) ring.splice(0, ring.length - ERROR_RING);
	76	prune(now);
	77	const minutes = buckets.get(scope) ?? new Map<number, number>();
	78	const minute = Math.floor(now / MINUTE_MS);
	79	minutes.set(minute, (minutes.get(minute) ?? 0) + 1);
	80	buckets.set(scope, minutes);
	81	}
	82
	83	/** Errors in the last hour, in total and per scope, and the newest lines first. */
	84	export function recentErrors(
	85	limit = 5,
	86	now = Date.now(),
	87	): { lastHour: number; byScope: Record<string, number>; latest: ErrorLine[] } {
	88	prune(now);
	89	const byScope: Record<string, number> = {};
	90	let lastHour = 0;
	91	for (const [scope, minutes] of buckets) {
	92	let n = 0;
	93	for (const c of minutes.values()) n += c;
	94	byScope[scope] = n;
	95	lastHour += n;
	96	}
	97	return { lastHour, byScope, latest: ring.slice(-limit).reverse() };
	98	}
	99
	100	/** Forget everything kept. For tests. */
	101	export function clearErrors(): void {
	102	ring.length = 0;
	103	buckets.clear();
	104	}
	105
50	106	export function createLog(scope: string): Log {
51	107	const emit = (level: LogLevel, message: string, fields?: LogFields) => {
52	108	if (order[level] < order[threshold]) return;
		@@ -59,6 +115,10 @@ export function createLog(scope: string): Log {
59	115	}
60	116	}
61	117	line = redactSecrets(line);
	118	if (level === "error") {
	119	const body = line.slice(line.indexOf(`[${scope}] `) + scope.length + 3);
	120	record(scope, body, Date.now());
	121	}
62	122	console[level === "debug" ? "log" : level](line);
63	123	};
64	124	return {
		@@ -9,11 +9,14 @@
9	9	import type { Database } from "bun:sqlite";
10	10	import { statfsSync } from "node:fs";
11	11	import { freemem, totalmem } from "node:os";
	12	import { recentErrors, type ErrorLine } from "./log.ts";
12	13	import { leaseLapsed, listRunning, queueDepth } from "../core/runs.ts";
13	14	import { STALE_AFTER_MS } from "../runs/lease.ts";
14	15
15	16	/** Free disk under this share of the volume is something to say. */
16	17	export const DISK_FREE_MIN = 0.1;
	18	/** This many error lines in an hour is a burst worth saying. */
	19	export const ERROR_BURST = 20;
17	20	/** A run still running this long after it started is stuck even if it breathes. */
18	21	export const NO_PROGRESS_MS = 6 * 3_600_000;
19	22	/** A run that has waited this long to start is a queue that is not moving. */
		@@ -41,6 +44,7 @@ export interface Vitals {
41	44	since: string;
42	45	}[];
43	46	readonly apps: { serving: number; asleep: number; previews: number };
	47	readonly errors: { lastHour: number; latest: ErrorLine[] };
44	48	readonly at: string;
45	49	}
46	50
		@@ -99,6 +103,12 @@ export function vitals(input: VitalsInput): Vitals {
99	103	else if (e.state === "running") apps.serving++;
100	104	}
101	105
	106	const seen = recentErrors(5, now);
	107	if (seen.lastHour >= ERROR_BURST)
	108	needs.push(
	109	`${seen.lastHour} errors in the last hour (${ERROR_BURST} or more is a burst).`,
	110	);
	111
102	112	return {
103	113	ok: needs.length === 0,
104	114	needs,
		@@ -111,6 +121,7 @@ export function vitals(input: VitalsInput): Vitals {
111	121	queue,
112	122	stuck,
113	123	apps,
	124	errors: { lastHour: seen.lastHour, latest: seen.latest },
114	125	at: new Date(now).toISOString(),
115	126	};
116	127	}
		@@ -34,6 +34,7 @@ import { pruneTokens } from "./core/tokens.ts";
34	34	if (process.argv[2] === "hook") {
35	35	const name = process.argv[3];
36	36	if (!isHookName(name)) {
	37	// CLI message on stderr for the person at the terminal.
37	38	console.error(`forge: unknown hook ${name}`);
38	39	process.exit(1);
39	40	}
		@@ -95,6 +95,7 @@ export async function restoreSnapshot(
95	95	if (import.meta.main) {
96	96	const [name, dataDir] = process.argv.slice(2);
97	97	if (!name \|\| !dataDir) {
	98	// CLI usage on stderr for the person at the terminal, not a forge event.
98	99	console.error(
99	100	"usage: bun run src/snapshot/restore.ts <snapshot-name> <data-dir>",
100	101	);
		@@ -104,6 +105,7 @@ if (import.meta.main) {
104	105	const s3 = s3FromEnv();
105	106	const store = dir ? dirStore(dir) : s3 ? s3Store(s3) : undefined;
106	107	if (store === undefined) {
	108	// CLI message on stderr for the person at the terminal.
107	109	console.error(
108	110	"no store: set S3_* as the forge has them, or FORGE_SNAPSHOT_DIR",
109	111	);
		@@ -40,6 +40,7 @@ const username = flag("user");
40	40	const user =
41	41	username === undefined ? undefined : getUserByName(forge.db, username);
42	42	if (username !== undefined && user === undefined) {
	43	// CLI message on stderr for the person at the terminal.
43	44	console.error(`forge: no such user: ${username}`);
44	45	process.exit(1);
45	46	}
		@@ -267,6 +267,7 @@ export class TerminalSession {
267	267	const fatal = (e: unknown): void => {
268	268	this.leave();
269	269	// The terminal is restored; now let the error be seen normally.
	270	// Terminal is restored; the crash goes to the user's own stderr.
270	271	console.error(e);
271	272	process.exit(1);
272	273	};
		@@ -78,7 +78,7 @@ test("a site admin with a read-only token gets the shape; others get a 404", asy
78	78	expect(res.status).toBe(200);
79	79	const v = (await res.json()) as Record<string, any>;
80	80	expect(Object.keys(v).sort()).toEqual(
81		["apps", "at", "disk", "memory", "needs", "ok", "queue", "stuck"].sort(),
	81	["apps", "at", "disk", "errors", "memory", "needs", "ok", "queue", "stuck"].sort(),
82	82	);
83	83	expect(v.disk.totalBytes).toBeGreaterThan(0);
84	84	expect(v.memory.rssBytes).toBeGreaterThan(0);
		@@ -139,3 +139,35 @@ test("the number of queries does not grow with runs", () => {
139	139	expect(count()).toBe(before);
140	140	expect(before).toBe(2);
141	141	});
	142
	143	test("errors are counted, bounded, redacted, and a burst is said", async () => {
	144	const { createLog, clearErrors, recentErrors, ERROR_RING } = await import(
	145	"../src/kernel/log.ts"
	146	);
	147	const { ERROR_BURST } = await import("../src/kernel/vitals.ts");
	148	const orig = console.error;
	149	console.error = () => {};
	150	try {
	151	clearErrors();
	152	const log = createLog("probe");
	153	log.error("upstream refused", { token: "ghp_abcdefghijklmnop1234567890" });
	154	const v = (await (await health(admin)).json()) as ReturnType<typeof vitals>;
	155	expect(v.errors.lastHour).toBe(1);
	156	expect(v.errors.latest[0]!.scope).toBe("probe");
	157	const text = JSON.stringify(v);
	158	expect(text).toContain("[redacted]");
	159	expect(text).not.toContain("ghp_abcdefghijklmnop1234567890");
	160	expect(v.needs.some((n) => n.includes("errors in the last hour"))).toBe(false);
	161
	162	for (let i = 0; i < ERROR_RING + 50; i++) log.error(`boom ${i}`);
	163	const seen = recentErrors(1000);
	164	expect(seen.latest.length).toBe(ERROR_RING);
	165	expect(seen.lastHour).toBe(ERROR_RING + 51);
	166	expect(seen.lastHour).toBeGreaterThanOrEqual(ERROR_BURST);
	167	expect(vitals({ db: app.db, dataDir }).needs.some((n) => n.includes("errors in the last hour"))).toBe(true);
	168	expect(vitals({ db: app.db, dataDir, now: Date.now() + 2 * 3_600_000 }).errors.lastHour).toBe(0);
	169	} finally {
	170	console.error = orig;
	171	clearErrors();
	172	}
	173	});