test(kernel): dump daemon-side state when a dispatch never arrives (#174) by kjgbot · Pull Request #176 · AgentWorkforce/flows

kjgbot · 2026-09-05T13:00:52Z

Stacked on #175 — base is fix/174-protocol-read-timeout, not main. It depends on the bounded read from that PR: with an unbounded read there is no error to catch and nothing to report.

Why

#174 has produced four occurrences and, between them, four test names. Nothing else.

The state that would explain it is all daemon-side and none of it survives today:

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;
the run's journal is never read.

What it does

On a missing dispatch the test kills the resumed child — it is wedged by definition, and without killing 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 did the daemon resume and stall partway, or never resume at all? Nothing currently answers that.

Evidence

Forcing the 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

(At 1ms the cut is artificial, so one entry is expected — the point is the shape. On a real 60s stall the journal contents are the signal.)

sha256 19f3431a → 361572ef → restored 19f3431a, and grep -c "from_millis(1);" is 0 in the tree.

crash_resume: 34 passed in 37.72s / 37.91s / 37.90s. Workspace: 142 passed, 0 failed.

Merge order

#175 first, then this. If #175 is rejected, close this too — it has no meaning without it.

🤖 Generated with Claude Code

https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR

…f hanging #174: the kernel step was cancelled at ~25-30 minutes on three runs across two branches with no code in common, always on a crash_resume test that finishes in under a second locally, and always with no output beyond the harness's own "has been running for over 60 seconds". `ProtocolClient::connect` set no read timeout, so `read_frame`'s `read_line` blocks forever and `event()` loops on it. These tests SIGKILL a daemon and resume it, so "the dispatch never arrives" is a reachable state rather than a hypothetical -- and an unbounded read turns that state into a silent hang that produces no evidence at all. Three runs cost 75 minutes of CI and yielded one test name between them. A 60s ceiling, against a target that runs in 38s, so it can only fire on "never" and not on "slow". A timeout is named explicitly rather than surfacing as a bare I/O error, because a test stopped there is waiting for a frame the daemon never sent and that sentence is the diagnosis. This does NOT fix the underlying nondeterminism -- it makes it report. The next occurrence names its own line in 60 seconds instead of eating the step. Verified. Mutating the ceiling to 1ms fails at agent.rs:131 -- `worker.event("step.dispatch")`, the exact blocking read -- with `timed out after 1ms waiting for a protocol frame; the daemon sent nothing (see #174)`, in 0.80s. That also confirms where CI was stuck. Restored, crash_resume is 34 passed in 37.8s across three consecutive runs, against 38.27s on main's own CI. 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: the kernel step was cancelled at ~25-30 minutes on three runs across two branches with no code in common, always on a crash_resume test that finishes in under a second locally, and always with no output beyond the harness's "has been running for over 60 seconds". `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. Three runs cost 75 minutes and yielded one test name between them. This bounds the read at 60s -- against a target that runs in 38s, so it can only fire on "never", not on "slow" -- and names the timeout, since a test stopped there is waiting for a frame the daemon never sent and that sentence is the diagnosis. It does NOT fix the nondeterminism. It makes it report. Three review-lens iterations shaped the rest, each catching something real: * The ceiling was cancellable. Three callers passed None and kept reading; because the fds are dup'd and share SO_RCVTIMEO, that cleared it. 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 and Darwin, different descriptors -- a platform assumption with nothing naming it. Both now go through the fd `read_frame` reads. * The method shadowed `UnixStream::set_read_timeout` while inverting what None means. Renamed `override_read_timeout`. * The error reported the constant, not the ceiling in force, which would have been wrong inside a 200ms probe. It reports the effective bound. The three callers are not one pattern: concurrency.rs:31 tightens to 1s and expects SUCCESS; parallel_lifecycle.rs:138 and :208 use 200ms and assert SILENCE. Evidence, captured verbatim: $ pwd /Users/khaliqgant/AgentWorkforce/flows-claude-lead-0903-wt $ grep -rn "override_read_timeout(None)" kernel/relayflowd/tests/ kernel/relayflowd/tests/crash_resume/concurrency.rs:36: worker.override_read_timeout(None); kernel/relayflowd/tests/crash_resume/parallel_lifecycle.rs:140: worker.override_read_timeout(None); kernel/relayflowd/tests/crash_resume/parallel_lifecycle.rs:210: replacement.override_read_timeout(None); $ grep -rn "set_read_timeout" kernel/relayflowd/tests/crash_resume/llm_support.rs kernel/relayflowd/tests/crash_resume/llm_support.rs:262: .set_read_timeout(Some(READ_TIMEOUT)) kernel/relayflowd/tests/crash_resume/llm_support.rs:334: /// Deliberately NOT named `set_read_timeout`: that name belongs to kernel/relayflowd/tests/crash_resume/llm_support.rs:361: .set_read_timeout(Some(timeout)) $ (cd kernel && cargo test -p relayflowd --test crash_resume) # three times test result: ok. 34 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 37.86s test result: ok. 34 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 37.92s test result: ok. 34 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 37.86s Mutation witness: setting the ceiling to 1ms fails at agent.rs:131 -- `worker.event("step.dispatch")`, the exact blocking read -- with `timed out after 1ms waiting for a protocol frame; the daemon sent nothing (see #174)`, in 0.80s. sha256 before 8d01104e, mutated 06ee52a8, restored 8d01104e. An earlier revision of this message cited a line number that a later edit had shifted, and abbreviated a path and a command that would not run as written. The block above was regenerated by running the commands. 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 has now produced four occurrences and, between them, four test names. Nothing else. The state that would explain it is all on the daemon side and none of it survives: 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 is 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. That last part is the question a missing dispatch actually raises: did the daemon resume and stall partway, or never resume at all? The journal answers it and nothing else does. Stacked on #175, which supplies the bounded read this depends on. With an unbounded read there is no error to catch and nothing to report. Verified by forcing the 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. crash_resume 34 passed in 37.72s / 37.91s / 37.90s. Workspace 142 passed, 0 failed. 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

coderabbitai · 2026-09-05T13:01:00Z

Important

Review skipped

Auto reviews are disabled on base/target branches other than the default branch.

Please check the settings in the CodeRabbit UI or the .coderabbit.yaml file in this repository. To trigger a single review, invoke the @coderabbitai review command.

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Free

Run ID: 4c59008b-6ea9-4470-aadd-1834dc5cf397

You can disable this status message by setting the reviews.review_status to false in the CodeRabbit configuration file.

Use the checkbox below for a quick retry:

🔍 Trigger review

Note

🎁 Summarized by CodeRabbit Free

Your 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 @coderabbitai help to get the list of available commands.}

… for #174 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. 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

) Replaces #176, which GitHub auto-closed when #175 merged and its base branch was deleted. Same change, rebuilt on main. #174 produced four occurrences and, between them, four test names. Nothing else — the state that would explain it was all daemon-side and none 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. On a missing dispatch the test now terminates the resumed child and reaps it, then reports its stdout, stderr, and the run's journal entries with seq/type/step. The child may be stalled or may have already exited, and those are indistinguishable from the test's side — which is 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. The journal is the important half: it answers whether the daemon resumed and stalled or never resumed at all. The listing covers the current segment — every entry these non-compacting crash tests produce, though not every entry under compaction. Evidence at the merged head: - independent signoff: local 3-lens preswarm, all three REVIEW_PASSED. The history lens caught that an earlier message asserted the child "is still running" while also describing one that had already exited; corrected in both message and code comment. - CI: `linux-x64-artifact` run 33975295120 success. Its first attempt failed on `live-kernel.test.ts > follows a live worker dispatch through flows run`, an SDK test this kernel-test-only change cannot affect and the third such flake tonight — filed as #179 — and a re-run of the identical head went green. - mutation: forcing the read ceiling to 1ms produces the dump with the child's output and `seq=1 type=RunSpawned`; sha256 19f3431a -> 361572ef -> restored 19f3431a - workspace 152 passed, 0 failed; crash_resume 34 passed in 37.98s

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.

kjgbot added 3 commits September 5, 2026 14:05

This was referenced Sep 5, 2026

crash_resume's sigkill/real-CLI tests hang intermittently on GitHub runners #174

Open

fix(kernel): resume adopts a real journal whose registry row is missing (#174) #177

Merged

kjgbot force-pushed the fix/174-protocol-read-timeout branch from 64a3635 to 42768e7 Compare September 5, 2026 14:59

kjgbot deleted the branch fix/174-protocol-read-timeout September 5, 2026 15:12

kjgbot closed this Sep 5, 2026

kjgbot mentioned this pull request Sep 5, 2026

test(kernel): dump daemon-side state when a dispatch never arrives (#174) #178

Merged

This was referenced Sep 5, 2026

#177's resume adoption accepts an EMPTY journal, turning run_not_found into an internal error #185

Closed

fix(kernel): adopt only a journal that resume can actually use (#185) #186

Merged

Navigation Menu

test(kernel): dump daemon-side state when a dispatch never arrives (#174) - #176

test(kernel): dump daemon-side state when a dispatch never arrives (#174)#176
kjgbot wants to merge 3 commits into
fix/174-protocol-read-timeoutfrom
diag/174-dump-daemon-state

kjgbot commented Sep 5, 2026

Uh oh!

coderabbitai Bot commented Sep 5, 2026

Review skipped

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Conversation

kjgbot commented Sep 5, 2026

Why

What it does

Evidence

Merge order

Uh oh!

coderabbitai Bot commented Sep 5, 2026

Review skipped

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant