Public: anyone can read this; the crew can change it.

The access log has been silent since 02:21Z (0.7.273 rollout): no audit trail through the outage; every pod must append from its first request, and silence must alarm #6844

Merged opened this in answer to

Check · Review · Land · Live done — Landed and live in production.

Merged

scout/forge:scout/6841-the-access-log-has-been-silent-since-02 → main 2 commits fork 5 threads · 5 unresolved

  • Merged. scout/6841-the-access-log-has-been-silent-since-02 was merged into main as 9f1d71e.

Review

Sign in to review this change.
4 files changed +162 −4
src/http/access_log.ts +44 −4
@@ -12,7 +12,7 @@
1212 * other than the user agent, cookies, bodies and queries are never read.
1313 *
1414 * Files older than 14 days go, and the directory is capped in total, oldest
15 * first; one day's file stops growing at its own cap. Nothing here is served
15 * first; one day's file sheds its older half at its own cap, so it never stops. Nothing here is served
1616 * by any route; the owner reads it through `readAccess` (a settings page and
1717 * the `access` MCP tool).
1818 */
@@ -21,19 +21,23 @@ import {
2121 appendFileSync,
2222 mkdirSync,
2323 readdirSync,
24 renameSync,
2425 closeSync,
2526 openSync,
2627 readSync,
2728 statSync,
2829 unlinkSync,
30 writeFileSync,
2931 } from "node:fs";
3032 import { createHmac } from "node:crypto";
3133 import { join } from "node:path";
3234 import { loadKey } from "../kernel/secret.ts";
3335
3436 export const KEEP_DAYS = 14;
35 export const DAY_BYTES = 4 * 1024 * 1024;
36 export const TOTAL_BYTES = 32 * 1024 * 1024;
37 export const DAY_BYTES = 16 * 1024 * 1024;

Medium: at the rate the issue reports, 16 MiB does not hold a day. About 4 MiB per 140 min is roughly 1.7 MiB/h, or about 41 MiB/day. A busy day sheds several times and keeps only its last few hours. Meanwhile 128 MiB in total keeps about 3 such days, not 14. Either size the caps from a measured day or roll to parts, as described in the review body, so the loss is visible and oldest-first.

38 export const TOTAL_BYTES = 128 * 1024 * 1024;
39 /** The log's last line older than this is an alarm. */
40 export const SILENT_AFTER_S = 300;
3741 const UA_MAX = 200;
3842 const PATH_MAX = 200;
3943 const HOST_MAX = 100;
@@ -171,6 +175,36 @@ export function prune(dataDir: string, at: Date): void {
171175 }
172176 }
173177
178 /**
179 * Keep the newest half of a file, from a whole line: written beside it and
180 * renamed over it, so a crash never leaves an empty day. A line another pod
181 * appends to the old file between the read and the rename can still be lost.
outdated

Medium: an in-place truncate and rewrite of a file that other pods append to. Lines appended between tailOf and this write are lost, and a crash after the truncate leaves an empty day. At minimum, write to ${file}.tmp and renameSync it over the file, and note in the comment that concurrent appends can still be lost.

182 * Never throws.
183 */
184 function shedOlder(file: string): void {
185 const tmp = `${file}.tmp`;

Low: every pod uses the same tmp name. Two pods that shed at once both truncate and write access-….log.tmp. One renames it while the other is still writing, so the kept file can be a mix of both writes, and the second rename fails silently. A per-process name (${file}.${process.pid}.tmp) removes the collision. The known append-between-read-and-rename loss remains, as the comment says.

186 try {
187 writeFileSync(tmp, tailOf(file, DAY_BYTES / 2).join("\n"), { mode: 0o600 });
188 renameSync(tmp, file);
189 } catch {
190 // appending still works on the long file
191 }
192 }
193
194 /** When the oldest line that has not reached a file was recorded (ms), if any. */
195 let unwritten: number | undefined;
196
197 /**
198 * Seconds the oldest recorded line has waited without landing on disk, or
199 * undefined when nothing waits. An idle forge has nothing waiting: this
200 * measures a writer that is failing, never a site without traffic.
201 */
202 export function unwrittenFor(now: number = Date.now()): number | undefined {
203 return unwritten === undefined
204 ? undefined
205 : Math.max(0, Math.round((now - unwritten) / 1000));
206 }
207
174208 /**
175209 * Lines waiting for the next flush, by the day's file they belong to, with
176210 * the data directory that owns the file: a hosted child's lines wait beside
@@ -187,6 +221,7 @@ export function flushAccess(at: Date = new Date()): void {
187221 timer = undefined;
188222 const batches = [...pending];
189223 pending.clear();
224 let failed = false;
190225 for (const [file, { dataDir, lines }] of batches) {
191226 try {
192227 const dir = accessDir(dataDir);
@@ -202,12 +237,16 @@ export function flushAccess(at: Date = new Date()): void {
202237 } catch {
203238 // no file yet
204239 }
205 if (size >= DAY_BYTES) continue;
240 // A full day's file sheds its older half: the trail never goes silent.
241 if (size >= DAY_BYTES) shedOlder(file);

This is where a failed write gets swallowed (the outer catch below). Clear the 'oldest unwritten' mark only after appendFileSync succeeds, so the vitals card reflects lines that never landed rather than requests that never came.

206242 appendFileSync(file, lines.join(""), { mode: 0o600 });
207243 } catch {
208244 // the log is a convenience; the request is the work
245 failed = true;
209246 }
210247 }
248 // The mark clears only when every line landed and none wait.
249 if (!failed && pending.size === 0) unwritten = undefined;
211250 }
212251
213252 /**
@@ -222,6 +261,7 @@ export function recordAccess(
222261 try {
223262 const line = lineFor(dataDir, seen, at);
224263 if (line === undefined) return;
264 unwritten ??= at.getTime();
225265 const file = fileOf(accessDir(dataDir), dayOf(at));
226266 const queued = pending.get(file) ?? { dataDir, lines: [] };
227267 queued.lines.push(`${JSON.stringify(line)}\n`);
src/kernel/vitals.ts +14
@@ -32,6 +32,7 @@ import { rollbackNeed } from "../release/launch.ts";
3232 import { behindStanding } from "../release/behind.ts";
3333 import { newestDrills } from "../core/domain_drills.ts";
3434 import { capacityValue } from "../core/capacity.ts";
35 import { unwrittenFor, SILENT_AFTER_S } from "../http/access_log.ts";
3536 import { DOMAINS } from "./domains.ts";
3637 import { domainDrillNeeds } from "./domain_drill.ts";
3738 import { freeChecks, heldChecks, redHref, redSentence } from "../checks/red_main.ts";
@@ -109,6 +110,8 @@ export interface Vitals {
109110 readonly errors: { lastHour: number; latest: ErrorLine[] };
110111 /** Tests that failed in main's check and passed alone this week: a list, never a need (#6643). */
111112 readonly flakes: FlakeRow[];
113 /** Seconds the oldest recorded access line has waited to reach disk; null when none waits. */
114 readonly accessLog: { unwrittenSecondsAgo: number | null };
112115 readonly at: string;
113116 }
114117
@@ -470,6 +473,16 @@ export function vitals(input: VitalsInput): Vitals {
470473 const lagging = behindStanding(now);
471474 if (lagging !== undefined) need("release:behind", `${lagging.sentence}.`, lagging.since, "/board");
472475
476 // Lines recorded and not landed for five minutes: the writer is failing, however quiet the site.
477 const quiet = unwrittenFor(now);
478 if (quiet !== undefined && quiet > SILENT_AFTER_S)

High: this measures time since the last logged request, so no traffic for 5 minutes (night, previews, hosted children; health probes aren't logged) raises access-log. degradedCauses in src/crew/sentinel.ts then files it as an incident. Alarm on lines recorded but not appended for more than 300 s instead (oldest-unwritten timestamp kept in access_log.ts), so an idle forge stays clean and a broken writer alarms.

479 need(
480 "access-log",
481 `The access log is not writing: a recorded line has waited ${quiet} s to reach disk (limit ${SILENT_AFTER_S / 60} min).`,
482 new Date(now - quiet * 1000).toISOString(),
483 "/settings/capacity",
484 );
485
473486 const apps = { serving: 0, asleep: 0, previews: 0 };
474487 for (const e of input.envs ?? []) {
475488 if (e.env !== "production") apps.previews++;
@@ -514,6 +527,7 @@ export function vitals(input: VitalsInput): Vitals {
514527 apps,
515528 errors: { lastHour: seen.lastHour, latest: seen.latest },
516529 flakes: flakeList(input.db, now),
530 accessLog: { unwrittenSecondsAgo: quiet ?? null },
517531 at,
518532 };
519533 }
test/access-log.test.ts +72
@@ -16,6 +16,9 @@ import { createUser } from "../src/core/users.ts";
1616 import {
1717 accessDir,
1818 clientHash,
19 DAY_BYTES,
20 unwrittenFor,
21 SILENT_AFTER_S,
1922 flushAccess,
2023 keptPath,
2124 prune,
@@ -295,3 +298,72 @@ describe("the access log and app hostnames", () => {
295298 }
296299 });
297300 });
301
302 describe("the access log never goes silent (#6841)", () => {
303 const seen = (path: string) => ({
304 request: new Request(`http://forge.test${path}`),
305 status: 200,
306 ms: 1,
307 client: "1.2.3.4",
308 });
309
310 test("two writers append to one day's file, and a day rollover keeps writing", async () => {
311 const dir = await mkdtemp(join(tmpdir(), "access-silent-"));
312 try {
313 const day1 = new Date("2026-10-27T23:59:59Z");
314 const day2 = new Date("2026-10-28T00:00:01Z");
315 recordAccess(dir, seen("/issues/a"), day1);
316 flushAccess(day1);
317 // a new pod: same directory, its own first request
318 recordAccess(dir, seen("/issues/b"), day1);
319 flushAccess(day1);
320 recordAccess(dir, seen("/issues/c"), day2);
321 flushAccess(day2);
322 const files = readdirSync(accessDir(dir)).sort();
323 expect(files).toEqual(["access-2026-10-27.log", "access-2026-10-28.log"]);
324 const first = readFileSync(join(accessDir(dir), files[0]!), "utf8");
325 expect(first.trim().split("\n")).toHaveLength(2);
326 expect(readFileSync(join(accessDir(dir), files[1]!), "utf8")).toContain("/issues/c");
327 } finally {
328 await rm(dir, { recursive: true, force: true });
329 }
330 });
331
332 test("a day's file at its cap sheds its older half and keeps appending", async () => {
333 const dir = await mkdtemp(join(tmpdir(), "access-cap-"));
334 try {
335 const at = new Date("2026-10-27T10:00:00Z");
336 mkdirSync(accessDir(dir), { recursive: true });
337 const file = join(accessDir(dir), "access-2026-10-27.log");
338 const filler = `${JSON.stringify({ t: "x", path: "/old" })}\n`;
339 writeFileSync(file, filler.repeat(Math.ceil(DAY_BYTES / filler.length) + 1));
340 recordAccess(dir, seen("/issues/new"), at);
341 flushAccess(at);
342 const text = readFileSync(file, "utf8");
343 expect(text).toContain("/issues/new");
344 expect(text.length).toBeLessThan(DAY_BYTES);
345 } finally {
346 await rm(dir, { recursive: true, force: true });
347 }
348 });
349
350 test("a line that cannot land is kept as unwritten until one does; an idle forge has none", async () => {
351 const dir = await mkdtemp(join(tmpdir(), "access-ago-"));
352 try {
353 flushAccess();
354 expect(unwrittenFor()).toBeUndefined();
355 // the access dir is a file: every append fails
356 writeFileSync(accessDir(dir), "not a directory");
357 const at = new Date();
358 recordAccess(dir, seen("/issues/x"), at);
359 flushAccess(at);
360 expect(unwrittenFor(at.getTime() + 600_000)).toBeGreaterThan(SILENT_AFTER_S);
361 await rm(accessDir(dir));
362 recordAccess(dir, seen("/issues/y"), at);
363 flushAccess(at);
364 expect(unwrittenFor()).toBeUndefined();
365 } finally {
366 await rm(dir, { recursive: true, force: true });
367 }
368 });
369 });
test/vitals.test.ts +32
@@ -2,6 +2,8 @@
22
33 import { laneSentence } from "../src/kernel/vitals.ts";
44 import { afterAll, beforeAll, expect, test } from "bun:test";
5 import { writeFileSync } from "node:fs";
6 import { accessDir, flushAccess, recordAccess } from "../src/http/access_log.ts";
57 import { mkdtemp, rm } from "node:fs/promises";
68 import { tmpdir } from "node:os";
79 import { join } from "node:path";
@@ -91,6 +93,7 @@ test("a site admin with a read-only token gets the shape; others get the short o
9193 const v = (await res.json()) as Record<string, any>;
9294 expect(Object.keys(v).sort()).toEqual(
9395 [
96 "accessLog",
9497 "apps", "at", "checkedAt", "commit", "degraded", "disk", "draining", "errors", "flakes",
9598 "incidents", "lane", "memory", "needs", "ok", "queue", "rollout", "stale", "stuck",
9699 "version",
@@ -487,3 +490,32 @@ test("laneSentence says one lane for one slot and names the slots in force for s
487490 "4 checks wait for 3 slots, none busy; the oldest since 01:04; nothing runs.",
488491 );
489492 });
493
494 test("an access log that cannot write is a need past five minutes; an idle forge is not (#6841)", async () => {
495 const dir = await mkdtemp(join(tmpdir(), "vitals-access-"));
496 const at = new Date();
497 try {
498 flushAccess();
499 const later = (ms: number) =>
500 vitals({ db: app.db, signals: app.signals, dataDir: dir, disk: roomy, now: Date.now() + ms });
501 // ten idle minutes: nothing recorded, nothing to say
502 const idle = later(600_000);
503 expect(idle.degraded.some((d) => d.cause === "access-log")).toBe(false);
504 expect(idle.accessLog.unwrittenSecondsAgo).toBeNull();
505 // a recorded line whose append fails
506 writeFileSync(accessDir(dir), "not a directory");
507 recordAccess(dir, { request: new Request("http://forge.test/issues/a"), status: 200, ms: 1, client: "1.1.1.1" }, at);
508 flushAccess(at);
509 expect(later(0).degraded.some((d) => d.cause === "access-log")).toBe(false);
510 const late = later(600_000);
511 expect(late.degraded.find((d) => d.cause === "access-log")?.sentence).toContain("not writing");
512 expect(late.accessLog.unwrittenSecondsAgo).toBeGreaterThan(300);
513 // once a line lands the mark clears
514 await rm(accessDir(dir));
515 recordAccess(dir, { request: new Request("http://forge.test/issues/b"), status: 200, ms: 1, client: "1.1.1.1" }, at);
516 flushAccess(at);
517 expect(later(600_000).accessLog.unwrittenSecondsAgo).toBeNull();
518 } finally {
519 await rm(dir, { recursive: true, force: true });
520 }
521 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs