acpmux: the event log through one append-only journal, behind store.journal (R-DURABILITY S2)

Merged
LA
2d ago
+2786-215

Summary

Stage 2 of the R-DURABILITY rewrite (design: handoff/rewrites/R-DURABILITY/DESIGN.md 3.3, 3.3a, 3.3b and 3.3c). It needs #33919 (the cmux-journal crate), merged into feat-cmux-next as da881c3b3c1.

Today no acpmux event-log append is synced. A line a client was told about (a queue edit, a permission decision, prompt_accepted, a status) reaches the disk only at the next flush, which runs at shutdown. So an OS crash or a power loss takes back every line since the daemon started its last flush (DESIGN E12). With store.journal on, each line goes to the chat's events/*.ndjson as before and then one record with the same line goes to <home>/journal/ (group commit, one sync per batch; a power loss takes back at most the last second, always a suffix). Readers, segment files and every file format stay as they are.

The switch store.journal is off by default. With it off, nothing changes, except that a journal left by a run with it on is first written into the logs (below).

What changes

  • cmux-journal: Journal::retire_through(lsn), the crate's one delete: it removes the journal segments that hold no record after the caller's compaction point (tests: a crash, process, OS or power loss, at every storage operation of a retirement). Journal::check_append(len): whether an append would be refused now (closed, behind), asked before the caller writes anything else.
  • acpmux/src/store/journal_store.rs (new), JournalStore over LocalStore:
    • append: under one lock, check_append, the line to the chat's log, then the record. So every record's line went to the log, and a refused line is never journaled. A log line may lack its record (a crash between the two, a record still in memory at a kill). Agent stream lines (in session/update, claude.*, codex.*) are Stream records, every other line is Ack.
    • checkpoint (<home>/journal-projected.json): every 30 s while the journal grew, past 64 MiB of it, at flush (shutdown) and before a retention commit. It syncs every log written since and the sessions folder, writes an LSN at or before the journal's durable end (temporary file, sync, rename, folder sync, every error checked), then retires the journal before it. A failed fsync (in it, at a log's close, or in flush_session) freezes it: it then returns an error (a retention commit does not go ahead), and the store asks the daemon to stop with a restart (Store::stop_reason, a select branch in daemon.rs), whose replay writes the logs again. Ten failed checkpoints in a row ask the same. So the journal past the checkpoint stays bounded.
    • recovery at open repairs each chat's log with its records after the checkpoint and never deletes a whole line or a folder: the log's lines and the journal's merge by seq (a line in both must be equal; a line only the log has stays; a line only the journal has goes in its place); only bytes that do not parse as a whole JSON line (a torn tail, a hole of zeros, a line a hole ran into a later one) are dropped. Every merged line is written again from the repair start, so the first checkpoint after a restart syncs bytes this process wrote (a killed daemon's writes may be in the page cache only; a failed sync's dropped pages still read back). The lines only the log holds from there are journaled and made durable before the cut, so a crash inside the repair loses no line. A chat whose folder is gone is not written again. A log that moved on without the journal (a line in both that differs, lines out of order: a run with the switch off or an older build after a crash) is left as it is, and the journal's lines go to <home>/journal-unapplied/, as do the lines of a chat whose log cannot be read or written; the open goes on.
    • delete: a forget record under the lock (the replay then drops the chat's earlier journaled lines), then the folder's removal off the lock, with no wait.
    • seal: the logs refuse writes and the journal syncs fully; the shutdown's flush then checkpoints.
    • The journal's files go through FencedStorage, which refuses writes under a lost home (config::refuse_lost_home). An unreadable checkpoint fails the open. The open waits up to 5 s for the journal lock (a restart overlaps the old daemon's exit). Crashed checkpoint temporaries are removed.
  • store::open with the switch off: a journal a run with it on left is replayed, checkpointed and retired first (journal_store::catch_up), so a crash with the switch on and a start with it off keep every acknowledged line.
  • LocalStore: append is serialize + append_line; sync_log; a failed fsync is a SyncFailed error; a failed sync at a log's close is noted.
  • MemoryStore and the store settings move to store/memory.rs and config/store_config.rs (a pure move, so the over-limit store.rs and config.rs do not grow). README lists store.journal.

Review fixes (independent review FIX at ab0e9535d9da, comment 6624439824)

findingfixregression test (red on the code before the fix)
1a the replay's cut deleted lines written with the switch off after a crashrecovery merges and repairs, never rebuilds; the switch-off start replays a left journal firstlines_written_with_the_switch_off_survive_turning_it_on_again, switching_off_after_a_crash_keeps_every_acknowledged_line
1b a kill while the writer syncs: lines in the log, records in memory, cut by the replaysamea_kill_while_the_journal_syncs_keeps_the_lines_the_log_got
1c lines flush_session synced whose records an OS crash took backsamea_line_flush_session_made_durable_survives_losing_its_record
1, a hole: lines only the log holds after a hole of zeros, also through a crash in the repairthey are journaled and durable before the cutan_os_crash_hole_is_repaired_and_the_lines_after_it_kept, a_crash_inside_a_repair_loses_no_line
2 the replay deleted a folder a rename put backthe replay never deletes a foldera_folder_put_back_after_a_delete_is_not_deleted_by_the_replay
3 a kill in a delete wrote the chat's last lines back into a new folderthe replay never makes a missing folder againa_kill_in_a_delete_leaves_the_chat_whole_or_gone
4 delete removed the folder under the appends' lock and waited up to 5 s on a Tokio workerremoval off the lock, no waita_delete_does_not_wait_for_the_journal_sync
5 a failed sync in a checkpoint did not freeze it; no bound when it keeps failingfreeze on a failed fsync, stop for a restart; ten failures in a row stop tooa_failed_log_sync_freezes_the_checkpoint, a_checkpoint_that_keeps_failing_asks_the_daemon_to_stop
6 one chat's folder error failed the open (every restart)that chat's lines go to journal-unapplied/, the open goes onone_chat_that_cannot_be_repaired_does_not_stop_the_open
7 the journal wrote past the lost-home fenceFencedStoragethe_journal_storage_refuses_a_lost_home
nit: Ahead after a normal crashthe checkpoint is never past the durable enda_crash_right_after_a_checkpoint_reports_no_damage
nit: an unreadable checkpoint read as LSN 0the open failsan_unreadable_checkpoint_fails_the_open
nit: the lock race at restartthe open waits up to 5 sthe_open_waits_for_the_previous_daemon_to_let_go_of_the_journal
nit: crashed checkpoint temporaries stayedremoved at opena_crashed_checkpoint_temporary_is_removed_at_open
nit: a lost cancel record wrote a refused line againlog first, then the record: no cancela_line_the_log_refused_is_never_written_later (kept)
nits: kind-index copy order, damage never cleared, frozen checkpoint returned Ok, on_written unused, READMEcopy removed before the cut; damage cleared after the next checkpoint; frozen returns an error; on_written removed; README entry(by reading; the frozen error is in the freeze test)

check_append has its own test in the crate: check_append_says_what_append_would_do.

Review 2 fixes (independent review FIX at dcfecade4df, comment 6629184957)

The logs' OS crash model in the tests now follows the syncs that ran (store/sync_model.rs, tests only): a segment keeps its length at its last sync that counts; a failed sync loses what was written since the one before, and a later sync does not bring it back; a cut ends a loss it removes. Every log segment sync goes through log_sync::sync_segment.

findingfixregression test (red on the code before the fix)
1a after a kill, the restart's first checkpoint retired records whose log lines were in the page cache onlythe repair writes every merged line again from the repair start; the checkpoint then syncs bytes this process wrotean_os_crash_after_a_restart_from_a_kill_keeps_every_acked_line
1b after a failed sync, the restart read the dropped pages back, wrote nothing, and its checkpoint retired the recordssamean_os_crash_after_a_restart_from_a_failed_sync_keeps_every_acked_line
2 a hole that starts inside a line made the repair leave the whole log as it wasa piece is a line only when it parses as one JSON value (piece_seq)a_hole_that_starts_inside_a_line_is_repaired (the reviewer's test)
3 a failed sync in flush_session did not freeze the checkpointits file sync is a SyncFailed; the journal store freezes on ita_failed_sync_in_flush_session_freezes_the_checkpoint
nit: no sync of events/ between a cut's removals and the lines written againcut_at syncs events/ after its removals, and the kind-index folder after its copies go(by reading)
nit: DESIGN.md said 256 MiB, the code stops after ten failuresDESIGN.md 3.3c says ten failures in a row(text)
nit: with the switch on, a line over 64 MiB is refusedthe README says it(text)

Found by the S2c A/B, fixed here: the hub's tap logs an ACP session/update under its sessionUpdate kind, so agent chunks were Ack records (a sync each). The record's method now says Stream (an_agent_chunk_is_a_stream_record; red a43e979ae39, fleet 2b6becd0; green ce8dcba5458, fleet 409c5cfa).

Risk: high

  • It adds deletes of user data, behind the default-off switch: the journal's retire_through (journal segments that a synced checkpoint covers), and the repair's cut of a chat's log, which removes only bytes that do not read and lines it writes back, after every line only the log held is durable in the journal.
  • Rollback: turn store.journal off. The next start writes the journal's lines into the logs first, then runs as today. An older build that does not know the journal reads the logs as they are; if it ran after a crash with the switch on, it misses at most the lines since the last checkpoint (30 s), and turning the switch on again later keeps every line that build wrote (a log that moved on is left as it is; the journal's lines go to journal-unapplied/).

Known gaps

  • Replies and events do not wait for their records to be durable yet: a client can be told about a line that a crash then takes back. S2c (the next PR, stacked on this one) holds each reply and acknowledged event until its record is durable.
  • A change the hub makes in memory before its record is appended can be seen before the record exists: a rename sets the chat's name, then appends renamed, so another connection's reply (a session list) can show the new name in that window, and a crash in it loses the rename that the reply showed. S2c's wait does not close it, because the reply can be built before the record is appended. S3 (chat metadata through the journal, due 2026-11-05 18:00Z) appends the metadata image under the chat's meta lock with the change, which closes it.
  • The daemon does not stop when the journal's writer ends (a panic on its thread); appends then fail and are logged. S2c makes the daemon stop for a restart.
  • The journal writer thread keeps the process's utility I/O policy. S2c measures acknowledged-reply latency under disk stress with and without it first (lead rule: a reply the person waits for never waits on a throttled sync).

Testing

acpmux store::journal_store_tests (the journal on the simulated file system cmux_journal::SimStorage; the chat logs are real files, and an OS crash of them follows the syncs that ran, store/sync_model.rs), 28 tests: the 6 below, the 17 regressions of review 1, the 4 of review 2 and the Stream class test.

  • a_line_the_store_says_is_durable_survives_an_os_crash, a_kill_keeps_every_line_once, a_deleted_chat_stays_deleted_after_a_crash, a_line_the_log_refused_is_never_written_later, a_line_after_the_seal_is_refused_and_never_written_later, a_chat_made_again_after_its_delete_keeps_its_files_through_a_replay.

cmux-journal: the retirement tests and check_append_says_what_append_would_do.

Red on the code before each fix:

  • First round, red on LocalStore (53e933431e0): fleet a736b8cd (hq run 41773493313): a_line_the_store_says_is_durable_survives_an_os_crash failed (lines 2..20 lost), in the full run and alone. At 00512a295dea: fleet dc9dde1c (hq run 41780243300): a_chat_made_again_after_its_delete_keeps_its_files_through_a_replay failed (None, wanted Some("again")).

  • Review regressions at e030f4fe402e: 17 of 17 new tests fail, each also alone, the 6 earlier ones pass: owned Mac aws-m4pro-4 fleet d8e7037d, Linux fleet 1c22175e (hq run 41791487676); the crate's check_append test: fleet 63604b26 (hq run 41791488139). The failures name the findings: the switch-off lines gone ([1..5], wanted [1..9]), a kill lost line 4, flush_session's line 3 gone, the put-back chat deleted ([]), a deleted chat back in part ([2]), the delete waited 5.0 s, the hole's last line gone ([1..9]), the open failed on chat-b's link, Ahead { journal_end: 1, from: 3 }, the lock not waited for, and so on.

  • The freeze test as it is now (it fails the log sync itself, 8b71b4f7a690): fleet 4addcf1e (hq run 41794281768): a_failed_log_sync_freezes_the_checkpoint failed ("a checkpoint after a failed sync went ahead"), also alone.

  • Review 2 regressions at d2c63860ece (red): owned Mac aws-m4pro-7, fleet bec8251c, and Linux, fleet 17755e95 (hq run 41825080459): the 4 new tests fail, each also alone, the other 24 pass. 1a and 1b give [1] (wanted [1..5]), 2 gives [1, 2, 3, 4, 5, 9] (wanted [1..9]), 3 "a checkpoint after a failed sync in flush_session went ahead".

  • The Stream class test at a43e979ae39 (red): fleet 2b6becd0, the agent chunk read back as Ack.

Green at the head 3273b2ade1f81deb90a9367229ffb85040af4d6a (feat-cmux-next merged twice with scripts/merge-main.sh: 3b245c15615 merges b43ce2b4ae2, with one conflict in daemon.rs's module list, feat's term_sender from #35147 and S2's stop_causes, both kept; 3273b2ade1f merges d3d5a6246ab cleanly):

  • fleet 22f1a1fe (Linux, hq run 41832790237): all store::: fmt, clippy and 317 of 317 tests pass.
  • fleet b65e73b6 (Linux) and 8cdb6cd0 (owned Mac aws-m4pro-7): journal_store_tests 28 of 28.
  • fleet 8196015c (owned Mac aws-m4pro-6): daemon 821 of 822; the one failure is the base red acpmux_daemon_idle_has_no_periodic_wakeups (below).

Green at the previous head 84f9c266975af5eec7216f751ea055e279ba7467 (the head the review 3 SHIP names):

  • fleet a380f52d (owned Mac): journal_store_tests 28 of 28. fleet 490a1dae (Linux, hq run 41826018179): 28 of 28.
  • fleet 9b3ba15b (Linux, hq run 41826017850): all store::: fmt pass, tests 316 of 316 (filter store::); clippy red only at cmux-tui/crates/cmux-tui/tests/link_push_bench.rs:59 (type_complexity), the base red from #34538.
  • fleet 9b985930 (owned Mac): daemon tests 810 of 812. acpmux_daemon_idle_has_no_periodic_wakeups fails the same way on the merge base d422b94b60d alone (fleet 6c027917: an idle daemon woke 8, 3 and 4 times per 10 s window): a base red. router_exits_when_its_daemon_is_killed failed once in the full run (set_read_timeout EINVAL at tests/router_lifetime.rs:248, the router had already closed the socket) and passed on its rerun; it passes alone on the base too (fleet bfb4e48d): a timing flake, not this PR.

Green at the previous head dcfecade4df4421713ec773e0255ccde78d28cf3 (the review fix merged with feat-cmux-next d422b94b60d, which holds #33919 as da881c3b3c1; the cmux-journal files conflicted only as add/add, and feat's copy equals the S1 head 51cfdee876b):

  • fleet 89e53e31 (hq run 41800044755): all store: fmt green, tests 616 of 616 passed. Its only red step is clippy at cmux-tui/crates/cmux-tui/tests/link_push_bench.rs:59 (type_complexity): a base red from #34538 (586595362c2), a file this PR does not touch; S2c's server step (335b7dac) has the same single red.
  • fleet 64fc71c9 (owned Mac aws-m4pro-7): journal_store_tests 23 of 23, cmux-tui-rust-check: green.
  • fleet 74864ef6: panic ratchet green; no hit names a file of this PR, and cmux-journal has no line.
  • fleet 104f7e6b: daemon tests 815 of 816. The one failure, a_daemon_whose_home_is_removed_stops (ENOTEMPTY when the test removes the daemon's home), fails the same way on feat d422b94b60d alone (fleet e0522147, hq run 41803060724): a base red, owned by BASE RED ACPMUX (a bisect of 3a436460eaa1..d422b94b60d); this PR does not touch it. It passed at this branch before the feat merge (fleet 5f5c5b49, hq run 41796145764).
  • Before the merge, at 7a8bbdce62c: fleet 6798b9c1 (hq run 41798793202) all store green (fmt, clippy, 592 of 592); at 92b52bfe6f0: fleet 92e85362 cmux_journal_tests and ed455835 crash sim green (the crate did not change since).

Observed / Not run

  • Observed: the fleet steps above (Linux: Blacksmith 8-vCPU Ubuntu 24.04; macOS: owned Macs aws-m4pro-*).
  • Not run: the whole acpmux test suite (the store and daemon filters run the store's, the hub's store and the daemon's tests; the PR's CI runs the rest), and a daemon with store.journal on (no dogfood yet: the switch is off by default). The daemon's stop branch (store_asks_to_stop) has no daemon-level test; the store's side (stop_reason set on a freeze and after ten failures) has.
  • Panic ratchet: green at the merged head (the base red acpmux: clippy::indexing_slicing 703 > 686 was fixed on feat by #34735 and #34941, which this branch now has).

Changelog

none

Proof

No capture: a daemon storage change behind a default-off setting, with no UI.

Review receipt

Review (r-durability-s2-merge-reviewer): SHIP at 3273b2ade1f81deb90a9367229ffb85040af4d6a (comment 6632437161): the merge resolution at this head. Review 3 (r-durability-s2-reviewer): SHIP at 84f9c266975af5eec7216f751ea055e279ba7467 (comment 6630992897): the code before the merges. Non-green checks at this head are base findings (comment 6632519884). Its non-blocking follow-ups go in their own PRs: a repair that fails after it changed a log keeps its chat's records past the checkpoint; a hole that ends at a line start; the open's sync cost per replayed chat, measured against the start budget; the idle checkpointer's 30 s wake.