test(kernel): bound protocol reads so a missing frame fails instead of hanging (#174) by kjgbot · Pull Request #175 · AgentWorkforce/flows

kjgbot · 2026-09-05T12:06:18Z

Addresses #174, which is currently the binding constraint on the whole lane: no kernel-touching PR can obtain a green CI run.

What was happening

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:

run	branch	hung on
33922391055	`feat/gate2-wake-context` (#168)	`agent::rung_c_sigkill_boundaries_…`
33961987292	`fix/160-claim-repair-race` (#171)	`agent::rung_c_sigkill_boundaries_…`
33961987292 (rerun)	`fix/160-claim-repair-race` (#171)	`agent::rung_c_sigkill_boundaries_…`
33960456965	`fix/160-claim-repair-race` (#171)	`llm::sigkill_sweep_covers_before_…`

The only output any of them produced was the harness's own line:

test <name> has been running for over 60 seconds
##[error]The operation was canceled.

Three runs, 75 minutes of CI, one test name between them.

Cause

ProtocolClient::connect set no read timeout, so read_frame's read_line blocks indefinitely and event() loops on it. These tests SIGKILL a daemon and resume it, so "the dispatch never arrives" is a reachable state, not a hypothetical — and an unbounded read turns that state into a silent hang with no evidence.

Both hanging tests reach the socket through this one client, which is why two unrelated branches produced the identical signature.

What this does — and does not — do

It bounds the read at 60s and names the timeout. It does not fix the underlying nondeterminism. The next occurrence will fail in 60 seconds naming its own line, instead of consuming the 30-minute step and telling us nothing. That is the prerequisite for diagnosing the real defect, which cannot be done from the evidence we have today.

60s against a target that runs in 38s, so it can only fire on "never", not on "slow".

Evidence

Mutating the ceiling to 1ms fails at exactly the predicted line:

panicked at relayflowd/tests/crash_resume/agent.rs:131:54:
called `Result::unwrap()` on an `Err` value: timed out after 1ms waiting for a
protocol frame; the daemon sent nothing (see #174)
test result: FAILED. 0 passed; 1 failed ... finished in 0.80s

agent.rs:131 is worker.event("step.dispatch") — which also confirms where CI was stuck.

Restored (sha256 verified identical to pre-mutation), crash_resume is 34 passed in 37.8s across three consecutive runs, against 38.27s on main's own CI. Workspace: 142 passed, 0 failed.

Note on this PR's own CI

This is the bootstrap out of the deadlock: if the hang recurs on this very PR, the fix converts it into a named 60-second failure rather than another cancelled step. Either outcome is informative.

🤖 Generated with Claude Code

https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR

coderabbitai · 2026-09-05T12:06:26Z

Warning

Review limit reached

Next included review available in 30 minutes.

Check out review usage here.

View limit details

Limit 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.
You're only billed for reviews past your plan's rate limits ($0.25/file).

Learn how review limits work.

Review configuration:

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Free

Run ID: 761f399d-07fb-4a35-bde8-62bd96a60f9a

📥 Commits

Reviewing files that changed from the base of the PR and between 4e0df51 and 42768e7.

📒 Files selected for processing (3)

kernel/relayflowd/tests/crash_resume/concurrency.rs
kernel/relayflowd/tests/crash_resume/llm_support.rs
kernel/relayflowd/tests/crash_resume/parallel_lifecycle.rs

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.}

kjgbot · 2026-09-05T12:35:44Z

Signoff: obtained. CI: red — and the red is the point.

Condition 1 — independent signoff: met. Local 3-lens preswarm at this head:

PRESWARM_maintainability: REVIEW_PASSED
PRESWARM_history:         REVIEW_PASSED
PRESWARM_structure:       REVIEW_PASSED

It took four iterations, and each one caught something real, all now fixed:

the ceiling was cancellable — three callers passed None and kept reading, which cleared it (dup'd fds share SO_RCVTIMEO), so my "reads are bounded" claim was false as written;
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;
the method 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;
and two commit messages of mine were inaccurate: one described all three callers as "200ms probes" when concurrency.rs:31 uses 1s and expects success, and one cited a line number a later edit had shifted. Both regenerated by running the commands.

Condition 2 — green CI: not met, because the bug this PR exposes is real. Run 33966141540:

panicked at relayflowd/tests/crash_resume/llm.rs:110:54:
timed out after 60s waiting for a protocol frame; the daemon sent nothing (see #174)
test result: FAILED. 33 passed; 1 failed ... finished in 65.58s

That is the intended behaviour of this change: 65 seconds and a location, where the same failure previously consumed a cancelled 30-minute step and produced nothing. It is the first actionable evidence #174 has ever generated (posted there).

Not merging. I have no green CI run and the rule is explicit, so this is for a human to weigh. My recommendation is to take it: main already has this defect and currently expresses it as an intermittent 30-minute cancellation with no diagnosis. Merging does not add a failure — it converts one that already exists into one that names itself in a minute. But that is a judgement about accepting a knowingly-red check on main, which is not mine to make unattended.

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

…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 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 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: 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

) 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

merged 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.

kjgbot force-pushed the fix/174-protocol-read-timeout branch 2 times, most recently from 030fb78 to 64a3635 Compare September 5, 2026 12:28

kjgbot mentioned this pull request Sep 5, 2026

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

Open

This was referenced Sep 5, 2026

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

Closed

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

Merged

kjgbot added 2 commits September 5, 2026 16:56

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

kjgbot merged commit 696d3e3 into main Sep 5, 2026
3 of 5 checks passed

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

This was referenced Sep 5, 2026

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

Merged

SDK suite flakes intermittently in CI, costing a full cycle each time #179

Closed

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

Uh oh!

test(kernel): bound protocol reads so a missing frame fails instead of hanging (#174) - #175

test(kernel): bound protocol reads so a missing frame fails instead of hanging (#174)#175
kjgbot merged 2 commits into
mainfrom
fix/174-protocol-read-timeout

kjgbot commented Sep 5, 2026

Uh oh!

coderabbitai Bot commented Sep 5, 2026 •

edited

Loading

Review limit reached

Uh oh!

kjgbot commented Sep 5, 2026

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Uh oh!

Conversation

kjgbot commented Sep 5, 2026

What was happening

Cause

What this does — and does not — do

Evidence

Note on this PR's own CI

Uh oh!

coderabbitai Bot commented Sep 5, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Review limit reached

Uh oh!

kjgbot commented Sep 5, 2026

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

coderabbitai Bot commented Sep 5, 2026 •

edited

Loading