fix(acpmux): a log read pages within a byte limit; raw Claude stream events are not logged

Merged
TE
16d ago
+696-45

The supervised acpmux daemon on huge-blue grew from 61 MB to about 1 GB in 24 minutes with no peer connected. Its heap held one 31 MB chat log (activity-indicators, 46,000 of its 50,000 records) three and four times over as serde_json::Value trees: the reply to a single _acpmux/events read of the whole log. acpmux session tail --since asks for 100,000 records in one page and names no byte limit, and the daemon built that page as records, then copied every record into a second tree for the reply, then serialized it.

The deferred log load isn't the cause: load_logs reads each log's tail past lastSeq and the queue kinds and keeps nothing else. Nothing per session holds parsed records after it.

What changes:

  • A page of _acpmux/events or _acpmux/attach ends at maxBytes of JSON: 1 MiB when the caller names none, at most 4 MiB (server/requests/events.rs). Callers already page through hasMore; the app's own pages are 128 and 256 KiB. The page's records move into the reply instead of being copied (into_event_value).
  • acpmux session tail --since pages through hasMore; turn_reply and last_replies ask for transcript records only in the largest page (maxBytes 4 MiB), so raw harness lines can't push a turn out of their page.
  • Clients that read a child's whole log page on hasMore: optchat-chief's acpmux::events (it went on only after a full 10,000-record page) and the mux host's AcpmuxClient.events (one request); both stop when a page doesn't move the cursor. The mux fake daemon pages the same way.
  • docs/acpmux-schema.json documents maxBytes (1 MiB default, 4 MiB max) for _acpmux/events and _acpmux/attach.
  • Raw claude.stream_event lines (text and tool-input deltas) are mostly not logged; the translated session/update records carry their content. They were 44,000 of the 54,000 records the daemon logged in those 24 minutes, and each one went to every subscriber and into every read of the log. Two kinds stay, because optchat-chief reads them back to time each model request (fold.rs time_request: headers_ms and ttft_ms): every main-agent message_start, and the first content_block_delta after it (per session, an AtomicBool in the tap). A subagent's stream lines (parent_tool_use_id) are never kept, so one streaming alongside the main agent can't take its first delta.
  • optchat-chief's TurnFold tells a subagent's translated update (text, thought, tool call) by its session (<acp>/<toolu>) alone. It used the last raw line before the update, which with the deltas gone would let a subagent's text into the turn's reply, or drop the main agent's text after a background subagent's raw line. A dropped line still counts as logged, so the agent host drops it as before.
  • A hub event's record is an Arc<EventRecord>: the broadcast channel clones it once per receiver, and that clone was a deep copy of the record's JSON for every connection.

Changelog

Fixed: the acpmux daemon no longer grows by hundreds of MB when a client reads a long chat log from its start.

Testing

tests/daemon_page_memory.rs runs the real daemon over a 40 MB Claude-shaped log (93,816 records, mostly raw stream events), reads it from the start the way acpmux session tail --since does, then on through hasMore, checks every record comes back once and in order, and budgets the daemon's peak resident growth (Linux VmHWM) at 64 MB.

Command: ./scripts/verify-cmux-tui-hosted.sh --filter a_long_log_read_from_its_start_is_paged_within_a_memory_budget

  • Red on the test commit a1367bd9 (run 39560315960, test (linux)): one page, page_rss_growth_mb: 1007, "reading the log grew the daemon by 1007 MB (budget 64 MB)".
  • With a 4 MiB default page (7e100cd6, run 39561304479): 11 pages, 95 MB growth, still red; hence the 1 MiB default.
  • Green on head 32fcff6c (run 39569327289, test (linux)): the 1 MiB pages stay within the 64 MB budget. The macOS job of these runs was still queued, so the test has only run on Linux. The same holds for every focused run on this PR.

tests/claude_stream_timing.rs drives the fake Claude Code (fake_claude.py timing-probe: two requests, each a message_start and several deltas) through the hub's connection and reads the log with _acpmux/events: each message_start and the first delta after it are in the log, no later delta.

Command: ./scripts/verify-cmux-tui-hosted.sh --filter a_claude_log_keeps_each_requests_start_and_first_delta_only

Also on head 55151b40: the page-memory test, now with the daemon under MALLOC_ARENA_MAX=2 so its peak doesn't track the host's core count, passes (run 39574501899, test (linux)); the optchat-chief suite passes, 452 tests (--filter optchat_chief, run 39574502542, optchat-chief tests (real daemon)); mux bun test passes, including the new host/tests/acpmux-events-paging.test.ts (run 39574487173).

Subagent lines, after review: claude_stream_timing.rs's probe puts a subagent's message_start and delta between each main start and its first delta (test 456b6017, fix dc6d6edc; green on dc6d6edc, run 39583057717, test (linux)). optchat-chief/tests/turn_fold_subagent.rs covers a subagent's text with no raw line before it and the main agent's text after a background subagent's raw line (tests 3889b57d and 510badbb before their fixes). The optchat-chief suite passes on head 10ba3235 (run 39591123585, optchat-chief tests (real daemon)). The red runs of these three test commits were not run: the shared GitHub REST quota was exhausted; their failures on the parent commits were traced by hand in review.

Known gap, not changed here: a background subagent's line that arrives after its task_notification removed it is translated under the main session, so TurnFold counts its text as the turn's. The fix belongs in the acpmux translator.

Observed / Not run

Observed: the heap of the live huge-blue daemon (pid 704218, read through /proc/PID/mem without stopping it). Uuids of every record of the activity-indicators log appear 3 to 4 times; a 4,000-record window of another chat appears too. About 714 MB of its 1.1 GB of writable pages are mostly-zero pages of 632-byte BTreeMap<String, Value> leaf nodes, the serde_json object nodes. I couldn't tell live objects from freed ones the allocator kept (zig-built musl), so the share of the 1 GB this read explains is an estimate: the test's 40 MB log read grew a daemon by 1007 MB, which is the same order.

Not run: the full acpmux suite (CI on this PR runs it); the macOS jobs of the focused runs (still queued); lint (linux) stops at a base clippy error in cmux-worktree-care (sort_by_key), so clippy didn't reach acpmux. cmux-next checks is red on Tier routing (CmuxNextHomeEngineTests is not a target in the Swift package graph), which this PR doesn't touch. No change was deployed to huge-blue, and its daemon wasn't restarted.

🤖 Generated with Claude Code

Agent session: cosmic-gray