PR #35895 - manaflow-ai/cmux

Summary

This fixes the acpmux event journal behind store.journal (default off; R-DURABILITY). The review of #35866 found the bug (finding 2's base part), and it is split out of that PR because the bug is older than #35866.

A checkpoint could retire the record of a line whose log sync had just failed on another thread. checkpoint_once checked frozen only at its start. Since S3a (#35483), the checkpoint waits on its own thread until every record through its LSN is durable, which takes one group commit, and longer on a slow disk. Meanwhile a request's flush_session could fail its sync of a chat's log and freeze the store. The checkpoint went on anyway. Its own sync of that log reported success for the pages the failed sync dropped (the kernel can mark them clean), so it wrote its LSN and retired the line's record. No restart then wrote the line again, and an OS crash lost an acknowledged line.

Culprit (bisect)

The reviewer's test, a_checkpoint_in_flight_does_not_go_past_a_freeze, appended alone to each commit (scratch branches fix/r-durability-freeze-bisect-*-nomerge, never merged), on owned Macs:

Commit	What it is	Result	Fleet
`d2c63860ece`	S2 review 2, red tests (#34901)	green	3ddeaac7
`84f9c266975`	S2 review 2 fix, S2's final code	green	3ec975bf
`6ad43f5d1bb`	S2 on feat (#34901)	green	534efbce
`f4aa1bf60ec`	S2c on feat (#35400)	green	8b6f41c2
`0505e9bee04`	S3a's red tests, on S2c	green	144adf85
`71bc09a1e63`	S3a's first implementation	red	c87a998e
`00655a40430`	S3a on feat (#35483)	red	ff9a3db6

So 71bc09a1e63 (S3a, "chat metadata through the event journal") brought it in: it added the checkpoint's wait for durability at its start (journal.wait_durable(lsn, SEAL_WAIT), for E13), which holds a checkpoint in flight for a group commit while other threads run. Before it, the S2 checkpoint took min(applied, durable) and did not wait. The narrow form (a sync that has failed and not yet frozen the store, second test below) needs no wait and is as old as S2's checkpoint; no S2 test reached it.

store.journal (default off) stays off until this lands; the race needs the journal store.

What changes

Inner::counted_sync runs each sync of the store's files whose failure freezes the store: LocalStore::flush_session (the chat's open log segment, its events folder, its folder and the sessions folder), the write of a chat's session.json in write_through (a file and its folder, from a settle or from the checkpoint), and the folder syncer's sync of the sessions folder. Only the sync is counted, never a wait before it (a settle's wait for its record).
Each counted sync holds a ticket (SyncsUnderWay). The ticket ends after the sync's failure, if any, froze the store. A drop guard ends it on a panic too.
Before it writes its LSN, checkpoint_once waits until every sync that held a ticket at that moment has ended, then reads frozen. A failed sync freezes the store before its ticket ends, so a checkpoint either sees the store frozen or knows that the sync ended without a failure.
A log's close (SegmentWriter::close: close_log, an eviction, a segment's end, a retention commit) syncs and then notes a failed sync in sync_failed, both under the writers' lock. The checkpoint now reads that note under the same lock (LocalStore::close_sync_failed), so a close whose sync failed before the read has noted it (review finding 1).
A panic in a counted sync freezes the store before its ticket ends, because what the sync did is then not known (review P3).

The wait: its bound, and who can wait

Bound: the wait ends when the syncs that are under way at its start have ended. It never waits for a sync that begins later, because such a sync cannot undo a sync the checkpoint saw end. So many later syncs cannot hold it back. Each counted sync is at most one of these: LocalStore::flush_session (one segment sync and three folder syncs; it can first wait for the writers' lock, which appends and other counted syncs hold only for bounded work), one session.json write (a file sync, a rename and a folder sync), or one folder sync. There is no timer and no retry. Reading a log close's note takes the writers' lock once; its other holders do bounded work too (an append, a close's sync, a flush_session's syncs, a compaction's renames).

Only a checkpoint can wait, and these are all the callers that run one:

Caller	Thread
`run_checkpointer`	the store's checkpointer thread
`JournalStore::open`, after the replay	the opening thread, before the folder syncer starts and before any request, so no ticket exists
the one-shot catch-up before its seal (`journal_store.rs`)	its own store, which no other thread uses, so no ticket exists
`Store::flush`: `Hub::seal` and `Hub::flush` (`hub/shutdown.rs`), and `daemon.rs` when agents miss the shutdown budget	shutdown only, after the sessions end
`Store::commit_compaction` from the retention pass (`hub/retention.rs`)	a `spawn_blocking` thread. The pass already waits for its own compaction and for this checkpoint's fsyncs

No request path runs a checkpoint: JournalStore::flush_session and session_dir do not. No counted sync takes a lock that a waiting checkpoint holds (checkpointing, and in the retention pass the chat's append lock), so the wait cannot deadlock.

The first fix's regression (f04357c3378), fixed here

The first fix counted the whole settle before session_dir and flush_session, including the settle's test hold and its wait for its record (up to 5 s). A checkpoint that found a sync under way failed with Deferred. So a_late_settle_never_writes_an_older_image_over_a_checkpointed_one failed on macOS (fleet e71ea9a4) and Linux (fleet 0f3f469b): its flush() returned Deferred while a late settle was held. No image was written wrongly, because the deferred checkpoint wrote nothing. But a checkpoint failed for syncs that succeed, and that failure also refuses a compaction's commit and leaves the shutdown's checkpoint undone. This head counts only syncs and removes Deferred.

Testing

acpmux store::journal_store_tests and store::journal_meta_tests. The four race tests order their threads only by handshakes, with no timer (lead's review). A seam holds a thread at a point, or a one-shot note says that a thread is about to block (NOTE_BEFORE_SYNCS_WAIT, NOTE_BEFORE_CLOSE_NOTE_READ). After such a note the thread cannot return before the test's release, so "it has not returned" is checked exactly. On code without the fix no note comes: the checkpoint's thread says first that it returned.

a_checkpoint_in_flight_does_not_go_past_a_freeze (the reviewer's test of #35866): the checkpoint is held right after its start (HOLD_AFTER_START) while flush_session fails its log sync and freezes the store. After a restart and an OS crash, the line must still be there. The earlier version used a 2 s journal sync and a 300 ms sleep to keep the checkpoint in flight; the bisect below used that version.
a_checkpoint_never_goes_past_a_sync_that_is_failing_on_another_thread: the failing sync is held right before it freezes the store (HOLD_BEFORE_FREEZE). A checkpoint on a second thread must wait for it (its note), and must not retire the line's record.
a_checkpoint_waits_for_a_sync_under_way_on_another_thread (new): a flush_session that succeeds is held once it is under way (HOLD_IN_SYNC). A checkpoint on a second thread must wait for it (its note), must not return before the release, and must then succeed.
a_checkpoint_never_goes_past_a_log_close_whose_sync_is_failing_on_another_thread (the reviewer's test, finding 1): a checkpoint clones the open log and is held (HOLD_AFTER_LOG_CLONE); close_log on another thread fails its sync and is held before its note, holding the writers' lock (HOLD_BEFORE_CLOSE_NOTE). The checkpoint goes on, syncs its clone (success), and must wait at the writers' lock (its note) until the close is let go. After a restart and an OS crash, the line must still be there.
a_late_settle_never_writes_an_older_image_over_a_checkpointed_one (S3a's): the first fix's regression.

Red, the handshake tests on the code before their fix (branches fix/r-durability-freeze-red-{a,b,c}-nomerge, never merged; each adds only the seams' declarations, and for a the start hold):

a, at 75927e9adc5 (feat fb972951429 with no fix): tests 1 and 2: both fail, in the full run and alone, for their reasons (macOS fleet 4c010e50): test 1 "went on past a freeze and retired the record of a line whose sync failed"; test 2 "it did not wait and returned ok".
b, at a17ad740d21 (the first fix, which deferred): the wait test: fails, in the full run and alone (macOS fleet 561d9863): "a checkpoint did not wait for a sync under way on another thread: it returned a sync of the store's files was under way: the checkpoint is left for the next turn" (the first fix's Deferred).
c, at 0f690fe75e3 (the wait, without the locked read of a close's note): the close test: fails, in the full run and alone (macOS fleet e409caaf): "a checkpoint went past a log close whose sync was failing on another thread (it did not wait for the close's note and returned ok)".

Red, the earlier timed versions (same scenarios):

Tests 1 and 2 at 75927e9adc5: both fail, in the full run and alone (macOS fleet a592f07e, Linux fleet 6e7293c3). Test 2 on a second thread at 83a49aec920: fails (macOS fleet d49f69a5).
At a17ad740d21, macOS journal_ (fleet dd7904ff): 341 of 343 pass; only the late-settle test (its flush() returns the first fix's Deferred) and the wait test fail, in the full run and alone.
The close test: the reviewer's repro at f04357c3378 (macOS fleet 2157d2b5) and at 03e5a01d564 (macOS fleet a8909da1), and this PR's version at 0f690fe75e3 (macOS fleet 610b15e6): each fails with "a checkpoint went past a log close whose sync was failing on another thread (it returned ok)".
a_late_settle_never_writes_an_older_image_over_a_checkpointed_one passes on the first fix's parent 75927e9adc5 (macOS fleet ff54f2e2, Linux fleet 217c3b3d), so the first fix broke it.

Green at the head 95ef426862cb1ae0388893b0e82bdf29fddc7a36 (merge of feat with S2fu #35562; conflicts resolved, see below):

macOS: journal_, fleet a3cb17dc: 359 of 359 pass.
Linux: all store:: with fmt and clippy -D warnings, fleet f4c2a127: 360 of 360 pass (Blacksmith; log in hq run 41931305772).

Before the merge, at a8d5094c927: macOS journal_ 344 of 344 (fleet ce451c69); Linux all store:: 345 of 345 with fmt and clippy (fleet 9a8ec491, Blacksmith; hq run 41928977118).

The merge ff7d15f1396 (feat 0b9e1668a7b, S2fu): S2fu changed the same store files. Both sides are kept: feat's checkpointer seams and this PR's thread seams (this PR's slot type renamed HoldSlot, feat's Hold is the channel pair); both new Inner fields (syncs, idle); both sets of new tests (45 = 29 + 12 + 4). checkpoint.rs gets back use std::sync::atomic::Ordering as AtomicOrdering, which S2fu's idle checkpointer uses. S2fu adds no sync that freezes the store (its repair syncs run at the open, before the checkpointer and any request), so no new site is counted. 95ef426862c merges feat 2292a30d124 (no acpmux change).

Earlier heads: 03e5a01d564 macOS journal_ green (fleet 9b73d5af) and Linux all store:: green (fleet bd614e74); 3edea4f4cf5 (the close fix with the timed tests): macOS fleet bb762d83 and Linux fleet 59f2d4ff, macOS journal_ 344 of 344 (fleet bb762d83), Linux all store:: 345 of 345 with fmt and clippy -D warnings (fleet 59f2d4ff, Blacksmith; log in hq run 41927184980).

Observed / Not run

Observed: the fleet steps above, with each log read.
Not run: a real disk's failed fsync (the tests use the sync seams and the crash model, store/sync_model.rs); a dogfood daemon with the switch on; a load test of the checkpoint's wait.

Follow-ups (each in its own PR, red test first)

#35904 (a log close's note read before the close writes it) is fixed here, at the review's request; the issue closes when this lands.
#35915: four older gaps the reviews found (transfer syncs of sessions/, a restart that skips a metadata image after a failed folder sync, a stale repair file at delete, S2's Gone rule).
#35905: store sync failures that do not freeze the store (compaction's folder sync and marker write, kept-aside files) can let a later checkpoint go past them.

Risk

risk:normal (set by the risk classifier: no new delete of user data and no on-disk format change). It was still reviewed under the risk:high rules: an independent SHIP at the exact head (comment 6645003520) and greens on macOS and Linux at that head. Behind the default-off switch. The PR adds one wait on the checkpoint's thread, bounded by the syncs under way, one take of the writers' lock per checkpoint, and one short mutex per counted sync. It changes only when a checkpoint writes its LSN.

Changelog

none

Proof

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