fix(sandbox): keep timeout teardown from erasing the timeout - #1081
Open
tulerfeng wants to merge 1 commit into
Open
fix(sandbox): keep timeout teardown from erasing the timeout#1081tulerfeng wants to merge 1 commit into
tulerfeng wants to merge 1 commit into
Conversation
Signalling a child that asyncio has already reaped raises ProcessLookupError,
which escapes the `except TimeoutError` handler before the RuntimeError
describing the timeout is ever raised. That exception carries no args, so
`f"verifier crashed: {e}"` renders with nothing after the colon: a finished
rollout is scored `rewards: null` under a message naming neither the failure
nor the fact that it had no detail.
The window is one loop tick wide — asyncio clears its process handle from a
`call_soon` callback — so it is rare on an idle loop and routine under
concurrency. `subprocess.Popen.send_signal` already absorbs this race
(bpo-38630, bpo-40550), which is why only the asyncio call sites are exposed.
Guard all five of them, and render verifier errors through the existing
`describe_exception` helper that the agent-side funnel already uses.
Fixes benchflow-ai#1065
2 tasks
Contributor
There was a problem hiding this comment.
🔍 Devin Review: 1 flag
Not posted on this PR by your GitHub settings — view it in Devin Review. (Configure)
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Fixes #1065.
When a sandbox exec runs out of time, the code kills the child and then raises "Command timed out after N seconds". But killing a child that has already finished raises
ProcessLookupError, and that escapes the handler before the timeout message is ever raised.ProcessLookupErrorcarries no text at all, sof"verifier crashed: {e}"renders asverifier crashed:with nothing after the colon — a finished rollout scoredrewards: nullunder a message that names neither the failure nor the fact that it had no detail.This PR makes teardown tolerate a child that is already gone, in every place that signals one, and stops the verifier error from ever rendering empty.
Why this happens, precisely
The report says the race needs the child to have exited and been reaped. That is the right shape, but the window turned out to be narrower, and finding the exact edge is what made it reproducible.
terminate()only fails if asyncio has cleared its handle on the process. That clearing happens in_call_connection_lost, which asyncio schedules withcall_soon— so it runs on the next loop tick after the child exits. The failure therefore needs the timeout to fire in the gap between that callback andcommunicate()returning. One tick wide.That detail matters because it says who is affected. On an idle loop those two events land practically on top of each other. On a loop that is busy — many concurrent rollouts, which is exactly the
--concurrency 16setup in the report — callbacks spread out, the gap opens, and the failure stops being occasional.I measured both ends:
Same code, same machine. Under load it is not a rare race; it is the normal outcome. That is consistent with a batch hitting it repeatedly rather than once.
What the fix covers
The issue names two spots in
docker.py. Auditing every process-signalling site turned up three more with the same defect, so the PR fixes all of them.The audit had a clean dividing line. CPython's
subprocess.Popen.send_signalalready handles this race for us — it polls first, skips a process it knows has died, and swallowsProcessLookupErroranyway (bpo-38630, bpo-40550).asyncio.subprocess.Processhas no such guard and raises straight out. So every synchronous call site in the repo was already safe, and only the asyncio ones needed anything. That is what bounds this change to five places instead of sixteen.docker.py— compose execdocker.py— pre-compose hookacp/transport.py—close()SubprocessLiveProcess.close()next door has one and documents itself as "safe to call after process death"process/apple.py,apple_container.pykill()replaces theTimeoutErrorbeing re-raisedprocess/_base.py—close()returncodecheck cannot cover the escalation branch, because the grace period is anawaitand the child can exit across itThe
acp/transport.pyone is the one I would flag.close()runs during teardown, usually while another exception is already in flight — so an exception raised there replaces the real failure with an empty one.The empty message
The issue suggests
f"verifier crashed: {type(e).__name__}: {e}". I went a slightly different way, because the repo already solved this._utils/text.pyhasdescribe_exception, written for exactly this problem, and the agent-side error funnel inrollout/__init__.pyalready uses it with a comment explaining why:That reasoning applies word for word to the verifier path, which was simply missed. So rather than introduce a fourth way of rendering an exception, the three verifier sites now use the existing one.
verifier crashed:becomesverifier crashed: ProcessLookupError (no message).I checked this cannot disturb error classification:
classify_verifier_errormatches substrings, but every marker contains a space or punctuation, so a CamelCase class name can never match one.Tests
New file,
tests/test_timeout_teardown_reaped_child.py, 11 tests.They do not mock the failure. Each one spawns a real child, lets it exit, and lets asyncio reap it, so the
ProcessLookupErroris raised by the operating system through asyncio's own transport rather than by a fixture pretending to. What is controlled is the timing:communicateraisesTimeoutErrorinstead of sleeping, which turns a one-tick race into something that reproduces on every run and finishes in two seconds.Running them against the unmodified tree and against this one:
main(before)The three that pass on both sides are deliberate controls, and I would rather have them than a suite that is green only because the new code exists:
argsare empty — the premisedescribe_exception(ProcessLookupError())names the type — the tool already workedSubprocessLiveProcess.close()survives a dead child — the neighbour that already had the guard, now pinned so it cannot quietly lose itOne test drives the real
_verify_rolloutwithharden_before_verifyraisingProcessLookupError— the exact path in the report — and asserts the recorded string isverifier crashed: ProcessLookupError (no message)and does not end at a colon.End-to-end verification
A real container, both trees. I took a real running container, spawned the same
docker compose execthe sandbox builds, and ran each tree's teardown against that live process:main(before)ProcessLookupError (args=())'verifier crashed: 'RuntimeError: Command timed out after 10 seconds'verifier crashed: Command timed out after 10 seconds'The
mainrow is the symptom string from the report, reproduced against a real container rather than argued from the source.Honest limit on that one. In that experiment I forced the one condition the race normally leaves to chance — that the child had already finished. Everything else (container, compose invocation, process, exception) is real, but I want to be clear that I did not sit and wait for a real
bench eval runto hit this on its own. I tried: 164 real exec calls with the budget swept across the completion point, zero natural hits, becausedocker exec's own timing jitter is far wider than the one-tick window. The 288/288 result above is the natural, unforced reproduction, and it is at the asyncio layer.Normal runs are unaffected. A full
bench eval run(hello-world, oracle agent, docker sandbox) passes 1/1 with mean reward 1.00.No regressions. Full suite: 5931 passed. 11 failures, all in
tests/test_cli_live_progress.py, and that file fails identically onmain(11 failed / 54 passed on both).ruff checkandruff format --checkare clean.