fix(kernel): resume adopts a real journal whose registry row is missing (#174) - #177
Conversation
|
Warning Review limit reachedNext included review available in 39 minutes. View limit detailsLimit details: You’ve used the included review currently available. Enable usage-based reviews in Billing to review now. Otherwise, wait until the next included review is available. Review configuration: ⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Free Run ID: 📒 Files selected for processing (3)
ℹ️ Recent review info⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Free Run ID: 📒 Files selected for processing (2)
Included review availability: Your plan provides up to 1 included review per hour; 0 remain after this review. 📝 WalkthroughWalkthrough
ChangesRun resume recovery
Estimated code review effort: 2 (Simple) | ~10 minutes Poem
Note 🎁 Summarized by CodeRabbit FreeYour organization is on the Free plan. CodeRabbit will generate a high-level summary and a walkthrough for each pull request. For a comprehensive line-by-line review, please upgrade your subscription to CodeRabbit Essentials by visiting https://app.coderabbit.ai/settings/billing. Comment |
#174. A run SIGKILLed early was unrecoverable: its journal sat on disk, complete and resumable, and `resume` refused it forever. `Engine::start` creates the journal, appends RunSpawned, and registers the run LAST. A crash in that window leaves a journal with `seq=1 RunSpawned` and no `runs` row. `server.rs` answered `run_not_found` on the missing row alone, turning a recoverable run into a lost one. That is a durability hole, not a lookup miss. The journal is the authority and the registry is an index over it, so the index is repaired from the authority: on a missing row, open the run's journal and, IF IT SAYS IT IS THIS RUN, register it and continue. That second condition is load-bearing. `SqliteJournal::open` does not verify whose journal it opened -- it reports whatever run id the file carries. Adopting on a successful open alone would register a well-formed journal for run A sitting at `runs/B.sqlite3` as B, accepting a foreign file on the strength of its filename. DRIVE-LOG WP-12/F7 records filesystem-derived run existence being deliberately replaced with registry-owned lookup for exactly that reason, so the id comparison is what keeps this a repair of the index rather than a reopening of that hole. An earlier revision of this change omitted it, and claimed in its message that foreign files were refused; two review lenses caught both the gap and the false claim, and this commit is squashed so no message survives describing code that was never written. Three tests now state the rule together: refuse a file that is not a journal (pre-existing), refuse a journal that is not this run's (new), adopt the one that is (new). `Engine::run_path` is widened to `pub(crate)` and owns the `runs/{id}.sqlite3` convention, so the repair path cannot drift from every other opener. How this surfaced: four #174 occurrences looked like a 25-30 minute hang and produced nothing but a test name. #175 bounded the protocol read and #176 dumped daemon-side state; the first CI run carrying both showed the resumed process had exited INSTANTLY with `run_not_found` while the test waited 60s for a dispatch from an already-dead process. It looked runner-only because the test kills as soon as the journal shows zero completed steps -- the earliest possible instant, squarely inside the window. Locally `register` wins that race nearly always; the window is real everywhere and a loaded runner merely samples it. Same shape as #160, which #171 fixes for the event-claim path: writing the index after the fact leaves a window where a run exists in one store and not the other. Here the cost is durability rather than exactly-once. Verified: * replacing the id comparison with `true` fails run_resume_refuses_a_valid_journal_that_belongs_to_another_run while the other two pass (sha256 dba64b31 -> 4f0bdeb3 -> restored dba64b31) * making adoption return run_not_found fails run_resume_adopts_a_real_journal_whose_registry_row_is_missing with the literal pre-fix error, while the orphan-file test still passes * workspace 144 passed, 0 failed, no warnings * CI `linux-x64-artifact` green, with crash_resume 34 passed in 39.4s -- the suite that had been hanging all night Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR Session-Id: c228933d-4f94-4d83-9a9a-daf3c83b94f1
8acd36f to
3f84b2e
Compare
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR Session-Id: c228933d-4f94-4d83-9a9a-daf3c83b94f1
Two racing deliveries of one event each started a run (#160). CI caught it as `left: 2` on the racing test; it is an exactly-once violation, not a flake. `claim_event` repaired a claim whose run never materialised, testing for that with "no row in `runs` for the claimed run_id". That predicate is true of two different situations it could not tell apart: * a run that CRASHED before registering -- nobody will ever spawn it, so the claim must be taken over; * a run that is IN FLIGHT and has not registered yet -- taking its claim over starts a second run for one event. `wake.rs` makes the window explicit: the claim is written, and only several statements later does `SqliteJournal::create` bring the run into existence. A second delivery landing in that gap judged the first abandoned and spawned its own run. The claim now carries the engine's boot id. A claim from THIS boot is in flight, so it dedupes; a claim from a previous boot with no registered run is wreckage, so it is repaired exactly as before -- preserving the crash recovery the original comment defends, which was guarding a real exactly-once bug of its own. That rule creates one obligation: a claim this boot takes but cannot turn into a run would strand the event, since every retry inside the process would be told "duplicate" with no run to carry it. The span from claim to `register` is therefore a named method, `spawn_claimed_run`, whose failure path releases the claim, scoped to the claiming run_id so a release cannot steal a claim another delivery legitimately holds. Concurrency also had to be made to work at all, which is a separate question from who owns a claim, and conflating the two cost time: * `Registry::open` had no busy timeout, so two concurrent deliveries failed with `database is locked` rather than waiting. * `PRAGMA journal_mode = WAL` does NOT honour the busy handler -- SQLite takes an exclusive lock for it -- so the timeout cannot cover that statement however early it is set. It retries explicitly and then VERIFIES the mode, returning `RegistryNotWal` otherwise; swallowing it would leave the registry in rollback-journal mode silently. * The timeout is armed AFTER the switch. The retry is bounded in attempts, not wall-clock, so arming it first let one open block 50 x 5s, which on a runner turned `crash_resume` into a step that ran past 25 minutes. Rejected: a time-based abandonment threshold, which swaps a correctness bound for a timing guess. Deferred and tracked, not papered over: a panic between the claim and `register` unwinds without releasing, stranding the event for the life of the boot (#173). A restart clears it, since the claim is then a previous boot's. Evidence is the mutation witnesses rather than test totals, because totals drift with the base and a witness does not: * seeding the guard off (`if false && existing_boot == boot_id`) fails `a_same_boot_claim_with_no_run_yet_is_a_duplicate_not_wreckage` deterministically, with `left: None, right: Some("run-a")` * the racing integration test is probabilistic by construction and catches the seeded bug about 3 times in 30 -- the winner usually registers before any loser reads, and more racers do not help because SQLite serialises the writes. It exercises the real path and cannot false-positive, but the deterministic registry tests are the gate, not it. Squashed to one commit: earlier messages on this branch carried test totals that were true against the old base and false after rebasing onto #177, and a superseded "8 in 10" figure for the racing test. Keeping them would leave the record asserting numbers the tree does not support. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR Session-Id: c228933d-4f94-4d83-9a9a-daf3c83b94f1
…f hanging (#175) `ProtocolClient::connect` set no read timeout, so `read_frame`'s `read_line` blocked forever and `event()` looped on it. These tests SIGKILL a daemon and resume it, so "the dispatch never arrives" is a reachable state — and an unbounded read turned it into a silent hang producing no evidence at all. Four #174 occurrences cost ~2 hours of runner time and yielded four test names between them. This bounds the read at 60s (against a target that runs in 38s, so it can only fire on "never", not "slow") and names the timeout, because a test stopped there is waiting for a frame the daemon never sent and that sentence is the diagnosis. It is what made #174 findable: the first CI run carrying it produced `timed out after 60s ... the daemon sent nothing` at a specific line, which led directly to #177's root-cause fix (a run registered after its journal was unrecoverable if killed in between). Three review iterations shaped the rest, each catching something real: - the ceiling was cancellable — three callers passed `None` and kept reading, which cleared it via shared `SO_RCVTIMEO`. `None` now restores the default, so no read is unbounded. - the override wrote to `self.stream` while `connect` wrote to the reader's fd — same socket on Linux/Darwin, different descriptors, a platform assumption with nothing naming it. Both now go through the fd `read_frame` reads. - it shadowed `UnixStream::set_read_timeout` while inverting what `None` means; renamed `override_read_timeout`. - the error reported the constant rather than the ceiling in force, which would have been wrong inside a 200ms probe. Evidence at the merged head 42768e7: - independent signoff: local 3-lens preswarm, all three REVIEW_PASSED - CI: `linux-x64-artifact` run 33973416493 success on this sha. Its first attempt failed on `cli-hn-monitor.test.ts > terminates (exit 1) when the worker emits an error asynchronously` (`expected +0 to be 1`), an async-timing test in the SDK suite that this kernel-test-only change cannot affect; a re-run of the identical head went green. - mutation: setting the ceiling to 1ms fails at `agent.rs:131` — `worker.event("step.dispatch")`, the exact blocking read — with the named message, in 0.80s - `crash_resume` 34 passed in 37.66s / 37.62s / 37.75s; workspace 152 passed, 0 failed This does not fix nondeterminism; it makes it report. #177 fixed the cause this exposed.
#174 produced four occurrences and, between them, four test names. Nothing else. The state that would explain it was all on the daemon side and none of it survived: the resumed child is still running when the read gives up, so `wait_with_output` is never reached and its output is dropped in the unwind, and the run's journal was never read. On a missing dispatch the test now kills the resumed child -- it is wedged by definition, and without killing it first the read below would block exactly as long as the one that already timed out -- then reports its stdout, its stderr, and every journal entry with seq, type and step. The journal is the important half. The question a missing dispatch raises is whether the daemon resumed and stalled partway or never resumed at all, and nothing else answers it. This is what found #174's root cause. Its first CI run showed the resumed child had exited INSTANTLY with `run_not_found` while the test waited 60s for a dispatch from an already-dead process -- a run whose journal existed but whose registry row did not, because `Engine::start` registers last. Fixed in #177. Verified by forcing the read ceiling to 1ms: before-first: no step.dispatch after resume: timed out after 1ms waiting for a protocol frame; the daemon sent nothing (see #174) --- resume child --- stdout (0 bytes): stderr (0 bytes): --- journal (1 entries) --- seq=1 type=RunSpawned step=None sha256 19f3431a -> 361572ef -> restored 19f3431a, with no 1ms literal left in the tree. Measured at THIS head, on main after #175 and #177: workspace 152 passed, 0 failed, no warnings; crash_resume 34 passed. An earlier revision of this message carried 142, which was true against the base it was written on and false after rebasing -- the count drifts, the mutation witness above does not. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR Session-Id: c228933d-4f94-4d83-9a9a-daf3c83b94f1
#174 produced four occurrences and, between them, four test names. Nothing else. The state that would explain it was all on the daemon side and none of it survived: `wait_with_output` is never reached, so the child's output is dropped in the unwind, and the run's journal was never read at all. On a missing dispatch the test now attempts to terminate the resumed child and reaps it, then reports its stdout, its stderr, and the run's journal entries with seq, type and step. The child may be STALLED or may have ALREADY EXITED, and the two are indistinguishable from the test's side -- which is exactly why the dump matters. #174 turned out to be the second case: the resume died instantly with `run_not_found` while the test waited 60s on it. An earlier revision of this message asserted the child "is still running" and was "wedged by definition", which contradicted the very failure it described; the helper terminates and reaps either way, discarding both results because "already gone" is a normal outcome here rather than an error. The journal is the important half. The question a missing dispatch raises is whether the daemon resumed and stalled partway or never resumed at all, and nothing else answers it. The listing covers the CURRENT segment, which is what `journal_entries` scans -- every entry these non-compacting crash tests produce, though not every entry under compaction. This is what found #174's root cause: a run whose journal existed but whose registry row did not, because `Engine::start` registers last. Fixed in #177. Verified by forcing the read ceiling to 1ms: before-first: no step.dispatch after resume: timed out after 1ms waiting for a protocol frame; the daemon sent nothing (see #174) --- resume child --- stdout (0 bytes): stderr (0 bytes): --- journal (1 entries) --- seq=1 type=RunSpawned step=None sha256 19f3431a -> 361572ef -> restored 19f3431a, no 1ms literal left in the tree. Measured at THIS head, on main after #175 and #177: workspace 152 passed, 0 failed, no warnings; crash_resume 34 passed in 37.98s. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR Session-Id: c228933d-4f94-4d83-9a9a-daf3c83b94f1
Closes #166. #140 shipped with committed conflict markers in `sdk/tests/authored-flow.test.ts`; resolving them meant taking main's copy whole, which protected main's merged coverage but dropped four cases the branch had added plus the helpers they used. `6384600` **is** the conflicted commit, so each incoming side is a fragment whose closing braces live in the shared trailing context after the `>>>>>>>` marker. Each was rebuilt from its hunk plus that context, then checked brace- and paren-balanced with zero markers left. The loopback also needed `outputFor(command)` back — main hardcoded `stdout_tail` for a single command, so none of these cases could observe a value. Restored: direct input into the journal-backed body; the `it.each` operator table (7 rows — truthiness, negation, loose/strict equality, ternary, logical and, logical or); separately awaited sibling ordering before the join; and an explicit completion after journal-backed steps. **One case could not be restored verbatim, and chasing that found a hole.** It asserted `missing_completion`; main refuses with `unawaited_step`, because `verifyAuthoredOperations` runs before the completion check and throws first — even though the body does await its step. Filed as #183. It now asserts the refusal's class, with the reason in a comment, so it neither fails on main nor bakes in a label that reads wrong. Then: disabling the completion check entirely (`if (false && requestedCompletion === undefined)`) left **every test in the file green** — `missing_completion` had no coverage for that shape at all. Added `refuses a body that completes nothing at all`, which reaches it and fails under that mutation. sha256 `58b3edbf` → `5e35ffc5` → restored `58b3edbf`. Evidence at the merged head b8ecaa7: - signoff: local 3-lens preswarm, maintainability / history / structure all REVIEW_PASSED - CI: run 33982088411 success on b8ecaa7. Its first attempt failed on `agent::rung_c_sigkill_boundaries_...`, unrelated to this SDK-test-only change; that failure is now filed as #185 (an empty journal being adopted by #177's resume repair), and a re-run of the identical head went green. - `authored-flow.test.ts` 23 passed; full SDK suite 32 files / 662 passed / 3 skipped
…nd and filed as #185 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR Session-Id: c228933d-4f94-4d83-9a9a-daf3c83b94f1
Fixes #185 — a regression I introduced in #177. `Engine::start` creates the journal, appends `RunSpawned`, then registers, so a crash leaves two different residues and #177 only recognised one. Its gate was `journal.run_id() == params.run_id`; an empty journal still carries a meta row with the run id, so a file killed *before* the `RunSpawned` append was adopted and registered, and resume then died on `read run spec: Query returned no rows` — an internal failure where the honest answer is that the run does not exist. Before #177 that returned a clean `run_not_found`. Adoption now also requires `run_spec()` to succeed: the predicate resume itself calls next, so we adopt only what resume can use. Found by the diagnostics from #175 and #176 on run 33982088411, where the crash-resume test failed in 63 seconds instead of hanging for 30 minutes and the dump printed `--- journal (0 entries) ---` alongside the spec-read error. That chain has now paid for itself twice. Evidence at the merged head 11edaa0: - signoff: local 3-lens preswarm, maintainability / history / structure all REVIEW_PASSED, first pass - CI: run 33983563713 success on 11edaa0 - mutation: dropping the `run_spec()` requirement restores #177's gate exactly and fails **only** the new test, while `run_resume_adopts_a_real_journal_whose_registry_row_is_missing` keeps passing — narrowing adoption without undoing what #177 fixed. Full transcript with runnable commands and sha256 before/mutated/restored is in the commit message. - kernel workspace 157 passed, 0 failed, no warnings The four tests now state the rule together: refuse a file that is not a journal, refuse a journal that is not this run's, refuse a journal that never recorded its run, adopt the one that did.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR Session-Id: c228933d-4f94-4d83-9a9a-daf3c83b94f1
Closes #167. The row claimed gate 2 was missing "a test proving a duplicate event does not double-execute". That was already false when #167 was filed, and tonight's work went further, so the row understated progress and the gate at once. Done, each claim checked against main rather than remembered: sequential duplicates (#14); concurrent racing deliveries under the production topology of one `Engine` per protocol request (#171); claims surviving the process that made them (#171 boot id, #182 panic unwind); resume adopting only a journal it can actually use (#177, #186). Still missing, narrowly: the RFC-0001 Appendix A wake-time context contract — nothing specifies what `wake_context` guarantees, or that a resumed run observes the same context rather than a recomputed one. And the correction #167 cared about most: the row was understating the gate. RFC-0001 §3's bar is `hn-monitor` running as a relayflow in production on its real events with zero bespoke persistence, not a passing test suite. Evidence at the merged head 8e57b17: - signoff: local 3-lens preswarm, maintainability / history / structure all REVIEW_PASSED - CI: none applies. `cloud-runtime-artifact.yml` filters on `kernel/**`, `sdk/**`, `testdata/**` and `scripts/cloud-artifact*`; this touches only `ops/SCOREBOARD.md`, so no artifact run was triggered — verified by reading the workflow's `paths:` rather than waiting on a run that was never going to start. The `review` check is red for the reason common to every flows PR: the gate invokes `agent-relay` and no step installs it. No counts in the row, deliberately — counts drift with the base, PR numbers and test names do not.
Nothing verified main. `cloud-runtime-artifact.yml` triggered only on `pull_request` and `workflow_dispatch`, and `review-swarm.yml` only on `pull_request` — so every PR is checked at its own head and never as merged, and since we squash-merge onto a main that has moved since that CI ran, the composed result went unverified. Not theoretical: twelve PRs merged on 2026-09-05 across the exactly-once claim path (#171, #182), resume adoption (#177, #186), the authored-flow executor (#184, #187) and the CLI run loop (#180) — each green on its own branch, the composed tree never run until dispatched by hand: ``` run 33987924703 workflow_dispatch main completed/success ed917bf ``` Main is fine. But nobody knew that, and finding out required knowing to ask. Without this, a bad compose surfaces as an unrelated PR going red — the most expensive way to find it, since the author debugs their own change first. Tonight already produced three failures on PRs that belonged to something else (#179, #185, the #174 chain), and each cost a tick to attribute. Paths are deliberately not filtered on the push trigger: on a PR the question is "does this change affect the runtime", on main it is "is the tree good", and a docs-only merge can land on a tree someone else broke. Evidence at the merged head d1cb32a: - signoff: local 3-lens preswarm, maintainability / history / structure all REVIEW_PASSED - CI: run 33988314276 success on d1cb32a, verified by headSha and event=pull_request - YAML parsed and asserted: triggers are `pull_request`, `push`, `workflow_dispatch`; push is branch-scoped to main; the pull_request path filter is unchanged
Fixes #174 at the root. Should also unblock #171 and #168, which have no green CI run because of it.
The bug
A run SIGKILLed early was unrecoverable. Its journal sat on disk, complete and resumable, and
resumerefused it forever.Engine::startregisters the run last:A crash in that window leaves a journal with
seq=1 RunSpawnedand norunsrow.server.rsansweredrun_not_foundon the missing row alone — turning a recoverable run into a lost one. That is a durability hole, not a lookup miss.The fix
The journal is the authority; the registry is an index over it. So repair the index from the authority: on a missing row, open
runs/<id>.sqlite3, and if it is a real journal, register it and continue.The codebase already assumed this asymmetry elsewhere — the journal-opening path falls back to the conventional location with
unwrap_or_else(|| self.run_path(run_id)). The two paths disagreeing on the same condition is what made this reachable.Adoption is gated on
SqliteJournal::opensucceeding, not on the file existing, so a truncated or foreign file is still refused. The existingrun_resume_asks_the_registry_instead_of_treating_an_orphan_file_as_a_runtest pins that and still passes. The new test is its counterpart, and the pair states the rule together: adopt a journal that is real, refuse a file that is not.How it surfaced
This is the root cause of #174. Four occurrences looked like a 25–30 minute hang and produced nothing but a test name. #175 bounded the read; #176 dumped the daemon-side state; the first CI run carrying both named it outright:
The resumed process had exited instantly. It never hung — the test waited 60s for a dispatch from a process that was already dead.
It also explains the runner-only appearance: the test kills as soon as the journal shows zero completed steps, the earliest possible instant and squarely inside the window. Locally
registerwins that race nearly always. The window is real everywhere; a loaded runner just samples it.Relationship to #160
Same shape. Writing the index after the fact leaves a window where a run exists in one store and not the other. #171 closes it for the event-claim path; here the cost is durability rather than exactly-once.
Evidence
Mutating the adopt arm to return
run_not_foundfails the new test with the literal pre-fix error:while
..._orphan_file_...still passes — so the existing guarantee is intact. sha256e83b2fdd→665973d2→ restorede83b2fdd.Workspace: 143 passed, 0 failed, no warnings.
Independent of #175/#176 — those improve diagnosis, this removes the cause. All three are worth having.
🤖 Generated with Claude Code
https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR