From e6a557d268a14234b9d453807a10ec25968ccfdc Mon Sep 17 00:00:00 2001 From: kjgbot Date: Sat, 5 Sep 2026 15:00:48 +0200 Subject: [PATCH] test(kernel): dump daemon-side state when a dispatch never arrives #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) Claude-Session: https://claude.ai/code/session_01FtQSAcGDta5VH9xiZFT4sR Session-Id: c228933d-4f94-4d83-9a9a-daf3c83b94f1 --- kernel/relayflowd/tests/crash_resume/agent.rs | 20 +++++-- kernel/relayflowd/tests/crash_resume/llm.rs | 21 ++++++- .../relayflowd/tests/crash_resume/support.rs | 55 +++++++++++++++++++ 3 files changed, 89 insertions(+), 7 deletions(-) diff --git a/kernel/relayflowd/tests/crash_resume/agent.rs b/kernel/relayflowd/tests/crash_resume/agent.rs index 3ea4f7b5e..136e9630f 100644 --- a/kernel/relayflowd/tests/crash_resume/agent.rs +++ b/kernel/relayflowd/tests/crash_resume/agent.rs @@ -17,8 +17,8 @@ use super::{ start_run, }, support::{ - completed_step_count, journal_entries, kill_group, kill_process_group, read_pid, - resume_cli, wait_until, + completed_step_count, describe_stalled_resume, journal_entries, kill_group, + kill_process_group, read_pid, resume_cli, wait_until, }, }; @@ -127,8 +127,20 @@ fn rung_c_sigkill_boundaries_resume_only_unfinished_steps_via_real_cli() { let _server = fixture.server(); let mut worker = attached_worker(&fixture, "boundary-agent-stub"); let run_id = super::support::only_run_id(&fixture.data_dir); - let resume = spawn_resume(&fixture, &run_id); - let dispatch = worker.event("step.dispatch").unwrap(); + let mut resume = spawn_resume(&fixture, &run_id); + // Do not `.unwrap()` this. A missing dispatch is #174, and the whole + // difficulty there has been that the failure carries no daemon-side + // state -- so capture it here rather than losing it to the unwind. + // This fires on ANY protocol error, not only a timeout; the dump is + // useful either way, since it reports whether the child is stalled or + // already gone. + let dispatch = match worker.event("step.dispatch") { + Ok(dispatch) => dispatch, + Err(error) => panic!( + "{label}: no step.dispatch after resume: {error}{}", + describe_stalled_resume(&fixture.data_dir, &mut resume) + ), + }; assert!(!record_effect(&fixture, &mut worker, &dispatch).unwrap()); complete(&mut worker, &dispatch).unwrap(); let output = resume.wait_with_output().unwrap(); diff --git a/kernel/relayflowd/tests/crash_resume/llm.rs b/kernel/relayflowd/tests/crash_resume/llm.rs index c3e357bad..d0dcf2f59 100644 --- a/kernel/relayflowd/tests/crash_resume/llm.rs +++ b/kernel/relayflowd/tests/crash_resume/llm.rs @@ -11,7 +11,10 @@ use super::{ llm_support::{ LlmFixture, ProtocolClient, ServerGuard, attached_worker, complete, spawn_resume, start_run, }, - support::{journal_entries, kill_group, only_run_id, read_pid, resume_cli, wait_until}, + support::{ + describe_stalled_resume, journal_entries, kill_group, only_run_id, read_pid, + resume_cli, wait_until, + }, }; #[test] @@ -106,8 +109,20 @@ fn sigkill_sweep_covers_before_and_between_the_rung_b_steps() { let _server = ServerGuard::start(&fixture); let mut worker = attached_worker(&fixture, "boundary-stub"); let run_id = only_run_id(&fixture.data_dir); - let resume = spawn_resume(&fixture, &run_id); - let dispatch = worker.event("step.dispatch").unwrap(); + let mut resume = spawn_resume(&fixture, &run_id); + // Do not `.unwrap()` this. A missing dispatch is #174, and the whole + // difficulty there has been that the failure carries no daemon-side + // state -- so capture it here rather than losing it to the unwind. + // This fires on ANY protocol error, not only a timeout; the dump is + // useful either way, since it reports whether the child is stalled or + // already gone. + let dispatch = match worker.event("step.dispatch") { + Ok(dispatch) => dispatch, + Err(error) => panic!( + "{label}: no step.dispatch after resume: {error}{}", + describe_stalled_resume(&fixture.data_dir, &mut resume) + ), + }; complete(&mut worker, &dispatch, json!({"answer": 4})).unwrap(); let output = resume.wait_with_output().unwrap(); assert!( diff --git a/kernel/relayflowd/tests/crash_resume/support.rs b/kernel/relayflowd/tests/crash_resume/support.rs index 97444c864..80ce8e654 100644 --- a/kernel/relayflowd/tests/crash_resume/support.rs +++ b/kernel/relayflowd/tests/crash_resume/support.rs @@ -156,6 +156,61 @@ pub fn journal_entries(data_dir: &Path) -> Option> { journal.scan_segment(segment).ok() } +/// Everything known about a stalled resume, as one panic message. +/// +/// When a dispatch never arrives (#174) the useful state is all on the daemon +/// side and none of it is captured today: `wait_with_output` is never reached, +/// so the child's output is discarded when the test unwinds, and the journal is +/// never read. Four occurrences produced four test names and nothing else. +/// +/// The child may be STALLED or may have ALREADY EXITED -- #174 turned out to be +/// the second, a resume that died instantly with `run_not_found` while the test +/// waited on it. Both look identical from here, which is the point: this +/// attempts termination and reaps it either way (both results are discarded +/// because "already gone" is a normal outcome, not an error), then reports its +/// output alongside the run's journal. +/// +/// The journal listing covers the CURRENT segment, which is what +/// `journal_entries` scans. These crash tests do not compact, so that is every +/// entry they produce; it would not be under compaction. +pub fn describe_stalled_resume(data_dir: &Path, resume: &mut Child) -> String { + let mut report = String::new(); + + // Kill before read. The child is not going to finish on its own. + let _ = resume.kill(); + let _ = resume.wait(); + + let mut stdout = String::new(); + let mut stderr = String::new(); + if let Some(mut handle) = resume.stdout.take() { + let _ = std::io::Read::read_to_string(&mut handle, &mut stdout); + } + if let Some(mut handle) = resume.stderr.take() { + let _ = std::io::Read::read_to_string(&mut handle, &mut stderr); + } + report.push_str(&format!( + "\n--- resume child ---\nstdout ({} bytes):\n{stdout}\nstderr ({} bytes):\n{stderr}\n", + stdout.len(), + stderr.len() + )); + + // The journal says how far the run actually got, which is the question a + // missing dispatch raises: did the daemon resume and stall, or never resume? + match journal_entries(data_dir) { + None => report.push_str("--- journal --- absent (no run directory)\n"), + Some(entries) => { + report.push_str(&format!("--- journal ({} entries) ---\n", entries.len())); + for entry in &entries { + report.push_str(&format!( + " seq={} type={:?} step={:?}\n", + entry.seq, entry.entry_type, entry.step_id + )); + } + } + } + report +} + pub fn completed_step_count(entries: &[JournalEntry]) -> usize { entries .iter()