Report harness timeouts as TIMED_OUT, reply from daemon outer handler, add stall/timeout regression tests

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")

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

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