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
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/6841-the-access-log-has-been-silent-since-02 → main 2 commits fork 5 threads · 5 unresolved
src/http/access_log.ts +44 −4
| @@ -12,7 +12,7 @@ | ||
| 12 | 12 | * other than the user agent, cookies, bodies and queries are never read. |
| 13 | 13 | * |
| 14 | 14 | * 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 | |
| 16 | 16 | * by any route; the owner reads it through `readAccess` (a settings page and |
| 17 | 17 | * the `access` MCP tool). |
| 18 | 18 | */ |
| @@ -21,19 +21,23 @@ import { | ||
| 21 | 21 | appendFileSync, |
| 22 | 22 | mkdirSync, |
| 23 | 23 | readdirSync, |
| 24 | renameSync, | |
| 24 | 25 | closeSync, |
| 25 | 26 | openSync, |
| 26 | 27 | readSync, |
| 27 | 28 | statSync, |
| 28 | 29 | unlinkSync, |
| 30 | writeFileSync, | |
| 29 | 31 | } from "node:fs"; |
| 30 | 32 | import { createHmac } from "node:crypto"; |
| 31 | 33 | import { join } from "node:path"; |
| 32 | 34 | import { loadKey } from "../kernel/secret.ts"; |
| 33 | 35 | |
| 34 | 36 | 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; | |
| 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; | |
| 37 | 41 | const UA_MAX = 200; |
| 38 | 42 | const PATH_MAX = 200; |
| 39 | 43 | const HOST_MAX = 100; |
| @@ -171,6 +175,36 @@ export function prune(dataDir: string, at: Date): void { | ||
| 171 | 175 | } |
| 172 | 176 | } |
| 173 | 177 | |
| 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 |
||
| 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 |
||
| 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 | ||
| 174 | 208 | /** |
| 175 | 209 | * Lines waiting for the next flush, by the day's file they belong to, with |
| 176 | 210 | * 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 { | ||
| 187 | 221 | timer = undefined; |
| 188 | 222 | const batches = [...pending]; |
| 189 | 223 | pending.clear(); |
| 224 | let failed = false; | |
| 190 | 225 | for (const [file, { dataDir, lines }] of batches) { |
| 191 | 226 | try { |
| 192 | 227 | const dir = accessDir(dataDir); |
| @@ -202,12 +237,16 @@ export function flushAccess(at: Date = new Date()): void { | ||
| 202 | 237 | } catch { |
| 203 | 238 | // no file yet |
| 204 | 239 | } |
| 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 |
||
| 206 | 242 | appendFileSync(file, lines.join(""), { mode: 0o600 }); |
| 207 | 243 | } catch { |
| 208 | 244 | // the log is a convenience; the request is the work |
| 245 | failed = true; | |
| 209 | 246 | } |
| 210 | 247 | } |
| 248 | // The mark clears only when every line landed and none wait. | |
| 249 | if (!failed && pending.size === 0) unwritten = undefined; | |
| 211 | 250 | } |
| 212 | 251 | |
| 213 | 252 | /** |
| @@ -222,6 +261,7 @@ export function recordAccess( | ||
| 222 | 261 | try { |
| 223 | 262 | const line = lineFor(dataDir, seen, at); |
| 224 | 263 | if (line === undefined) return; |
| 264 | unwritten ??= at.getTime(); | |
| 225 | 265 | const file = fileOf(accessDir(dataDir), dayOf(at)); |
| 226 | 266 | const queued = pending.get(file) ?? { dataDir, lines: [] }; |
| 227 | 267 | queued.lines.push(`${JSON.stringify(line)}\n`); |
src/kernel/vitals.ts +14
| @@ -32,6 +32,7 @@ import { rollbackNeed } from "../release/launch.ts"; | ||
| 32 | 32 | import { behindStanding } from "../release/behind.ts"; |
| 33 | 33 | import { newestDrills } from "../core/domain_drills.ts"; |
| 34 | 34 | import { capacityValue } from "../core/capacity.ts"; |
| 35 | import { unwrittenFor, SILENT_AFTER_S } from "../http/access_log.ts"; | |
| 35 | 36 | import { DOMAINS } from "./domains.ts"; |
| 36 | 37 | import { domainDrillNeeds } from "./domain_drill.ts"; |
| 37 | 38 | import { freeChecks, heldChecks, redHref, redSentence } from "../checks/red_main.ts"; |
| @@ -109,6 +110,8 @@ export interface Vitals { | ||
| 109 | 110 | readonly errors: { lastHour: number; latest: ErrorLine[] }; |
| 110 | 111 | /** Tests that failed in main's check and passed alone this week: a list, never a need (#6643). */ |
| 111 | 112 | 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 }; | |
| 112 | 115 | readonly at: string; |
| 113 | 116 | } |
| 114 | 117 | |
| @@ -470,6 +473,16 @@ export function vitals(input: VitalsInput): Vitals { | ||
| 470 | 473 | const lagging = behindStanding(now); |
| 471 | 474 | if (lagging !== undefined) need("release:behind", `${lagging.sentence}.`, lagging.since, "/board"); |
| 472 | 475 | |
| 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 |
||
| 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 | ||
| 473 | 486 | const apps = { serving: 0, asleep: 0, previews: 0 }; |
| 474 | 487 | for (const e of input.envs ?? []) { |
| 475 | 488 | if (e.env !== "production") apps.previews++; |
| @@ -514,6 +527,7 @@ export function vitals(input: VitalsInput): Vitals { | ||
| 514 | 527 | apps, |
| 515 | 528 | errors: { lastHour: seen.lastHour, latest: seen.latest }, |
| 516 | 529 | flakes: flakeList(input.db, now), |
| 530 | accessLog: { unwrittenSecondsAgo: quiet ?? null }, | |
| 517 | 531 | at, |
| 518 | 532 | }; |
| 519 | 533 | } |
test/access-log.test.ts +72
| @@ -16,6 +16,9 @@ import { createUser } from "../src/core/users.ts"; | ||
| 16 | 16 | import { |
| 17 | 17 | accessDir, |
| 18 | 18 | clientHash, |
| 19 | DAY_BYTES, | |
| 20 | unwrittenFor, | |
| 21 | SILENT_AFTER_S, | |
| 19 | 22 | flushAccess, |
| 20 | 23 | keptPath, |
| 21 | 24 | prune, |
| @@ -295,3 +298,72 @@ describe("the access log and app hostnames", () => { | ||
| 295 | 298 | } |
| 296 | 299 | }); |
| 297 | 300 | }); |
| 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 @@ | ||
| 2 | 2 | |
| 3 | 3 | import { laneSentence } from "../src/kernel/vitals.ts"; |
| 4 | 4 | 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"; | |
| 5 | 7 | import { mkdtemp, rm } from "node:fs/promises"; |
| 6 | 8 | import { tmpdir } from "node:os"; |
| 7 | 9 | 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 | ||
| 91 | 93 | const v = (await res.json()) as Record<string, any>; |
| 92 | 94 | expect(Object.keys(v).sort()).toEqual( |
| 93 | 95 | [ |
| 96 | "accessLog", | |
| 94 | 97 | "apps", "at", "checkedAt", "commit", "degraded", "disk", "draining", "errors", "flakes", |
| 95 | 98 | "incidents", "lane", "memory", "needs", "ok", "queue", "rollout", "stale", "stuck", |
| 96 | 99 | "version", |
| @@ -487,3 +490,32 @@ test("laneSentence says one lane for one slot and names the slots in force for s | ||
| 487 | 490 | "4 checks wait for 3 slots, none busy; the oldest since 01:04; nothing runs.", |
| 488 | 491 | ); |
| 489 | 492 | }); |
| 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 | }); |
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.