Journal read right after a Log write can miss the new entry under load (read-your-writes with #549 snapshots) #653

Open
opened 2026-10-02 01:31:42 +00:00 by kayg · 7 comments
Owner

Found while gating merge round 6 (head c4a61e8cf, branch job/merge-round-6): calternal-plugin-notes test tests::daily_and_composer_preserve_unrelated_bytes failed once in the full crate run under host load (load ~25) and passed 5/5 when run alone.

thread 'tests::daily_and_composer_preserve_unrelated_bytes' panicked at crates/plugins/notes/src/lib.rs:9417:9
test result: FAILED. 166 passed; 1 failed

Line 9417 is assert_eq!(day["entries"].as_array().unwrap().len(), 2): right after POST /journal/log returned 201, GET /journal/2026-09-24 returned the day without the new entry. Round 6 includes #549's committed Journal snapshots ("reads never wait on reconciliation: serve the last consistent projection"). Under load, that design can break read-your-writes: a User adds a Log entry and the Calendar/Journal they reload does not show it.

Expected: a read issued after a write was acknowledged to the same User must include that write (read-your-writes), while reads still never block on a long reconcile. Typical approach: the write path publishes the new snapshot (or a per-User write generation) before acknowledging; the read path compares its snapshot generation with the User's last acknowledged write generation and, if older, either applies the pending in-memory delta or waits only for that one publish (bounded, a few ms), never for a full reconcile.

Tests: a stress test that interleaves 200 write→read pairs under a held reconcile and CPU contention, asserting every read includes its preceding write; plus the existing held-reconcile latency test (#549) must still pass.

Found while gating merge round 6 (head c4a61e8cf, branch job/merge-round-6): `calternal-plugin-notes` test `tests::daily_and_composer_preserve_unrelated_bytes` failed once in the full crate run under host load (load ~25) and passed 5/5 when run alone. ```text thread 'tests::daily_and_composer_preserve_unrelated_bytes' panicked at crates/plugins/notes/src/lib.rs:9417:9 test result: FAILED. 166 passed; 1 failed ``` Line 9417 is `assert_eq!(day["entries"].as_array().unwrap().len(), 2)`: right after `POST /journal/log` returned 201, `GET /journal/2026-09-24` returned the day **without** the new entry. Round 6 includes #549's committed Journal snapshots ("reads never wait on reconciliation: serve the last consistent projection"). Under load, that design can break **read-your-writes**: a User adds a Log entry and the Calendar/Journal they reload does not show it. Expected: a read issued after a write was acknowledged to the same User must include that write (read-your-writes), while reads still never block on a long reconcile. Typical approach: the write path publishes the new snapshot (or a per-User write generation) before acknowledging; the read path compares its snapshot generation with the User's last acknowledged write generation and, if older, either applies the pending in-memory delta or waits only for that one publish (bounded, a few ms), never for a full reconcile. Tests: a stress test that interleaves 200 write→read pairs under a held reconcile and CPU contention, asserting every read includes its preceding write; plus the existing held-reconcile latency test (#549) must still pass.
Author
Owner

Started #653 on branch job/ryw-653, base c4a61e8cf090170f35b1bed3350d9de20c83ecd5. Read the issue and repo contract. Tracing legacy Log ID repair and acknowledgement publication for Journal, Calendar, DAV and Note reads. No push or deploy.

Started #653 on branch `job/ryw-653`, base `c4a61e8cf090170f35b1bed3350d9de20c83ecd5`. Read the issue and repo contract. Tracing legacy Log ID repair and acknowledgement publication for Journal, Calendar, DAV and Note reads. No push or deploy.
Author
Owner

Finding: journal_index does not replace journal_day_snapshots when any parsed Log lacks a block ID. A Log append to an imported Daily note can commit new Calendar/resource rows but retain the old Journal source; journal_snapshot attempts repair only when no snapshot exists and its User mutex is idle. This makes the GET depend on scheduling. The batch path also published only Journal source content, leaving Calendar range/year and DAV resources queued.

Decision (#653): publish before acknowledgement. Repair missing IDs inside the same checked Daily note edit; reuse that repair for imported ID reconciliation and direct Note body/property edits. Commit each batch source through the existing Note projection transaction before 201 (Journal content/ETags, Calendar rows and Note lookup together); retain the durable job for Task dependency repair. This adds one Note transaction per affected source, not per entry. Generation waits would add scheduler delay to reads; pending read-through would duplicate Calendar/DAV and ETag rules. WAL reads stay independent of reconcile. No new dependency or migration.

Finding: `journal_index` does not replace `journal_day_snapshots` when any parsed Log lacks a block ID. A Log append to an imported Daily note can commit new Calendar/resource rows but retain the old Journal source; `journal_snapshot` attempts repair only when no snapshot exists and its User mutex is idle. This makes the GET depend on scheduling. The batch path also published only Journal source content, leaving Calendar range/year and DAV resources queued. Decision (#653): publish before acknowledgement. Repair missing IDs inside the same checked Daily note edit; reuse that repair for imported ID reconciliation and direct Note body/property edits. Commit each batch source through the existing Note projection transaction before 201 (Journal content/ETags, Calendar rows and Note lookup together); retain the durable job for Task dependency repair. This adds one Note transaction per affected source, not per entry. Generation waits would add scheduler delay to reads; pending read-through would duplicate Calendar/DAV and ETag rules. WAL reads stay independent of reconcile. No new dependency or migration.
Author
Owner

Test contract changes for review: #653 moves legacy Log ID repair before ACK. daily_and_composer_preserve_unrelated_bytes now checks the exact imported line plus its assigned block ID immediately after POST, rather than requiring an ID-free line until GET. CRLF, opaque tail, entry count, unique IDs and ETag assertions remain. The queued batch repair test now first requires two Calendar rows after 201, removes only those derived test rows, and retains the existing zero-row/rebuild-to-two checks. This preserves queued repair coverage while testing the immediate visibility required by #653.

Test contract changes for review: #653 moves legacy Log ID repair before ACK. `daily_and_composer_preserve_unrelated_bytes` now checks the exact imported line plus its assigned block ID immediately after POST, rather than requiring an ID-free line until GET. CRLF, opaque tail, entry count, unique IDs and ETag assertions remain. The queued batch repair test now first requires two Calendar rows after 201, removes only those derived test rows, and retains the existing zero-row/rebuild-to-two checks. This preserves queued repair coverage while testing the immediate visibility required by #653.
Author
Owner

The first full Notes run found one additional manifestation: fix_journal_line creates a parsed Log without an ID, so its acknowledged fix leaves the previous Journal snapshot. The common checked edit now assigns the missing ID before this ACK too. The line-fix response keeps its existing suggested raw text. Its byte regression checks the exact original file with only the requested correction plus the new Log ID, and immediately reads the repaired entry while the reconcile guard is held. First run: test result: FAILED. 167 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 138.73s; the sole failure was the old ID-free byte expectation. The 200-pair contention test and #549 held-reconcile latency test both passed. Final gates are running after this contract update.

The first full Notes run found one additional manifestation: `fix_journal_line` creates a parsed Log without an ID, so its acknowledged fix leaves the previous Journal snapshot. The common checked edit now assigns the missing ID before this ACK too. The line-fix response keeps its existing suggested raw text. Its byte regression checks the exact original file with only the requested correction plus the new Log ID, and immediately reads the repaired entry while the reconcile guard is held. First run: `test result: FAILED. 167 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 138.73s`; the sole failure was the old ID-free byte expectation. The 200-pair contention test and #549 held-reconcile latency test both passed. Final gates are running after this contract update.
Author
Owner

Progress: core fix ce79ad42d; Calendar API regression d8f2f0b28; stale imported-snapshot regression 62184448c; real-server probe and benchmark profile 9b06f0491.

Final Notes gates pass, including 200 interleaved pairs under CPU contention, stale imported snapshots for single/batch POST, and #549 held-reconcile latency. Final Calendar gates pass, including range/year reads under held Notes and SQLite writer guards. Server clippy passes; server tests and a release build are in progress. Web check: svelte-check found 0 errors and 0 warnings; web tests: Tests 1053 passed (1053). git fetch origin and git merge origin/dev ran once; output: Already up to date. (origin/dev is the supplied base). The real-server round and perf VM measurements remain. No push, deploy or branch merge into dev/main.

Progress: core fix `ce79ad42d`; Calendar API regression `d8f2f0b28`; stale imported-snapshot regression `62184448c`; real-server probe and benchmark profile `9b06f0491`. Final Notes gates pass, including 200 interleaved pairs under CPU contention, stale imported snapshots for single/batch POST, and #549 held-reconcile latency. Final Calendar gates pass, including range/year reads under held Notes and SQLite writer guards. Server clippy passes; server tests and a release build are in progress. Web check: `svelte-check found 0 errors and 0 warnings`; web tests: `Tests 1053 passed (1053)`. `git fetch origin` and `git merge origin/dev` ran once; output: `Already up to date.` (`origin/dev` is the supplied base). The real-server round and perf VM measurements remain. No push, deploy or branch merge into dev/main.
Author
Owner

All required Rust gates pass. Server: test result: ok. 107 passed; 0 failed; 3 ignored; 0 measured; 0 filtered out; finished in 28.70s (the three live-app cases are executed by the separate-process wrapper). The release build then stopped because the shared sccache daemon retained TMPDIR from a removed worktree: sccache: caused by: Failed to create temp dir. Retrying only this release build with RUSTC_WRAPPER=; the shared daemon and other jobs are unchanged. Real-server and measured checks still remain.

All required Rust gates pass. Server: `test result: ok. 107 passed; 0 failed; 3 ignored; 0 measured; 0 filtered out; finished in 28.70s` (the three live-app cases are executed by the separate-process wrapper). The release build then stopped because the shared sccache daemon retained TMPDIR from a removed worktree: `sccache: caused by: Failed to create temp dir`. Retrying only this release build with `RUSTC_WRAPPER=`; the shared daemon and other jobs are unchanged. Real-server and measured checks still remain.
Author
Owner

Completed #653 on job/ryw-653. Head: 4723c5f3b1. Six atomic commits. Fetched origin and merged origin/dev once before final gates: Already up to date. No push, deploy, or merge to dev/main.

Built:

  • Checked Daily note writes assign missing Log IDs in the same durable write. This prevents an incomplete source from retaining an older Journal snapshot after acknowledgement.
  • Single and batch writes publish Journal source, Note lookup, Calendar rows and DAV resource ETags before 201. Batch publication uses the existing per-source Index transaction. Task dependency repair keeps its durable queued job.
  • Healthy reads still use committed WAL projections without a full reconcile wait. API/MCP Note reads use the shared Note route and durable source.
  • Deterministic tests cover stale imported snapshots, 200 alternating single/batch write-read pairs with two busy CPU threads and held reconcile during reads, Calendar range/year with a held Notes guard and uncommitted SQLite writer, DAV ETags and Note reads. The #549 held-reconcile latency test passes.
  • Added one real-server adversarial round and a reusable average/worst-case bench profile. Generated OpenAPI, action registry and TypeScript metadata are current; parity has zero adapter gaps.

Files:

  • bench/journal-read-your-writes.py
  • contracts/actions.json
  • contracts/openapi.json
  • crates/plugins/calendar/src/view.rs
  • crates/plugins/notes/src/lib.rs
  • crates/plugins/notes/src/store.rs
  • docs/perf/runs/2026-10-02-journal-read-your-writes-653.json
  • packages/api-client/src/generated.ts
  • tests/adversarial/journal-read-your-writes.py
  • tests/adversarial/run.sh
  • tests/adversarial/setup.mjs

Decisions:

  • Choose publication before acknowledgement. A per-User generation wait adds scheduling delays to reads; pending read-through duplicates Calendar/DAV projection and ETag rules. The Notes module docs record these alternatives.
  • Repair legacy missing Log IDs during checked Daily note writes, using the existing reverse replacement logic. Existing IDs and unrelated source bytes are preserved. No dependency or migration was added.
  • The issue changes publication timing. The daily and line-repair tests now assert exact original bytes apart from the new Log identity; the line repair response remains unchanged. The queued-repair test first requires published rows, then deletes derived rows and retains its original repair check. These expectation changes were documented during the job.
  • Generated metadata includes mechanical refresh of existing #549 Journal and #626 Mail summaries. No route, schema or authority changed.

Performance (release build copied to perf-test VM; separate exclusive /root/perf.lock sessions, load recorded inside each lock):

  • Measured runtime source: 9b06f0491e. Later commits only add comments/generated documentation and measurements.
  • Average, 200 sequential pairs: write p50/p95 151.84/411.38 ms; Journal 2.37/6.67 ms; Calendar range 2.95/6.25 ms. Server CPU 87.66 s (229.35%); RSS mean/peak 488.20/511.80 MiB.
  • Worst, 10,000 Logs and eight concurrent pairs: write p50/p95 25376.83/34233.28 ms; Journal 139.32/195.77 ms; Calendar range 111.70/209.92 ms. CPU 105.05 s (304.46%); RSS mean/peak 654.77/700.54 MiB. Every acknowledged write was visible.
  • Baseline docs/perf/baseline.json Calendar range p50/p95 is 1.7/4 ms with a smaller fixture. Average p95 is 56.25% above it. No paired Journal or resource baseline exists for this workload. Recorded follow-up #706: #706 . Full load and measurement data is committed in docs/perf/runs/2026-10-02-journal-read-your-writes-653.json.

Known gaps:

  • Worst-case write p95 is 34.23 seconds. Performance is not a merge gate; #706 records this and the Calendar range baseline comparison for follow-up. No crash, 5xx, lost acknowledgement, or inconsistent read was found in the bounded adversarial round.
  • MCP reuses the API Note handler; tests cover that shared read path rather than a separate MCP transport session.
  • No UI screen changed. No screenshot artifacts are needed.
  • The first release attempt hit a shared sccache temporary-directory failure. Rebuilding with the command-local wrapper disabled succeeded; the shared daemon was not changed.

Gates (verbatim summary output; cargo fmt --check exited 0 with no output):

api-clippy:

    Finished `dev` profile [unoptimized + debuginfo] target(s) in 38.85s

api-test:

    Finished `test` profile [unoptimized + debuginfo] target(s) in 30.83s
test result: ok. 9 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.08s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

notes-clippy:

    Finished `dev` profile [unoptimized + debuginfo] target(s) in 56.98s

notes-test:

    Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 32s
test result: ok. 169 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 166.00s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.47s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

calendar-clippy:

    Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 12s

calendar-test:

    Finished `test` profile [unoptimized + debuginfo] target(s) in 3m 11s
test result: ok. 84 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 8.03s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.15s
test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.12s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

server-clippy:

    Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 20s

server-test:

    Finished `test` profile [unoptimized + debuginfo] target(s) in 4m 24s
test result: ok. 107 passed; 0 failed; 3 ignored; 0 measured; 0 filtered out; finished in 20.90s

web-check:

svelte-check found 0 errors and 0 warnings

web-test:

 Test Files  153 passed (153)
      Tests  1053 passed (1053)

client-test:

 18 pass
 0 fail
 49 expect() calls
Ran 18 tests across 1 file. [976.00ms]

adversarial:

PASS #653: malformed/oversized/invalid-zone/date/attachment requests rejected; Unicode bytes preserved; 200 write-read pairs and eight-writer burst visible in Journal, Calendar range/year API Note reads and DAV REPORT

The three ignored server cases run through the passing live_apps_run_in_separate_processes wrapper. Final generated checks passed:

Action registry: 333 operations, 315 generated tools
Parity matrix: 333 API actions, 126 shortcuts, 2 static commands, 145 menu actions, 35 settings groups, 0 actions with adapter gaps

Doc comments in every touched source file were re-read. git diff --check passed. The private perf VM fixture, private local adversarial fixture and web build output were removed. cargo clean completed (verbatim):

     Removed 25764 files, 12.0GiB total
Completed #653 on job/ryw-653. Head: 4723c5f3b1ebfaa90905376e4a3d14e2ee60ae63. Six atomic commits. Fetched origin and merged origin/dev once before final gates: Already up to date. No push, deploy, or merge to dev/main. Built: - Checked Daily note writes assign missing Log IDs in the same durable write. This prevents an incomplete source from retaining an older Journal snapshot after acknowledgement. - Single and batch writes publish Journal source, Note lookup, Calendar rows and DAV resource ETags before 201. Batch publication uses the existing per-source Index transaction. Task dependency repair keeps its durable queued job. - Healthy reads still use committed WAL projections without a full reconcile wait. API/MCP Note reads use the shared Note route and durable source. - Deterministic tests cover stale imported snapshots, 200 alternating single/batch write-read pairs with two busy CPU threads and held reconcile during reads, Calendar range/year with a held Notes guard and uncommitted SQLite writer, DAV ETags and Note reads. The #549 held-reconcile latency test passes. - Added one real-server adversarial round and a reusable average/worst-case bench profile. Generated OpenAPI, action registry and TypeScript metadata are current; parity has zero adapter gaps. Files: - `bench/journal-read-your-writes.py` - `contracts/actions.json` - `contracts/openapi.json` - `crates/plugins/calendar/src/view.rs` - `crates/plugins/notes/src/lib.rs` - `crates/plugins/notes/src/store.rs` - `docs/perf/runs/2026-10-02-journal-read-your-writes-653.json` - `packages/api-client/src/generated.ts` - `tests/adversarial/journal-read-your-writes.py` - `tests/adversarial/run.sh` - `tests/adversarial/setup.mjs` Decisions: - Choose publication before acknowledgement. A per-User generation wait adds scheduling delays to reads; pending read-through duplicates Calendar/DAV projection and ETag rules. The Notes module docs record these alternatives. - Repair legacy missing Log IDs during checked Daily note writes, using the existing reverse replacement logic. Existing IDs and unrelated source bytes are preserved. No dependency or migration was added. - The issue changes publication timing. The daily and line-repair tests now assert exact original bytes apart from the new Log identity; the line repair response remains unchanged. The queued-repair test first requires published rows, then deletes derived rows and retains its original repair check. These expectation changes were documented during the job. - Generated metadata includes mechanical refresh of existing #549 Journal and #626 Mail summaries. No route, schema or authority changed. Performance (release build copied to perf-test VM; separate exclusive /root/perf.lock sessions, load recorded inside each lock): - Measured runtime source: 9b06f0491ecf4f06586f25d8f31d68e13da2afac. Later commits only add comments/generated documentation and measurements. - Average, 200 sequential pairs: write p50/p95 151.84/411.38 ms; Journal 2.37/6.67 ms; Calendar range 2.95/6.25 ms. Server CPU 87.66 s (229.35%); RSS mean/peak 488.20/511.80 MiB. - Worst, 10,000 Logs and eight concurrent pairs: write p50/p95 25376.83/34233.28 ms; Journal 139.32/195.77 ms; Calendar range 111.70/209.92 ms. CPU 105.05 s (304.46%); RSS mean/peak 654.77/700.54 MiB. Every acknowledged write was visible. - Baseline docs/perf/baseline.json Calendar range p50/p95 is 1.7/4 ms with a smaller fixture. Average p95 is 56.25% above it. No paired Journal or resource baseline exists for this workload. Recorded follow-up #706: https://git.kayg.org/kayg/calternal/issues/706 . Full load and measurement data is committed in docs/perf/runs/2026-10-02-journal-read-your-writes-653.json. Known gaps: - Worst-case write p95 is 34.23 seconds. Performance is not a merge gate; #706 records this and the Calendar range baseline comparison for follow-up. No crash, 5xx, lost acknowledgement, or inconsistent read was found in the bounded adversarial round. - MCP reuses the API Note handler; tests cover that shared read path rather than a separate MCP transport session. - No UI screen changed. No screenshot artifacts are needed. - The first release attempt hit a shared sccache temporary-directory failure. Rebuilding with the command-local wrapper disabled succeeded; the shared daemon was not changed. Gates (verbatim summary output; cargo fmt --check exited 0 with no output): api-clippy: ```text Finished `dev` profile [unoptimized + debuginfo] target(s) in 38.85s ``` api-test: ```text Finished `test` profile [unoptimized + debuginfo] target(s) in 30.83s test result: ok. 9 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.08s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s ``` notes-clippy: ```text Finished `dev` profile [unoptimized + debuginfo] target(s) in 56.98s ``` notes-test: ```text Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 32s test result: ok. 169 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 166.00s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.47s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s ``` calendar-clippy: ```text Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 12s ``` calendar-test: ```text Finished `test` profile [unoptimized + debuginfo] target(s) in 3m 11s test result: ok. 84 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 8.03s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.15s test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.12s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s ``` server-clippy: ```text Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 20s ``` server-test: ```text Finished `test` profile [unoptimized + debuginfo] target(s) in 4m 24s test result: ok. 107 passed; 0 failed; 3 ignored; 0 measured; 0 filtered out; finished in 20.90s ``` web-check: ```text svelte-check found 0 errors and 0 warnings ``` web-test: ```text Test Files 153 passed (153) Tests 1053 passed (1053) ``` client-test: ```text 18 pass 0 fail 49 expect() calls Ran 18 tests across 1 file. [976.00ms] ``` adversarial: ```text PASS #653: malformed/oversized/invalid-zone/date/attachment requests rejected; Unicode bytes preserved; 200 write-read pairs and eight-writer burst visible in Journal, Calendar range/year API Note reads and DAV REPORT ``` The three ignored server cases run through the passing live_apps_run_in_separate_processes wrapper. Final generated checks passed: ```text Action registry: 333 operations, 315 generated tools Parity matrix: 333 API actions, 126 shortcuts, 2 static commands, 145 menu actions, 35 settings groups, 0 actions with adapter gaps ``` Doc comments in every touched source file were re-read. git diff --check passed. The private perf VM fixture, private local adversarial fixture and web build output were removed. cargo clean completed (verbatim): ```text Removed 25764 files, 12.0GiB total ```
Sign in to join this conversation.
No labels
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
kayg/calternal#653
No description provided.