Chat collection stores every server's log tail every 15s, faster than cleanup can delete it #62

Closed
opened 2026-10-08 16:33:29 -04:00 by goddard · 1 comment
Collaborator
  • The chat job (worker.ts:65) runs every 15 s and fetches the last 2,000 log lines from every server (chat.ts:113,126), even empty ones.
  • Each fetch is a logs.read agent operation. The whole reply (up to 256 KB) is stored in ec_host_operations.result (hosts/index.ts:603-613) and kept for a day by default. That's 5,760 stored log tails per server per day.
  • Cleanup deletes at most 500 of these every 5 minutes (retention.ts:298, worker.ts:29), or 144,000 a day. Above roughly 25 servers the table grows without limit; below that it still writes a day of log tails through SQLite.
  • Each pass also re-parses those lines plus up to 2,000 matches and 10,000 telemetry rows per server on the main thread.
  • While a host is offline, the job logs one error per server every 15 s.

Fix

  • Read only new log bytes since the last offset
  • Skip servers with no players or an unchanged log
  • Store only metadata for logs.read results, not the full reply
  • Let cleanup keep looping until it has caught up
- The `chat` job (`worker.ts:65`) runs every 15 s and fetches the last 2,000 log lines from every server (`chat.ts:113,126`), even empty ones. - Each fetch is a `logs.read` agent operation. The whole reply (up to 256 KB) is stored in `ec_host_operations.result` (`hosts/index.ts:603-613`) and kept for a day by default. That's 5,760 stored log tails per server per day. - Cleanup deletes at most 500 of these every 5 minutes (`retention.ts:298`, `worker.ts:29`), or 144,000 a day. Above roughly 25 servers the table grows without limit; below that it still writes a day of log tails through SQLite. - Each pass also re-parses those lines plus up to 2,000 matches and 10,000 telemetry rows per server on the main thread. - While a host is offline, the job logs one error per server every 15 s. **Fix** - [x] Read only new log bytes since the last offset - [x] Skip servers with no players or an unchanged log - [x] Store only metadata for `logs.read` results, not the full reply - [x] Let cleanup keep looping until it has caught up
goddard added the
priority
high
type/bug
labels 2026-10-08 16:39:09 -04:00
josh was assigned by goddard 2026-10-08 17:31:45 -04:00
Author
Collaborator

Reviewed c10f602e8e. All four fix items are done, so I'm closing this.

Checklist

  • Only new bytes are read. Agent 1.8.5 adds read_log_chunk (ec_agent.py:2244) and advertises logs.read-offset. After the first tail, the controller sends a cursor and gets back only the bytes appended since its offset (files.ts:90). A hash of the 256 bytes before the offset detects copy-truncate and regrowth, and a new inode or a shrunken file triggers a reset. Incomplete lines are buffered until their newline arrives. Local servers get the same logic in readLogChunk (logs.ts:62).
  • Empty servers and unchanged logs are skipped. collectFleetChat drops servers on disconnected hosts, stopped containers and servers reporting zero players (chat.ts:203-207), with one final read after the last player leaves. When the log hasn't changed, the agent returns no content and the controller skips parsing (chat.ts:182). The cursor survives the skip, so the next read picks up anything written in between.
  • Only metadata is stored for logs.read. reportHostOperationStatus stores logResultMetadata (size, mtime, line or byte count) instead of the reply (hosts/index.ts:619). The body goes only to the reader waiting on that operation, held in memory (hosts/index.ts:627,659). The waiter registers synchronously right after the operation is queued, so a fast agent reply can't arrive before it. A one-time pass in drainRetention also strips bodies from existing history and releases their blob references (retention.ts:322-333).
  • Cleanup loops until caught up. drainRetention (retention.ts:312) repeats pruneHistory and pruneSampleHistory until a pass removes nothing, yielding between batches. I checked every policy: each either deletes its rows or marks them (history_expired_at or retention_expirations) so its own selection excludes them, so the loop always ends. It still runs as a single flight every 5 minutes (worker.ts:67).

Review notes

  • Two good extra catches beyond the fix list. The chat timeline queries are now limited to the time span of the lines being parsed (chat.ts:21,34) instead of the last 2,000 matches and 10,000 telemetry rows. Offline hosts are skipped, and errors are logged at most once per server every 5 minutes (chat.ts:218). That also covers the issue's last two bullets.
  • Hosts on agents older than 1.8.5 still get a 2,000-line tail each pass until they update. It's no longer stored, and an unchanged size and mtime still skips parsing.
  • static/agent/ec-agent.py matches agent/ec_agent.py, and its SHA-256 matches manifest.json.
  • The 6 affected test files pass locally (66 tests), the agent suite passes (285 tests), and npm run check reports 0 errors.
  • Minor and non-blocking: if more than 256 KB is appended between reads (for example, after a server sat empty for a long time), catch-up takes one read per 256 KB, and until it finishes the chat view shows the entries from before the backlog (chat.ts:169). Worth a look only if that delay shows up in practice.
Reviewed c10f602e8ee961b48c4fc99c5e1882e62ff5839d. All four fix items are done, so I'm closing this. **Checklist** - [x] **Only new bytes are read.** Agent 1.8.5 adds `read_log_chunk` (`ec_agent.py:2244`) and advertises `logs.read-offset`. After the first tail, the controller sends a cursor and gets back only the bytes appended since its offset (`files.ts:90`). A hash of the 256 bytes before the offset detects copy-truncate and regrowth, and a new inode or a shrunken file triggers a reset. Incomplete lines are buffered until their newline arrives. Local servers get the same logic in `readLogChunk` (`logs.ts:62`). - [x] **Empty servers and unchanged logs are skipped.** `collectFleetChat` drops servers on disconnected hosts, stopped containers and servers reporting zero players (`chat.ts:203-207`), with one final read after the last player leaves. When the log hasn't changed, the agent returns no content and the controller skips parsing (`chat.ts:182`). The cursor survives the skip, so the next read picks up anything written in between. - [x] **Only metadata is stored for `logs.read`.** `reportHostOperationStatus` stores `logResultMetadata` (size, mtime, line or byte count) instead of the reply (`hosts/index.ts:619`). The body goes only to the reader waiting on that operation, held in memory (`hosts/index.ts:627,659`). The waiter registers synchronously right after the operation is queued, so a fast agent reply can't arrive before it. A one-time pass in `drainRetention` also strips bodies from existing history and releases their blob references (`retention.ts:322-333`). - [x] **Cleanup loops until caught up.** `drainRetention` (`retention.ts:312`) repeats `pruneHistory` and `pruneSampleHistory` until a pass removes nothing, yielding between batches. I checked every policy: each either deletes its rows or marks them (`history_expired_at` or `retention_expirations`) so its own selection excludes them, so the loop always ends. It still runs as a single flight every 5 minutes (`worker.ts:67`). **Review notes** - Two good extra catches beyond the fix list. The chat timeline queries are now limited to the time span of the lines being parsed (`chat.ts:21,34`) instead of the last 2,000 matches and 10,000 telemetry rows. Offline hosts are skipped, and errors are logged at most once per server every 5 minutes (`chat.ts:218`). That also covers the issue's last two bullets. - Hosts on agents older than 1.8.5 still get a 2,000-line tail each pass until they update. It's no longer stored, and an unchanged size and mtime still skips parsing. - `static/agent/ec-agent.py` matches `agent/ec_agent.py`, and its SHA-256 matches `manifest.json`. - The 6 affected test files pass locally (66 tests), the agent suite passes (285 tests), and `npm run check` reports 0 errors. - Minor and non-blocking: if more than 256 KB is appended between reads (for example, after a server sat empty for a long time), catch-up takes one read per 256 KB, and until it finishes the chat view shows the entries from before the backlog (`chat.ts:169`). Worth a look only if that delay shows up in practice.
Sign in to join this conversation.