| 1 | """Timed command execution with admitted-output capture.
|
| 2 |
|
| 3 | This is the measurement primitive every CLI lane shares: run a command under a
|
| 4 | monotonic clock, capture full output bytes to disk, and admit only a capped
|
| 5 | character window into token estimates (full byte counts are always recorded).
|
| 6 |
|
| 7 | Memory: the child's peak RSS is captured at reap time via os.wait4 (rusage),
|
| 8 | so no wrapper binary or sampling thread perturbs the timing. ru_maxrss units
|
| 9 | differ by platform (bytes on macOS, KiB on Linux); peak_rss_bytes is always
|
| 10 | bytes. None means unmeasured (ADR-0002), never zero — e.g. on platforms
|
| 11 | without wait4.
|
| 12 | """
|
| 13 |
|
| 14 | from __future__ import annotations
|
| 15 |
|
| 16 | import os
|
| 17 | import signal
|
| 18 | import subprocess
|
| 19 | import sys
|
| 20 | import tempfile
|
| 21 | import threading
|
| 22 | import time
|
| 23 | from dataclasses import dataclass
|
| 24 | from pathlib import Path
|
| 25 | from typing import Any, Optional
|
| 26 |
|
| 27 | _HAS_WAIT4 = hasattr(os, "wait4")
|
| 28 | PEAK_RSS_SOURCE = "os_wait4_ru_maxrss" if _HAS_WAIT4 else None
|
| 29 | # CPU and block I/O come from the same wait4 rusage as peak RSS: the direct
|
| 30 | # child's own usage (on macOS and Linux, including descendants it reaped
|
| 31 | # before exiting; daemons it leaves running are not included).
|
| 32 | RUSAGE_SOURCE = "os_wait4_child_rusage" if _HAS_WAIT4 else None
|
| 33 |
|
| 34 |
|
| 35 | @dataclass(frozen=True)
|
| 36 | class TimedCapture:
|
| 37 | elapsed_ms: float
|
| 38 | returncode: int
|
| 39 | stdout_text: str
|
| 40 | stdout_bytes: int
|
| 41 | stdout_truncated: bool
|
| 42 | stderr_text: str
|
| 43 | stderr_bytes: int
|
| 44 | stderr_truncated: bool
|
| 45 | peak_rss_bytes: Optional[int] = None
|
| 46 | stdout_full_text: Optional[str] = None
|
| 47 | stdout_full_text_truncated: Optional[bool] = None
|
| 48 | stderr_full_text: Optional[str] = None
|
| 49 | stderr_full_text_truncated: Optional[bool] = None
|
| 50 | timed_out: bool = False
|
| 51 | stdout_raw: bytes | None = None
|
| 52 | cpu_user_ms: Optional[float] = None
|
| 53 | cpu_sys_ms: Optional[float] = None
|
| 54 | io_read_blocks: Optional[int] = None
|
| 55 | io_write_blocks: Optional[int] = None
|
| 56 | major_page_faults: Optional[int] = None
|
| 57 |
|
| 58 |
|
| 59 | def stop_owned_process(proc: subprocess.Popen[Any]) -> None:
|
| 60 | """Stop the timed child and its owned process group, then always reap it."""
|
| 61 | try:
|
| 62 | if os.name == "posix":
|
| 63 | os.killpg(proc.pid, signal.SIGTERM)
|
| 64 | else:
|
| 65 | proc.terminate()
|
| 66 | except (OSError, ProcessLookupError):
|
| 67 | pass
|
| 68 | try:
|
| 69 | proc.wait(timeout=1.0)
|
| 70 | except subprocess.TimeoutExpired:
|
| 71 | pass
|
| 72 |
|
| 73 | # The process-group leader may exit on SIGTERM while a descendant ignores
|
| 74 | # it. Probe and kill the owned group even after the leader has been reaped.
|
| 75 | if os.name == "posix":
|
| 76 | try:
|
| 77 | os.killpg(proc.pid, 0)
|
| 78 | except (OSError, ProcessLookupError):
|
| 79 | pass
|
| 80 | else:
|
| 81 | try:
|
| 82 | os.killpg(proc.pid, signal.SIGKILL)
|
| 83 | except (OSError, ProcessLookupError):
|
| 84 | pass
|
| 85 | elif proc.poll() is None:
|
| 86 | try:
|
| 87 | proc.kill()
|
| 88 | except (OSError, ProcessLookupError):
|
| 89 | pass
|
| 90 |
|
| 91 | if proc.poll() is None:
|
| 92 | proc.wait()
|
| 93 |
|
| 94 |
|
| 95 | class _RusagePopen(subprocess.Popen):
|
| 96 | """Popen that records the child's rusage when it is reaped.
|
| 97 |
|
| 98 | Overriding _try_wait keeps a single wait4 syscall as both the reap and the
|
| 99 | measurement; there is no race against the kernel discarding rusage and no
|
| 100 | extra process in the timed path.
|
| 101 | """
|
| 102 |
|
| 103 | rusage = None
|
| 104 |
|
| 105 | def _try_wait(self, wait_flags): # type: ignore[override]
|
| 106 | try:
|
| 107 | pid, sts, rusage = os.wait4(self.pid, wait_flags)
|
| 108 | except ChildProcessError:
|
| 109 | pid = self.pid
|
| 110 | sts = 0
|
| 111 | else:
|
| 112 | if pid == self.pid:
|
| 113 | self.rusage = rusage
|
| 114 | return (pid, sts)
|
| 115 |
|
| 116 |
|
| 117 | def _peak_rss_bytes(rusage: Any) -> Optional[int]:
|
| 118 | if rusage is None:
|
| 119 | return None
|
| 120 | maxrss = getattr(rusage, "ru_maxrss", None)
|
| 121 | if not maxrss or maxrss < 0:
|
| 122 | return None
|
| 123 | # macOS reports bytes; Linux (and most other Unixes) report KiB.
|
| 124 | return int(maxrss) if sys.platform == "darwin" else int(maxrss) * 1024
|
| 125 |
|
| 126 |
|
| 127 | def rusage_fields(rusage: Any) -> dict[str, Any]:
|
| 128 | """CPU user/sys ms and block I/O counts; None when unmeasured (ADR-0002).
|
| 129 |
|
| 130 | ru_inblock/ru_oublock count real block I/O, so a warm page cache yields a
|
| 131 | measured 0, not an unmeasured value.
|
| 132 | """
|
| 133 | if rusage is None:
|
| 134 | return {"cpu_user_ms": None, "cpu_sys_ms": None, "io_read_blocks": None,
|
| 135 | "io_write_blocks": None, "major_page_faults": None}
|
| 136 | return {
|
| 137 | "cpu_user_ms": round(float(rusage.ru_utime) * 1000.0, 3),
|
| 138 | "cpu_sys_ms": round(float(rusage.ru_stime) * 1000.0, 3),
|
| 139 | "io_read_blocks": int(rusage.ru_inblock),
|
| 140 | "io_write_blocks": int(rusage.ru_oublock),
|
| 141 | "major_page_faults": int(rusage.ru_majflt),
|
| 142 | }
|
| 143 |
|
| 144 |
|
| 145 | def read_admitted_text(handle: Any, char_limit: int) -> tuple[str, int, bool]:
|
| 146 | handle.flush()
|
| 147 | handle.seek(0, os.SEEK_END)
|
| 148 | byte_count = handle.tell()
|
| 149 | handle.seek(0)
|
| 150 | if char_limit <= 0:
|
| 151 | return "", byte_count, byte_count > 0
|
| 152 | raw = handle.read(char_limit * 4 + 16)
|
| 153 | text = raw.decode("utf-8", "replace")[:char_limit]
|
| 154 | return text, byte_count, byte_count > len(text.encode("utf-8", "replace"))
|
| 155 |
|
| 156 |
|
| 157 | def read_full_text_with_byte_limit(handle: Any, byte_limit: int) -> tuple[str | None, bool]:
|
| 158 | handle.flush()
|
| 159 | handle.seek(0, os.SEEK_END)
|
| 160 | byte_count = handle.tell()
|
| 161 | if byte_limit < 0:
|
| 162 | return None, byte_count > 0
|
| 163 | if byte_count > byte_limit:
|
| 164 | return None, True
|
| 165 | handle.seek(0)
|
| 166 | return handle.read().decode("utf-8", "replace"), False
|
| 167 |
|
| 168 |
|
| 169 | def run_timed(
|
| 170 | command: list[str],
|
| 171 | cwd: Path,
|
| 172 | env: dict[str, str],
|
| 173 | admitted_output_chars: int,
|
| 174 | full_output_bytes: int | None = None,
|
| 175 | timeout_seconds: float | None = None,
|
| 176 | raw_output_bytes: int | None = None,
|
| 177 | watchdog_seconds: float | None = None,
|
| 178 | ) -> TimedCapture:
|
| 179 | """Run ``command`` under a monotonic clock.
|
| 180 |
|
| 181 | ``timeout_seconds`` uses ``Popen.wait(timeout)``, which on Python < 3.11
|
| 182 | polls with a doubling sleep (up to 50 ms), quantizing short timings.
|
| 183 | ``watchdog_seconds`` bounds the command instead with a timer thread that
|
| 184 | kills the owned process group while the caller blocks in a single
|
| 185 | ``wait4``, so the measured time does not depend on the bound. Pass one or
|
| 186 | the other; existing callers keep their behaviour.
|
| 187 | """
|
| 188 | if timeout_seconds is not None and timeout_seconds <= 0:
|
| 189 | raise ValueError("timeout_seconds must be positive")
|
| 190 | if watchdog_seconds is not None and watchdog_seconds <= 0:
|
| 191 | raise ValueError("watchdog_seconds must be positive")
|
| 192 | if timeout_seconds is not None and watchdog_seconds is not None:
|
| 193 | raise ValueError("pass timeout_seconds or watchdog_seconds, not both")
|
| 194 | if raw_output_bytes is not None and raw_output_bytes < 0:
|
| 195 | raise ValueError("raw_output_bytes must be nonnegative")
|
| 196 | popen_cls = _RusagePopen if _HAS_WAIT4 else subprocess.Popen
|
| 197 | start = time.perf_counter()
|
| 198 | with tempfile.TemporaryFile() as stdout_fh, tempfile.TemporaryFile() as stderr_fh:
|
| 199 | proc = popen_cls(
|
| 200 | command,
|
| 201 | cwd=cwd,
|
| 202 | env=env,
|
| 203 | stdout=stdout_fh,
|
| 204 | stderr=stderr_fh,
|
| 205 | start_new_session=(timeout_seconds is not None or watchdog_seconds is not None) and os.name == "posix",
|
| 206 | )
|
| 207 | timed_out = False
|
| 208 | if watchdog_seconds is not None:
|
| 209 | fired = threading.Event()
|
| 210 | done = threading.Lock()
|
| 211 |
|
| 212 | def _expire() -> None:
|
| 213 | with done:
|
| 214 | if proc.returncode is None:
|
| 215 | fired.set()
|
| 216 | try:
|
| 217 | os.killpg(proc.pid, signal.SIGKILL) if os.name == "posix" else proc.kill()
|
| 218 | except (OSError, ProcessLookupError):
|
| 219 | pass
|
| 220 |
|
| 221 | timer = threading.Timer(watchdog_seconds, _expire)
|
| 222 | timer.daemon = True
|
| 223 | timer.start()
|
| 224 | try:
|
| 225 | returncode = proc.wait()
|
| 226 | finally:
|
| 227 | with done:
|
| 228 | timer.cancel()
|
| 229 | if fired.is_set():
|
| 230 | timed_out = True
|
| 231 | returncode = 124
|
| 232 | else:
|
| 233 | try:
|
| 234 | returncode = proc.wait(timeout=timeout_seconds)
|
| 235 | except subprocess.TimeoutExpired:
|
| 236 | timed_out = True
|
| 237 | stop_owned_process(proc)
|
| 238 | returncode = 124
|
| 239 | elapsed_ms = (time.perf_counter() - start) * 1000
|
| 240 | stdout_text, stdout_bytes, stdout_truncated = read_admitted_text(stdout_fh, admitted_output_chars)
|
| 241 | stderr_text, stderr_bytes, stderr_truncated = read_admitted_text(stderr_fh, admitted_output_chars)
|
| 242 | stdout_raw = None
|
| 243 | if raw_output_bytes is not None and stdout_bytes <= raw_output_bytes:
|
| 244 | stdout_fh.seek(0)
|
| 245 | stdout_raw = stdout_fh.read()
|
| 246 | stdout_full_text = None
|
| 247 | stdout_full_text_truncated = None
|
| 248 | stderr_full_text = None
|
| 249 | stderr_full_text_truncated = None
|
| 250 | if full_output_bytes is not None:
|
| 251 | stdout_full_text, stdout_full_text_truncated = read_full_text_with_byte_limit(
|
| 252 | stdout_fh, full_output_bytes
|
| 253 | )
|
| 254 | stderr_full_text, stderr_full_text_truncated = read_full_text_with_byte_limit(
|
| 255 | stderr_fh, full_output_bytes
|
| 256 | )
|
| 257 | return TimedCapture(
|
| 258 | elapsed_ms=elapsed_ms,
|
| 259 | returncode=returncode,
|
| 260 | stdout_text=stdout_text,
|
| 261 | stdout_bytes=stdout_bytes,
|
| 262 | stdout_truncated=stdout_truncated,
|
| 263 | stderr_text=stderr_text,
|
| 264 | stderr_bytes=stderr_bytes,
|
| 265 | stderr_truncated=stderr_truncated,
|
| 266 | peak_rss_bytes=_peak_rss_bytes(getattr(proc, "rusage", None)),
|
| 267 | stdout_full_text=stdout_full_text,
|
| 268 | stdout_full_text_truncated=stdout_full_text_truncated,
|
| 269 | stderr_full_text=stderr_full_text,
|
| 270 | stderr_full_text_truncated=stderr_full_text_truncated,
|
| 271 | timed_out=timed_out,
|
| 272 | stdout_raw=stdout_raw,
|
| 273 | **rusage_fields(getattr(proc, "rusage", None)),
|
| 274 | )
|