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

The kernel test step hangs and is cancelled at ~25-30 minutes, on a test that normally finishes in under a second. It is intermittent and not branch-specific.

Observed:

run	branch	hung on
33922391055	`feat/gate2-wake-context` (#168)	cancelled at 30m14s, `Test kernel`
33960456965	`fix/160-claim-repair-race` (#171)	`llm::sigkill_sweep_covers_before_and_between_the_rung_b_steps`
33961987292	`fix/160-claim-repair-race` (#171)	`agent::rung_c_sigkill_boundaries_resume_only_unfinished_steps_via_real_cli`
33919448689	`main`	passed — both tests ok, `34 passed ... in 38.27s`

Two different tests on the same branch, and a branch (#168) that changes no registry or engine code at all, rules out a single caller's change. Both hangs are in tests/crash_resume, in cases that SIGKILL a child and wait for a resume through a real CLI.

The log signature is always the same:

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

— i.e. it stops producing output entirely rather than failing.

Locally the whole crash_resume target is 34 passed in ~38s, so this does not reproduce on a developer machine; a runner is the only place it has been seen.

Cost so far: it is the reason #171 has no green CI run, and it consumed the 30-minute step on #168. Each occurrence burns ~25-30 minutes of runner time.

This is the hang half of #160. The left: 2 half was a genuine exactly-once bug and is fixed in #171; the two were conflated because they appeared in the same runs. They are unrelated defects.

Worth attacking with a per-test timeout so the failure names itself instead of consuming the whole step, plus stderr capture from the spawned CLI — right now a hang produces no evidence at all about which side is stuck.

Confirmed, and narrowed to one test.

agent::rung_c_sigkill_boundaries_resume_only_unfinished_steps_via_real_cli has now hung three times, on two branches with no code in common:

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_…`

feat/gate2-wake-context changes kernel/relayflowd-journal/src/registry.rs by 0 lines (git diff origin/main...origin/feat/gate2-wake-context --stat -- <that file>), so it shares none of #171's engine or registry changes. A defect that reproduces on both is in neither.

It is intermittent rather than universal — main's run 33919448689 passed both tests, 34 passed … in 38.27s. But it has now hit 3 of the 4 most recent non-main runs, so "intermittent" understates it: on current evidence a kernel-touching PR is more likely to hang than not.

Consequence: #171 and #168 cannot obtain a green CI run, and neither will any future kernel PR at this rate. This is now the binding constraint on the lane, ahead of anything in those PRs.

I have not attempted a fix. It wants a per-test timeout so a hang names itself instead of eating the 30-minute step, and stderr capture from the spawned CLI — today a hang produces no evidence at all about which side is stuck, which is why three runs cost 75 minutes and yielded one test name.

test(kernel): bound protocol reads and restore the ceiling on override

Reproduced on CI with a location and a diagnosis, for the first time.

#175 bounds the protocol read. Its own CI run (33966141540) hit the bug, and instead of a cancelled 30-minute step it produced:

test llm::sigkill_sweep_covers_before_and_between_the_rung_b_steps ... FAILED

---- llm::sigkill_sweep_covers_before_and_between_the_rung_b_steps stdout ----
thread '…' panicked at relayflowd/tests/crash_resume/llm.rs:110:54:
called `Result::unwrap()` on an `Err` value: timed out after 60s waiting for a
protocol frame; the daemon sent nothing (see #174)

test result: FAILED. 33 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 65.58s

65 seconds instead of 30 minutes, and it names the line.

What this establishes, which was previously unknown:

The hang is a daemon that never sends the frame, not a slow test and not a stuck harness. The read waited a full 60s on a runner where the whole target normally finishes in 38s.
It is at llm.rs:110, the event(...) awaiting a dispatch after a SIGKILL-and-resume.
It reproduces on demand on a runner while never reproducing locally (34/34 in ~37.9s across many runs here), so it is environment-dependent — most likely a timing or process-group interaction that only a runner exhibits.

That is enough to actually chase the daemon side now. Until #175 lands, every occurrence still costs a cancelled 30-minute step and yields nothing.

Note the previous three hangs split across two different tests (agent::rung_c_sigkill_boundaries_… twice, llm::sigkill_sweep_… twice counting this one). Both wait on the same event(...) read, so it is one defect with two witnesses, not two.

docs(drive-log): 2026-09-05 12:40Z — #174 diagnosable, #175 opened

Two hypotheses tested and eliminated, both by measurement

Neither is the cause. Recording them so nobody spends the time again.

1. Missing analyzer/provider environment on the runner — NO

The Test kernel step in cloud-runtime-artifact.yml has no env: block at all, while Test SDK carries RELAYFLOWS_ALLOW_ANALYZER_SKIP: '1'. That asymmetry looked like the answer: a kernel test needing a model on a runner that has none.

It is not. The fixture uses a stub:

"model": "deterministic-stub"

No provider is reached, so there is nothing for a missing analyzer to break.

2. Pipe-buffer deadlock on the resumed daemon — NO

This one fit every fact. Both spawn_resume helpers (llm_support.rs:250-251, agent_support.rs:230-231) set Stdio::piped() on stdout and stderr, and the test does not drain them until wait_with_output(), which runs only after the dispatch it is waiting for. A child that writes past the ~64KB pipe buffer blocks on write and never dispatches — deadlock. Those two helpers are also the only piped spawns in crash_resume, matching "two tests in two files, one signature" exactly.

Measured instead of assumed:

PROBE before-first:      stdout=111 bytes stderr=0 bytes
PROBE between-first-llm: stdout=111 bytes stderr=0 bytes

111 bytes against a 64KB buffer. Not close, and RUST_LOG=trace changes nothing because the daemon has no RUST_LOG plumbing — so log volume is fixed and small. Dead.

Where that leaves it

The daemon genuinely does not send the dispatch on a runner, and it is not the environment and not backpressure. Beyond this I would be guessing, which has cost enough today.

The next useful step is daemon-side evidence, which nothing currently captures: on a dispatch timeout the resumed child is still running, so its output is never read and the journal state at the moment of the stall is never inspected. #175 gives the test-side name and line; a follow-up should kill the child on timeout and dump its captured output plus the run's journal rows. That turns the next occurrence into a diagnosis instead of another data point.

docs(drive-log): 2026-09-05 12:58Z — two #174 hypotheses eliminated b…

docs(drive-log): 2026-09-05 13:16Z — #176 opened, daemon-side capture…

Root cause found. It is a product durability bug, not a test bug.

#176's very first CI run answered it. The diagnostic paid for itself immediately:

before-first: no step.dispatch after resume: timed out after 60s waiting for a
protocol frame; the daemon sent nothing (see #174)
--- resume child ---
stdout (0 bytes):

stderr (68 bytes):
Error: run_not_found: run 01M1RTPC3PE8AN71QD8CQZJ26D does not exist

--- journal (1 entries) ---
  seq=1 type=RunSpawned step=None

The resumed process exited immediately. It never hung. The test then waited 60 seconds for a dispatch from a process that was already dead — which is why every previous occurrence looked like a hang and told us nothing.

The defect

Engine::start registers the run last:

let run_id = Ulid::new().to_string();
let path = self.run_path(&run_id);
SqliteJournal::create(&path, &run_id, now_ms)?;   // journal exists
self.append(... EntryType::RunSpawned ...)?;      // journal has RunSpawned
self.registry()?.register(&run_id, &path)?;       // ← registry row, LAST

A SIGKILL between the append and the register leaves precisely the state above: a journal containing seq=1 RunSpawned, and no runs row.

And resume requires that row, with no fallback (server.rs:177-186):

if registry.lookup(&params.run_id)?.is_none() {
    return Err(("run_not_found", format!("run {} does not exist", params.run_id)));
}

So the run is unrecoverable: its journal is on disk, intact, and nothing can resume it.

Worth noting the codebase already disagrees with itself here. The journal-opening path tolerates a missing registry row and falls back to the conventional location:

let path = registered.map(|r| r.file).unwrap_or_else(|| self.run_path(run_id));

One path self-heals; the other hard-fails on the same condition.

Why it looks like a runner-only flake

The test kills as soon as completed_step_count == 0, which is true the moment the journal exists — i.e. the earliest possible instant, squarely inside the window. Locally register wins that race essentially always; on a loaded runner it does not. Nothing about the runner is broken. The window is real everywhere and the runner just samples it.

This is the same shape as #160

Register-after-the-fact leaves a window in which a run exists in one store and not the other. #171 fixes that for the event-claim path. This is the same class in the start path, and it costs durability rather than exactly-once: a run SIGKILLed early can never be resumed.

Fix options

Make resume self-healing — on a missing registry row, look for runs/<id>.sqlite3, and if a valid journal is there, re-register and continue. Eliminates the window rather than shrinking it, and matches what the journal path already does. My preference.
Register earlier — immediately after SqliteJournal::create, before the first append. Shrinks the window; does not close it.
Both.

(1) also recovers runs already orphaned by this bug, which (2) does not.

I have not implemented it: this is kernel-core durability and wants its own PR with a real signoff, not a rider on the diagnostic that found it.

docs(drive-log): 2026-09-05 13:34Z — #174 root cause: run registered …

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

fix(kernel): resume adopts a real journal whose registry row is missi…

docs(drive-log): 2026-09-05 13:56Z — #174 fixed and merged as #177

test(kernel): bound protocol reads so a missing frame fails instead o…

test(kernel): bound protocol reads and restore the ceiling on override

test(kernel): bound protocol reads so a missing frame fails instead o…

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

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

ci: run the artifact workflow on push to main (#191)

Reopening: this is still firing on main, and it now has a much larger sample behind it.

Seven commits landed on main within ten minutes today (#193, #196, #203, #202, #198, #200, #194). Of the runs that have completed, two failed on exactly this test:

faf625b (#193)  success
25f38ec (#196)  FAILURE   <- llm::sigkill_sweep_covers_before_and_between_the_rung_b_steps
082c62a (#203)  success
755b37a (#202)  FAILURE   <- same test
99b6f61 (#198)  success

Both failures are the same assertion, crash_resume/llm.rs:121:

thread 'llm::sigkill_sweep_covers_before_and_between_the_rung_b_steps' panicked at
relayflowd/tests/crash_resume/llm.rs:121:27
test result: FAILED. 33 passed; 1 failed

which is the no step.dispatch after resume path — the one the comment right above it already attributes to this issue.

Why it looks new and is not. Every main run before today succeeded, which makes this read like a regression from one of the merges. It is not: 755b37a is a shell-only change to swarm-verdict.sh and cannot touch the kernel, yet it failed, while 99b6f61 passed with identical kernel code. And the same workflow failed on fix/174-protocol-read-timeout, diag/174-dump-daemon-state and fix/160-claim-repair-race on 2026-09-05, before any of today's merges.

What changed is the sample size, not the failure rate. main normally sees about one run a day; today it saw seven in ten minutes. A roughly 2-in-7 intermittent failure is invisible at one run a day and obvious at seven in ten minutes.

That is the argument for reopening rather than re-closing: the fix work under this number reduced the rate enough that a low-traffic branch stopped showing it, which is not the same as the hang being gone. Anything that raises merge frequency — the review swarm actually running, for one — will surface it again immediately.

I have not investigated the hang itself; I ran into it while verifying that today's merges left main healthy, and establishing that they did is what turned this up.

docs(drive-log): main's post-merge failures are #174 flake, not a reg…

docs(drive-log): my NEXT.md wasted four drive cycles; retargeted at #174

docs(next): point drive runs at #174 instead of human-blocked credent…

Kill the rung-B before-first sweep only after the run exists

Harden agent transport recovery and diagnostics (#501)

Navigation Menu

Repository navigation

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

Reproduced on CI with a location and a diagnosis, for the first time.

Two hypotheses tested and eliminated, both by measurement

1. Missing analyzer/provider environment on the runner — NO

2. Pipe-buffer deadlock on the resumed daemon — NO

Where that leaves it

Root cause found. It is a product durability bug, not a test bug.

The defect

Why it looks like a runner-only flake

This is the same shape as #160

Fix options

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

kjgbot commented on Sep 5, 2026

kjgbot commented on Sep 5, 2026

Reproduced on CI with a location and a diagnosis, for the first time.

kjgbot commented on Sep 5, 2026

Two hypotheses tested and eliminated, both by measurement

1. Missing analyzer/provider environment on the runner — NO

2. Pipe-buffer deadlock on the resumed daemon — NO

Where that leaves it

kjgbot commented on Sep 5, 2026

Root cause found. It is a product durability bug, not a test bug.

The defect

Why it looks like a runner-only flake

This is the same shape as #160

Fix options

kjgbot commented on Sep 6, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions