From 982cb1411593ff478297d26fd0267767d95b7f24 Mon Sep 17 00:00:00 2001 From: Marius Ciepluch <11855163+norandom@users.noreply.github.com> Date: Wed, 23 Sep 2026 16:15:01 +0200 Subject: [PATCH] fix(replay): stream each case's output and survive a deadline overrun The 13.3 replay on 7cf256b crashed on case 1: `pre-push` ran past its 7,200 s deadline plus the harness's 60 s grace, `subprocess.run` raised TimeoutExpired, the harness died without running cases 2 and 3, and the case's captured output died with it. Each case now streams stdout and stderr to files with INFO logging on; an overrun kills the case's process group, is recorded as `deadline_overrun` with its size -- the product failing its cancellation contract -- and the next case still runs. `--only` reruns selected cases. CLI log lines now carry a timestamp, so a log can say where the time went. Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_01EmM1j46qgKMh3zqD1QMwEo --- benchmarks/push/transfer_replay.py | 37 ++++++++++++++++++++++++------ src/openultrasast/cli.py | 2 +- 2 files changed, 31 insertions(+), 8 deletions(-) diff --git a/benchmarks/push/transfer_replay.py b/benchmarks/push/transfer_replay.py index 7fedd5a..44f4ed7 100644 --- a/benchmarks/push/transfer_replay.py +++ b/benchmarks/push/transfer_replay.py @@ -20,6 +20,7 @@ import hashlib import json import os import platform +import signal import subprocess import sys import time @@ -147,6 +148,7 @@ def main() -> int: # gets asked at all. It bounds the RUN, never the repository: the artifact's own census reports what was # left unexamined, and a bounded population establishes transfer rather than coverage. parser.add_argument("--max-regions", type=int, default=500) + parser.add_argument("--only", default="", help="comma-separated case ids to run; the rest are recorded as skipped") args = parser.parse_args() args.out.mkdir(parents=True, exist_ok=False) out = args.out.resolve() @@ -217,7 +219,11 @@ def main() -> int: } write(out / "transfer-record.json", record) + only = {c.strip() for c in args.only.split(",") if c.strip()} for case in cases: + if only and case["id"] not in only: + record["cases"].append({"case_id": case["id"], "status": "skipped_by_only"}) + continue target = targets.get(case["id"]) if target is None: record["cases"].append({"case_id": case["id"], "status": "no_declared_target"}) @@ -248,22 +254,39 @@ def main() -> int: "--experimental-declarations", str(declarations), ] + # Streamed to files as it runs, with the engine's own timing logs on. Captured in memory, a case that + # overran its deadline took its output with it: the 2026-09-23 replay crashed on case 1 and left no + # record of where 95 minutes went. An overrun is recorded as what it is -- the product failing its + # cancellation contract -- and the next case still runs. + stdout_path, stderr_path = out / (case["id"] + ".stdout"), out / (case["id"] + ".stderr") started = time.monotonic() - process = subprocess.run(command, capture_output=True, text=True, timeout=args.deadline + 60) # noqa: S603 + overrun = None + with stdout_path.open("w") as stdout, stderr_path.open("w") as stderr: + process = subprocess.Popen( # noqa: S603 + command, stdout=stdout, stderr=stderr, text=True, env={**os.environ, "OUSAST_LOG_LEVEL": "INFO"}, start_new_session=True + ) + try: + returncode: int | None = process.wait(timeout=args.deadline + 60) + except subprocess.TimeoutExpired: + os.killpg(process.pid, signal.SIGKILL) + process.wait() + returncode = None + overrun = round(time.monotonic() - started - args.deadline, 1) elapsed = time.monotonic() - started - (out / (case["id"] + ".stdout")).write_text(process.stdout) - (out / (case["id"] + ".stderr")).write_text(process.stderr) + terminal = stdout_path.read_text(errors="replace") entry: dict[str, Any] = { "case_id": case["id"], "label": case["label"], "role": role_of(case), "base_oid": pins[case["base"]], "head_oid": pins[case["tip"]], - "exit_code": process.returncode, + "exit_code": returncode, "elapsed_seconds": elapsed, - "terminal": process.stdout, + "terminal": terminal, } - if artifact.is_file(): + if overrun is not None: + entry["outcome"] = {"instrument_error": "deadline_overrun", "overrun_seconds": overrun} + elif artifact.is_file(): data = json.loads(artifact.read_text()) entry["provenance_matches"] = all( data["provenance"].get(k) == installed[k] for k in ("engine", "facts", "queries", "policy", "core", "semantics") @@ -273,7 +296,7 @@ def main() -> int: entry["outcome"] = {"instrument_error": "missing_artifact"} record["cases"].append(entry) write(out / "transfer-record.json", record) - print(json.dumps({"case": case["id"], "elapsed": round(elapsed, 1), "exit": process.returncode}), flush=True) + print(json.dumps({"case": case["id"], "elapsed": round(elapsed, 1), "exit": returncode}), flush=True) outcomes = {c["case_id"]: c.get("outcome", {}) for c in record["cases"]} regressions = [(c["case_id"], c.get("outcome", {})) for c in record["cases"] if c.get("role") == "regression"] diff --git a/src/openultrasast/cli.py b/src/openultrasast/cli.py index f615822..dd8479d 100644 --- a/src/openultrasast/cli.py +++ b/src/openultrasast/cli.py @@ -116,7 +116,7 @@ def _configure_logging() -> None: if level not in {"DEBUG", "INFO", "WARNING", "ERROR"}: return handler = logging.StreamHandler() - handler.setFormatter(logging.Formatter("%(levelname)s %(name)s %(message)s")) + handler.setFormatter(logging.Formatter("%(asctime)s %(levelname)s %(name)s %(message)s", "%H:%M:%S")) root = logging.getLogger("openultrasast") root.handlers = [handler] root.setLevel(getattr(logging, level))