Bound the AutoSetup wait, and stop the task holding it from outliving the run - #208
Bound the AutoSetup wait, and stop the task holding it from outliving the run#208shellygr wants to merge 3 commits into
Conversation
The wait for the child to exit sits in a `finally`, which is also the path a run takes on its way out after a cancellation or after a sink raised. It had no bound, so a child that never exits parks the whole run there: no timeout above it can help, and nothing is left running to say why. Two cloud runs sat like that for 22 hours until the job's hard time cap killed them, and that cap skips the results upload. `_reap` waits up to 30s, kills the child, waits another 30s, then gives up rather than block. A child we could not reap is reported as a failed AutoSetup, since it has told us nothing about whether it succeeded. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
| finally: | ||
| _logger.debug("AutoSetup process complete, waiting for exit") | ||
| returncode = await proc.wait() | ||
| returncode = await _reap(proc) |
There was a problem hiding this comment.
I'm confused, do we know why this hung? how did proc.kill(); proc.wait() not work??
There was a problem hiding this comment.
I am also confused how it happened, but either the kill in the exception didn't kill the process on a timely manner, or gather returned without the process actually ending. The question is whether we think that this fix is hiding a more serious issue.
Claude's commentary:
▎ We don't. The run sat in that wait until the job's hard time cap killed
▎ the process, so there was nothing left to inspect.
▎
▎ On the kill: it only runs in the except BaseException branch. If the gather returns
▎ normally with the child still alive, nothing kills it, and the old await proc.wait()
▎ in the finally just blocks. And where we do kill, the wait after it was that same
▎ unbounded wait, so a child that doesn't die on SIGKILL parks the run the same way. The
▎ bound is what ends it either way.
There was a problem hiding this comment.
Claude answers: We do now, from the container logs. One of the two runs ends with the CancelledError coming out of _drain, then the debug line in the finally. So asyncio.run's teardown cancelled the drain, proc.kill() did run, and the run was last seen going into the unbounded proc.wait().
The kill only exists in the except branch, and the wait after it is that same unbounded wait, so nothing there was a bound on anything. Whether the wait itself is what held for 22h I can't tell from that log, because nothing logged when it returned. The other run froze at the same point in teardown with its autosetup already exited 0, so this isn't the whole incident.
I've pushed the rest: the task holding the subprocess is now cancelled with the extraction it runs beside instead of being left for teardown, the reap logs how it ended, and there's a test for the path that actually happened.
The task is started to overlap with extraction and awaited once extraction is done. Nothing cancels it in between, so an extraction that raises leaves it running with the pipeline already unwinding. What reaches it then is asyncio.run's teardown, which cancels it after the run's exit handlers have finished and then waits for it with no bound of its own, and an AutoSetup subprocess still live inside it is waited on for exactly as long. _alongside ties a background task to the block it accompanies, so it is cancelled and awaited where that block ends. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…utdown The reap logs where it begins and says nothing on the way out, so a log that stops at that line cannot afterwards be read as either a wait that never returned or one that returned at once. It now reports the exit status and how long it took. console-autoprove drives the loop through an explicit Runner, which gives the close a before and an after in the log and a place to name the tasks still running when it starts. Those tasks are what the unbounded cancel-and-wait inside close() is spent on. The reap tests gain the shape a cancelled run takes: the reap running in the finally of a task that has already been cancelled. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
shellygr
changed the title
2 participants
What went wrong
Two cloud runs sat for 22 hours until the job's hard time cap killed them, and that cap skips the results upload, so both were a total loss.
An Anthropic API error killed one extraction task in each run. The failure unwound out of the pipeline, the run's exit handlers ran, and then
asyncio.run's teardown cancelled what was left and waited for it. One of the two runs had an AutoSetup subprocess live inside an orphaned task at that moment; its log ends with theCancelledErrorcoming out of_drainand then the debug line in thefinally, so it was last seen going intoawait proc.wait()with nothing bounding it. The other had finished AutoSetup cleanly twelve seconds earlier and froze at the same point in teardown with no subprocess anywhere on its stack.So this PR is not the fix for the incident. The process-level backstop is AIAutoProver#80.
The change
_reap: wait up to 30s, kill the child, wait another 30s, then give up and let the run continue. Nothing is killed on the normal path, where the first wait returns as soon as the pipes are at EOF. A child that could not be reaped is reported as a failed AutoSetup. The bound is a loop timer rather than anything about the child, so it holds whether or not the child can be reaped.The orphan: the formalization task is started to overlap with extraction and awaited after it, and nothing cancels it in between. An extraction that raises therefore leaves it running into teardown.
_alongsideties it to the block it accompanies, so it is cancelled and awaited while the loop is still healthy rather than after the exit handlers have run.The log: the reap said where it began and nothing on the way out, which is why the incident logs are ambiguous about whether the wait ever returned. It now reports the exit status and how long it took.
console-autoprovedrives the loop through an explicitRunner, which gives the close a before and an after and a place to name the tasks still running when it starts; those are what the unbounded cancel-and-wait insideclose()is spent on.Tests
tests/test_autosetup_reap.py: a child that exits reports its status, a child that ignores SIGTERM is killed and reaped within the bound, the reap ends when it runs in thefinallyof an already-cancelled task, and it says how it ended.🤖 Generated with Claude Code