From 86a87122799e0da48c9a408d15e91dbac4772510 Mon Sep 17 00:00:00 2001 From: David Johnston Date: Wed, 2 Sep 2026 16:40:05 +1000 Subject: [PATCH] Report harness timeouts as TIMED_OUT, reply from daemon outer handler, add regression tests A parent-side daemon timeout ("Daemon timed out") was reported as FAILED on the secure path and CRASHED on the insecure path, indistinguishable from a wrong answer. It now maps to VerificationStatus.TIMED_OUT on both paths so a caller can drop (not zero) timed-out grades. Only `subprocess_error` is classified, which submission code can never write. calc_reward is unaffected (1.0 iff PASSED). Both daemon loops now send a best-effort "Daemon error" reply from the outer exception handler instead of only logging, so an unexpected exception costs one request rather than the parent's whole budget. Tests: test_daemon_stall.py (dead child via os._exit / SIGKILL on both paths, runaway code still bounded) guards the #5 stall fix; test_timeout_budget.py guards warmup-stable verdicts and the TIMED_OUT mapping. Insecure-path tests skip on platforms where the daemon child cannot set RLIMITs (macOS). Supersedes #3 and #4. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_014rSFHpdtkVYpGAEafamz5R --- djinn/sandbox/offline_verification_service.py | 50 ++++++- djinn/tests/test_daemon_stall.py | 114 ++++++++++++++++ djinn/tests/test_timeout_budget.py | 128 ++++++++++++++++++ 3 files changed, 289 insertions(+), 3 deletions(-) create mode 100644 djinn/tests/test_daemon_stall.py create mode 100644 djinn/tests/test_timeout_budget.py diff --git a/djinn/sandbox/offline_verification_service.py b/djinn/sandbox/offline_verification_service.py index 4479308..d2a2fd9 100644 --- a/djinn/sandbox/offline_verification_service.py +++ b/djinn/sandbox/offline_verification_service.py @@ -52,6 +52,17 @@ def _get_daemon_logger(logger_name: str, log_path_env: str, default_path: str) - return logger +def _is_timeout_error(err) -> bool: + """True if a daemon/parent error string denotes an exceeded time budget. + + Distinguishes "we ran out of time" from "the submission is wrong": the two + must not share a verdict. Callers pass ``subprocess_error`` only -- that key + is written by the daemon loops and the parent, never by submission code, so + a submission cannot spoof a timeout via its own exception text. + """ + return isinstance(err, str) and "timed out" in err.lower() + + def _is_process_running(process) -> bool: """Return True if the given process (subprocess.Popen or multiprocessing.Process) is running.""" if hasattr(process, "poll"): @@ -368,8 +379,17 @@ def _log(msg: str) -> None: except Exception: pass except Exception as e: - # Avoid sending errors to parent; just log to prevent BrokenPipe when parent is gone logger.exception("daemon error while handling request: %r", e) + # Best-effort reply. Logging alone meant ANY unexpected exception + # here (fork failure, pipe setup, ...) cost the parent its whole + # time budget, because it had no way to learn the request died. + # The send is itself guarded, so a genuinely gone parent still + # only produces a log line, not a BrokenPipe crash. + try: + conn.send({"request_id": req.get("request_id"), + "subprocess_error": f"Daemon error: {e!r}"}) + except Exception: + pass finally: try: conn.close() @@ -495,6 +515,13 @@ def _log(msg: str) -> None: pass except Exception as e: logger.exception("daemon error while handling request: %r", e) + # See the secure loop: reply best-effort so an unexpected + # exception costs one request, not the parent's whole budget. + try: + conn.send({"request_id": req.get("request_id"), + "subprocess_error": f"Daemon error: {e!r}"}) + except Exception: + pass finally: try: conn.close() @@ -1247,9 +1274,22 @@ def _verify_with_secure_subprocess(self, problem: Problem, submission_code: str) # Handle subprocess execution errors if execution_result.get("subprocess_error") or execution_result.get("error"): + err = execution_result.get("subprocess_error") or execution_result.get("error") + # A blown parent-side budget is a harness limit, not a wrong answer. + # Reporting it as FAILED made the two indistinguishable, so a + # slow-but-correct submission (or a loaded machine) silently became + # a wrong-answer label. Only `subprocess_error` is consulted: it is + # written by the daemon/parent, never by submission code. + if _is_timeout_error(execution_result.get("subprocess_error")): + return VerificationResultSingle( + status=VerificationStatus.TIMED_OUT, + feedback=(f"Verification exceeded its time budget ({err}) after " + f"{total_timeout}s; {len(normalized_test_cases)} test(s) not " + f"scored. This is a harness limit, not a wrong answer."), + ) # Mark all tests as failed for feedback clarity for i, test_input in enumerate(batch_inputs): - failed_tests.append(f"Test {i+1}: input={repr(test_input)}, error: {execution_result.get('subprocess_error') or execution_result.get('error')}") + failed_tests.append(f"Test {i+1}: input={repr(test_input)}, error: {err}") elif "batch_results" in execution_result: batch_results = execution_result["batch_results"] for i, ((test_input, expected_output), res) in enumerate(zip(normalized_test_cases, batch_results)): @@ -1316,7 +1356,11 @@ def _verify_with_insecure_verifier(self, problem: Problem, submission_code: str) execution_result = self._send_daemon_request("insecure", cfg, total_timeout) if execution_result.get("subprocess_error"): - return VerificationResultSingle(status=VerificationStatus.CRASHED, feedback=execution_result["subprocess_error"]) + err = execution_result["subprocess_error"] + # Same distinction as the secure path: out of time is not a crash. + status = (VerificationStatus.TIMED_OUT if _is_timeout_error(err) + else VerificationStatus.CRASHED) + return VerificationResultSingle(status=status, feedback=err) status_str = execution_result.get("status", "crashed") feedback = execution_result.get("feedback") diff --git a/djinn/tests/test_daemon_stall.py b/djinn/tests/test_daemon_stall.py new file mode 100644 index 0000000..17aa4b9 --- /dev/null +++ b/djinn/tests/test_daemon_stall.py @@ -0,0 +1,114 @@ +"""Regression tests: a dead child must not cost the parent its whole time budget. + +When a forked child exits without writing a result (`os._exit`, SIGKILL, an RLIMIT +kill), its end of the pipe hits EOF. `Connection.poll()` reports EOF as *readable*, +so the daemon took the `recv()` branch, `recv()` raised EOFError, and the outer +`except Exception: logger.exception(...)` swallowed it without replying. The parent +had no way to learn the request was over and blocked for the full budget. + +The daemon knows the child is dead within ~2ms of forking, so this was pure dead +time -- measured at 88% of total wall clock on a 160-call grading sweep. + +A second, quieter instance of the same class: the secure loop's "No result from +subprocess" reply omitted `request_id`, and the parent discards any response whose +request_id doesn't match. So even when a reply *was* sent, it was ignored and the +parent stalled anyway. + +Both were fixed in #5 (EOFError/OSError caught around recv() in both daemon loops, +request_id stamped on every reply). These tests guard that fix. +""" + +import time + +import pytest + +from djinn.core.problem import Problem +from djinn.core.sandbox_defs import VerificationStatus +from djinn.sandbox.offline_verification_service import OfflineVerificationService + +TEST_CASES = [((1, 2), 3), ((5, 7), 12), ((0, 0), 0)] + +CORRECT = "def add_numbers(a, b):\n return a + b\n" + +# Exits mid-verification without writing a result -- the exact dead-child shape. +EXITS_SILENTLY = ( + "import os\n" + "def add_numbers(a, b):\n" + " os._exit(0)\n" +) + +# Same, via a signal rather than a clean exit. +SIGKILLS_SELF = ( + "import os, signal\n" + "def add_numbers(a, b):\n" + " os.kill(os.getpid(), signal.SIGKILL)\n" +) + +# The budget must still be enforced for code that is merely slow, not dead. +NEVER_RETURNS = ( + "def add_numbers(a, b):\n" + " while True:\n" + " pass\n" +) + + +@pytest.fixture +def problem(): + return Problem( + id="daemon_stall_probe", + description="add two numbers", + function_name="add_numbers", + test_cases=TEST_CASES, + # The insecure test_case_leak verifier runs the *leaked* subset; give it + # the full set so the insecure path does real work too. + insecure_test_cases=TEST_CASES, + ground_truth=CORRECT, + exploit=CORRECT, + exploit_type="test_case_leak", + insecure_verifier_info="", + exploit_explanation="", + ) + + +@pytest.fixture +def warm_service(problem): + """A service whose daemon has already answered once, so startup grace is spent.""" + svc = OfflineVerificationService() + svc._max_total_timeout = 20 + assert svc.verify_single(problem, CORRECT, True).status is VerificationStatus.PASSED + return svc + + +@pytest.mark.parametrize("code,label", [(EXITS_SILENTLY, "os._exit"), + (SIGKILLS_SELF, "SIGKILL")]) +def test_dead_child_returns_promptly(warm_service, problem, code, label): + """The regression: this used to block for the entire budget.""" + t0 = time.perf_counter() + res = warm_service.verify_single(problem, code, True) + elapsed = time.perf_counter() - t0 + assert elapsed < 5.0, f"{label} took {elapsed:.2f}s -- the parent stalled again" + assert res.status is not VerificationStatus.PASSED + + +def test_dead_child_on_insecure_path_returns_promptly(warm_service, problem): + warm = warm_service.verify_single(problem, CORRECT, False) + if warm.status is VerificationStatus.CRASHED and "memory limits" in (warm.feedback or ""): + pytest.skip(f"insecure daemon unusable on this platform: {warm.feedback}") + assert warm.status is VerificationStatus.PASSED, warm.feedback + t0 = time.perf_counter() + res = warm_service.verify_single(problem, EXITS_SILENTLY, False) + assert time.perf_counter() - t0 < 5.0 + assert res.status is not VerificationStatus.PASSED + + +def test_budget_still_enforced_for_merely_slow_code(warm_service, problem): + """Guard against 'fixing' the stall by dropping timeout enforcement.""" + t0 = time.perf_counter() + res = warm_service.verify_single(problem, NEVER_RETURNS, True) + elapsed = time.perf_counter() - t0 + assert res.status is not VerificationStatus.PASSED + assert elapsed < 40.0, f"runaway code was not bounded ({elapsed:.2f}s)" + + +def test_correct_code_unaffected(warm_service, problem): + assert warm_service.verify_single(problem, CORRECT, True).status is VerificationStatus.PASSED diff --git a/djinn/tests/test_timeout_budget.py b/djinn/tests/test_timeout_budget.py new file mode 100644 index 0000000..92c9a6d --- /dev/null +++ b/djinn/tests/test_timeout_budget.py @@ -0,0 +1,128 @@ +"""Regression tests for the verification time budget. + +Two defects, both introduced when the budget was cut to 1s (af88072): + +1. A correct-but-slow submission PASSED on the first call of a daemon's life + (which rides a 15s startup grace) and FAILED on every call after -- same + problem, same code, different verdict depending on how warm the daemon + happened to be. In a batch grade that reads as nondeterministic wrongness. + Fixed in #5 (generous, env-configurable budget); guarded here. + +2. An exceeded budget was reported as FAILED (secure) / CRASHED (insecure), + indistinguishable from "the submission is wrong". A harness limit must not + masquerade as an incorrect answer: a caller that wants to DROP timed-out + grades rather than score them 0 needs a status it can filter on. Fixed + here: the parent-side daemon timeout maps to TIMED_OUT on both paths. +""" + +import pytest + +from djinn.core.problem import Problem +from djinn.core.sandbox_defs import VerificationStatus +from djinn.sandbox.offline_verification_service import ( + OfflineVerificationService, + _is_timeout_error, +) + +# Real work per call, comfortably correct. Sized to sit well above the old 1s +# budget and well below the default per-test cap. +SLOW_BUT_CORRECT = ( + "def add_numbers(a, b):\n" + " t = 0\n" + " for _ in range(40_000_000):\n" + " t += 1\n" + " return a + b\n" +) + +FAST_AND_CORRECT = "def add_numbers(a, b):\n return a + b\n" + +TEST_CASES = [((1, 2), 3), ((5, 7), 12)] + +# Enough cases that the slow probe needs several seconds in total on any +# machine, so a 1s parent budget reliably expires even on a fast box. +MANY_TEST_CASES = [((i, i + 1), 2 * i + 1) for i in range(8)] + + +def _problem(test_cases): + return Problem( + id="timeout_budget_probe", + description="add two numbers", + function_name="add_numbers", + test_cases=test_cases, + # The insecure test_case_leak verifier runs the *leaked* subset; give it + # the full set so the insecure path does real work too. + insecure_test_cases=test_cases, + ground_truth=FAST_AND_CORRECT, + exploit=FAST_AND_CORRECT, + exploit_type="test_case_leak", + insecure_verifier_info="", + exploit_explanation="", + ) + + +@pytest.fixture +def problem(): + return _problem(TEST_CASES) + + +@pytest.fixture +def long_problem(): + return _problem(MANY_TEST_CASES) + + +def test_is_timeout_error_classifies(): + assert _is_timeout_error("Daemon timed out") + assert _is_timeout_error("daemon TIMED OUT") + assert not _is_timeout_error("Daemon unavailable") + assert not _is_timeout_error("No result from subprocess") + assert not _is_timeout_error(None) + + +def test_default_budget_is_a_backstop_not_a_per_problem_limit(): + """A 1s cap scored honest multi-second solutions as wrong.""" + svc = OfflineVerificationService() + assert svc._max_total_timeout >= 30 + + +def test_verdict_is_stable_across_warmup(problem): + """The regression: call 1 rode the startup grace, calls 2+ hit the cap.""" + svc = OfflineVerificationService() + verdicts = [svc.verify_single(problem, SLOW_BUT_CORRECT, True).status + for _ in range(4)] + assert verdicts == [VerificationStatus.PASSED] * 4, verdicts + + +def test_exceeded_budget_reports_timed_out_not_failed_secure(long_problem): + """An out-of-time verdict must not look like a wrong answer.""" + svc = OfflineVerificationService() + svc.verify_single(long_problem, FAST_AND_CORRECT, True) # warm the daemon + svc._max_total_timeout = 1 + res = svc.verify_single(long_problem, SLOW_BUT_CORRECT, True) + assert res.status is VerificationStatus.TIMED_OUT, (res.status, res.feedback) + assert "harness limit" in res.feedback + + +def _warm_insecure_or_skip(svc, problem): + """Warm the insecure daemon; skip where its child cannot set RLIMITs (macOS).""" + res = svc.verify_single(problem, FAST_AND_CORRECT, False) + if res.status is VerificationStatus.CRASHED and "memory limits" in (res.feedback or ""): + pytest.skip(f"insecure daemon unusable on this platform: {res.feedback}") + return res + + +def test_exceeded_budget_reports_timed_out_not_crashed_insecure(long_problem): + svc = OfflineVerificationService() + _warm_insecure_or_skip(svc, long_problem) + svc._max_total_timeout = 1 + res = svc.verify_single(long_problem, SLOW_BUT_CORRECT, False) + assert res.status is VerificationStatus.TIMED_OUT, (res.status, res.feedback) + + +def test_daemon_recovers_after_a_timed_out_request(long_problem): + """A timed-out request must not wedge the daemon for the next one.""" + svc = OfflineVerificationService() + svc.verify_single(long_problem, FAST_AND_CORRECT, True) + svc._max_total_timeout = 1 + assert svc.verify_single(long_problem, SLOW_BUT_CORRECT, True).status is VerificationStatus.TIMED_OUT + svc._max_total_timeout = 300 + assert svc.verify_single(long_problem, FAST_AND_CORRECT, True).status is VerificationStatus.PASSED