The recovery harness reads a worker's word once the worker has said it by jorgemanrubia · Pull Request #752 · basecamp/basecamp-cli

jorgemanrubia · 2026-09-18T11:04:40Z

TestRecoveryAtEveryLedgerState/acp/dispatched,_attempt_running_before_the_prompt fails most runs on main, with nothing applied: 13 of 20 here. It came in with the acp harness row in Six stacked pull requests, landed as one.

Originally tracked in A recovery test fails four runs in five on main.

What it is

A test race, and the harness was asserting something the design does not promise at that moment. The connector loses nothing.

The credential check runs the instant the connector exits and counted, right there, whether every worker that started had either taken its token or said why it could not. But the word is the worker's, written from its own process at its own pace, and it is due by the worker's exit — not the connector's. At this kill point the connector is killed at its running line, which it writes once the socket is armed and the attempt is recorded, while the handoff itself is still in flight on the socket's own goroutine. The acp row's worker starts the bind that dials the socket as the last act of its handshake (the socket cannot be armed until NewSession returns, so it cannot start it sooner), learns of the death as a reset on the socket, and writes bind-failed: … connection reset by peer about 200 µs after the parent saw the connector go. Instrumented timeline from a failing run: worker dialed at .727558, connector dead by .728645, bind-failed written at .728851, parent had already read the log. The word was said; it was read too early.

The spawn rows pass the same check at the same kill point for a worse reason: the connector dies about a millisecond after StartWorker, before the wrapper has exec'd the Go binary, so the check counts zero workers and asserts over nobody. The later runs of the same test see that worker start after the death, dial a dead socket, and say so.

What changes

The check now waits for every worker owed a word — the process the ledger recorded for the attempt, and every one that reached its agent — to say it or to be gone, and counts from that reading. Each is waited on by its identity (pid and kernel start time, through the same ProcessGone the connector uses), not by a pid the kernel may have given away. Both halves are held: a worker still alive without a word when the wait runs out fails, and so does one gone without ever saying it. The watch for a token in a file runs until then too. The real-agent rows leave no agent log and are owed nothing.

After: 0 of 20 runs on the acp row, 0 of 5 each on claude and codex — which now count the worker they start (1 workers started, 0 bound, 1 said why not) instead of nobody — and 0 failures over 432 subtests, three runs of the whole recovery table under the stricter check. About 20 ms per run. Under -race this row does not run at all (it is not in the representative subset), so there is no rate to give there.

Nothing in the connector changed: at that kill point the restart recovers the attempt as lost with one notice, as the row expects, and did before.

Two more things the same standard turned up

The acp fake spoke only once its bind had started, and its bind starts at the read-back, the last act of the handshake. A worker whose connector died before that exited with a start entry and no word — the one case the original assertion was written for, and one it could only see once it read the log at the right moment. The fake now says so on that exit; the spawn fakes bind before they speak and never had the gap.

The guard rows kill the connector as it posts the guard acknowledgement, due 50 ms after admission, and assumed the launch had finished by then. On a loaded CI runner the acp launch had not, the kill landed on an attempt still launching with no worker recorded, and the restart held it — as it must — so the surviving run never settled. Reproduced under CPU load, 3 of 3. The fake Basecamp now holds the acknowledgement until the connector has written its running line, so the order is made rather than waited for and the guard's period stays at 50 ms: 0 of 10 loaded, 0 of 5 plain across the drivers, 0 of 5 under -race.

The watch for a token in a file now runs for the harness rather than for a run — a worker that has spoken may still be running and able to write one — and a worker's word is matched to it by pid and kernel start time, never by a pid alone, with a small test holding that: on pid-only matching, three of its four cases fail.

The reading of that watch joins the loop that registers watchers before it reads them, so a watcher cannot be registered after the reading and left unread — a race older than this branch — and a token first seen in the loop's last interval is still watched, once, by the reading itself. A test holds it; on the previous watcher it fails 20 of 20.

The credential check runs the moment the connector exits, and counted there whether every worker that started had taken its token or said why it could not. The word is the worker's, written from its own process at its own pace, and it is due by the worker's exit, not the connector's. At the kill point where the attempt is running before the prompt the two are not one moment: the connector is killed at its "running" line with the token handoff still in flight on the socket's goroutine, and the acp row's worker, whose bind began as the last act of its handshake, learns of the death as a reset on the socket and says so a fraction of a millisecond after the parent has seen the connector go. Read at the exit, the log counted it as a worker that said nothing: 13 of 20 runs on main. The spawn rows passed the same check at the same kill point over nobody, since their worker had not even reached its agent when the connector died a millisecond after starting it. The check now waits for every worker owed a word — the process the ledger recorded for the attempt, and every one that reached its agent — to say it or to be gone, and counts from that reading. A worker that is gone without a word still fails it. 0 of 20 runs after, and the spawn rows now count the worker they start: it dials a dead socket and says so.

Copilot

🟡 Changes recommended

The harness can still accept incomplete worker reporting and miss transient credential leaks.

Get a fresh assessment by requesting another Copilot review.

Pull request overview

Stabilizes recovery credential checks by waiting for worker outcomes after connector exit.

Changes:

Waits for recorded workers to report binding outcomes or exit.
Adds worker outcome counts to test diagnostics.
Reads worker PIDs from the recovery ledger.

[!TIP]
If you aren't ready for review, convert to a draft PR.
Click "Convert to draft" or run gh pr ready --undo.
Click "Ready for review" or run gh pr ready to reengage.

File summaries

File	Description
internal/connector/recovery_harness_test.go	Synchronizes worker outcome collection in recovery tests.

Review details

Files reviewed: 1/1 changed files
Comments generated: 3
Review effort level: Balanced

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

… the watch still running The wait for the workers' word ran after the parent had stopped watching for a token in a file, though the workers it waits on are exactly the ones still able to write one; it discarded its own deadline, so a worker still alive without a word thirty seconds after the connector died left a partial log to count; a worker the ledger recorded that was gone without ever reaching its agent made the count zero of zero; and it waited on bare pids, which the kernel gives away, so it could have waited on a stranger or taken a stranger's exit for the worker's (Copilot on #752). The watch now stops once the workers have spoken. The wait fails on its deadline, and fails again on a worker gone without a word. Each worker is waited on by its identity — the kernel start time the ledger recorded, or the one the fake writes on its own start entry, which used to carry a wall-clock stamp no identity check would answer about — through the same ProcessGone the connector uses. 0 of 20 runs on the acp row, 0 of 5 each on claude and codex, 0 of 432 subtests over three runs of the whole recovery table.

jorgemanrubia · 2026-09-18T11:27:39Z

🤖 On the Tests failure of the first push (run 35337837155): it was not this package. internal/connector passed there (197.6 s) — the first CI pass of that package since #748, whose own main run 35334061041 failed on exactly the row this PR fixes, as did three other branches' runs today (connect-worktree-codex-and-arming, doctor-runs-the-preflight ×2).

What failed was TestAnUnsafeSessionStillReportsItsRefusals in internal/connector/driver/codex (the result carries what the ledger carries: 1 refusal expected, 0 in the result). It is a pre-existing CI-only flake: it also failed on connect-stack at ab8a610 (run 35325609423) before this branch existed, and it passes 300 of 300 locally. The mechanism is a race in the fake's favour on a fast machine: the driver verifies the rollout on its own goroutine and, on approval_policy = on-request, finishUnsafe SIGKILLs the worker at once; the fake emits turn.started, the denial and turn.completed in sequence, and when the kill lands before the denial has been flushed to stdout, lastWord reads the stderr refusals but the event was never written. That is a separate card, not this PR.

For completeness, TestAFailedHandshakeLeavesNoGroupBehind (driver/acp) failed on two of those runs too, and is likewise not touched here.

Copilot

🟡 Changes recommended

Worker identity matching and watcher lifetime can still allow the recovery harness to miss worker activity.

Get a fresh assessment by requesting another Copilot review.

Review details

Suppressed comments (1)

Previously missed (1) — in code that hasn't changed since the last review.

internal/connector/recovery_harness_test.go:822

Keep the parent file watcher active for every worker that can still write, not only workers that still owe a terminal word. A fake linger worker logs bound before remaining alive, so it is removed from workersOwingAWord; real-agent workers are also omitted at lines 814-816. The check then stops the watcher while those processes can still create and remove a token-bearing file, which the later point-in-time scan cannot detect. Separate word accounting from worker-lifetime tracking, and preserve the watcher across runs until each recorded process identity exits, without blocking rows whose next restart intentionally terminates a lingering worker.

Files reviewed: 3/3 changed files
Comments generated: 1
Review effort level: Balanced

…s worker by identity The acp fake spoke only once its bind had started, and its bind starts at the read-back, the last act of the handshake. A worker whose handshake never got there — the connector dead before it, as on a CI runner where a guard fired mid-launch — exited with a "start" entry and no word, and the check named it as gone without one (run 35339688393, pid 16811). It now says so on that exit: no server started, no token was asked for. The spawn fakes bind before they speak and never had the gap. The check matched a word to a worker by pid alone, though the log and the ledger both accumulate across a harness's connector runs, so a word an earlier worker said could have discharged a later one the kernel named alike. It now matches by pid and kernel start time, the same identity ProcessGone waits on (Copilot on #752). Run with stdin closed before any handshake, the fake of 77d00ec leaves "start" alone in the agent log; this one leaves "start" and "bind-failed: the session ended before its MCP servers started, so no token was asked for".

The guard is due a delay after admission, and the rows kill the connector as it posts the acknowledgement. That kill has to land on an attempt already running, with a worker recorded, or the restart holds an attempt it cannot identify and the surviving run never settles: 120 seconds and a failure that names neither. At 50ms a loaded CI runner lost that race (run 35339688393, both acp rows), and so does this machine under load: 3 of 3 runs, each with the attempt left mid-launch. A second is the guard's own period, sized so a working directory, the ledger, the token socket, the agent's wrapper and, for the acp row, its whole handshake fit inside it; 0 of 10 loaded runs after, 0 of 10 without load. A check after the kill now says in a moment when the launch still lost, rather than at the surviving run's deadline.

jorgemanrubia · 2026-09-18T12:02:11Z

🤖 On the second push's Tests run (35339688393), which hit the 600 s package timeout: that runner was badly loaded (driver/acp 99 s vs 39 s the run before; TestAFloodOfPermissionRequestsIsBounded, TestAFailedHandshakeLeavesNoGroupBehind and TestAResumedThreadIsJudgedByItsNewTurn failed alongside, none of them in this package). Within internal/connector the failures were both acp rows of TestRecoveryTheGuardAcknowledgementIsPostedAtMostOnce, 120 s each, and they are worth being precise about because one of them was mine to answer.

The primary failure was pre-existing and in the same class as this PR's root cause. The guard is due 50 ms after admission, and the row kills the connector as it posts the acknowledgement; on that runner the acp launch (workspace, ledger, token socket, the sh wrapper exec of the test binary, four JSON-RPC round trips) did not fit in 50 ms, so the kill landed on an attempt still launching, with no worker recorded. The restart then held "an attempt left mid-launch whose worker cannot be identified" — as it must — and the surviving run could never settle. Reproduced here under CPU load: 3 of 3 runs, each with the attempt left mid-launch; 0 of 10 loaded runs and 0 of 10 without load after a4542b2, which sizes the guard's period so the launch fits and fails in a moment, naming the assumption, if it still does not.

The secondary one was mine. The killed run's check reported 0 workers started — the acp worker had not exec'd yet — and it exec'd after the connector died, wrote its start entry, read EOF before any handshake and exited without a word, because the acp fake only spoke once its bind had started at the read-back. The old started == bound+unbound would have failed on that too (1 vs 0); the new check named the pid. e59f064 makes the fake say so on that exit (bind-failed: … no token was asked for). Run with stdin closed before any handshake, the previous fake leaves start alone in the agent log; this one leaves the word too. The assertion is unchanged.

Rates on the whole set now: acp kill-point row 0/20, claude and codex 0/5 each, guard acp rows 0/10 loaded and 0/10 plain, whole recovery table 0 failures over 432 subtests.

Copilot

🔵 Needs a closer look

Worker identity and token-watcher edge cases can still let recovery checks pass prematurely.

Review details

Suppressed comments (2)

Previously missed (2) — in code that hasn't changed since the last review.

internal/connector/recovery_harness_test.go:822

The wait tracks only workers that have not yet logged bound or bind-failed. A bound worker is removed from workersOwingAWord immediately, although scenarios such as linger leave that process running after the connector exits. stopWatchingForTokenFiles can therefore stop while a token-holding worker is still able to create and remove a token-bearing file, defeating the transient-leak check. Track worker lifetime separately from terminal-word accounting, and keep the watcher active until each token-holding worker has exited (including across the recovery run that terminates lingering workers).
internal/connector/recovery_harness_test.go:874
Terminal entries with no kernel start stamp can currently satisfy a ledger record that has the same PID and a NULL process_started. That bypasses ProcessGone, even though the record is not an identity and could refer to an earlier process whose PID was reused. Exclude zero-stamped terminal entries from said; the remaining recorded/start entry will then reach ProcessGone or the final silent-worker assertion instead of being accepted by PID alone.

Files reviewed: 4/4 changed files
Comments generated: 0 new
Review effort level: Balanced

… no identity discharges nobody The watch stopped at each run's credential check, though a worker that has said its word may still be running — one left lingering for a restart to end, a real agent — and can write a token to a file in the gap between one run's exit and the next run's start, or after the last. It now starts with the first run and ends at cleanup, once every worker this harness started has been ended, and reports then (Copilot on #752, the note it held back at 77d00ec and again at a4542b2). A word written with no kernel start stamp could have discharged a ledger record with none — no identity matching no identity, by pid alone. Such a word now discharges nobody; the worker it was meant for reaches ProcessGone, or the silent check, and is answered for there. TestAWorkersWordIsMatchedByItsIdentity holds the matching to this. On the pid-only matching of 77d00ec three of its four cases fail: an earlier process's word under the same pid discharges the later worker, a word with no identity discharges it, and a start entry is discharged by a word that was never its own.

jorgemanrubia · 2026-09-18T12:22:29Z

🤖 Copilot's review body on a4542b2 held back two notes it did not post as threads ("previously missed", recovery_harness_test.go:822 and :874). Both taken, in 9666371, and here is why neither could make the check pass early before, and cannot now.

The wait has no deciding snapshot. awaitWorkersWord recomputes the owed set on every 5 ms poll from a fresh read of the log; it ends only when every owed identity is gone per driver.ProcessGone; and the reading it counts from is taken after that, when a gone process can write nothing more. A worker that speaks after any poll is not owed on the next; one alive without a word holds the wait open and fails it at 30 s by name; one gone without a word fails require.Empty. The :822 note was about something else: a linger worker has spoken, so it is not owed, and the per-run file watcher stopped while it still lived — a gap that predates this PR (the watcher always stopped at the connector's exit) and that the restart re-watched. It is now closed structurally: the watch starts with the first run, no run's check stops it, and it stops in a cleanup registered before killAgents, so it reports after every worker this harness started has been ended. No row leaks a token, so there is no rate to show for it; the whole table is unaffected (0 failures over 432 subtests, three runs).

Identity. Both sides key by pid plus kernel start time; ProcessGone compares exactly and answers ErrIdentityUnknown for a live record without a stamp, which fails the check rather than passing it; and per :874, a word without a stamp now discharges nobody. TestAWorkersWordIsMatchedByItsIdentity holds that. On the pid-only matching of 77d00ec, three of its four cases fail — an earlier process's word under the same pid discharges the later worker, a word with no identity discharges it, and a start entry is discharged by a word that was never its own:

--- FAIL: TestAWorkersWordIsMatchedByItsIdentity/an_earlier_process's_word,_under_the_same_pid,_does_not
        expected: []int{4242}   actual  : []int{}
--- FAIL: TestAWorkersWordIsMatchedByItsIdentity/a_word_with_no_identity_discharges_nobody
        expected: []int{4242}   actual  : []int{}
--- FAIL: TestAWorkersWordIsMatchedByItsIdentity/a_start_entry_is_owed_by_its_own_identity_too
        expected: []int{4343}   actual  : []int{}

Green on the head. Rates on the final tree: acp kill-point row 0/20, claude and codex 0/5 each, guard acp rows 0/5 plain (0/10 loaded on the previous head, which this commit does not touch), whole recovery table 0 failures over 432 subtests. Full gate green.

Copilot

🟡 Changes recommended

Token-watcher cleanup can race with late watcher registration and discard detected leaks.

Get a fresh assessment by requesting another Copilot review.

Review details

Files reviewed: 4/4 changed files
Comments generated: 1
Review effort level: Balanced

… before it reads them The loop that registers a watcher for each token and the cleanup that stopped and read the watchers shared the map with nothing ordering them: the loop could read the tokens on disk, the cleanup could drain the map, and the loop could then register a watcher nobody would stop or read — a leak it went on to see, discarded. The race was per run before this branch and per harness after it; a check inside the loop would have narrowed it (Copilot on #752), and joining the loop removes it. A watcher is now started in one place only, from that loop, and the reading closes the loop and waits for it to return before it touches the map. Then the reading registers, once, whatever token the loop's last interval never got to — a watcher scans before it is stopped — and only then stops and reads every watcher there is. Nothing found is dropped: every watcher ever started is in the map, and every one in the map is read by the one goroutine that can still reach it. TestTheTokenWatchReadsEveryWatcherItCouldHaveStarted holds it: a token taken just before the reading is watched and counted by it, no watcher is registered after, and a later reading watches what it knows and reads it. On the watcher of 9666371 it fails 20 of 20 runs — the token taken just before the reading was not watched at all.

jorgemanrubia · 2026-09-18T12:41:57Z

🤖 On Copilot's round at 9666371 — "cleanup can race with late watcher registration and discard detected leaks" — that was a real race, older than this branch (the per-run watcher had it too), and the worst failure mode this harness has: a leak seen and then dropped, reported green. 2f9b074 removes it structurally rather than checking for it.

A watcher is started in one place only, from the registering loop. The reading (stopWatchingForTokenFiles, the harness's cleanup after killAgents) closes the loop and waits for it to return before it touches the map, so a registration after the reading is not caught, it is impossible. The reading then registers, once, any token the loop's last interval never reached — a watcher scans before it is stopped — and only then stops and reads every watcher there is. Every watcher ever started is in the map, and every one in the map is read by the one goroutine that can still reach it; nothing found is dropped.

TestTheTokenWatchReadsEveryWatcherItCouldHaveStarted holds three things deterministically: a token taken just before the reading is watched and counted by it; no watcher is registered after it; a later reading watches what it knows and reads it. On the watcher of 9666371, with the same test, 20 of 20 runs fail:

--- FAIL: TestTheTokenWatchReadsEveryWatcherItCouldHaveStarted
        Messages: the token taken just before the reading is watched and counted by it   (expected 1, actual 0)
        Messages: a later reading watches every token it knows, once, and reads it      (expected 2, actual 0)

Green 20 of 20 on the head. Rates on this tree: acp kill-point row 0/20, claude and codex 0/5 each, guard acp rows 0/5, whole recovery table 0 failures over 432 subtests. Full gate green. No open threads.

Copilot

🔵 Needs a closer look

The guard recovery test still relies on worker startup completing within a fixed one-second window.

Review details

Suppressed comments (1)

Previously missed (1) — in code that hasn't changed since the last review.

internal/connector/recovery_dispatch_test.go:635

This still makes the ordering under test depend on worker launch completing within a one-second wall-clock window. If startup or the ACP handshake is delayed beyond that, the guard kills the connector while the attempt is still launching, and recordedWorkers fails even though the connector behaved correctly. The new assertion makes the failure faster but does not remove the flakiness. Coordinate guard posting with an observed worker record, such as through a test barrier or controllable clock, instead of extending the delay.

Files reviewed: 4/4 changed files
Comments generated: 0 new
Review effort level: Balanced

The guard is due a delay after admission, and the rows kill the connector as it posts the acknowledgement. That kill has to land on an attempt already running, with a worker recorded, and a4542b2 bought the launch that time with a period of one second: a window, not an order, and a window sized on one machine (Copilot on #752, and the reviewer of 2f9b074). The fake Basecamp now holds a guard acknowledgement until the connector has written its running line for an attempt ("guard-after-running", a fault of the run's like the two it had). The line is the connector's own, written to the harness's file once MarkRunning has committed, and the post is made outside any transaction of the ledger's, so nothing the launch needs is held while Basecamp waits; the only bound is the harness's 30-second waitFor, which is a deadline on the launch itself. The guard's period goes back to 50ms, and the check after the kill is what that order promises rather than a hope about a machine. Under CPU load, at 50ms without the hold: 3 of 3 runs lost the launch, the attempt left mid-launch. With it: 0 of 10 loaded, 0 of 5 without load across all three drivers. Under -race, where a process takes over a second to start and neither row is in the representative subset, run with that gate lifted for the measurement: 0 of 5 for the guard rows and 0 of 10 for the acp kill-point row, no data race. The whole recovery table: 0 failures over 432 subtests.

jorgemanrubia · 2026-09-18T13:06:16Z

🤖 On the note held back at 2f9b074 — "the guard recovery test still relies on worker startup completing within a fixed one-second window" — agreed, and said as much in a4542b2's own message: a period sized so the launch fits is a window, not an order. 5385798 replaces it with the order.

The fake Basecamp now holds a guard acknowledgement until the connector has written its running line for an attempt (guard-after-running, a fault of the run's like stall-catch-up and repair-stall). The line is the connector's own, written to the harness's lines file by the same process once MarkRunning has committed, and Post is made outside any ledger transaction (that is what the post-before/post-after kill points sit between), so nothing the launch needs is held while Basecamp waits. The guard's period is back to 50 ms; the only bound is the harness's 30 s waitFor, a deadline on the launch itself, not on the order. The check after the kill is now what that order promises.

Rates: at 50 ms without the hold, under CPU load, 3 of 3 runs lost the launch (attempt left mid-launch, 120 s each). With it: 0 of 10 loaded, 0 of 5 without load across all three drivers. Under -race — where a process takes over a second to start, and where neither this row nor the kill-point row runs in CI (raceSubset) — measured with that gate lifted locally: 0 of 5 for the guard rows, 0 of 10 for the acp kill-point row, no data race reported. Whole recovery table 0 failures over 432 subtests; full gate green.

Copilot

🟢 Approved

The test-only changes address the documented races with focused regression coverage.

Review details

Files reviewed: 6/6 changed files
Comments generated: 0 new
Review effort level: Balanced

Copilot AI balanced review requested due to automatic review settings September 18, 2026 11:04

github-actions Bot added the tests Tests (unit and e2e) label Sep 18, 2026

Copilot started reviewing on behalf of jorgemanrubia September 18, 2026 11:05 View session