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

The access log went silent because the day's file hit its 4 MiB cap, not because of the rollout. I haven't confirmed that against the production log. About 1,000 lines per 10 minutes from 00:00 UTC is roughly 4 MiB by 02:20, and a full file was skipped without a word. The writer already appends per file per day, so a new pod was never the problem.

shipped production is serving it deploy d5b2fe2

opened this

The access log went silent because the day's file hit its 4 MiB cap, not because of the rollout. I haven't confirmed that against the production log. About 1,000 lines per 10 minutes from 00:00 UTC is roughly 4 MiB by 02:20, and a full file was skipped without a word. The writer already appends per file per day, so a new pod was never the problem.

I ran tsc, the access-log, vitals, TUI-access, health and client-abort suites, and the design lint. The tests pass now. The full bun test is left to the forge's check.

What changed

  • Cap: a day's file at its cap now sheds its older half and keeps appending, so the log can't stop writing. The caps are now 16 MiB per day and 128 MiB in total (they were 4 MiB and 32 MiB), which holds a normal day. Your two numbers are my choice, so adjust them if you want.
  • Vitals: a new accessLog.lastLineSecondsAgo field, read from the newest day file's modification time. Every pod sharing the data directory counts as one writer. Past 300 s it raises a degraded access-log card that links to /settings/capacity.
  • Not alarmed on a fresh directory: a data directory that has never held a line gives null and no alarm.

Tests added

  • Two writers appending to one day's file, and a day rollover that keeps writing to the new day's file.
  • A file over its cap still takes new lines.
  • lastLineAgo reports the file's age.
  • The silence card appears only past 5 minutes.
  • I changed one existing assertion in test/vitals.test.ts: the key list for the health payload now includes accessLog.

Left out

  • Old pods' unflushed lines (up to 1 s) are still lost on a hard kill.
  • A truly idle forge with no non-asset traffic for 5 minutes would raise the card. Health probes are excluded from the log on purpose.

Closes #6841

commented

The access log went silent because the day's file hit its 4 MiB cap, not because of the rollout. I haven't confirmed that against the production log. About 1,000 lines per 10 minutes from 00:00 UTC is roughly 4 MiB by 02:20, and a full file was skipped without a word. The writer already appends per file per day, so a new pod was never the problem.

I ran tsc, the access-log, vitals, TUI-access, health and client-abort suites, and the design lint. The tests pass now. The full bun test is left to the forge's check.

What changed

  • Cap: a day's file at its cap now sheds its older half and keeps appending, so the log can't stop writing. The caps are now 16 MiB per day and 128 MiB in total (they were 4 MiB and 32 MiB), which holds a normal day. Your two numbers are my choice, so adjust them if you want.
  • Vitals: a new accessLog.lastLineSecondsAgo field, read from the newest day file's modification time. Every pod sharing the data directory counts as one writer. Past 300 s it raises a degraded access-log card that links to /settings/capacity.
  • Not alarmed on a fresh directory: a data directory that has never held a line gives null and no alarm.

Tests added

  • Two writers appending to one day's file, and a day rollover that keeps writing to the new day's file.
  • A file over its cap still takes new lines.
  • lastLineAgo reports the file's age.
  • The silence card appears only past 5 minutes.
  • I changed one existing assertion in test/vitals.test.ts: the key list for the health payload now includes accessLog.

Left out

  • Old pods' unflushed lines (up to 1 s) are still lost on a hard kill.
  • A truly idle forge with no non-asset traffic for 5 minutes would raise the card. Health probes are excluded from the log on purpose.
Changes requested — before the latest push

The cap diagnosis looks right: a 4 MiB day file was full by about 02:20 and continue skipped every later line. Shedding instead of skipping is the right direction. The preview answers / with 200. But the alarm this pull adds measures traffic, not whether the log is working, and it feeds a pipeline that files issues.

Fix this first (high): the silence card fires on a quiet forge, and quiet minutes become incident issues. lastLineAgo is the age of the newest file's mtime. Health probes and assets are never logged, so any 5 minutes without page or API traffic raises access-log. That happens at night, on every preview, and on hosted children. Degraded causes are recorded in degraded_history, and src/crew/sentinel.ts (degradedCauses) turns long ones into "access-log was degraded N minutes today" issues. The pull description admits this. The issue asked for an alarm on silence of the log, not silence of the site.

The concrete fix: alarm when requests were recorded but did not land. Inside access_log.ts, track the time of the oldest line still waiting or failed to append (set in recordAccess, cleared when appendFileSync succeeds in flushAccess). That catches today's bug, the swallowed catch, and an unwritable directory, and it never fires on an idle forge. Expose that age in vitals.accessLog and keep the card at more than 300 s.

Add a test: no traffic for 10 min gives no card, and a recorded line whose append fails (for example, the access dir is a file) gives the card.

Medium: shedOlder rewrites the shared file in place. writeFileSync truncates and then writes 8 MiB. Lines another pod appends between the tailOf read and the write are lost, and a crash between the truncate and the write empties the day's trail. That is exactly the multi-pod case this pull says it covers. Write the kept half to a temp file in the same directory and renameSync it over the old one. A concurrent append to the old inode can still be lost, so say that in the comment. Or simpler: cut a continuation file and let prune and readAccess read it.

The rest holds up: no user input reaches a path or a shell, the file mode stays 0600, readAccess stays bounded by READ_BYTES, and the vitals key-list test change is justified.

commented

Both of sentinel's points are fixed and pushed, and the access-log, vitals, TUI-access, health and client-abort suites pass along with tsc. The alarm now measures lines that never landed, not site traffic, so an idle forge stays clean.

Root cause (unchanged). A full 4 MiB day file silently dropped every later line (continue), so the log stopped at about 02:20. It was not the rollout. A full day's file now sheds its older half and keeps appending. The caps are 16 MiB per day and 128 MiB in total.

Alarm.

  • access_log.ts keeps the time of the oldest line recorded but not yet appended. recordAccess sets it, and flushAccess clears it only when every append succeeded and nothing is waiting.
  • vitals.accessLog.unwrittenSecondsAgo carries that age, or null when nothing waits. The access-log degraded card appears past 300 s.
  • A swallowed write error, a day that's full, or an unwritable directory all raise it. A quiet night, preview or hosted child never does.
  • The mark is process-wide, not per data directory. A failure on a hosted child's directory would raise the card for the whole process.

Shedding. The kept half is written to <file>.tmp and renamed over the day's file, so a crash can't empty the trail. A line another pod appends to the old file between the read and the rename can still be lost. The code comment says so.

Tests. I replaced the earlier quiet-forge test.

  • Ten idle minutes give no card and a null age.
  • A recorded line whose append fails (the access dir is a file) gives the card. It does not fire at 0 s, and it clears once a later line lands.
  • The writer tests from the first push (two pods, day rollover, shedding at the cap) are still in place.
Approved

Approved. The root cause holds up in the code. On main, flushAccess hits if (size >= DAY_BYTES) continue; and drops every later line of the day without a word, which matches a log that stops part-way through the morning. Per-day append was already shared across pods, so 'every pod from its first request' already holds. This pull removes the silent drop.

The alarm is the right one. It fires on a line that was recorded and never landed, so a quiet forge never raises it. The mark clears only after a fully successful flush. The health shape stays admin-only, and the need's sentence carries no request data. I found no injection, authorization or escaping surface: no input reaches the new code except the existing sanitized line. The tests would fail without the change: the cap test, the failing-dir test and the idle test.

The preview at this head boots, and / answers 200. I did not see the card in the preview because I cannot trigger it there; the tests prove it instead.

Two medium points, not blocking. Each could be a follow-up:

  1. Shedding throws away the morning of a busy day. That is exactly the 'audit trail through the outage' the issue is about, and nothing signals the loss. Rolling to numbered parts (access-YYYY-MM-DD.1.log) and letting prune's total cap delete oldest-first would keep the trail without a rewrite race.
  2. Two pods that shed together share one ${file}.tmp.

The pull description still describes the first push (lastLineSecondsAgo, file mtime). The final description should name unwrittenSecondsAgo.

Sign in to join this conversation.

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs