diff --git a/dokimi/changelog.d/20261026_120100_antonwolfy_verify-sidecar-stop-timeout.md b/dokimi/changelog.d/20261026_120100_antonwolfy_verify-sidecar-stop-timeout.md new file mode 100644 index 000000000..00edfa7cd --- /dev/null +++ b/dokimi/changelog.d/20261026_120100_antonwolfy_verify-sidecar-stop-timeout.md @@ -0,0 +1,11 @@ +### Fixed + +- **A verifier sidecar whose removal times out no longer replaces the verdict** — on a + `docker-*` run with an allowlisted verifier, a `docker rm` of the `-verify` sidecar that + timed out after `test.sh` turned the computed reward into a TIMEOUT cell (exit 124, reward + 0), and the sandbox teardown did not know the sidecar, so it stayed on the run's network. + The verifier's verdict and `metrics.network.verify_egress` now stand, the timeout goes to + `run.log`, and the teardown retries the removal before it drops the network. + The same holds for a `-verify` sidecar whose start failed and whose removal then timed + out, and the next run with the same id removes a `-verify` sidecar a crashed run left, + before it creates the network. diff --git a/dokimi/dokimi/harnesses/container_agent.py b/dokimi/dokimi/harnesses/container_agent.py index f0c324805..da04add5a 100644 --- a/dokimi/dokimi/harnesses/container_agent.py +++ b/dokimi/dokimi/harnesses/container_agent.py @@ -135,6 +135,7 @@ class ContainerSandbox: _log_read: bool = False # a teardown read of the sidecar's log has succeeded _scratch: Optional[Path] = None runner: process.Runner = field(default=process.run, repr=False) # starts the probe's docker exec + _verifier: Optional["ContainerSandbox"] = field(default=None, repr=False) # close() retries its removal @classmethod def open(cls, run_id: str, docker: Docker, log, *, source_env: dict[str, str], @@ -155,8 +156,9 @@ def open(cls, run_id: str, docker: Docker, log, *, source_env: dict[str, str], sandbox = cls(network=f"dokimi-net-{run_id}", proxy_name=f"dokimi-egress-{run_id}", allow=sorted(set(allow)), binary=binary, files=files, label=f"{LABEL}={run_id}", runner=runner) - # A crashed run with the same id may still hold the network: container first. - for leftover in (run_id, sandbox.proxy_name): + # A crashed run with the same id may still hold the network: containers first, + # its verifier sidecar too (a removal that timed out twice leaves it running). + for leftover in (run_id, sandbox.proxy_name, f"{sandbox.proxy_name}-verify"): docker(["rm", "-f", leftover], log, check=False) docker(["network", "rm", sandbox.network], log, check=False) docker(["network", "create", "--internal", "--label", sandbox.label, sandbox.network], log) @@ -189,15 +191,17 @@ def _start_proxy(self, docker: Docker, log) -> None: def verifier_sidecar(self, docker: Docker, log, allow: list[str]) -> "ContainerSandbox": """A fresh sidecar on this network for the verifier's allowlist, after :meth:`stop_proxy`. - Its own name and decision log; no LLM hosts. The caller stops it before :meth:`close`. + Its own name and decision log; no LLM hosts. The caller stops it once the verifier is + done (:meth:`stop_proxy_quietly`); :meth:`close` retries a removal that timed out. """ side = ContainerSandbox(network=self.network, proxy_name=f"{self.proxy_name}-verify", allow=sorted(allow), binary=None, label=self.label, runner=self.runner) docker(["rm", "-f", side.proxy_name], log, check=False) + self._verifier = side # before the start: close() retries a removal that times out below try: side._start_proxy(docker, log) - except BaseException: # started, it holds the upstream proxy env and the network: close() can't see it - docker(["rm", "-f", side.proxy_name], log, check=False) + except BaseException: # started, it holds the upstream proxy env and the network + side._stopped = not docker(["rm", "-f", side.proxy_name], log, check=False).timed_out raise return side @@ -358,14 +362,21 @@ def stop_proxy(self, docker: Docker, log) -> None: raise subprocess.TimeoutExpired(removed.argv, DOCKER_STEP_TIMEOUT) self._stopped = True - def close(self, docker: Docker, log, output_dir: Optional[Path]) -> None: - """Stop the sidecar, save its decisions as ``egress.jsonl``, drop the network. - No file when the log is unknown: an empty one would read as a clean run.""" + def stop_proxy_quietly(self, docker: Docker, log) -> None: + """:meth:`stop_proxy` once nothing runs behind the sidecar: a removal that times out is + logged, not raised, and :meth:`close` retries it.""" try: self.stop_proxy(docker, log) except subprocess.TimeoutExpired as exc: # teardown is best-effort: go on to the network if log is not None: - log.write(f"\n[sidecar removal] timed out after {exc.timeout:g}s\n") + log.write(f"\n[sidecar removal] {self.proxy_name} timed out after {exc.timeout:g}s\n") + + def close(self, docker: Docker, log, output_dir: Optional[Path]) -> None: + """Stop the sidecars, save the solve's decisions as ``egress.jsonl``, drop the network. + No file when the log is unknown: an empty one would read as a clean run.""" + for side in (self._verifier, self): # a verifier sidecar left running holds the network too + if side is not None: + side.stop_proxy_quietly(docker, log) if output_dir is not None and self.log_known: with (output_dir / "egress.jsonl").open("w", encoding="utf-8") as fh: for row in self.log: diff --git a/dokimi/dokimi/harnesses/docker_solver.py b/dokimi/dokimi/harnesses/docker_solver.py index 52d5ae20b..732b4ae72 100644 --- a/dokimi/dokimi/harnesses/docker_solver.py +++ b/dokimi/dokimi/harnesses/docker_solver.py @@ -699,7 +699,7 @@ def _verify_phase(self, task: TaskSpec, net: PhasePolicy, container: str, output return self._verify(task, container, output_dir, log, net) finally: if side is not None: - side.stop_proxy(self._docker, log) + side.stop_proxy_quietly(self._docker, log) network["verify_egress"] = side.egress_summary() # ── helpers ───────────────────────────────────────────────────────────── diff --git a/dokimi/tests/test_cleanup_timeouts.py b/dokimi/tests/test_cleanup_timeouts.py index 100e6e79c..396cfa83a 100644 --- a/dokimi/tests/test_cleanup_timeouts.py +++ b/dokimi/tests/test_cleanup_timeouts.py @@ -70,8 +70,10 @@ def test_stop_proxy_timeout_retried_in_close(tmp_path): test_calls = [c for c in cli.calls if c.argv[1] == "exec" and "test.sh" in " ".join(c.argv)] assert len(test_calls) == 0, "Verification should not run after stop_proxy timeout" - # Verify that rm was called for egress cleanup (stop_proxy + retry in close) - rm_calls = [c for c in cli.calls if c.argv[1] == "rm" and "egress" in " ".join(c.argv)] + # Verify that rm was called for egress cleanup (stop_proxy + retry in close); the solve + # sidecar's, not the leftover verifier sidecar open() also clears + rm_calls = [c for c in cli.calls if c.argv[1] == "rm" and "egress" in c.argv[-1] + and not c.argv[-1].endswith("-verify")] assert len(rm_calls) == 3, f"Should attempt sidecar removal 3 times (open + stop_proxy + close), got {len(rm_calls)}" # close() goes on past the timed-out sidecar removal: the egress record is saved diff --git a/dokimi/tests/test_network_policy.py b/dokimi/tests/test_network_policy.py index a305fba4c..b7db5657e 100644 --- a/dokimi/tests/test_network_policy.py +++ b/dokimi/tests/test_network_policy.py @@ -213,7 +213,49 @@ def never_ready(call): result = harness.run(load_task(_task(tmp_path)), output_dir=tmp_path / "out") assert "-verify did not start" in result.metrics["error"] started = _index(cli.args, lambda a: a[0] == "start" and a[-1].endswith("-verify")) - assert any(a[:2] == ["rm", "-f"] and a[-1].endswith("-verify") for a in cli.args[started:]) + # removed once: close() leaves a sidecar it saw removed alone + assert sum(a[:2] == ["rm", "-f"] and a[-1].endswith("-verify") for a in cli.args[started:]) == 1 + + +def test_a_verify_sidecar_whose_failed_start_cannot_be_removed_is_retried_by_close(tmp_path, monkeypatch): + monkeypatch.setattr("dokimi.harnesses.container_agent.time.sleep", lambda _s: None) + + def stuck(call): + if call.argv[-1].endswith("-verify") and call.argv[1] in ("logs", "rm"): + return reply("") if call.argv[1] == "logs" else reply(timed_out=True) + return None + + cli = DockerCLI(answer=stuck) + harness = replace(create_harness("docker-oracle", runner=cli), network=("verify=allowlist:pypi.org",)) + result = harness.run(load_task(_task(tmp_path)), output_dir=tmp_path / "out") + assert "-verify did not start" in result.metrics["error"] + started = _index(cli.args, lambda a: a[0] == "start" and a[-1].endswith("-verify")) + network_rm = max(i for i, a in enumerate(cli.args) if a[:2] == ["network", "rm"]) + removals = [i for i, a in enumerate(cli.args) if a[:2] == ["rm", "-f"] and a[-1].endswith("-verify")] + # the failed start's own removal, then close()'s retry, both before the network goes + assert len([i for i in removals if started < i < network_rm]) == 2 + + +def test_open_clears_a_verify_sidecar_a_crashed_run_left(tmp_path): + cli, _ = _oracle(tmp_path, "verify=allowlist:pypi.org") + create = _index(cli.args, lambda a: a[:3] == ["network", "create", "--internal"]) + assert any(a[:2] == ["rm", "-f"] and a[-1].endswith("-verify") for a in cli.args[:create]) + + +def test_a_verify_sidecar_removal_that_times_out_keeps_the_verdict_and_is_retried(tmp_path): + def slow_removal(call): + return reply(timed_out=True) if call.argv[1] == "rm" and call.argv[-1].endswith("-verify") else None + + cli = DockerCLI(answer=slow_removal) + harness = replace(create_harness("docker-oracle", runner=cli), network=("verify=allowlist:pypi.org",)) + result = harness.run(load_task(_task(tmp_path)), output_dir=tmp_path / "out") + assert (result.returncode, result.reward) == (0, 1.0) # the verifier had finished: its verdict stands + assert result.metrics["network"]["verify_egress"]["status"] == "ok" + verified = _index(cli.args, _exec_of("test.sh")) + removals = [i for i, a in enumerate(cli.args) if a[:2] == ["rm", "-f"] and a[-1].endswith("-verify")] + network_rm = max(i for i, a in enumerate(cli.args) if a[:2] == ["network", "rm"]) + # stopped after the verifier, then retried by close() before the network goes + assert len([i for i in removals if verified < i < network_rm]) == 2 and removals[-1] < network_rm def test_build_none_builds_offline(tmp_path):