schaefera/utStudyBIble

Watch

Fork 0

A log line is one write, so the e2e cases read it whole #132

Merged

claude-bot merged 1 commit from fix/log-line-atomic into main

2026-10-30 12:18:09 +00:00

claude-bot commented

2026-10-30 11:32:09 +00:00

Collaborator

What

The app's log lines from core are now written to stderr in one piece. eprintln! wrote each part of a line separately, so a line logged at the same moment by another thread (Qt's) could land in the middle of it. On main (run 247), the e2e restore case read utsb: restored utsb: window loaded after 375 ms and failed, although the position had been restored. The new log_line! (core/src/log.rs) builds the whole line, then writes it once. The log text is unchanged.

Blast radius

Tier: trunk
Trunk paths touched: core/src/worker/session*, core/src/db.rs, core/src/tasks/exec.rs (only their log calls)
Testing tier: standard
Gate / rollback: revert this merge (log output only; no data or behaviour change).

Proof

CI on ac8f8b3: changes, rust, audit, app, e2e and click all succeeded.
cargo make locally: fmt, clippy, tests (coverage 94.97 % of lines), cargo-deny and cargo-audit pass.
Fails without the change: with write_line writing as eprintln! does, log::tests::a_line_is_one_write fails. The line goes out as ["utsb: restored ", "KJV", " ", "20", " ", "0.", "341", "\n"], eight writes, the gaps that let Qt's line in. With the change it is one write.
Not shown: the interleaving in the e2e case itself. It depends on timing and was seen once.

Review

Reviewer: fresh-context code-review at high (review 350): 0 findings.
Review-Confidence: 100/100. The review covered all the trunk files, the test is shown to fail without the change, and CI is green on the final commit. Only the cause is demonstrated, not the e2e symptom.

Confidence by part

log_line! and its uses: high. The text is unchanged, so the e2e and mem-check greps still match.
That this was the only cause of the restore flake: medium. The log of run 247 shows this split. Qt's own lines are assumed to be written in one call, as its default handler does.

🤖 Generated with Claude Code

## What The app's log lines from `core` are now written to stderr in one piece. `eprintln!` wrote each part of a line separately, so a line logged at the same moment by another thread (Qt's) could land in the middle of it. On main (run 247), the e2e `restore` case read `utsb: restored utsb: window loaded after 375 ms` and failed, although the position had been restored. The new `log_line!` (`core/src/log.rs`) builds the whole line, then writes it once. The log text is unchanged. ## Blast radius **Tier:** trunk **Trunk paths touched:** `core/src/worker/session*`, `core/src/db.rs`, `core/src/tasks/exec.rs` (only their log calls) **Testing tier:** standard **Gate / rollback:** revert this merge (log output only; no data or behaviour change). ## Proof - CI on ac8f8b3: changes, rust, audit, app, e2e and click all succeeded. - `cargo make` locally: fmt, clippy, tests (coverage 94.97 % of lines), cargo-deny and cargo-audit pass. - Fails without the change: with `write_line` writing as `eprintln!` does, `log::tests::a_line_is_one_write` fails. The line goes out as `["utsb: restored ", "KJV", " ", "20", " ", "0.", "341", "\n"]`, eight writes, the gaps that let Qt's line in. With the change it is one write. - Not shown: the interleaving in the e2e case itself. It depends on timing and was seen once. ## Review **Reviewer:** fresh-context `code-review` at high (review 350): 0 findings. **Review-Confidence:** 100/100. The review covered all the trunk files, the test is shown to fail without the change, and CI is green on the final commit. Only the cause is demonstrated, not the e2e symptom. ## Confidence by part - `log_line!` and its uses: high. The text is unchanged, so the e2e and mem-check greps still match. - That this was the only cause of the `restore` flake: medium. The log of run 247 shows this split. Qt's own lines are assumed to be written in one call, as its default handler does. 🤖 Generated with [Claude Code](https://claude.com/claude-code)

claude-bot added 1 commit

2026-10-30 11:32:09 +00:00

core: a log line is one write, so another thread's can't split it

CI / changes (pull_request) Successful in 8s

Details

CI / rust (pull_request) Successful in 7m31s

Details

CI / audit (pull_request) Successful in 12s

Details

CI / app (pull_request) Successful in 3m11s

Details

CI / e2e (pull_request) Successful in 10m22s

Details

CI / click (pull_request) Successful in 2m18s

Details

ac8f8b347d

eprintln! writes each piece of its format separately to the unbuffered
stderr. On main (run 247), Qt's "window loaded" line landed inside
"utsb: restored KJV 20 0.341", and the e2e restore case read the wrong
value and failed although the position was restored. log_line! formats
the whole line, then writes it at once.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

claude-review reviewed

2026-10-30 11:33:06 +00:00

claude-review left a comment

claude-review, level high, commit ac8f8b347d, range origin/main...HEAD.

No high, medium or low findings. Checked: the macro_export path (crate::log_line!) resolves in-crate; log lines keep byte-identical text so the e2e/mem-check greps (utsb: saved/restored/back to/jump from/switch from) are unaffected; no eprintln! remains in the app paths (only core/src/bible/refs/sweep.rs, a dev sweep, and sword examples/tests); qt/ has no Rust eprintln and its qInfo lines are outside this change. A single write_all of a pre-formatted line is one write(2) for lines under PIPE_BUF, which is the intended fix; dropping a write error instead of panicking is the stated behavior.

Files reviewed: core/src/log.rs, core/src/lib.rs, core/src/db.rs, core/src/tasks/exec.rs, core/src/worker/session.rs, core/src/worker/session/jump.rs, core/src/worker/session/switch.rs, core/src/bible/refs/sweep.rs, qt/main.cpp, tools/e2e/cases/*.sh (grep of log lines), clippy.toml, CLAUDE.md

claude-review, level high, commit ac8f8b347dab80f8d5932b5adae4547f18d7054f, range origin/main...HEAD. No high, medium or low findings. Checked: the macro_export path (`crate::log_line!`) resolves in-crate; log lines keep byte-identical text so the e2e/mem-check greps (`utsb: saved/restored/back to/jump from/switch from`) are unaffected; no `eprintln!` remains in the app paths (only core/src/bible/refs/sweep.rs, a dev sweep, and sword examples/tests); qt/ has no Rust eprintln and its qInfo lines are outside this change. A single `write_all` of a pre-formatted line is one write(2) for lines under PIPE_BUF, which is the intended fix; dropping a write error instead of panicking is the stated behavior. Files reviewed: core/src/log.rs, core/src/lib.rs, core/src/db.rs, core/src/tasks/exec.rs, core/src/worker/session.rs, core/src/worker/session/jump.rs, core/src/worker/session/switch.rs, core/src/bible/refs/sweep.rs, qt/main.cpp, tools/e2e/cases/*.sh (grep of log lines), clippy.toml, CLAUDE.md

claude-bot changed title from ~~WIP: A log line is one write, so the e2e cases read it whole~~ to A log line is one write, so the e2e cases read it whole

2026-10-30 12:17:31 +00:00

claude-review approved these changes

2026-10-30 12:17:52 +00:00

claude-review left a comment

Merge gate, commit ac8f8b3. Checked: review 350 (high) had no findings and there are no fix commits; no commits on the branch after ac8f8b3; CI green on head (changes, rust, audit, app, e2e, click all succeeded); PR body Proof lists no unrun elevated, maximum or AI-behaviour gate (it states the e2e interleaving is not reproduced, which is a disclosed limit); Review-Confidence 100. Approved.

Merge gate, commit ac8f8b3. Checked: review 350 (high) had no findings and there are no fix commits; no commits on the branch after ac8f8b3; CI green on head (changes, rust, audit, app, e2e, click all succeeded); PR body Proof lists no unrun elevated, maximum or AI-behaviour gate (it states the e2e interleaving is not reproduced, which is a disclosed limit); Review-Confidence 100. Approved.

claude-bot merged commit 9dd48001d3 into main

2026-10-30 12:18:09 +00:00

claude-bot referenced this pull request from a commit

2026-10-30 12:18:10 +00:00

Merge pull request 'A log line is one write, so the e2e cases read it whole' (#132) from fix/log-line-atomic into main