diff --git a/src/hyperloom/agents/robustness/SKILL.md b/src/hyperloom/agents/robustness/SKILL.md index b8586ee192..b018c35eee 100644 --- a/src/hyperloom/agents/robustness/SKILL.md +++ b/src/hyperloom/agents/robustness/SKILL.md @@ -126,12 +126,20 @@ host -> subprocess -> envelope -> upstream PolicyGate path. | `LLM_MODEL` | no | provider default | RCA model name. With neither override set the chain is openai: `OPENAI_MODEL` → `CODEX_MODEL` → `gpt-5.6-sol`, else anthropic: `ANTHROPIC_MODEL` → `CLAUDE_MODEL` → `claude-opus-5`. | | `ROBUSTNESS_LLM_RCA_DISABLED` | no | unset | Set to `1` to forcibly disable the LlmRcaEngine even when credentials are present. | +`Config.discover()` reads the variables above plus the deployment-shape ones +(`ROBUSTNESS_DISABLE_LOCAL_PROBE`, `ROBUSTNESS_ENABLE_CLUSTER_POD_METRICS`, +`ROBUSTNESS_NODES`) and nothing else. Every threshold — stall timeouts, disk and +shm percentages, GPU temperatures — is a field on `Config` with a default in +`config.py`, changed in code or by whoever constructs the `Config`, not from the +environment. + ## Symptom -> intent mapping (M1 / M1.5) | Symptom | Severity | Intents emitted | Source | |---------|----------|-----------------|--------| | `agent_stall` (≥ stall_timeout_s) | medium | `alert(medium)` | M1 | | `agent_stall` (≥ severity_high_after_s) | high | `alert(high)` | M1 | +| `agent_quiet_work_progressing` (own dispatched work reported within `stall_timeout_s`) | low | `send_message(observation)` | M1.5 | | `crash_count_rising` (≥ 2) | medium | `alert(medium)` | M1 | | `crash_count_high` (≥ 5) | high | `alert(high)` | M1 | | `crash_count_emergency` (≥ 10) | high | `alert(high)` | M1 | @@ -141,6 +149,7 @@ host -> subprocess -> envelope -> upstream PolicyGate path. | `pod_not_running` (other non-Running) | medium | `alert(medium)` | M1 | | `pod_no_metrics` (≥ no_metrics_warn_s) | low | `send_message(observation)` | M1 | | `local_server_unreachable` (any target down) | medium / high (all down) | `alert(medium)` / `alert(high)` | M1.5 | +| `local_server_unreachable`, no server process and no benchmark client of this session | — | suppressed (an idle stretch, not an outage) | M1.5 | | `log_error_pattern` (CUDA OOM / NCCL / segfault) | high | `alert(high)` | M1.5 | | `log_error_pattern` (RuntimeError / generic) | medium | `alert(medium)` | M1.5 | | `gpu_thermal_high` (≥ warn_c) | medium | `alert(medium)` | M1.5 | diff --git a/src/hyperloom/agents/robustness/config.py b/src/hyperloom/agents/robustness/config.py index a4e32a7cea..a09db3b05d 100644 --- a/src/hyperloom/agents/robustness/config.py +++ b/src/hyperloom/agents/robustness/config.py @@ -30,6 +30,8 @@ deepseek_compat_env, ) +from .sources.local_probe import _OTHER_PROCESS_PATTERNS, _SERVER_PROCESS_PATTERNS + log = logging.getLogger(__name__) # Primary data source: an optional explicit endpoint (ROBUSTNESS_SERVER_URL), @@ -94,8 +96,14 @@ def coordinator_db_path(self) -> Path: return self.session_dir / "storage" / "coordinator.db" # -- thresholds -- + # Set in code, by whoever constructs the Config: :meth:`discover` reads only + # the deployment-shape variables listed in SKILL.md, so none of the + # thresholds below is settable from the environment. gpu_temp_warn_c: float = 85.0 agent_stall_timeout_s: float = 300.0 + # Silence past which an agent_stall is HIGH rather than MEDIUM. Deployments + # whose work units differ move it; it does not grade a withheld accusation. + agent_stall_high_after_s: float = 900.0 # -- LLM for RCA (auto-detected from Claw sandbox env) -- llm_model: str = "claude-opus-5" @@ -279,33 +287,18 @@ def coordinator_db_path(self) -> Path: state_store_enabled: bool = True # -- server process patterns -- - # Mirrors ``local_probe._DEFAULT_PROCESS_PATTERNS`` so the - # gpu_memory_leaked "no live owner" check matches every legitimate VRAM - # holder. + # Defaulted from the probe's own lists rather than restated here: a + # framework added to one copy but not the other used to appear as a matched + # process that is not a server, which silently disabled + # ``local_server_unreachable``. ``server_process_patterns`` is what a health + # probe may hold accountable for answering a port; the benchmark list adds + # the other legitimate VRAM holders the gpu_memory_leaked "no live owner" + # check has to see. server_process_patterns: list[str] = field( - default_factory=lambda: [ - # SGLang - "sglang.srt", - "sglang.launch_server", - # vLLM - "vllm.entrypoints", - "vllm serve", - "vllm.v1.engine.core", - "vllm.engine.async_llm_engine", - "EngineCore", - # Magpie / InferenceX - "Magpie", - "inferencex", - # Ray + JIT compilation - "ray::IDLE", - "raylet", - "hipcc", - ] + default_factory=lambda: list(_SERVER_PROCESS_PATTERNS), ) benchmark_process_patterns: list[str] = field( - default_factory=lambda: [ - "benchmark_serving", - ] + default_factory=lambda: list(_OTHER_PROCESS_PATTERNS), ) @classmethod diff --git a/src/hyperloom/agents/robustness/factory.py b/src/hyperloom/agents/robustness/factory.py index 0340dc2e28..d8d726fd4d 100644 --- a/src/hyperloom/agents/robustness/factory.py +++ b/src/hyperloom/agents/robustness/factory.py @@ -93,6 +93,68 @@ async def aclose(self) -> None: await self.server_client.aclose() +def _build_local_probe_config(config: Config) -> LocalProbeConfig: + """Project the agent config onto the local probe's own configuration. + + ``server_process_patterns`` is passed through as both the server subset and + part of the match list, so a framework an operator adds to that knob is + matched *and* recognised as a server. Splitting those two decisions across + separately-maintained lists is what let a configured framework show up as + ``is_server=False`` and silently disable ``local_server_unreachable``. + + Args: + config (Config): The discovered agent configuration. + + Returns: + LocalProbeConfig: Configuration for :class:`LocalProbeSource`. + """ + # Auto-include the local inference server health endpoint. + probe_targets = list(config.health_probe_targets) + if ( + config.auto_probe_inference_server + and config.inference_server_health_url + and config.inference_server_health_url not in probe_targets + ): + probe_targets.append(config.inference_server_health_url) + + extra_log_globs: tuple[str, ...] = ( + "runs/*/*/server.log", + "runs/*/*/server_log", + "runs/*/server.log", + "runs/*/*/*/server.log", + "runs/*/*/*/*/server.log", + ) + if config.server_log_extra_globs: + extra_log_globs = ( + *extra_log_globs, + *(g.strip() for g in config.server_log_extra_globs.split(":") if g.strip()), + ) + + return LocalProbeConfig( + session_dir=config.session_dir, + process_patterns=tuple(config.server_process_patterns + config.benchmark_process_patterns), + server_process_patterns=tuple(config.server_process_patterns), + health_probe_targets=tuple(probe_targets), + health_probe_timeout_s=config.health_probe_timeout_s, + ray_probe_enabled=config.ray_probe_enabled, + ray_probe_timeout_s=config.ray_probe_timeout_s, + fd_probe_enabled=config.fd_probe_enabled, + fd_probe_pid=config.fd_probe_pid, + decision_audit_enabled=config.decision_audit_enabled, + decision_audit_max_integrate=config.decision_audit_max_integrate, + decision_audit_max_oob_attempts=(config.decision_audit_max_oob_attempts), + preflight_enabled=config.preflight_enabled, + critic_health_enabled=config.critic_health_enabled, + max_critic_judge_bundles=config.critic_health_max_judge_bundles, + extra_server_log_globs=extra_log_globs, + max_extra_server_logs=config.server_log_max_extra, + state_integrity_enabled=config.state_integrity_enabled, + external_deps_enabled=config.external_deps_enabled, + external_mount_stat_timeout_s=(config.external_mount_stat_timeout_s), + external_gateway_probe_url=config.external_gateway_probe_url, + ) + + def build_reactor_components( config: Config, *, @@ -138,28 +200,6 @@ def build_reactor_components( "config.robustness_server_url is empty", ) - # Auto-include the local inference server health endpoint. - probe_targets = list(config.health_probe_targets) - if ( - config.auto_probe_inference_server - and config.inference_server_health_url - and config.inference_server_health_url not in probe_targets - ): - probe_targets.append(config.inference_server_health_url) - - extra_log_globs: tuple[str, ...] = ( - "runs/*/*/server.log", - "runs/*/*/server_log", - "runs/*/server.log", - "runs/*/*/*/server.log", - "runs/*/*/*/*/server.log", - ) - if config.server_log_extra_globs: - extra_log_globs = ( - *extra_log_globs, - *(g.strip() for g in config.server_log_extra_globs.split(":") if g.strip()), - ) - # Multi-node guard: ``disable_local_probe`` swaps LocalProbe for a quiet stub. fallback: Source if config.disable_local_probe: @@ -168,30 +208,7 @@ def build_reactor_components( reason="config.disable_local_probe is True (multi-node policy)", ) else: - fallback = LocalProbeSource( - LocalProbeConfig( - session_dir=config.session_dir, - process_patterns=tuple(config.server_process_patterns + config.benchmark_process_patterns), - health_probe_targets=tuple(probe_targets), - health_probe_timeout_s=config.health_probe_timeout_s, - ray_probe_enabled=config.ray_probe_enabled, - ray_probe_timeout_s=config.ray_probe_timeout_s, - fd_probe_enabled=config.fd_probe_enabled, - fd_probe_pid=config.fd_probe_pid, - decision_audit_enabled=config.decision_audit_enabled, - decision_audit_max_integrate=config.decision_audit_max_integrate, - decision_audit_max_oob_attempts=(config.decision_audit_max_oob_attempts), - preflight_enabled=config.preflight_enabled, - critic_health_enabled=config.critic_health_enabled, - max_critic_judge_bundles=config.critic_health_max_judge_bundles, - extra_server_log_globs=extra_log_globs, - max_extra_server_logs=config.server_log_max_extra, - state_integrity_enabled=config.state_integrity_enabled, - external_deps_enabled=config.external_deps_enabled, - external_mount_stat_timeout_s=(config.external_mount_stat_timeout_s), - external_gateway_probe_url=config.external_gateway_probe_url, - ) - ) + fallback = LocalProbeSource(_build_local_probe_config(config)) router = DegradeRouter( primary, @@ -211,6 +228,7 @@ def build_reactor_components( signal_configs: dict[str, Any] = { "stall": StallConfig( stall_timeout_s=config.agent_stall_timeout_s, + severity_high_after_s=config.agent_stall_high_after_s, ), "crash": CrashConfig(), "event": EventConfig( @@ -225,6 +243,7 @@ def build_reactor_components( shm_used_crit_pct=config.shm_used_crit_pct, fd_warn_used_pct=config.fd_warn_used_pct, fd_crit_used_pct=config.fd_crit_used_pct, + session_dir=config.session_dir, ), "gpu_leak": GpuLeakConfig( util_mem_pct_threshold=config.gpu_leak_util_mem_pct_threshold, @@ -498,6 +517,9 @@ async def fetch(self, ctx: Any) -> SourceData: # noqa: ARG002 - protocol """ return SourceData( degraded_reason=f"local-probe disabled: {self.reason}", + # Nothing looked: an empty process list here is ignorance, not + # evidence that no server is running. + local_processes_known=False, sources_used=[self.name], ) diff --git a/src/hyperloom/agents/robustness/prompts/rca.md b/src/hyperloom/agents/robustness/prompts/rca.md index 083c3f3637..067277c54d 100644 --- a/src/hyperloom/agents/robustness/prompts/rca.md +++ b/src/hyperloom/agents/robustness/prompts/rca.md @@ -26,7 +26,7 @@ Symptoms come from these signal families; knowing the family helps you interpret | H — Time / budget | `budget_strategy_drift`, `budget_burn_no_gain`, `deadline_imminent`, `deadline_warning`, `deadline_hard_cutoff` | | I — State integrity | `state_json_corrupt`, `coordinator_wal_bloat`, `stale_lease`, `inbox_bloat`, `coordinator_zombie` | | J — External deps | `gateway_auth_outage`, `wekafs_degraded`, `tracelens_cli_missing` | -| baseline / stall | `agent_stall`, `crash_count_rising`, `crash_count_high`, `crash_count_emergency`, `repeated_policy_denied`, `repeated_failure`, `recover_unsuccessful`, `cluster_fault` | +| baseline / stall | `agent_stall`, `agent_quiet_work_progressing`, `crash_count_rising`, `crash_count_high`, `crash_count_emergency`, `repeated_policy_denied`, `repeated_failure`, `recover_unsuccessful`, `cluster_fault` | ## Output contract diff --git a/src/hyperloom/agents/robustness/signals/local_health.py b/src/hyperloom/agents/robustness/signals/local_health.py index ff67e5a7bc..a4e805c44b 100644 --- a/src/hyperloom/agents/robustness/signals/local_health.py +++ b/src/hyperloom/agents/robustness/signals/local_health.py @@ -11,7 +11,10 @@ from __future__ import annotations +import os +from collections.abc import Iterator from dataclasses import dataclass +from pathlib import Path from typing import Any from ..role.prompt_inputs import ReactorContext @@ -19,6 +22,14 @@ from .symptom import Symptom, SymptomSeverity +# Load generators that only run while an inference server is expected to answer, +# so their presence turns "no server process" from an idle stretch into an +# outage. Deliberately narrower than the harness patterns the process probe +# matches: the outer Magpie/InferenceX harness is also up while it launches a +# server and while it tears one down, when a refused port is the correct reading. +_BENCHMARK_CLIENT_PATTERNS: tuple[str, ...] = ("benchmark_serving",) + + @dataclass class LocalHealthConfig: """Thresholds for the LocalProbe-derived health rules. @@ -40,6 +51,11 @@ class LocalHealthConfig: symptom. fd_crit_used_pct (float): File-descriptor used-percent for a HIGH symptom. + benchmark_client_patterns (tuple[str, ...]): Commands whose presence + means a server is supposed to be answering right now. + session_dir (Path | None): This session's directory, used to tell its + own processes from a co-tenant's. ``None`` leaves the benchmark + client check host-wide, which is only safe on a dedicated node. """ gpu_temp_warn_c: float = 90.0 @@ -53,6 +69,8 @@ class LocalHealthConfig: shm_used_crit_pct: float = 90.0 fd_warn_used_pct: float = 80.0 fd_crit_used_pct: float = 95.0 + benchmark_client_patterns: tuple[str, ...] = _BENCHMARK_CLIENT_PATTERNS + session_dir: Path | None = None # HIGH-severity log patterns; anything else from ``local_log_errors`` falls back to MEDIUM. @@ -111,7 +129,7 @@ def evaluate_local_health_signals( """ cfg = config or LocalHealthConfig() out: list[Symptom] = [] - out.extend(_server_unreachable(data)) + out.extend(_server_unreachable(data, cfg)) out.extend(_log_error_symptoms(data)) out.extend(_gpu_thermal_symptoms(data, cfg)) out.extend(_disk_pressure_symptoms(data, cfg)) @@ -121,20 +139,45 @@ def evaluate_local_health_signals( return out -def _server_unreachable(data: SourceData) -> list[Symptom]: +def _server_unreachable(data: SourceData, cfg: LocalHealthConfig) -> list[Symptom]: """Emit ``local_server_unreachable`` for each failed local HTTP probe. + The probe detects "process is alive but the server is wedged", so a refusal + with no server process behind the port is the expected reading, not a + fault: a session spends long stretches — preparation, analysis, the gap + between two variants — with no server up by design, and alerting there + tells an operator to restart something that was never meant to be running. + + That reasoning needs to know there is no server, which is not the same as + failing to find one. When the process probe could not answer at all, the + symptom is emitted with the uncertainty recorded in its evidence, so a + broken ``ps`` cannot mute an unrelated finding. + + "No server process" also does not always mean no server was wanted. A + server that died mid-benchmark leaves that exact snapshot while its own + load generator keeps sending requests into a closed port, so a benchmark + client of *this session* is treated as proof that something was supposed to + be answering and the alert stands. A co-tenant's client on a shared node + proves nothing about this session's port. + Severity is HIGH when every probed target is unreachable, otherwise MEDIUM. Args: data (SourceData): Collected source data including - ``local_server_health``. + ``local_server_health``, ``local_processes`` and + ``local_processes_known``. + cfg (LocalHealthConfig): Thresholds; provides the benchmark-client + patterns. Returns: list[Symptom]: One symptom per unreachable probe target, possibly empty. """ if not data.local_server_health: return [] + server_seen = any(proc.get("is_server") for proc in data.local_processes) + client_seen = _benchmark_client_seen(data, cfg) + if data.local_processes_known and not server_seen and not client_seen: + return [] bad = [entry for entry in data.local_server_health if not entry.get("reachable")] if not bad: return [] @@ -153,6 +196,8 @@ def _server_unreachable(data: SourceData) -> list[Symptom]: "status": status, "status_code": entry.get("status_code"), "error": entry.get("error"), + "server_process_seen": server_seen if data.local_processes_known else None, + "benchmark_client_seen": client_seen if data.local_processes_known else None, }, subject={"url": url}, source="local", @@ -166,6 +211,100 @@ def _server_unreachable(data: SourceData) -> list[Symptom]: return out +def _benchmark_client_seen(data: SourceData, cfg: LocalHealthConfig) -> bool: + """Report whether a load generator that needs *this session's* server runs. + + The process probe reads a whole-host ``ps``, so on a shared node another + session's load generator is in the snapshot too — and it vouches for a port + it has never sent a request to, turning this session's idle stretch back + into an outage. Only a client that can be tied to this session counts. + + Args: + data (SourceData): Collected source data including ``local_processes``. + cfg (LocalHealthConfig): Thresholds; provides the benchmark-client + patterns and the session anchor. + + Returns: + bool: ``True`` when a probed process matches a configured + benchmark-client pattern and belongs to this session. + """ + anchor = os.path.realpath(cfg.session_dir) if cfg.session_dir else "" + for proc in data.local_processes: + if not isinstance(proc, dict): + continue + cmd = str(proc.get("cmd") or "") + if not any(pattern in cmd for pattern in cfg.benchmark_client_patterns): + continue + if _in_session(proc, anchor): + return True + return False + + +def _in_session(proc: dict[str, Any], anchor: str) -> bool: + """Report whether a probed process can be tied to the session at ``anchor``. + + The harness is launched with its working directory inside the session and + children inherit it, so the cwd is the anchor; a client that names a path + under the session on its command line (``--result-dir``) counts too, for the + launch paths that chdir elsewhere. Both readings go through + :func:`_under_session` so neither can drift into accepting a path that only + starts with the session's. + + Args: + proc (dict[str, Any]): One ``local_processes`` entry. + anchor (str): Resolved session directory, or ``""`` when the session is + unknown — nothing to compare against, so every match counts and the + check stays host-wide. + + Returns: + bool: ``True`` when the process belongs to this session. + """ + if not anchor: + return True + if _under_session(str(proc.get("cwd") or ""), anchor): + return True + return any(_under_session(path, anchor) for path in _command_line_paths(str(proc.get("cmd") or ""))) + + +def _under_session(path: str, anchor: str) -> bool: + """Report whether ``path`` is the session directory or something inside it. + + Compared a path component at a time, never as a string prefix: a co-tenant's + ``-retry`` — a retry, a backup, or any sibling an operator names + after ours — starts with the session path without being in the session, and + a prefix test would let it vouch for its own port. + + Args: + path (str): Candidate path; ``""`` belongs to nobody. + anchor (str): Resolved session directory. + + Returns: + bool: ``True`` when ``path`` lies at or under ``anchor``. + """ + return bool(path) and Path(path).is_relative_to(anchor) + + +def _command_line_paths(cmd: str) -> Iterator[str]: + """Yield the path-shaped pieces of a command line. + + Each whitespace-separated token, plus what follows the first ``=`` in it, so + ``--result-dir /run/x`` and ``--result-dir=/run/x`` read the same. Tokens are + yielded whole rather than searched for a substring, which is what lets the + caller apply a directory boundary to them. + + Args: + cmd (str): The process command line. + + Yields: + str: One candidate path per token, and its ``key=value`` value. + """ + for token in cmd.split(): + yield token + _, sep, value = token.partition("=") + if sep: + yield value + + def _log_error_symptoms(data: SourceData) -> list[Symptom]: """Emit ``log_error_pattern`` symptoms grouped by matched log pattern. diff --git a/src/hyperloom/agents/robustness/signals/stall.py b/src/hyperloom/agents/robustness/signals/stall.py index e613a84b17..7e24a09fba 100644 --- a/src/hyperloom/agents/robustness/signals/stall.py +++ b/src/hyperloom/agents/robustness/signals/stall.py @@ -7,10 +7,37 @@ :attr:`SourceData.coordinator_events` (plus inbox tail) and alerts when idle past the threshold. Any event counts as activity, including heartbeats. + +Silence is only evidence of a stall when nothing else is moving. A phase whose +work is one multi-hour deterministic task — a baseline pair, a profile and its +roofline, an explore grid — has no LLM turn to emit, so agent silence there is +the design rather than a fault, and alerting on it trains operators to ignore +the signal. :attr:`SourceData.local_task_progress` carries the counter-evidence: +while an agent's *own* dispatched work is still reporting units, the accusation +is withheld and the tick reports ``agent_quiet_work_progressing`` instead. The +suppression has no wall-clock ceiling, because the work units it covers +routinely run past any threshold worth setting — a single warmup runs 3941s — +and a ceiling would make the alert fire on exactly the healthy runs it was +written to stay quiet about. What bounds it instead is the freshness of the +evidence: the moment the work stops reporting, the next tick accuses, at full +severity. + +Severity therefore follows the evidence and not the length of the wait. A phase +that keeps reporting throughout stays an observation however long it runs; +elapsed silence only decides how loud the *accusation* is, once there is no +fresh evidence left to withhold it. The two cases carry different symptom names +so RCA can tell a healthy long phase from an agent that went quiet past +:attr:`StallConfig.severity_high_after_s`. + +One reporting unit is enough to withhold even when the agent owns several, since +a quiet unit is not an agent fault and has the lease watchdog behind it. It is +still named in the evidence, so the healthy sibling stops being the only thing +an operator can see. """ from __future__ import annotations +import logging from dataclasses import dataclass from typing import Any @@ -21,6 +48,9 @@ from .symptom import Symptom, SymptomSeverity +log = logging.getLogger(__name__) + + # Agents tracked for stall detection; robustness excludes itself. _TRACKED_AGENTS: frozenset[str] = frozenset( { @@ -33,7 +63,16 @@ @dataclass class StallConfig: - """Knobs for :func:`evaluate_stall_signals`.""" + """Knobs for :func:`evaluate_stall_signals`. + + Attributes: + stall_timeout_s (float): Silence past which an agent is accused, and + the freshness a heartbeat must beat to count as counter-evidence. + severity_high_after_s (float): Silence past which an accusation is HIGH + rather than MEDIUM. It does not grade a withheld accusation: an + agent whose work is still reporting is not more suspect for having + been dispatched a longer unit. + """ stall_timeout_s: float = 300.0 severity_high_after_s: float = 900.0 @@ -45,11 +84,14 @@ def evaluate_stall_signals( *, config: StallConfig | None = None, ) -> list[Symptom]: - """Emit ``agent_stall`` symptoms for tracked agents that have gone silent. + """Report each tracked agent that has gone silent past the stall timeout. Computes per-agent idle time from the most recent activity timestamp and - fires MEDIUM (or HIGH past ``severity_high_after_s``) once idle time exceeds - the stall timeout. + fires ``agent_stall`` MEDIUM (or HIGH past ``severity_high_after_s``) once + idle time exceeds the stall timeout. An agent whose own dispatched work is + still reporting is not accused at all: work units outlive the stall window + by design, so it reports ``agent_quiet_work_progressing`` (LOW) for as long + as the evidence stays fresh. Args: ctx (ReactorContext): Reactor context (provides inbox and current time). @@ -58,8 +100,8 @@ def evaluate_stall_signals( when ``None``. Returns: - list[Symptom]: One ``agent_stall`` symptom per stalled agent, possibly - empty. + list[Symptom]: One ``agent_stall`` or ``agent_quiet_work_progressing`` + symptom per silent agent, possibly empty. """ cfg = config or StallConfig() last_seen = _collect_last_seen(ctx.inbox, data.coordinator_events) @@ -72,26 +114,182 @@ def evaluate_stall_signals( idle_s = max(0.0, ctx.now_unix - ts) if idle_s < cfg.stall_timeout_s: continue - severity = SymptomSeverity.HIGH if idle_s >= cfg.severity_high_after_s else SymptomSeverity.MEDIUM out.append( - Symptom( - name="agent_stall", - severity=severity, - summary=(f"agent {agent} silent for {int(idle_s)}s (threshold={int(cfg.stall_timeout_s)}s)"), - evidence={ - "agent": agent, - "idle_seconds": int(idle_s), - "last_seen_unix": int(ts), - "threshold_s": int(cfg.stall_timeout_s), - }, - subject={"agent": agent}, - source="local" if data.coordinator_events else "inbox", - suggestion=("escalate strategy if agent remains silent"), + _stall_symptom( + agent, + last_seen_unix=ts, + idle_s=idle_s, + data=data, + now_unix=ctx.now_unix, + cfg=cfg, ) ) return out +def _stall_symptom( + agent: str, + *, + last_seen_unix: float, + idle_s: float, + data: SourceData, + now_unix: float, + cfg: StallConfig, +) -> Symptom: + """Build the symptom for one agent that has gone silent. + + Args: + agent (str): The silent agent. + last_seen_unix (float): Its most recent activity timestamp. + idle_s (float): Seconds of silence. + data (SourceData): Collected source data; supplies the in-flight + progress counter-evidence and the symptom ``source``. + now_unix (float): Current time. + cfg (StallConfig): Thresholds. + + Returns: + Symptom: ``agent_stall`` at MEDIUM (HIGH past + ``severity_high_after_s``) when accused, or + ``agent_quiet_work_progressing`` at LOW while the agent's own work is + still reporting and the accusation is withheld. + """ + work_idle_s, work_task = _agent_in_flight_work( + data.local_task_progress, + agent=agent, + now_unix=now_unix, + ) or (None, "") + evidence: dict[str, Any] = { + "agent": agent, + "idle_seconds": int(idle_s), + "last_seen_unix": int(last_seen_unix), + "threshold_s": int(cfg.stall_timeout_s), + } + if work_idle_s is not None: + evidence["in_flight_work_idle_seconds"] = int(work_idle_s) + evidence["in_flight_work"] = work_task + evidence.update( + _quiet_sibling_evidence( + data.local_task_progress, + agent=agent, + now_unix=now_unix, + fresh_idle_s=work_idle_s, + cfg=cfg, + ) + ) + withheld = work_idle_s is not None and work_idle_s < cfg.stall_timeout_s + if not withheld: + severity = SymptomSeverity.HIGH if idle_s >= cfg.severity_high_after_s else SymptomSeverity.MEDIUM + return Symptom( + name="agent_stall", + severity=severity, + summary=(f"agent {agent} silent for {int(idle_s)}s (threshold={int(cfg.stall_timeout_s)}s)"), + evidence=evidence, + subject={"agent": agent}, + source="local" if data.coordinator_events else "inbox", + suggestion=("escalate strategy if agent remains silent"), + ) + evidence["accusation_withheld"] = True + evidence["withheld_while_work_reports_within_s"] = int(cfg.stall_timeout_s) + summary = ( + f"agent {agent} silent for {int(idle_s)}s but its dispatched work " + f"({work_task or 'unknown'}) reported {int(work_idle_s)}s ago; " + f"accusation withheld while that work keeps reporting" + ) + log.info("stall: %s", summary) + return Symptom( + name="agent_quiet_work_progressing", + severity=SymptomSeverity.LOW, + summary=summary, + evidence=evidence, + subject={"agent": agent}, + source="local" if data.coordinator_events else "inbox", + suggestion=("no action while this agent's own work keeps reporting units"), + ) + + +def _agent_in_flight_work( + task_progress: dict[str, Any], + *, + agent: str, + now_unix: float, + ts_key: str = "last_progress_unix", + task_key: str = "task", +) -> tuple[float, str] | None: + """Seconds since one of ``agent``'s own dispatched units reported. + + Progress belonging to another agent is deliberately invisible here: one + busy task must not vouch for an agent it has nothing to do with. + + Args: + task_progress (dict[str, Any]): :attr:`SourceData.local_task_progress`. + agent (str): The agent under accusation. + now_unix (float): Current time. + ts_key (str): Snapshot key holding the timestamp to read — the agent's + freshest note by default, ``"oldest_progress_unix"`` for its + quietest. + task_key (str): Snapshot key naming the unit ``ts_key`` belongs to. + + Returns: + tuple[float, str] | None: ``(idle_seconds, task_kind)``, or ``None`` + when this agent has no attributed heartbeat — no heartbeat is no + evidence either way, so the caller falls back to agent silence. + """ + entry = (task_progress.get("by_agent") or {}).get(agent) if task_progress else None + if not isinstance(entry, dict): + return None + ts = to_unix(entry.get(ts_key)) + if ts is None: + return None + return max(0.0, now_unix - ts), str(entry.get(task_key) or "") + + +def _quiet_sibling_evidence( + task_progress: dict[str, Any], + *, + agent: str, + now_unix: float, + fresh_idle_s: float, + cfg: StallConfig, +) -> dict[str, Any]: + """Name the agent's quietest unit when a busier sibling is speaking for it. + + One unit reporting still answers the question this signal asks — is this + agent's work progressing — so the accusation stays withheld. Declining to + withhold instead would fire on healthy runs: a Ray-backed baseline round has + no liveness callback to give it, and reports on entry and then not again + until it returns. What must not happen is the quiet unit leaving no trace, + which is what a snapshot carrying only the freshest heartbeat did. + + Args: + task_progress (dict[str, Any]): :attr:`SourceData.local_task_progress`. + agent (str): The agent under accusation. + now_unix (float): Current time. + fresh_idle_s (float): Idle seconds of the agent's freshest unit. + cfg (StallConfig): Thresholds. + + Returns: + dict[str, Any]: ``{quiet_in_flight_work, + quiet_in_flight_work_idle_seconds}`` when a strictly quieter unit of the + same agent is past the stall window, otherwise empty. + """ + quietest = _agent_in_flight_work( + task_progress, + agent=agent, + now_unix=now_unix, + ts_key="oldest_progress_unix", + task_key="oldest_task", + ) + if quietest is None: + return {} + idle_s, task = quietest + if idle_s <= fresh_idle_s or idle_s < cfg.stall_timeout_s: + return {} + return { + "quiet_in_flight_work": task, + "quiet_in_flight_work_idle_seconds": int(idle_s), + } + + def _collect_last_seen( inbox: list[InboxItem], coordinator_events: list[dict[str, Any]], diff --git a/src/hyperloom/agents/robustness/sources/base.py b/src/hyperloom/agents/robustness/sources/base.py index 1fa295f8eb..a5642771d6 100644 --- a/src/hyperloom/agents/robustness/sources/base.py +++ b/src/hyperloom/agents/robustness/sources/base.py @@ -68,6 +68,11 @@ class SourceData: cluster_faults: list[dict[str, Any]] = field(default_factory=list) local_gpu: dict[str, Any] = field(default_factory=dict) local_processes: list[dict[str, Any]] = field(default_factory=list) + # ``False`` when the process probe could not answer (``ps`` missing, timed + # out, disabled). An empty ``local_processes`` then means "we do not know + # what is running", not "nothing is running", and a consumer must not read + # the absence of a process as evidence. + local_processes_known: bool = True local_disk: dict[str, Any] = field(default_factory=dict) local_log_tail: list[str] = field(default_factory=list) local_log_errors: list[dict[str, Any]] = field(default_factory=list) @@ -93,6 +98,12 @@ class SourceData: # TRACELENS_ROOT / TRACELENS_INTERNAL_ROOT / INFERENCEX_PATH), ``tracelens_cli``. local_external_deps: dict[str, Any] = field(default_factory=dict) coordinator_events: list[dict[str, Any]] = field(default_factory=list) + # In-flight work: ``{running, by_agent: {agent: {last_progress_unix, task, + # oldest_progress_unix, oldest_task}}}``. + # A composite task reports a heartbeat per internal unit, so this answers + # "is *this agent's* dispatched work still moving" for an agent that is + # legitimately quiet while it waits on one. + local_task_progress: dict[str, Any] = field(default_factory=dict) sources_used: list[str] = field(default_factory=list) degraded_reason: str | None = None diff --git a/src/hyperloom/agents/robustness/sources/local_probe.py b/src/hyperloom/agents/robustness/sources/local_probe.py index a05c163842..7de0b421e5 100644 --- a/src/hyperloom/agents/robustness/sources/local_probe.py +++ b/src/hyperloom/agents/robustness/sources/local_probe.py @@ -28,7 +28,7 @@ import httpx -from hyperloom.common.coerce import to_float +from hyperloom.common.coerce import to_float, to_unix from hyperloom.common.llm_config import LLMConfigError, resolve_openai_client_config from .base import SourceData, SourceUnavailable @@ -37,8 +37,16 @@ log = logging.getLogger(__name__) -# Process patterns for ``local_processes``: owners that may legitimately hold GPU VRAM. -_DEFAULT_PROCESS_PATTERNS: tuple[str, ...] = ( +# Inference-server commands, kept apart from the rest because "is a server +# supposed to be answering right now" is a different question from "what is +# running": a health probe against a port with no server behind it is an +# expected refusal, not a wedged server. +# +# The single source of truth for that distinction. ``LocalProbeConfig`` and the +# agent-level ``Config`` knob both default to this tuple rather than restating +# it, so a framework added in one place cannot show up matched-but-not-a-server +# in the other and silently disable ``local_server_unreachable``. +_SERVER_PROCESS_PATTERNS: tuple[str, ...] = ( # SGLang "sglang.srt", "sglang.launch_server", @@ -48,11 +56,16 @@ "vllm.v1.engine.core", "vllm.engine.async_llm_engine", "EngineCore", # covers ``EngineCore-`` child PIDs +) + +_OTHER_PROCESS_PATTERNS: tuple[str, ...] = ( # Magpie / InferenceX benchmark harness "Magpie", "inferencex", - # Ray + per-task workers + # Ray + per-task workers. ``ray::IDLE`` is the parked worker name only; + # a worker running a serving actor renames itself after the actor class. "ray::IDLE", + "ray::ServingActor", "raylet", # hipcc stuck mid-build holds GPU locks. "hipcc", @@ -60,6 +73,9 @@ "benchmark_serving", ) +# Process patterns for ``local_processes``: owners that may legitimately hold GPU VRAM. +_DEFAULT_PROCESS_PATTERNS: tuple[str, ...] = _SERVER_PROCESS_PATTERNS + _OTHER_PROCESS_PATTERNS + # Log error markers. Order matters: first matching pattern per line wins, so # specific patterns must come before generic ones. @@ -114,6 +130,9 @@ class LocalProbeConfig: # Surface ``/dev/shm`` alongside ``/`` so signals fire shm_pressure separately. disk_mountpoints: tuple[str, ...] = ("/", "/dev/shm") # nosec B108 - mountpoint probe, not temp file creation. process_patterns: tuple[str, ...] = _DEFAULT_PROCESS_PATTERNS + # The subset of ``process_patterns`` that names an inference server, i.e. + # something a health probe may hold accountable for answering a port. + server_process_patterns: tuple[str, ...] = _SERVER_PROCESS_PATTERNS coordinator_event_limit: int = 200 log_error_patterns: tuple[str, ...] = _DEFAULT_LOG_ERROR_PATTERNS log_error_window_lines: int = 500 @@ -201,8 +220,17 @@ async def fetch(self, ctx: Any) -> SourceData: cfg.coordinator_db_path, cfg.coordinator_event_limit, ) + local_task_progress = await asyncio.to_thread( + _read_task_progress, + cfg.coordinator_db_path, + ) local_disk = await asyncio.to_thread(_sample_disk, cfg.disk_mountpoints) - local_processes = await asyncio.to_thread(_sample_processes, cfg.process_patterns) + sampled_processes = await asyncio.to_thread( + _sample_processes, + cfg.process_patterns, + cfg.server_process_patterns, + ) + local_processes = sampled_processes or [] local_gpu = await asyncio.to_thread(_sample_gpu) local_log_tail = await asyncio.to_thread( _tail_logs, @@ -273,6 +301,7 @@ async def fetch(self, ctx: Any) -> SourceData: any_signal = bool( coordinator_events + or local_task_progress or local_disk or local_processes or local_gpu @@ -308,6 +337,8 @@ async def fetch(self, ctx: Any) -> SourceData: local_state_integrity=local_state_integrity, local_external_deps=local_external_deps, coordinator_events=coordinator_events, + local_task_progress=local_task_progress, + local_processes_known=sampled_processes is not None, sources_used=[self.name], ) @@ -317,6 +348,128 @@ async def fetch(self, ctx: Any) -> SourceData: # --------------------------------------------------------------------------- +def _read_task_progress(db_path: Path | None) -> dict[str, Any]: + """Summarize in-flight task progress from the session SQLite DB. + + Freshness comes from the progress notes ``TaskRegistry.record_progress`` + appends to a task's ``history``, not from ``updated_at``: that column also + moves when a task merely enters ``running``, and a state transition is no + evidence that anything is still happening. A note that names no owning + agent is counted as running work but vouches for nobody. + + Args: + db_path (Path | None): Path to ``coordinator.db``; ``None`` or a + missing file short-circuits to ``{}``. + + Returns: + dict[str, Any]: ``{running, by_agent}`` where ``by_agent`` maps an + owning agent to ``{last_progress_unix, task, oldest_progress_unix, + oldest_task}`` — the freshest and the quietest of the units it owns — + or ``{}`` when the DB is unreadable or nothing is running. + """ + if db_path is None or not db_path.exists(): + return {} + try: + conn = sqlite3.connect(f"file:{db_path}?mode=ro", uri=True, timeout=2.0) + except sqlite3.Error as exc: + log.debug("local_probe: cannot open %s: %s", db_path, exc) + return {} + try: + conn.row_factory = sqlite3.Row + rows = _try_select( + conn, + # Ordered so the fold below is reproducible: the merge itself is + # order-independent, but a snapshot whose row order is SQLite's + # discretion cannot be reasoned about or pinned by a test. + ["SELECT task_id, kind, history FROM tasks WHERE state='running' ORDER BY task_id"], + (), + ) + finally: + conn.close() + if not rows: + return {} + out: dict[str, Any] = {"running": len(rows)} + by_agent: dict[str, dict[str, Any]] = {} + for row in rows: + keys = row.keys() + note = _latest_progress_note(row["history"] if "history" in keys else None) + if note is None: + continue + ts, agent = note + task = str((row["kind"] if "kind" in keys else row["task_id"]) or "") + _merge_agent_progress(by_agent, agent=agent, ts=ts, task=task) + if by_agent: + out["by_agent"] = by_agent + return out + + +def _merge_agent_progress( + by_agent: dict[str, dict[str, Any]], + *, + agent: str, + ts: float, + task: str, +) -> None: + """Fold one unit's heartbeat into ``agent``'s freshest/quietest pair. + + Both ends are kept because the dispatcher runs units concurrently. The + freshest answers "is this agent's work progressing"; keeping only that one + left a sibling unit that had not reported in hours with no trace in the + snapshot at all. + + Args: + by_agent (dict[str, dict[str, Any]]): Accumulator, updated in place. + agent (str): The agent the note attributed itself to. + ts (float): Unix timestamp of the note. + task (str): Kind (or id) of the unit that reported it. + """ + known = by_agent.get(agent) + if known is None: + by_agent[agent] = { + "last_progress_unix": ts, + "task": task, + "oldest_progress_unix": ts, + "oldest_task": task, + } + return + if ts > known["last_progress_unix"]: + known["last_progress_unix"] = ts + known["task"] = task + if ts < known["oldest_progress_unix"]: + known["oldest_progress_unix"] = ts + known["oldest_task"] = task + + +def _latest_progress_note(history_json: Any) -> tuple[float, str] | None: + """Extract the newest attributed heartbeat from a task's ``history`` column. + + Args: + history_json (Any): Raw ``tasks.history`` JSON text. + + Returns: + tuple[float, str] | None: ``(unix_ts, owning_agent)`` for the newest + entry carrying a ``progress`` note that names its agent, or ``None`` + when the task has never reported one. + """ + if not isinstance(history_json, str): + return None + rows = _json_loads_or_none(history_json) + if not isinstance(rows, list): + return None + for entry in reversed(rows): + if not isinstance(entry, dict): + continue + note = entry.get("progress") + if not isinstance(note, dict): + continue + ts = to_unix(entry.get("ts")) + agent = str(note.get("agent") or "").strip() + if ts is None or not agent: + continue + return ts, agent + return None + + def _read_coordinator_events( db_path: Path | None, limit: int, @@ -461,23 +614,33 @@ def _sample_disk(mountpoints: tuple[str, ...]) -> dict[str, Any]: return out -def _sample_processes(patterns: tuple[str, ...]) -> list[dict[str, Any]]: +def _sample_processes( + patterns: tuple[str, ...], + server_patterns: tuple[str, ...] = _SERVER_PROCESS_PATTERNS, +) -> list[dict[str, Any]] | None: """List local processes whose command matches any pattern. - Runs ``ps -eo pid=,rss=,cmd=`` and keeps lines whose command - contains one of ``patterns``. Returns ``[]`` when ``ps`` is absent, - times out, or exits non-zero. + Runs ``ps -eo pid=,rss=,cmd=`` and keeps lines whose command contains one + of ``patterns``. An empty list means "nothing matched"; ``None`` means the + probe could not answer at all. Consumers must not read the second as the + first — an absent ``ps`` would otherwise become evidence that no server is + running, and mute a signal that has nothing to do with this probe. Args: patterns (tuple[str, ...]): Substrings matched against each process command line; empty disables the probe. + server_patterns (tuple[str, ...]): The subset naming an inference + server; matches are flagged ``is_server``. Returns: - list[dict[str, Any]]: One ``{pid, rss_mb, cmd}`` entry per - matching process. + list[dict[str, Any]] | None: One ``{pid, rss_mb, cmd, is_server, cwd}`` + entry per matching process, where ``is_server`` marks an inference + server as opposed to a harness, Ray, or build process and ``cwd`` is + what ties a process to a session on a shared node; ``None`` when + the probe is disabled, ``ps`` is absent, times out, or exits non-zero. """ if not patterns: - return [] + return None try: proc = subprocess.run( ["ps", "-eo", "pid=,rss=,cmd="], @@ -488,9 +651,10 @@ def _sample_processes(patterns: tuple[str, ...]) -> list[dict[str, Any]]: ) except (FileNotFoundError, subprocess.TimeoutExpired) as exc: log.debug("local_probe: ps failed: %s", exc) - return [] + return None if proc.returncode != 0: - return [] + log.debug("local_probe: ps exited %d", proc.returncode) + return None out: list[dict[str, Any]] = [] for line in proc.stdout.splitlines(): line = line.strip() @@ -507,10 +671,40 @@ def _sample_processes(patterns: tuple[str, ...]) -> list[dict[str, Any]]: rss_kb = int(rss_str) except ValueError: continue - out.append({"pid": pid, "rss_mb": round(rss_kb / 1024.0, 1), "cmd": cmd}) + out.append( + { + "pid": pid, + "rss_mb": round(rss_kb / 1024.0, 1), + "cmd": cmd, + "is_server": any(pat in cmd for pat in server_patterns), + "cwd": _process_cwd(pid), + } + ) return out +def _process_cwd(pid: int) -> str: + """Read a process's working directory from ``/proc//cwd``. + + A run's harness is launched with its working directory inside the session + and children inherit it, which is what lets a consumer tell one session's + processes from another's on a shared node. + + Args: + pid (int): The process to inspect. + + Returns: + str: The resolved directory, or ``""`` when it cannot be read — another + user's process, a process that exited between ``ps`` and this call, or a + sandbox with no ``/proc``. Unknown, never "somewhere else". + """ + try: + return os.readlink(f"/proc/{pid}/cwd") + except OSError as exc: + log.debug("local_probe: /proc/%d/cwd unreadable: %s", pid, exc) + return "" + + def _sample_gpu() -> dict[str, Any]: """Best-effort GPU snapshot using rocm-smi or nvidia-smi. @@ -1401,6 +1595,10 @@ def _load_ci_metrics( def _json_loads_or_none(text: str) -> Any: """Parse JSON text, returning ``None`` instead of raising on error. + ``RecursionError`` is caught alongside the decode errors: the probe reads + blobs written by other processes, and a deeply nested one would otherwise + take down the whole tick rather than just the sub-probe that read it. + Args: text (str): The JSON text to parse. @@ -1413,7 +1611,7 @@ def _json_loads_or_none(text: str) -> Any: try: return json.loads(text) - except (json.JSONDecodeError, ValueError): + except (json.JSONDecodeError, ValueError, RecursionError): return None diff --git a/src/hyperloom/agents/robustness/tests/test_decision_action_ladder.py b/src/hyperloom/agents/robustness/tests/test_decision_action_ladder.py index 6cc2aaa558..54d4dc0d9c 100644 --- a/src/hyperloom/agents/robustness/tests/test_decision_action_ladder.py +++ b/src/hyperloom/agents/robustness/tests/test_decision_action_ladder.py @@ -137,6 +137,48 @@ async def test_high_agent_stall_emits_alert_only(): assert IntentType.ESCALATE_STRATEGY_CHANGE not in types +async def test_a_withheld_stall_is_observed_not_alerted(): + """The LOW tier documented in SKILL.md: visible to an operator, no alert.""" + ladder = ActionLadder() + out = await ladder.decide( + [ + _sym( + "agent_quiet_work_progressing", + SymptomSeverity.LOW, + summary="agent orchestration silent for 400s but its dispatched work reported 10s ago", + subject={"agent": "orchestration"}, + ) + ], + tick_index=0, + now_unix=1.0, + ) + assert [i.type for i in out.intents] == [IntentType.SEND_MESSAGE] + assert out.intents[0].payload["topic"] == "observation" + + +async def test_medium_agent_stall_emits_a_medium_alert(): + """The rung a healthy long phase must not reach: MEDIUM is an alert. + + Documented in SKILL.md as ``alert(medium)``, which is why the withheld note + stays on the observation tier however long the phase runs. + """ + ladder = ActionLadder() + out = await ladder.decide( + [ + _sym( + "agent_stall", + SymptomSeverity.MEDIUM, + summary="agent orchestration silent for 3941s (threshold=300s)", + subject={"agent": "orchestration"}, + ) + ], + tick_index=0, + now_unix=1.0, + ) + assert [i.type for i in out.intents] == [IntentType.ALERT] + assert out.intents[0].payload["severity"] == "medium" + + async def test_repeated_failure_high_emits_alert_plus_prune_branch(): """Sustained repeated_failure (HIGH) prunes the offending family.""" ladder = ActionLadder() diff --git a/src/hyperloom/agents/robustness/tests/test_factory.py b/src/hyperloom/agents/robustness/tests/test_factory.py index af01875cba..8626b51350 100644 --- a/src/hyperloom/agents/robustness/tests/test_factory.py +++ b/src/hyperloom/agents/robustness/tests/test_factory.py @@ -59,6 +59,21 @@ async def test_factory_config_map_covers_all_registry_entries(tmp_path: Path): await bundle.aclose() +@pytest.mark.asyncio +async def test_the_stall_escalation_threshold_reaches_the_signal_from_the_config(tmp_path: Path): + """Deployments whose work units differ need the escalation point to move. + + In code: like every other threshold on ``Config`` it is set by whoever + constructs it, not by an environment variable ``discover`` reads. + """ + config = Config(session_dir=tmp_path, robustness_server_url="", agent_stall_high_after_s=7200.0) + bundle = build_reactor_components(config) + try: + assert bundle.components.classifier.signal_configs["stall"].severity_high_after_s == 7200.0 + finally: + await bundle.aclose() + + @pytest.mark.asyncio async def test_build_reactor_components_uses_server_url_when_set(tmp_path: Path): config = Config( @@ -421,6 +436,44 @@ async def test_factory_uses_quiet_fallback_when_local_probe_disabled(tmp_path: P await bundle.aclose() +@pytest.mark.asyncio +async def test_the_quiet_fallback_does_not_pass_its_empty_process_list_off_as_evidence(tmp_path: Path): + """Nothing looked, so "no processes" is ignorance and must not read as "no server". + + The stub probes no health targets of its own, so today the flag only matters + if its snapshot is ever merged with one that did probe — which is exactly the + consumer asserted here, the guard that suppresses + ``local_server_unreachable`` when the process probe saw no server. + """ + from dataclasses import replace + + from hyperloom.agents.robustness.role.prompt_inputs import ReactorContext, SharedStateSnapshot + from hyperloom.agents.robustness.signals import evaluate_local_health_signals + + config = Config(session_dir=tmp_path, disable_local_probe=True) + bundle = build_reactor_components(config) + try: + data = await bundle.components.router._fallback.fetch(None) # type: ignore[attr-defined] + assert data.local_processes_known is False + probed = replace( + data, + local_server_health=[ + {"url": "http://localhost:8888/health", "reachable": False, "status": "error", "error": "connect"}, + ], + ) + ctx = ReactorContext( + tick_index=0, + shared_state=SharedStateSnapshot(session_id="sess-1"), + inbox=[], + now_unix=1.0, + ) + matched = [s for s in evaluate_local_health_signals(ctx, probed) if s.name == "local_server_unreachable"] + assert len(matched) == 1 + assert matched[0].evidence["server_process_seen"] is None + finally: + await bundle.aclose() + + @pytest.mark.asyncio async def test_factory_default_keeps_local_probe_fallback(tmp_path: Path): from hyperloom.agents.robustness.sources.local_probe import LocalProbeSource @@ -468,6 +521,44 @@ async def test_factory_scriptable_skips_inference_server_probe(tmp_path: Path): await bundle.aclose() +@pytest.mark.asyncio +async def test_a_framework_added_to_the_config_knob_is_recognised_as_a_server(tmp_path: Path, monkeypatch): + """The documented knob decides ``is_server``, not a second copy of the list. + + A framework named only in ``server_process_patterns`` used to be matched as + a process yet flagged ``is_server=False``, which silently disabled + ``local_server_unreachable`` for the very deployment that configured it. + """ + import subprocess + + from hyperloom.agents.robustness.sources import local_probe + + config = Config(session_dir=tmp_path) + config.server_process_patterns.append("tinyserve.entrypoint") + bundle = build_reactor_components(config) + try: + probe_cfg = bundle.components.router._fallback._config # type: ignore[attr-defined] + monkeypatch.setattr( + local_probe.subprocess, + "run", + lambda *a, **k: subprocess.CompletedProcess( + a[0], 0, " 9 1048576 python -m tinyserve.entrypoint --port 8888\n", "" + ), + ) + + found = local_probe._sample_processes( + probe_cfg.process_patterns, + probe_cfg.server_process_patterns, + ) + + assert found is not None + assert [(p["pid"], p["rss_mb"], p["cmd"], p["is_server"]) for p in found] == [ + (9, 1024.0, "python -m tinyserve.entrypoint --port 8888", True) + ] + finally: + await bundle.aclose() + + @pytest.mark.asyncio async def test_factory_forwards_multi_node_options_to_server_source(tmp_path: Path): """``enable_cluster_pod_metrics`` / ``workload_uid`` reach the server source.""" diff --git a/src/hyperloom/agents/robustness/tests/test_signals_local_health.py b/src/hyperloom/agents/robustness/tests/test_signals_local_health.py index 5000fe993a..ca88b34a4e 100644 --- a/src/hyperloom/agents/robustness/tests/test_signals_local_health.py +++ b/src/hyperloom/agents/robustness/tests/test_signals_local_health.py @@ -33,12 +33,18 @@ def _ctx() -> ReactorContext: ) +def _live_server() -> list[dict]: + """A server process the probe can hold accountable for answering.""" + return [{"pid": 4242, "rss_mb": 1024.0, "cmd": "python -m sglang.launch_server", "is_server": True}] + + def test_one_target_down_emits_medium_alert(): data = SourceData( + local_processes=_live_server(), local_server_health=[ {"url": "http://localhost:30000", "reachable": True, "status": "ok"}, {"url": "http://localhost:30001", "reachable": False, "status": "error", "error": "connect"}, - ] + ], ) out = evaluate_local_health_signals(_ctx(), data) matched = [s for s in out if s.name == "local_server_unreachable"] @@ -49,10 +55,11 @@ def test_one_target_down_emits_medium_alert(): def test_all_targets_down_promotes_severity_to_high(): data = SourceData( + local_processes=_live_server(), local_server_health=[ {"url": "http://localhost:30000", "reachable": False, "status": "error"}, {"url": "http://localhost:30001", "reachable": False, "status": "http_error"}, - ] + ], ) out = evaluate_local_health_signals(_ctx(), data) matched = [s for s in out if s.name == "local_server_unreachable"] @@ -60,6 +67,145 @@ def test_all_targets_down_promotes_severity_to_high(): assert all(s.severity is SymptomSeverity.HIGH for s in matched) +def test_a_refused_port_with_no_server_behind_it_is_not_a_fault(): + """Preparation, analysis and the gap between variants all run with no server up.""" + data = SourceData( + local_processes=[{"pid": 7, "rss_mb": 12.0, "cmd": "python -m Magpie.bench", "is_server": False}], + local_server_health=[ + {"url": "http://localhost:8888/health", "reachable": False, "status": "error", "error": "connect"}, + ], + ) + out = evaluate_local_health_signals(_ctx(), data) + assert all(s.name != "local_server_unreachable" for s in out) + + +def test_a_server_that_died_under_a_running_benchmark_is_still_a_fault(): + """A benchmark client hammering the port proves a server was meant to answer it. + + "Probed successfully, saw no server" is the gap between two variants, but it + is also a server that crashed while its own client kept sending requests — + the one snapshot where suppressing the alert hides the outage. + + No session directory is configured here, so the client check has nothing to + attribute against and stays host-wide. + """ + data = SourceData( + local_processes=[ + {"pid": 7, "rss_mb": 12.0, "cmd": "python -m Magpie.bench", "is_server": False}, + {"pid": 8, "rss_mb": 96.0, "cmd": "python benchmark_serving.py --port 30000", "is_server": False}, + ], + local_server_health=[ + {"url": "http://localhost:30000/health", "reachable": False, "status": "error", "error": "connect"}, + ], + ) + out = evaluate_local_health_signals(_ctx(), data) + matched = [s for s in out if s.name == "local_server_unreachable"] + assert len(matched) == 1 + assert matched[0].severity is SymptomSeverity.HIGH + assert matched[0].evidence["server_process_seen"] is False + assert matched[0].evidence["benchmark_client_seen"] is True + + +def _client_snapshot(cmd: str, cwd: str) -> SourceData: + """A refused port, no server process, and one benchmark client running.""" + return SourceData( + local_processes=[{"pid": 8, "rss_mb": 96.0, "cmd": cmd, "cwd": cwd, "is_server": False}], + local_server_health=[ + {"url": "http://localhost:30000/health", "reachable": False, "status": "error", "error": "connect"}, + ], + ) + + +_OUTSIDE_ANY_SESSION = "/tmp" # nosec B108 - a path in a fixture, not a temp file. +_CLIENT = "python benchmark_serving.py --port 30000" +_CLIENT_RESULT_DIR = "python benchmark_serving.py --result-dir {dir}/runs/v1 --port 30000" +_CLIENT_RESULT_DIR_EQ = "python benchmark_serving.py --result-dir={dir}/runs/v1 --port 30000" + + +@pytest.mark.parametrize( + ("client_dir", "client_cwd", "client_cmd", "vouches"), + [ + pytest.param("ours", "{dir}/runs/v1", _CLIENT, True, id="ours_by_cwd"), + pytest.param("ours", "{dir}", _CLIENT, True, id="ours_by_cwd_at_the_session_root"), + pytest.param("ours", _OUTSIDE_ANY_SESSION, _CLIENT_RESULT_DIR, True, id="ours_by_result_dir"), + pytest.param("ours", _OUTSIDE_ANY_SESSION, _CLIENT_RESULT_DIR_EQ, True, id="ours_by_result_dir_joined_by_="), + pytest.param("ours", _OUTSIDE_ANY_SESSION, _CLIENT, False, id="no_anchor_at_all"), + pytest.param("theirs", "{dir}/runs/v1", _CLIENT_RESULT_DIR, False, id="unrelated_co_tenant"), + pytest.param("sibling", "{dir}/runs/v1", _CLIENT_RESULT_DIR, False, id="co_tenant_one_string_prefix_away"), + pytest.param( + "sibling", + _OUTSIDE_ANY_SESSION, + _CLIENT_RESULT_DIR_EQ, + False, + id="co_tenant_one_string_prefix_away_joined_by_=", + ), + ], +) +def test_only_this_sessions_benchmark_client_vouches_for_a_dead_server( + tmp_path, + client_dir, + client_cwd, + client_cmd, + vouches, +): + """A client vouches for a refused port only when it belongs to this session. + + The harness runs with its cwd inside the session and children inherit it, so + the cwd is the anchor; a launch path that chdirs elsewhere still names a path + under the session on its command line, which is the second anchor. Anything + else is somebody else's traffic — including the sibling directory whose name + merely starts with ours (``-retry``), which a substring test reads + as inside the session. The command line is held to that boundary in both + spellings of the flag, since the two are read by different code. + + A client with neither anchor is indistinguishable from a co-tenant's and + must not vouch either; every launch path in this repo carries one, which is + what the grid-runner cwd test holds it to. + """ + ours = tmp_path / "session-a" + dirs = {"ours": ours, "theirs": tmp_path / "session-b", "sibling": tmp_path / "session-a-retry"} + data = _client_snapshot( + cmd=client_cmd.format(dir=dirs[client_dir]), + cwd=client_cwd.format(dir=dirs[client_dir]), + ) + matched = [ + s + for s in evaluate_local_health_signals(_ctx(), data, config=LocalHealthConfig(session_dir=ours)) + if s.name == "local_server_unreachable" + ] + assert bool(matched) is vouches + if vouches: + assert matched[0].severity is SymptomSeverity.HIGH + assert matched[0].evidence["benchmark_client_seen"] is True + + +def test_a_refused_port_is_still_a_fault_when_nobody_could_look_for_the_server(): + """A broken ``ps`` must not mute a finding that has nothing to do with it.""" + data = SourceData( + local_processes=[], + local_processes_known=False, + local_server_health=[ + {"url": "http://localhost:8888/health", "reachable": False, "status": "error", "error": "connect"}, + ], + ) + out = evaluate_local_health_signals(_ctx(), data) + matched = [s for s in out if s.name == "local_server_unreachable"] + assert len(matched) == 1 + assert matched[0].evidence["server_process_seen"] is None + assert matched[0].evidence["benchmark_client_seen"] is None + + +def test_a_seen_server_is_recorded_in_the_evidence(): + data = SourceData( + local_processes=_live_server(), + local_server_health=[ + {"url": "http://localhost:30000", "reachable": False, "status": "error"}, + ], + ) + matched = [s for s in evaluate_local_health_signals(_ctx(), data) if s.name == "local_server_unreachable"] + assert matched and matched[0].evidence["server_process_seen"] is True + + def test_no_unreachable_targets_is_silent(): data = SourceData( local_server_health=[ @@ -123,6 +269,7 @@ def test_classifier_includes_local_health_rule(): data = SourceData( local_log_errors=[{"pattern": "CUDA out of memory", "line": "..."}], + local_processes=_live_server(), local_server_health=[{"url": "u", "reachable": False, "status": "error"}], local_gpu={"gpus": [{"gpu_id": 0, "temperature_c": 99.5}]}, ) diff --git a/src/hyperloom/agents/robustness/tests/test_sources_local_probe.py b/src/hyperloom/agents/robustness/tests/test_sources_local_probe.py index 29ebbd4f82..5b05ad9a3d 100644 --- a/src/hyperloom/agents/robustness/tests/test_sources_local_probe.py +++ b/src/hyperloom/agents/robustness/tests/test_sources_local_probe.py @@ -447,6 +447,8 @@ async def test_local_probe_skips_log_when_path_missing(tmp_path: Path): from typing import Any # noqa: E402 from unittest.mock import patch # noqa: E402 +from hyperloom.common.coerce import to_unix # noqa: E402 + from hyperloom.agents.robustness.sources import local_probe # noqa: E402 from hyperloom.agents.robustness.sources.local_probe import ( # noqa: E402 _is_pid_alive, @@ -1365,3 +1367,244 @@ async def test_fetch_populates_state_and_deps(tmp_path, monkeypatch): data = await LocalProbeSource(cfg).fetch(ctx=None) assert data.local_state_integrity["state_json"]["valid"] is True assert isinstance(data.local_external_deps.get("mounts"), list) + + +# --------------------------------------------------------------------------- +# In-flight task progress (``_read_task_progress``). + + +def _history(*notes: tuple[str, dict]) -> str: + """Render a ``tasks.history`` column from ``(ts, entry)`` pairs.""" + return json.dumps([{"ts": ts, **entry} for ts, entry in notes]) + + +def _tasks_db(path: Path, rows: list[tuple[str, str, str, str]]) -> Path: + """Write a ``tasks`` table holding ``(task_id, kind, state, history)`` rows.""" + conn = sqlite3.connect(str(path)) + conn.execute("CREATE TABLE tasks (task_id TEXT PRIMARY KEY, kind TEXT, state TEXT, history TEXT)") + conn.executemany("INSERT INTO tasks VALUES (?,?,?,?)", rows) + conn.commit() + conn.close() + return path + + +def test_task_progress_reports_the_freshest_heartbeat_per_agent(tmp_path): + """Attribution is what stops one agent's work from vouching for another.""" + db = _tasks_db( + tmp_path / "coordinator.db", + [ + ( + "t1", + "explore", + "running", + _history(("2026-08-13T10:00:00+00:00", {"progress": {"agent": "orchestration"}})), + ), + ( + "t2", + "roofline", + "running", + _history(("2026-08-13T10:42:00+00:00", {"progress": {"agent": "orchestration"}})), + ), + ( + "t3", + "baseline", + "succeeded", + _history(("2026-08-13T11:00:00+00:00", {"progress": {"agent": "orchestration"}})), + ), + ], + ) + out = local_probe._read_task_progress(db) + assert out["running"] == 2 + assert out["by_agent"] == { + "orchestration": { + "last_progress_unix": to_unix("2026-08-13T10:42:00+00:00"), + "task": "roofline", + "oldest_progress_unix": to_unix("2026-08-13T10:00:00+00:00"), + "oldest_task": "explore", + } + } + + +@pytest.mark.parametrize("freshest_first", [False, True]) +def test_task_progress_keeps_the_quietest_unit_a_fresher_sibling_would_hide(tmp_path, freshest_first): + """The dispatcher runs units concurrently; only the freshest used to survive. + + Keeping the newest is what answers "is this agent's work progressing", but + dropping the others left a unit that has not reported in hours with no trace + in the snapshot at all. + + Both visit orders are exercised, because only one of them reaches the branch + that records the quiet end: rows arrive ordered by ``task_id``, so which + unit's note is folded in first is what the parameter chooses. Seeing the + quiet one first makes the freshest note the one that has to overtake it, and + a snapshot built that way tells nothing about the other direction. + """ + quiet = ("baseline", "2026-08-13T08:00:00+00:00") + fresh = ("explore", "2026-08-13T10:42:00+00:00") + first, second = (fresh, quiet) if freshest_first else (quiet, fresh) + db = _tasks_db( + tmp_path / "coordinator.db", + [ + (f"t{index}", kind, "running", _history((ts, {"progress": {"agent": "orchestration"}}))) + for index, (kind, ts) in enumerate((first, second)) + ], + ) + entry = local_probe._read_task_progress(db)["by_agent"]["orchestration"] + assert entry["task"] == "explore" + assert entry["last_progress_unix"] == to_unix("2026-08-13T10:42:00+00:00") + assert entry["oldest_task"] == "baseline" + assert entry["oldest_progress_unix"] == to_unix("2026-08-13T08:00:00+00:00") + + +def test_a_bare_state_transition_is_not_a_heartbeat(tmp_path): + """``updated_at`` also moves when a task merely enters ``running``.""" + db = _tasks_db( + tmp_path / "coordinator.db", + [("t1", "explore", "running", _history(("2026-08-13T10:00:00+00:00", {"to": "running"})))], + ) + out = local_probe._read_task_progress(db) + assert out == {"running": 1} + + +def test_an_unattributed_heartbeat_vouches_for_nobody(tmp_path): + """A note that names no owner must not silence an accusation against anyone.""" + db = _tasks_db( + tmp_path / "coordinator.db", + [("t1", "explore", "running", _history(("2026-08-13T10:00:00+00:00", {"progress": {"unit": "variant"}})))], + ) + assert local_probe._read_task_progress(db) == {"running": 1} + + +def test_task_progress_is_empty_when_nothing_is_running(tmp_path): + db = _tasks_db( + tmp_path / "coordinator.db", + [("t1", "explore", "succeeded", _history(("2026-08-13T10:00:00+00:00", {"progress": {"agent": "x"}})))], + ) + assert local_probe._read_task_progress(db) == {} + + +def test_a_ray_serving_actor_is_a_process_the_probe_can_see(monkeypatch): + """``ray::IDLE`` only names a parked worker; a busy one is renamed.""" + ps_out = ( + " 1 1048576 ray::ServingActor.__call__\n" + " 2 2097152 python -m sglang.launch_server --model x\n" + ) + monkeypatch.setattr( + local_probe.subprocess, + "run", + lambda *a, **k: subprocess.CompletedProcess(a[0], 0, ps_out, ""), + ) + + found = local_probe._sample_processes(local_probe._DEFAULT_PROCESS_PATTERNS) + + assert found is not None + assert [(p["pid"], p["is_server"]) for p in found] == [(1, False), (2, True)] + + +def test_a_sampled_process_carries_the_directory_it_runs_in(monkeypatch): + """On a shared node the cwd is what says which session a process belongs to. + + A pid that is gone by the time ``/proc`` is read — or one owned by another + user — reports no directory rather than a wrong one. + """ + ps_out = ( + f" {os.getpid()} 1048576 python benchmark_serving.py --port 30000\n" + " 999999999 2048 python benchmark_serving.py --port 30001\n" + ) + monkeypatch.setattr( + local_probe.subprocess, + "run", + lambda *a, **k: subprocess.CompletedProcess(a[0], 0, ps_out, ""), + ) + + found = local_probe._sample_processes(("benchmark_serving",)) + + assert found is not None + assert [p["cwd"] for p in found] == [os.getcwd(), ""] + + +def test_the_caller_decides_which_patterns_name_a_server(monkeypatch): + """``is_server`` follows the patterns handed in, not a second copy of the list.""" + ps_out = " 9 1048576 python -m tinyserve.entrypoint --port 8888\n" + monkeypatch.setattr( + local_probe.subprocess, + "run", + lambda *a, **k: subprocess.CompletedProcess(a[0], 0, ps_out, ""), + ) + + found = local_probe._sample_processes(("tinyserve.entrypoint",), ("tinyserve.entrypoint",)) + + assert found is not None + assert [(p["pid"], p["is_server"]) for p in found] == [(9, True)] + + +@pytest.mark.parametrize( + "outcome", + [ + pytest.param(FileNotFoundError("ps"), id="ps-absent"), + pytest.param(subprocess.TimeoutExpired(cmd="ps", timeout=2.0), id="ps-timed-out"), + pytest.param(subprocess.CompletedProcess(["ps"], 1, "", "boom"), id="ps-failed"), + ], +) +def test_a_probe_that_could_not_look_says_so_instead_of_reporting_nothing(monkeypatch, outcome): + """``None`` (could not find out) must stay distinct from ``[]`` (nothing runs).""" + + def _run(*_a, **_k): + if isinstance(outcome, BaseException): + raise outcome + return outcome + + monkeypatch.setattr(local_probe.subprocess, "run", _run) + + assert local_probe._sample_processes(("sglang.srt",)) is None + + +def test_no_pattern_matching_is_an_answer_not_a_failure(monkeypatch): + monkeypatch.setattr( + local_probe.subprocess, + "run", + lambda *a, **k: subprocess.CompletedProcess(a[0], 0, " 1 1024 /bin/bash\n", ""), + ) + + assert local_probe._sample_processes(("sglang.srt",)) == [] + + +@pytest.mark.asyncio +async def test_a_failed_process_probe_is_reported_as_unknown_not_as_an_empty_machine(monkeypatch, tmp_path: Path): + """One sub-probe failing must not become evidence for an unrelated signal.""" + monkeypatch.setattr(local_probe, "_sample_processes", lambda *_a, **_k: None) + cfg = LocalProbeConfig(session_dir=None, disk_mountpoints=(str(tmp_path),)) + + data = await LocalProbeSource(cfg).fetch(ctx=None) + + assert data.local_processes == [] + assert data.local_processes_known is False + + +@pytest.mark.asyncio +async def test_a_process_probe_that_found_nothing_is_still_an_answer(monkeypatch, tmp_path: Path): + monkeypatch.setattr(local_probe, "_sample_processes", lambda *_a, **_k: []) + cfg = LocalProbeConfig(session_dir=None, disk_mountpoints=(str(tmp_path),)) + + data = await LocalProbeSource(cfg).fetch(ctx=None) + + assert data.local_processes == [] + assert data.local_processes_known is True + + +def test_a_pathologically_nested_blob_costs_only_its_own_sub_probe(): + """A blob written by another process must not take down the whole tick.""" + nested = "[" * 20_000 + "]" * 20_000 + + assert local_probe._json_loads_or_none(nested) is None + assert local_probe._latest_progress_note(nested) is None + + +def test_task_progress_survives_a_db_without_the_expected_columns(tmp_path): + """An older or foreign schema degrades to "no evidence", never to an exception.""" + conn = sqlite3.connect(str(tmp_path / "coordinator.db")) + conn.execute("CREATE TABLE tasks (id TEXT PRIMARY KEY, status TEXT)") + conn.commit() + conn.close() + assert local_probe._read_task_progress(tmp_path / "coordinator.db") == {} + assert local_probe._read_task_progress(tmp_path / "missing.db") == {} diff --git a/src/hyperloom/agents/robustness/tests/test_stall.py b/src/hyperloom/agents/robustness/tests/test_stall.py index a50e04febc..10a6f0f164 100644 --- a/src/hyperloom/agents/robustness/tests/test_stall.py +++ b/src/hyperloom/agents/robustness/tests/test_stall.py @@ -58,3 +58,155 @@ def test_evaluate_stall_no_activity_no_symptom() -> None: ctx = ReactorContext(inbox=[], now_unix=10_000.0) data = SourceData(coordinator_events=[]) assert evaluate_stall_signals(ctx, data) == [] + + +def _progress(agent: str, *, unix: float, task: str) -> dict: + """A ``local_task_progress`` snapshot holding one agent's single heartbeat.""" + return { + "running": 1, + "by_agent": { + agent: { + "last_progress_unix": unix, + "task": task, + "oldest_progress_unix": unix, + "oldest_task": task, + } + }, + } + + +def test_work_still_reporting_units_withholds_the_accusation() -> None: + """A phase whose work is one long deterministic task has no turn to emit.""" + ctx = ReactorContext(inbox=[_item("orchestration", ts=9_800.0)], now_unix=10_000.0) + data = SourceData(local_task_progress=_progress("orchestration", unix=9_950.0, task="roofline")) + out = evaluate_stall_signals(ctx, data, config=StallConfig(stall_timeout_s=100.0)) + assert [s.severity for s in out] == [SymptomSeverity.LOW] + assert out[0].evidence["accusation_withheld"] is True + assert out[0].evidence["in_flight_work"] == "roofline" + + +def test_a_withheld_accusation_still_leaves_a_trace() -> None: + """``return []`` made the near-miss unobservable; the operator needs to see it. + + Under its own name: RCA reading ``agent_stall`` off a healthy long phase + cannot tell it apart from an agent that really did go quiet. + """ + ctx = ReactorContext(inbox=[_item("orchestration", ts=9_800.0)], now_unix=10_000.0) + data = SourceData(local_task_progress=_progress("orchestration", unix=9_950.0, task="explore")) + out = evaluate_stall_signals(ctx, data, config=StallConfig(stall_timeout_s=100.0)) + assert out[0].name == "agent_quiet_work_progressing" + assert out[0].subject == {"agent": "orchestration"} + assert "explore" in out[0].summary and "withheld" in out[0].summary + + +def test_a_quiet_sibling_unit_is_named_even_though_a_busy_one_holds_the_accusation() -> None: + """Two units of one agent: one reporting, one quiet for hours. + + One unit reporting still answers the question the signal asks, so the + accusation stays withheld — a Ray-backed round has no liveness callback and + is quiet by design. What the snapshot must not do is lose the quiet one. + """ + ctx = ReactorContext(inbox=[_item("orchestration", ts=9_600.0)], now_unix=10_000.0) + progress = _progress("orchestration", unix=9_950.0, task="explore") + progress["by_agent"]["orchestration"].update(oldest_progress_unix=2_800.0, oldest_task="baseline") + progress["running"] = 2 + out = evaluate_stall_signals( + ctx, + SourceData(local_task_progress=progress), + config=StallConfig(stall_timeout_s=300.0), + ) + assert out[0].evidence["accusation_withheld"] is True + assert out[0].evidence["in_flight_work"] == "explore" + assert out[0].evidence["quiet_in_flight_work"] == "baseline" + assert out[0].evidence["quiet_in_flight_work_idle_seconds"] == 7_200 + + +def test_a_lone_reporting_unit_is_not_reported_as_its_own_quiet_sibling() -> None: + """With one unit the freshest and the quietest note are the same note.""" + ctx = ReactorContext(inbox=[_item("orchestration", ts=9_800.0)], now_unix=10_000.0) + data = SourceData(local_task_progress=_progress("orchestration", unix=9_950.0, task="explore")) + out = evaluate_stall_signals(ctx, data, config=StallConfig(stall_timeout_s=100.0)) + assert out[0].evidence["accusation_withheld"] is True + assert "quiet_in_flight_work" not in out[0].evidence + + +def test_busy_work_of_one_agent_does_not_silence_another() -> None: + """One busy task used to vouch for every agent at once, with no attribution.""" + ctx = ReactorContext( + inbox=[_item("orchestration", ts=9_800.0), _item("critic", ts=9_800.0)], + now_unix=10_000.0, + ) + data = SourceData(local_task_progress=_progress("orchestration", unix=9_950.0, task="explore")) + by_agent = { + s.subject["agent"]: s.severity + for s in evaluate_stall_signals(ctx, data, config=StallConfig(stall_timeout_s=100.0)) + } + assert by_agent["orchestration"] is SymptomSeverity.LOW + assert by_agent["critic"] is SymptomSeverity.MEDIUM + + +def test_an_hour_long_warmup_that_keeps_reporting_is_never_accused() -> None: + """A measured warmup runs 3941s and reports throughout; it is not a stall. + + Any tier above the observation one alerts — MEDIUM routes to + ``alert(medium)`` — so grading this by elapsed silence is the ceiling the + signal was written to drop, one rung lower. + """ + ctx = ReactorContext(inbox=[_item("orchestration", ts=10_000.0)], now_unix=13_941.0) + data = SourceData(local_task_progress=_progress("orchestration", unix=13_900.0, task="warmup")) + out = evaluate_stall_signals( + ctx, + data, + config=StallConfig(stall_timeout_s=300.0, severity_high_after_s=900.0), + ) + assert out[0].evidence["accusation_withheld"] is True + assert out[0].name == "agent_quiet_work_progressing" + assert out[0].severity is SymptomSeverity.LOW + + +def test_the_wait_does_not_grade_a_note_the_evidence_is_still_holding_up() -> None: + """Severity follows the evidence: same fresh note, 400s and 3941s of silence.""" + cfg = StallConfig(stall_timeout_s=300.0, severity_high_after_s=900.0) + data = SourceData(local_task_progress=_progress("orchestration", unix=13_900.0, task="warmup")) + by_idle = { + int(13_941.0 - last_seen): evaluate_stall_signals( + ReactorContext(inbox=[_item("orchestration", ts=last_seen)], now_unix=13_941.0), + data, + config=cfg, + )[0] + for last_seen in (13_541.0, 10_000.0) + } + assert [sym.severity for sym in by_idle.values()] == [SymptomSeverity.LOW, SymptomSeverity.LOW] + assert by_idle[3_941].evidence["withheld_while_work_reports_within_s"] == 300 + + +def test_the_moment_the_work_stops_reporting_the_next_tick_accuses() -> None: + """Freshness, not the clock, is what bounds the suppression.""" + ctx = ReactorContext(inbox=[_item("orchestration", ts=10_000.0)], now_unix=13_941.0) + stale = SourceData(local_task_progress=_progress("orchestration", unix=13_600.0, task="warmup")) + out = evaluate_stall_signals( + ctx, + stale, + config=StallConfig(stall_timeout_s=300.0, severity_high_after_s=900.0), + ) + assert [(s.name, s.severity) for s in out] == [("agent_stall", SymptomSeverity.HIGH)] + assert "accusation_withheld" not in out[0].evidence + + +def test_work_that_has_gone_quiet_too_lets_the_stall_through() -> None: + """Silent agents plus silent work is the case the signal exists for.""" + ctx = ReactorContext(inbox=[_item("orchestration", ts=100.0)], now_unix=10_000.0) + data = SourceData(local_task_progress=_progress("orchestration", unix=1_000.0, task="explore")) + out = evaluate_stall_signals(ctx, data, config=StallConfig(stall_timeout_s=300.0)) + assert [s.name for s in out] == ["agent_stall"] + assert out[0].evidence["in_flight_work"] == "explore" + assert out[0].evidence["in_flight_work_idle_seconds"] == 9_000 + + +def test_running_work_that_never_reported_is_no_evidence_either_way() -> None: + """Absent a heartbeat the signal must fall back to agent silence, not trust.""" + ctx = ReactorContext(inbox=[_item("orchestration", ts=100.0)], now_unix=10_000.0) + data = SourceData(local_task_progress={"running": 1}) + out = evaluate_stall_signals(ctx, data, config=StallConfig(stall_timeout_s=300.0)) + assert [s.name for s in out] == ["agent_stall"] + assert "in_flight_work_idle_seconds" not in out[0].evidence diff --git a/src/hyperloom/inference_optimizer/tests/conftest.py b/src/hyperloom/inference_optimizer/tests/conftest.py index 379166419d..3b0b9d4fcd 100644 --- a/src/hyperloom/inference_optimizer/tests/conftest.py +++ b/src/hyperloom/inference_optimizer/tests/conftest.py @@ -8,6 +8,7 @@ import json import os import subprocess +import time from pathlib import Path import pytest @@ -197,3 +198,138 @@ def _merged() -> tuple[str, ...]: return tuple(merged) monkeypatch.setattr(ip, "resolve_source_file_allowlist", _merged) + + +# --------------------------------------------------------------------------- +# Progress cadence: how long a long-running path may go unreported +# --------------------------------------------------------------------------- + + +# Production seconds per real test second. A heartbeat's honesty is a ratio — +# notes per suppression window — so the whole timescale is compressed and the +# assertions keep speaking in the numbers the window is actually configured +# with (a 60s tick, a 300s window, a benchmark that blocks for ten minutes). +PROGRESS_TIME_SCALE: float = 600.0 + + +class ProgressCadence: + """Records when a path reported progress, on a simulated production clock. + + A long-running path is not judged by whether it reports at all — every one + of them reports on entry — but by whether the gap between two consecutive + notes stays under the window a consumer waits before calling the owning + agent silent. That is the property a dropped liveness callback breaks and + an "it emitted a note" assertion cannot see. + + The clock is simulated rather than read off the wall: it advances only when + the fake child does a chunk of the work it is standing in for + (:func:`chatty_child` calls :meth:`sleep`). Reading real elapsed time and + scaling it by :data:`PROGRESS_TIME_SCALE` instead would multiply every + scheduling delay in the test — a slow import, a loaded runner starving the + event loop — by 600 and charge it to the path under test, which turns a 4x + headroom into a coin flip on a 2-vCPU CI runner. What the simulated clock + gives up is the ability to see a long *non-child* block, which no compressed + wall-clock measurement could tell apart from load anyway. + """ + + def __init__(self, scale: float = PROGRESS_TIME_SCALE) -> None: + """Start the clock at zero. + + Args: + scale (float): Production seconds per real second. + """ + self.scale = scale + self.notes: list[dict] = [] + self.reported_at: list[float] = [] + self._elapsed = 0.0 + + def now(self) -> float: + """Production seconds of simulated work done so far.""" + return self._elapsed + + def sleep(self, simulated_s: float) -> None: + """Charge ``simulated_s`` production seconds, blocking the real time they map to. + + The real block is what gives the heartbeat driver — ticking on the same + compressed timescale — its chance to notice the output and report. + + Args: + simulated_s (float): Production seconds the simulated child spent. + """ + self._elapsed += simulated_s + time.sleep(simulated_s / self.scale) + + def sink(self): + """Return the ambient progress sink to pass to ``progress_scope``.""" + + async def _sink(**note) -> None: + self.notes.append(note) + self.reported_at.append(self.now()) + + return _sink + + def widest_silence(self) -> float: + """Longest unreported stretch, in production seconds. + + Counts the run-up to the first note and the tail after the last one, so + a path that reports only on entry is measured over everything it then + stayed quiet for. + """ + marks = [0.0, *self.reported_at, self.now()] + return max(later - earlier for earlier, later in zip(marks, marks[1:])) + + +@pytest.fixture +def progress_cadence(monkeypatch) -> "ProgressCadence": + """A :class:`ProgressCadence` with the heartbeat tick on the same timescale.""" + from hyperloom.orchestrator.trace import task_progress + + monkeypatch.setattr( + task_progress, + "_OUTPUT_HEARTBEAT_INTERVAL_S", + task_progress._OUTPUT_HEARTBEAT_INTERVAL_S / PROGRESS_TIME_SCALE, + ) + return ProgressCadence() + + +def chatty_child(cadence: ProgressCadence, inner, *, blocks_for_s: float, line_every_s: float): + """Wrap a fake ``run_with_session_kill`` so its child talks while it blocks. + + Args: + cadence (ProgressCadence): Advanced by ``line_every_s`` per line, so it + is the simulated child's progress that moves the clock. + inner: The fake the path already uses; called for the return value once + the simulated child stops talking. + blocks_for_s (float): Production seconds the child runs for. + line_every_s (float): Production seconds between its output lines. + + Returns: + A ``run_with_session_kill`` stand-in that drives ``on_output``. + """ + + def _run(cmd, *args, on_output=None, **kwargs): + for _ in range(int(blocks_for_s / line_every_s)): + cadence.sleep(line_every_s) + if on_output is not None: + on_output() + return inner(cmd, *args, **kwargs) + + return _run + + +def suppression_window_s() -> float: + """The silence past which robustness accuses an agent of stalling.""" + from hyperloom.agents.robustness.signals.stall import StallConfig + + return StallConfig().stall_timeout_s + + +def enable_multi_node(monkeypatch, nodes: int = 2) -> None: + """Put the executors in multi-node mode with a no-op per-round server restart.""" + from hyperloom.orchestrator.actions.executors import _multi_node_server_lifecycle as mnl + + async def _no_restart(*_args, **_kwargs) -> None: + return None + + monkeypatch.setenv("INFERENCE_OPTIMIZER_NODES", str(nodes)) + monkeypatch.setattr(mnl, "restart_server_for_round", _no_restart) diff --git a/src/hyperloom/inference_optimizer/tests/test_baseline_warmup_double_run.py b/src/hyperloom/inference_optimizer/tests/test_baseline_warmup_double_run.py index 79c80d2aed..6215789206 100644 --- a/src/hyperloom/inference_optimizer/tests/test_baseline_warmup_double_run.py +++ b/src/hyperloom/inference_optimizer/tests/test_baseline_warmup_double_run.py @@ -31,6 +31,9 @@ run_grid, ) from hyperloom.orchestrator.state.shared_state import SharedState +from hyperloom.orchestrator.trace.task_progress import progress_scope + +from .conftest import chatty_child, enable_multi_node, suppression_window_s @pytest.fixture(autouse=True) @@ -174,6 +177,158 @@ def test_baseline_discards_cold_first_round_via_lifecycle(tmp_path, monkeypatch) assert captured[0]["benchmark"]["benchmark_script"] == "vllm_mi300x.sh" +def _run_capturing_rounds(executor, ctx, notes): + """Run ``executor`` and record which round notes existed at each launch.""" + at_launch: list[list[str]] = [] + inner, _state = _cold_then_hot_fake_run() + + def fake_run(cmd, *args, **kwargs): + at_launch.append([n["label"] for n in notes]) + return inner(cmd, *args, **kwargs) + + with ( + progress_scope(_sink_into(notes)), + patch( + "hyperloom.orchestrator.actions.executors.baseline.run_with_session_kill", + side_effect=fake_run, + ), + ): + return _run(executor(ctx)), at_launch + + +def _sink_into(notes: list): + """Build an ambient progress sink that appends every note to ``notes``.""" + + async def _sink(**note): + notes.append(note) + + return _sink + + +def test_each_double_run_round_reports_before_it_blocks(tmp_path): + """A round that boots a server and never returns must still have said it started.""" + base = tmp_path / "base.yaml" + _write_yaml(base, framework="vllm") + notes: list[dict] = [] + executor = _executor(base, tmp_path, baseline_double_run=True) + ctx = _make_ctx({"output_dir": str(tmp_path / "ws"), "timeout_sec": 10, "gpu_type": "mi300x"}) + + result, at_launch = _run_capturing_rounds(executor, ctx, notes) + + assert result["status"] == "succeeded" + assert at_launch == [["warmup"], ["warmup", "warmup", "measure"]] + assert [(n["label"], n["status"]) for n in notes] == [ + ("warmup", "started"), + ("warmup", "succeeded"), + ("measure", "started"), + ] + + +def test_the_single_round_path_reports_too(tmp_path): + """The non-double-run baseline used to report nothing at all.""" + base = tmp_path / "base.yaml" + _write_yaml(base, framework="vllm") + notes: list[dict] = [] + executor = _executor(base, tmp_path, baseline_double_run=False) + ctx = _make_ctx({"output_dir": str(tmp_path / "ws"), "timeout_sec": 10, "gpu_type": "mi300x"}) + + result, at_launch = _run_capturing_rounds(executor, ctx, notes) + + assert result["status"] == "succeeded" + assert at_launch == [["single"]] + + +def test_a_round_is_handed_the_liveness_callback_its_heartbeat_needs(tmp_path): + """A round outlives its start report; only child output can extend it.""" + base = tmp_path / "base.yaml" + _write_yaml(base, framework="vllm") + seen: list = [] + inner, _state = _cold_then_hot_fake_run() + + def fake_run(cmd, *args, **kwargs): + seen.append(kwargs.get("on_output")) + return inner(cmd, *args, **kwargs) + + executor = _executor(base, tmp_path, baseline_double_run=False) + ctx = _make_ctx({"output_dir": str(tmp_path / "ws"), "timeout_sec": 10, "gpu_type": "mi300x"}) + with patch( + "hyperloom.orchestrator.actions.executors.baseline.run_with_session_kill", + side_effect=fake_run, + ): + result = _run(executor(ctx)) + + assert result["status"] == "succeeded" + assert [callable(cb) for cb in seen] == [True] + + +def _cadence_ctx(tmp_path) -> SimpleNamespace: + """A single-round baseline context for the cadence tests.""" + return _make_ctx({"output_dir": str(tmp_path / "ws"), "timeout_sec": 10, "gpu_type": "mi300x"}) + + +def test_a_round_keeps_reporting_while_its_benchmark_blocks(tmp_path, progress_cadence): + """A round blocks for the better part of an hour; entry markers cannot cover that.""" + base = tmp_path / "base.yaml" + _write_yaml(base, framework="vllm") + inner, _state = _cold_then_hot_fake_run() + executor = _executor(base, tmp_path, baseline_double_run=False) + + with ( + progress_scope(progress_cadence.sink()), + patch( + "hyperloom.orchestrator.actions.executors.baseline.run_with_session_kill", + side_effect=chatty_child(progress_cadence, inner, blocks_for_s=600.0, line_every_s=30.0), + ), + ): + result = _run(executor(_cadence_ctx(tmp_path))) + + assert result["status"] == "succeeded" + assert progress_cadence.widest_silence() < suppression_window_s() + + +def test_the_multi_node_warmup_pass_keeps_reporting_too(tmp_path, monkeypatch, progress_cadence): + """The discarded MN warmup is a full benchmark pass and blocks just as long.""" + enable_multi_node(monkeypatch) + base = tmp_path / "base.yaml" + _write_yaml(base, framework="vllm") + inner, state = _cold_then_hot_fake_run() + executor = _executor(base, tmp_path, baseline_double_run=False) + + with ( + progress_scope(progress_cadence.sink()), + patch( + "hyperloom.orchestrator.actions.executors.baseline.run_with_session_kill", + side_effect=chatty_child(progress_cadence, inner, blocks_for_s=600.0, line_every_s=30.0), + ), + ): + result = _run(executor(_cadence_ctx(tmp_path))) + + assert result["status"] == "succeeded" + assert state["calls"] == 2 # the discarded warmup pass, then the measured one + assert progress_cadence.widest_silence() < suppression_window_s() + + +def test_a_failing_warmup_round_still_reported_that_it_started(tmp_path): + """The failure path returns early; only the entry report covers it.""" + base = tmp_path / "base.yaml" + _write_yaml(base, framework="vllm") + notes: list[dict] = [] + executor = _executor(base, tmp_path, baseline_double_run=True) + ctx = _make_ctx({"output_dir": str(tmp_path / "ws"), "timeout_sec": 10, "gpu_type": "mi300x"}) + + with ( + progress_scope(_sink_into(notes)), + patch( + "hyperloom.orchestrator.actions.executors.baseline.run_with_session_kill", + side_effect=lambda cmd, *a, **k: subprocess.CompletedProcess(cmd, 1, "", "boom"), + ), + ): + result = _run(executor(ctx)) + + assert result["status"] == "failed" + assert [(n["label"], n["status"]) for n in notes] == [("warmup", "started")] + + def test_deferred_accuracy_skips_eval_when_hot_throughput_regresses( tmp_path, ): diff --git a/src/hyperloom/inference_optimizer/tests/test_grid_runner.py b/src/hyperloom/inference_optimizer/tests/test_grid_runner.py index f7d69b5f08..4b73b955d5 100644 --- a/src/hyperloom/inference_optimizer/tests/test_grid_runner.py +++ b/src/hyperloom/inference_optimizer/tests/test_grid_runner.py @@ -868,6 +868,82 @@ def fake_run(cmd, *args, **kwargs): assert len({rd for _, rd in captured_envs}) == 2 +@pytest.mark.asyncio +async def test_run_grid_benchmark_runs_inside_the_session_that_owns_it(tmp_path): + """Every grid pass runs from the task workspace, so its children are ours. + + A load generator is what tells the robustness reactor that a refused port is + a server that died mid-benchmark rather than the idle gap between two + variants, and it is only believed when it can be tied to this session — + otherwise a co-tenant's client on a shared node vouches for a port it never + touched. The tie is the working directory the whole benchmark subtree + inherits, which the baseline arm already anchors to its own output dir. A + grid variant launched from the system temp directory carries no anchor at + all, so the outage it is running through reads as an idle stretch. + """ + from hyperloom.agents.robustness.role.prompt_inputs import ( + ReactorContext, + SharedStateSnapshot, + ) + from hyperloom.agents.robustness.signals.local_health import ( + LocalHealthConfig, + evaluate_local_health_signals, + ) + from hyperloom.agents.robustness.sources.base import SourceData + + base = tmp_path / "base.yaml" + _write_baseline_yaml_overrides(base) + session_dir = tmp_path / "session" + output_root = session_dir / "runs" / "explore" / "task-1" + captured_cwds: list[str] = [] + + def fake_run(cmd, *args, **kwargs): + out_idx = cmd.index("--output-dir") + slot = Path(cmd[out_idx + 1]) + captured_cwds.append(str(kwargs.get("cwd") or "")) + _fake_workspace(slot) + return subprocess.CompletedProcess(cmd, 0, "ok", "") + + with patch( + "hyperloom.orchestrator.actions.executors._grid_runner.run_with_session_kill", + side_effect=fake_run, + ): + await run_grid( + base_yaml_path=base, + base_extra_args="", + grid=[GridVariant("vA"), GridVariant("vB")], + output_root=output_root, + variant_timeout_sec=5, + ) + + assert captured_cwds + for cwd in captured_cwds: + assert Path(cwd).is_relative_to(session_dir), f"benchmark cwd {cwd} is outside the session {session_dir}" + + # The reactor's own reading of that cwd: a client inheriting it is ours even + # when nothing else on its command line names the session. + data = SourceData( + local_processes=[ + {"pid": 8, "rss_mb": 96.0, "cmd": "python benchmark_serving.py --port 30000", "cwd": captured_cwds[0]}, + ], + local_server_health=[ + {"url": "http://localhost:30000/health", "reachable": False, "status": "error", "error": "connect"}, + ], + ) + ctx = ReactorContext( + tick_index=0, + shared_state=SharedStateSnapshot(session_id=session_dir.name), + inbox=[], + now_unix=1.0, + ) + matched = [ + s + for s in evaluate_local_health_signals(ctx, data, config=LocalHealthConfig(session_dir=session_dir)) + if s.name == "local_server_unreachable" + ] + assert matched and matched[0].evidence["benchmark_client_seen"] is True + + @pytest.mark.asyncio async def test_run_grid_multi_node_removal_matches_materialized_yaml(tmp_path, monkeypatch): base = tmp_path / "base.yaml" diff --git a/src/hyperloom/inference_optimizer/tests/test_grid_runner_behavior_lock.py b/src/hyperloom/inference_optimizer/tests/test_grid_runner_behavior_lock.py index 9a136f90b8..6549e7314e 100644 --- a/src/hyperloom/inference_optimizer/tests/test_grid_runner_behavior_lock.py +++ b/src/hyperloom/inference_optimizer/tests/test_grid_runner_behavior_lock.py @@ -27,6 +27,9 @@ GridVariant, run_grid, ) +from hyperloom.orchestrator.trace.task_progress import progress_scope + +from .conftest import chatty_child, suppression_window_s @pytest.fixture(autouse=True) @@ -105,16 +108,30 @@ def _invalid_rc0_workspace(slot: Path) -> Path: class TestPulseMatrix: - """``_pulse_after_variant`` (delegating to ``_robustness_pulse``) fires on - every failure path EXCEPT the multi-node ``mn_server_restart_failed`` path, - which returns/continues before the pulse call.""" - - def _run_with_pulse_capture(self, *, multi_node, run_side_effect, base, out, restart=None, keep_going=True, grid_n=1): + """``_pulse_after_variant`` (progress note plus ``_robustness_pulse``) fires + on every variant outcome, including the multi-node + ``mn_server_restart_failed`` path that used to leave before reaching it.""" + + def _run_with_pulse_capture( + self, + *, + multi_node, + run_side_effect, + base, + out, + restart=None, + keep_going=True, + grid_n=1, + notes=None, + ): pulse_calls: list = [] async def fake_pulse(**kwargs): pulse_calls.append(kwargs) + async def collect(**note): + notes.append(note) + with ExitStack() as st: st.enter_context(patch.object(mne, "is_multi_node", lambda: multi_node)) st.enter_context(patch.object(gr, "_robustness_pulse", side_effect=fake_pulse)) @@ -124,6 +141,8 @@ async def fake_pulse(**kwargs): side_effect=run_side_effect, ) ) + if notes is not None: + st.enter_context(progress_scope(collect)) if restart is not None: st.enter_context(patch.object(mnsl, "restart_server_for_round", restart)) grid = [GridVariant(name=f"c{i}") for i in range(grid_n)] @@ -141,11 +160,19 @@ async def fake_pulse(**kwargs): ) return results, pulse_calls - def test_mn_server_restart_failed_does_not_pulse(self, tmp_path, monkeypatch): + def test_mn_server_restart_failed_reaches_the_variant_boundary(self, tmp_path, monkeypatch): + """A variant whose remote server never came back still ends its own row. + + This was the one outcome that recorded its result and left, so the row a + stall signal reads stayed at ``started`` for the rest of the session + while the variant was already over — and unlike a reaped round, nothing + else moves the task afterwards to make the stale row harmless. + """ # Warmup must be off so multi-node truly hits the restart path. monkeypatch.setenv("INFERENCE_OPTIMIZER_RUN_GRID_WARMUP", "0") base = tmp_path / "base.yaml" _write_base_yaml(base) + notes: list[dict] = [] async def _restart_fail(**_kwargs): raise mnsl.ServerRestartFailed("server /health did not return 200") @@ -156,15 +183,19 @@ async def _restart_fail(**_kwargs): base=base, out=tmp_path / "out", restart=_restart_fail, + notes=notes, ) assert results[0].status == "failed" assert results[0].error_class == "mn_server_restart_failed" - assert pulse_calls == [], "mn_server_restart_failed must NOT trigger a robustness pulse" + landed = [(n["label"], n["index"], n["status"]) for n in notes if n["unit"] == "variant"] + assert landed == [("c0", 1, "failed")] + assert [call["tick_index"] for call in pulse_calls] == [0] - def test_mn_server_restart_failed_no_pulse_even_for_multiple_variants(self, tmp_path, monkeypatch): + def test_mn_server_restart_failed_reports_each_variant_it_ends(self, tmp_path, monkeypatch): monkeypatch.setenv("INFERENCE_OPTIMIZER_RUN_GRID_WARMUP", "0") base = tmp_path / "base.yaml" _write_base_yaml(base) + notes: list[dict] = [] async def _restart_fail(**_kwargs): raise mnsl.ServerRestartFailed("health probe timed out") @@ -176,12 +207,16 @@ async def _restart_fail(**_kwargs): out=tmp_path / "out", restart=_restart_fail, grid_n=2, + notes=notes, ) assert [r.error_class for r in results] == [ "mn_server_restart_failed", "mn_server_restart_failed", ] - assert pulse_calls == [] + # Each variant is named by its own row, not by the tail of the batch. + landed = [(n["label"], n["index"]) for n in notes if n["unit"] == "variant"] + assert landed == [("c0", 1), ("c1", 2)] + assert [call["tick_index"] for call in pulse_calls] == [0, 1] def test_no_benchmark_workspace_failure_pulses(self, tmp_path, monkeypatch): monkeypatch.setenv("INFERENCE_OPTIMIZER_RUN_GRID_WARMUP", "0") @@ -573,3 +608,170 @@ def test_fallback_replace_mode_drops_inherited_base_args(self, tmp_path): # replace mode drops the inherited base env args. assert "--tp 8" not in out assert "--chunked-prefill 2048" in out + + +# --------------------------------------------------------------------------- +# Per-variant progress heartbeat +# --------------------------------------------------------------------------- + + +class TestVariantHeartbeat: + """A grid that runs for hours must be distinguishable from one that hung.""" + + def _run_capture_progress(self, run_side_effect, base, out, *, grid_n=2, notes=None, sink=None): + notes = [] if notes is None else notes + + async def _collect(**note): + notes.append(note) + + async def _no_pulse(**_kwargs): + return None + + with ( + progress_scope(sink or _collect), + patch.object(gr, "_robustness_pulse", side_effect=_no_pulse), + patch( + "hyperloom.orchestrator.actions.executors._grid_runner.run_with_session_kill", + side_effect=run_side_effect, + ), + ): + results = asyncio.run( + run_grid( + base_yaml_path=base, + base_extra_args="", + grid=[GridVariant(name=f"c{i}") for i in range(grid_n)], + output_root=out, + magpie_python=sys.executable, + variant_timeout_sec=10, + gpu_type="mi300x", + ) + ) + return results, notes + + def test_each_variant_reports_as_it_lands(self, tmp_path, monkeypatch): + monkeypatch.setenv("INFERENCE_OPTIMIZER_RUN_GRID_WARMUP", "0") + base = tmp_path / "base.yaml" + _write_base_yaml(base) + + def _ok(cmd, *a, **k): + out_idx = cmd.index("--output-dir") + _valid_workspace(Path(cmd[out_idx + 1])) + return subprocess.CompletedProcess(cmd, 0, "ok", "") + + results, notes = self._run_capture_progress(_ok, base, tmp_path / "out") + + landed = [n for n in notes if n["unit"] == "variant"] + assert [r.status for r in results] == ["succeeded", "succeeded"] + assert [(n["label"], n["index"], n["total"]) for n in landed] == [("c0", 1, 2), ("c1", 2, 2)] + assert all(n["status"] == "succeeded" for n in landed) + assert landed[0]["output_throughput"] == 800.0 + + def test_the_note_names_the_variant_that_ran_not_the_last_row(self): + """The tail of ``results`` is not always the variant that just reported. + + A stop cause that ends the batch — a session budget spent, an + orchestrator cancel — records the round it stopped and then a not-run row + for every later variant, so the tail becomes the last variant in the grid + while the one that ran is still where it was appended. Taking the note + off the tail renames the round in the only durable per-variant artefact + the run leaves while it is in flight, and the log line one frame away + keeps saying the right thing. + """ + grid = [GridVariant(name=f"c{i}") for i in range(3)] + stopped = gr.VariantResult( + name="c0", + extra_server_args="", + extra_envs={}, + status="skipped", + error_class="orchestrator_cancelled", + ) + never_ran = [ + gr.VariantResult( + name=variant.name, + extra_server_args="", + extra_envs={}, + status="not_run", + ) + for variant in grid[1:] + ] + + assert gr._variant_progress_note(grid, [stopped, *never_ran], 0) == { + "unit": "variant", + "label": "c0", + "index": 1, + "total": 3, + "status": "skipped", + "output_throughput": None, + } + + def test_a_failed_variant_reports_too(self, tmp_path, monkeypatch): + """Progress means "a unit finished", not "a unit worked".""" + monkeypatch.setenv("INFERENCE_OPTIMIZER_RUN_GRID_WARMUP", "0") + base = tmp_path / "base.yaml" + _write_base_yaml(base) + + _, notes = self._run_capture_progress( + lambda cmd, *a, **k: subprocess.CompletedProcess(cmd, 1, "stdout", "boom"), + base, + tmp_path / "out", + grid_n=1, + ) + + assert [n["status"] for n in notes if n["unit"] == "variant"] == ["failed"] + + def test_a_variant_reports_before_it_blocks(self, tmp_path, monkeypatch): + """A first variant that hangs inside the benchmark used to emit nothing at all.""" + monkeypatch.setenv("INFERENCE_OPTIMIZER_RUN_GRID_WARMUP", "0") + base = tmp_path / "base.yaml" + _write_base_yaml(base) + notes: list[dict] = [] + at_launch: list[dict] = [] + + def _capture_then_fail(cmd, *a, **k): + at_launch.extend(notes) + return subprocess.CompletedProcess(cmd, 1, "", "boom") + + self._run_capture_progress( + _capture_then_fail, + base, + tmp_path / "out", + grid_n=1, + notes=notes, + ) + + assert [(n["label"], n["status"]) for n in at_launch] == [ + ("c0:variant", "started"), + ("c0:benchmark", "started"), + ] + + def test_a_variant_keeps_reporting_while_its_benchmark_blocks( + self, + tmp_path, + monkeypatch, + progress_cadence, + ): + """Entry markers alone leave the row silent for a whole variant timeout. + + The benchmark is the longest single block in the session; bounding the + gap between notes is the only assertion a dropped liveness callback + cannot pass. + """ + monkeypatch.setenv("INFERENCE_OPTIMIZER_RUN_GRID_WARMUP", "0") + base = tmp_path / "base.yaml" + _write_base_yaml(base) + + def _ok(cmd, *_a, **_k): + out_idx = cmd.index("--output-dir") + _valid_workspace(Path(cmd[out_idx + 1])) + return subprocess.CompletedProcess(cmd, 0, "ok", "") + + results, _notes = self._run_capture_progress( + chatty_child(progress_cadence, _ok, blocks_for_s=600.0, line_every_s=30.0), + base, + tmp_path / "out", + grid_n=1, + sink=progress_cadence.sink(), + ) + + assert [r.status for r in results] == ["succeeded"] + assert progress_cadence.widest_silence() < suppression_window_s() diff --git a/src/hyperloom/inference_optimizer/tests/test_kill_spawned_server.py b/src/hyperloom/inference_optimizer/tests/test_kill_spawned_server.py index e1ca93a5ac..9a62476410 100644 --- a/src/hyperloom/inference_optimizer/tests/test_kill_spawned_server.py +++ b/src/hyperloom/inference_optimizer/tests/test_kill_spawned_server.py @@ -13,6 +13,7 @@ import signal import subprocess import sys +import threading import time from pathlib import Path @@ -310,6 +311,152 @@ def test_run_with_session_kill_streams_child_output_to_parent(capsys): assert "child-err" in captured.err +def test_run_with_session_kill_reports_each_line_of_child_output(): + """The liveness callback fires while the child runs, once per line it emits.""" + code = "import sys, time\nfor i in range(3):\n print(i, flush=True)\n time.sleep(0.05)\n" + lines: list[float] = [] + + cp = run_with_session_kill( + [sys.executable, "-c", code], + timeout=10, + on_output=lambda: lines.append(time.monotonic()), + ) + + assert cp.returncode == 0 + assert len(lines) == 3 + + +def _appends_until_stopped(path: Path, line: str, stop: threading.Event) -> threading.Thread: + """Start a writer that appends ``line`` to ``path`` until ``stop`` is set. + + Stands in for a writer that is provably not the child under test: the + inference server, which keeps logging while its benchmark client is wedged. + + Args: + path (Path): Log file to append to. + line (str): Line written each round, newline included. + stop (threading.Event): Set by the caller to end the writer. + + Returns: + threading.Thread: The started daemon writer. + """ + + def _write() -> None: + with path.open("a") as fh: + while not stop.wait(0.05): + fh.write(line) + fh.flush() + + writer = threading.Thread(target=_write, daemon=True) + writer.start() + return writer + + +@pytest.mark.parametrize( + ("appended_line", "reports_liveness"), + [ + ('INFO: 127.0.0.1:0 - "GET /health HTTP/1.1" 200 OK\n', False), + ("Avg generation throughput: 0.0 tokens/s, Running: 0 reqs\n", False), + ("Avg generation throughput: 123.4 tokens/s, Running: 8 reqs\n", True), + ], + ids=[ + "an_access_log_line", + "an_idle_engines_throughput_line", + "a_generation_throughput_line", + ], +) +def test_run_with_session_kill_reports_a_silent_child_alive_only_on_real_progress( + tmp_path, + appended_line: str, + reports_liveness: bool, +): + """A log that grew is not the child talking; a log that shows tokens flowing is. + + All three lines are written by the same third party, so growth alone cannot + tell them apart — and one of them is the access line vLLM and sglang emit + per request, including the health probe the robustness agent issues on its + own tick. Counting those as the child's output closes a loop where the + monitor's probe manufactures the evidence that suppresses its own stall + accusation, and turns the heartbeat into the bare timer it documents itself + as never being. A throughput line is different in kind — whoever logged it, + tokens were being produced during the interval — but only if it carries a + rate: some vLLM builds keep printing the stats line at ``0.0 tokens/s`` on + an idle engine, and an engine goes idle precisely when the client that was + driving it wedges, so the zero-rate line is the shape this failure actually + takes in production. + """ + log_path = tmp_path / "server.log" + log_path.write_text("Application startup complete\n") + stop = threading.Event() + writer = _appends_until_stopped(log_path, appended_line, stop) + reported: list[int] = [] + try: + cp = run_with_session_kill( + [sys.executable, "-c", "import time; time.sleep(2)"], + timeout=30, + server_log_path=str(log_path), + detok_stall_grace_sec=30.0, + on_output=lambda: reported.append(1), + ) + finally: + stop.set() + writer.join(timeout=5.0) + + assert cp.returncode == 0 + assert bool(reported) is reports_liveness, ( + f"a child that printed nothing was reported alive {len(reported)} times " + f"by {appended_line.strip()!r}" + ) + + +def test_run_with_session_kill_reports_the_output_a_child_redirected_to_disk(tmp_path): + """A round whose body writes only to ``benchmark_stderr.log`` is still working. + + The scriptable and bypass paths run the customer body with its stderr + redirected there rather than into the parent's pipe, and a long phase of one + — a client that logs its request counter but produces no server throughput + line yet — would otherwise have nothing left to report liveness with. + """ + bench = tmp_path / "benchmark_atom_20260731_085850" + bench.mkdir(parents=True) + (bench / "server.log").write_text("Application startup complete\n") + script = ( + "import sys, time\n" + "f = open(sys.argv[1], 'a')\n" + "for i in range(6):\n" + " time.sleep(0.2)\n" + " f.write('bench: request %d done\\n' % i); f.flush()\n" + ) + reported: list[int] = [] + + cp = run_with_session_kill( + [sys.executable, "-c", script, str(bench / "benchmark_stderr.log")], + timeout=30, + server_log_path=str(tmp_path / "server.log"), + detok_stall_grace_sec=30.0, + on_output=lambda: reported.append(1), + ) + + assert cp.returncode == 0 + assert reported, "a child talking only through its redirected stderr was never reported alive" + + +def test_run_with_session_kill_survives_a_broken_liveness_callback(): + """Reporting is best-effort; a raising callback must not eat child output.""" + + def _boom() -> None: + raise RuntimeError("callback is broken") + + cp = run_with_session_kill( + [sys.executable, "-c", "print('still-captured', flush=True)"], + timeout=10, + on_output=_boom, + ) + + assert cp.returncode == 0 + assert "still-captured" in (cp.stdout or "") + + def test_run_with_session_kill_legacy_timeout_still_raises(): """With ``soft_deadline_sec`` None, a child exceeding the hard ``timeout`` still raises ``TimeoutExpired``.""" with pytest.raises(subprocess.TimeoutExpired): @@ -517,6 +664,12 @@ def test_scan_server_log_increment_detects_ready_and_progress(tmp_path): f.write("HYPERLOOM_EVAL_START\n") off4, ready4, prog4, ev4 = _scan_server_log_increment(str(log_path), off3) assert ev4 is True and ready4 is False and prog4 is False and off4 == log_path.stat().st_size + # An idle engine keeps printing the same line with no rate on it: the value + # is the progress signal, not the marker. + with log_path.open("a") as f: + f.write("Avg generation throughput: 0.0 tokens/s, Running: 0 reqs\n") + off5, _ready5, prog5, _ev5 = _scan_server_log_increment(str(log_path), off4) + assert prog5 is False and off5 == log_path.stat().st_size def test_scan_logs_increment_reads_nested_stderr_for_eval_start(tmp_path): @@ -532,18 +685,48 @@ def test_scan_logs_increment_reads_nested_stderr_for_eval_start(tmp_path): assert not Path(passed).exists() offsets: dict[str, int] = {} - ready, _prog, eval_start, grew = _scan_logs_increment(passed, offsets) - assert ready is True and eval_start is False and grew is True + first = _scan_logs_increment(passed, offsets) + assert first.saw_ready is True and first.saw_eval_start is False and first.grew is True # The marker lands in stderr, never in server.log. with (bench / "benchmark_stderr.log").open("a") as f: f.write("HYPERLOOM_EVAL_START\n") - ready2, _prog2, eval_start2, grew2 = _scan_logs_increment(passed, offsets) - assert eval_start2 is True and ready2 is False and grew2 is True + second = _scan_logs_increment(passed, offsets) + assert second.saw_eval_start is True and second.saw_ready is False and second.grew is True # Nothing new appended: no re-trigger, offsets stay put. - _r3, _p3, eval_start3, grew3 = _scan_logs_increment(passed, offsets) - assert eval_start3 is False and grew3 is False + third = _scan_logs_increment(passed, offsets) + assert third.saw_eval_start is False and third.grew is False + + +def test_scan_logs_increment_tells_the_childs_own_log_from_the_servers(tmp_path): + """Only one of the resolved logs is written by the process being waited on. + + ``server.log`` is the inference server's; ``benchmark_stderr.log`` is where + Magpie redirects the benchmark body's own stderr, so the parent's pipe stays + empty for the whole round and that file is the only place the child's own + output shows up. Liveness that cannot tell them apart either vouches for a + wedged client or leaves a working one unable to report. + """ + bench = tmp_path / "benchmark_atom_20260731_085850" + bench.mkdir(parents=True) + server_log = bench / "server.log" + child_log = bench / "benchmark_stderr.log" + server_log.write_text("Application startup complete\n") + child_log.write_text("running benchmark\n") + passed = str(tmp_path / "server.log") + offsets: dict[str, int] = {} + _scan_logs_increment(passed, offsets) + + with server_log.open("a") as f: + f.write('INFO: 127.0.0.1:0 - "GET /health HTTP/1.1" 200 OK\n') + server_only = _scan_logs_increment(passed, offsets) + assert server_only.grew is True and server_only.child_spoke is False + + with child_log.open("a") as f: + f.write("bench: 128/2000 requests done\n") + child_only = _scan_logs_increment(passed, offsets) + assert child_only.grew is True and child_only.child_spoke is True def test_run_with_session_kill_detok_stall_reaps_ready_but_silent_server(tmp_path): diff --git a/src/hyperloom/inference_optimizer/tests/test_llm_stability_and_subprocess_kill.py b/src/hyperloom/inference_optimizer/tests/test_llm_stability_and_subprocess_kill.py index 7f6299211f..35a17c6cfb 100644 --- a/src/hyperloom/inference_optimizer/tests/test_llm_stability_and_subprocess_kill.py +++ b/src/hyperloom/inference_optimizer/tests/test_llm_stability_and_subprocess_kill.py @@ -9,6 +9,7 @@ import os import signal +import subprocess import time import pytest @@ -17,7 +18,10 @@ DEFAULT_API_TIMEOUT_MS, apply_llm_stability_env, ) -from hyperloom.orchestrator.kernel.request_handlers import _run_subprocess +from hyperloom.orchestrator.kernel.request_handlers import _run_subprocess, _tool_label +from hyperloom.orchestrator.trace.task_progress import progress_scope + +from .conftest import chatty_child, suppression_window_s def test_apply_llm_stability_env_sets_defaults(): @@ -54,6 +58,89 @@ async def test_run_subprocess_returns_output_normally(): assert "hello-stdout" in stdout +_ECHO_UNBUFFERED = ["python3", "-c", "import os; print(os.environ['PYTHONUNBUFFERED'])"] + + +async def test_run_subprocess_unbuffers_its_child(monkeypatch): + """A block-buffered child would look dead between flushes.""" + monkeypatch.delenv("PYTHONUNBUFFERED", raising=False) + rc, stdout, _stderr = await _run_subprocess(_ECHO_UNBUFFERED, timeout_sec=30) + assert rc == 0 + assert stdout.strip() == "1" + + +async def test_run_subprocess_leaves_an_operator_chosen_buffering_alone(monkeypatch): + """Defaulting is help; overriding an explicit setting is a surprise.""" + monkeypatch.setenv("PYTHONUNBUFFERED", "0") + rc, stdout, _stderr = await _run_subprocess(_ECHO_UNBUFFERED, timeout_sec=30) + assert rc == 0 + assert stdout.strip() == "0" + + +async def test_run_subprocess_counts_the_lines_its_child_emits(monkeypatch): + """The heartbeat above it reports only when this tally moves.""" + from hyperloom.orchestrator.actions.executors import _subprocess_kill + + counted: list[int] = [] + real = _subprocess_kill.run_with_session_kill + + def _spy(cmd, **kwargs): + calls = 0 + reported = kwargs.pop("on_output") + + def _count() -> None: + nonlocal calls + calls += 1 + reported() + + try: + return real(cmd, on_output=_count, **kwargs) + finally: + counted.append(calls) + + monkeypatch.setattr(_subprocess_kill, "run_with_session_kill", _spy) + await _run_subprocess( + ["python3", "-c", "print('a')\nprint('b')"], + timeout_sec=30, + ) + + assert counted == [2] + + +async def test_a_kernel_tool_keeps_reporting_while_its_child_works(monkeypatch, progress_cadence): + """A trace analysis blocks for the better part of an hour behind one ``await``. + + Bounding the gap between notes is what a dropped liveness callback fails; + asserting that a callback was passed is not. The child is faked rather than + spawned so the timeline is the simulated one — that a real child's lines + reach ``on_output`` is covered by + ``test_run_subprocess_counts_the_lines_its_child_emits``. + """ + from hyperloom.orchestrator.actions.executors import _subprocess_kill + + def _done(cmd, **_kwargs) -> subprocess.CompletedProcess: + return subprocess.CompletedProcess(cmd, 0, "", "") + + monkeypatch.setattr( + _subprocess_kill, + "run_with_session_kill", + chatty_child(progress_cadence, _done, blocks_for_s=600.0, line_every_s=30.0), + ) + + with progress_scope(progress_cadence.sink()): + rc, _stdout, _stderr = await _run_subprocess(["python3", "-c", "pass"], timeout_sec=30) + + assert rc == 0 + assert progress_cadence.widest_silence() < suppression_window_s() + + +def test_a_tool_is_named_after_the_script_it_runs(): + """``kernel_tool:tracelens_analysis`` is what an operator has to recognize.""" + assert _tool_label(["python3", "/opt/tools/tracelens_analysis.py", "--x"]) == "tracelens_analysis" + assert _tool_label(["ls", "-l"]) == "ls" + assert _tool_label([]) == "subprocess" + + @pytest.mark.skipif(os.name != "posix", reason="process-group kill is POSIX-only") async def test_run_subprocess_kills_grandchild_on_timeout(tmp_path): """A timed-out child that spawned a long-lived grandchild must have the @@ -74,9 +161,7 @@ async def test_run_subprocess_kills_grandchild_on_timeout(tmp_path): timeout_sec=2, ) # A hard timeout surfaces as TimeoutExpired. - import subprocess as _sp - - assert isinstance(excinfo.value, _sp.TimeoutExpired) + assert isinstance(excinfo.value, subprocess.TimeoutExpired) assert pidfile.exists(), "grandchild never recorded its pid" gc_pid = int(pidfile.read_text().strip()) diff --git a/src/hyperloom/inference_optimizer/tests/test_roofline_executor.py b/src/hyperloom/inference_optimizer/tests/test_roofline_executor.py index 523fab66e5..c3d8d2599a 100644 --- a/src/hyperloom/inference_optimizer/tests/test_roofline_executor.py +++ b/src/hyperloom/inference_optimizer/tests/test_roofline_executor.py @@ -10,12 +10,14 @@ import pytest +from hyperloom.orchestrator.actions.executors import roofline as roofline_mod from hyperloom.orchestrator.actions.executors.roofline import ( RooflineExecutor, _extract_trace_path, _failed, make_roofline_executor, ) +from hyperloom.orchestrator.trace.task_progress import progress_scope from hyperloom.orchestrator.state.shared_state import SharedState from hyperloom.orchestrator.loop.sub_agent_runner import RunnerContext from hyperloom.orchestrator.state.task_registry import Task @@ -1074,7 +1076,7 @@ def test_extract_skips_blank_mode_entries(): assert out[0] == "prefilldecode" -def _n26_patch_subs(profile_result, ta_results): +def _n26_patch_subs(profile_result, ta_results, *, on_ta_call=None): ta_calls = {"n": 0, "payloads": []} async def fake_profile(ctx): @@ -1084,6 +1086,8 @@ async def fake_ta(payload, *, session_dir): idx = ta_calls["n"] ta_calls["payloads"].append(dict(payload)) ta_calls["n"] += 1 + if on_ta_call is not None: + on_ta_call() if idx >= len(ta_results): return ta_results[-1] return ta_results[idx] @@ -1396,6 +1400,69 @@ async def test_431_zero_hot_without_degraded_health_no_warning(tmp_path): assert "cuda_graph_attribution_degraded" not in codes +def _progress_sink(notes: list[dict]): + """Build an ambient progress sink appending every note to ``notes``.""" + + async def _sink(**note): + notes.append(note) + + return _sink + + +@pytest.mark.asyncio +async def test_the_n26_retry_reports_before_it_runs(tmp_path): + """The retry re-runs TraceLens; unannounced, it is indistinguishable from a hang.""" + md = tmp_path / "analysis.md" + md.write_text("# Executive Summary\n", encoding="utf-8") + notes: list[dict] = [] + at_call: list[list[str]] = [] + fail = _ta_empty_chunk_failure(requested="mixed", non_empty=["prefilldecode"]) + p1, p2, _calls = _n26_patch_subs( + _profile_ok(), + [fail, _ta_ok(report_md=md)], + on_ta_call=lambda: at_call.append([n["label"] for n in notes]), + ) + + executor = RooflineExecutor(shared_state=_state()) + with p1, p2, progress_scope(_progress_sink(notes)): + result = await executor(_n26_ctx(tmp_path)) + + assert result["status"] == "succeeded" + assert at_call == [ + ["profile", "trace_analyze"], + ["profile", "trace_analyze", "trace_analyze_n26_retry"], + ] + assert all(n["unit"] == "roofline_step" and n["status"] == "started" for n in notes) + + +@pytest.mark.asyncio +async def test_the_compute_bound_reprofile_reports_both_of_its_steps(tmp_path, monkeypatch): + """A second profile and a second analysis, silent end to end until now.""" + md = tmp_path / "analysis.md" + md.write_text("# Executive Summary\n", encoding="utf-8") + host_bound = _ta_ok(report_md=md) + host_bound["trace_health_warnings"] = [ + {"code": "high_gpu_idle_pct", "severity": "warning"}, + ] + compute_bound = _ta_ok(report_md=md) + compute_bound["hot_kernels"] = [{"kernel_id": "k001", "name": "fused_moe", "gpu_pct": 30.0}] + notes: list[dict] = [] + p1, p2, _calls = _n26_patch_subs(_profile_ok(), [host_bound, compute_bound]) + monkeypatch.setattr(roofline_mod, "is_multi_node", lambda: True) + + executor = RooflineExecutor(shared_state=_state()) + with p1, p2, progress_scope(_progress_sink(notes)): + result = await executor(_n26_ctx(tmp_path)) + + assert result["status"] == "succeeded" + assert [n["label"] for n in notes] == [ + "profile", + "trace_analyze", + "profile_compute_bound", + "trace_analyze_compute_bound", + ] + + @pytest.mark.asyncio async def test_431_nonzero_hot_never_flags_degraded(tmp_path): """Even if trace_health says degraded, a non-empty hot_kernels list diff --git a/src/hyperloom/inference_optimizer/tests/test_scriptable_watchdog_gating.py b/src/hyperloom/inference_optimizer/tests/test_scriptable_watchdog_gating.py index 617de1aca8..f983e04748 100644 --- a/src/hyperloom/inference_optimizer/tests/test_scriptable_watchdog_gating.py +++ b/src/hyperloom/inference_optimizer/tests/test_scriptable_watchdog_gating.py @@ -43,7 +43,13 @@ def _count_scans(monkeypatch) -> dict[str, int]: def _scan(server_log_path, offsets): calls["scan"] += 1 - return False, False, False, False + return sk._LogScan( + saw_ready=False, + saw_progress=False, + saw_eval_start=False, + grew=False, + child_spoke=False, + ) def _death(path): calls["death"] += 1 diff --git a/src/hyperloom/inference_optimizer/tests/test_task_progress_heartbeat.py b/src/hyperloom/inference_optimizer/tests/test_task_progress_heartbeat.py new file mode 100644 index 0000000000..dba1b4e917 --- /dev/null +++ b/src/hyperloom/inference_optimizer/tests/test_task_progress_heartbeat.py @@ -0,0 +1,695 @@ +# SPDX-FileCopyrightText: 2026 Advanced Micro Devices, Inc. +# SPDX-License-Identifier: MIT + +"""A long task's heartbeat: reported by the executor, landed on its own row. + +Covers the plumbing that lets a multi-hour composite action say "unit 3 of 12 +is done" — the ambient reporter, the runner scope that binds it, and the +registry write that makes the row look alive. +""" + +from __future__ import annotations + +import asyncio +import logging +import sqlite3 +import threading +import time +from datetime import datetime, timezone +from pathlib import Path +from typing import Any + +import pytest + +from hyperloom.inference_optimizer.session import paths +from hyperloom.orchestrator.bus.resource_lock import ResourceLockManager, SqliteLeaseBackend +from hyperloom.orchestrator.bus.storage.connection import SqliteConnection +from hyperloom.orchestrator.loop.sub_agent_runner import ( + PROGRESS_OWNER_AGENT, + SubAgentRunner, + _format_progress, +) +from hyperloom.orchestrator.state.task_registry import TaskRegistry +from hyperloom.orchestrator.trace import task_progress +from hyperloom.orchestrator.trace.task_progress import ( + OutputActivity, + heartbeat_while_output_flows, + progress_scope, + report_progress, +) + + +def _runner(tmp_path: Path, monkeypatch) -> SubAgentRunner: + monkeypatch.setenv(paths.ENV_USER_DATA_PATH, str(tmp_path)) + sd = paths.make_session_dir() + db = SqliteConnection(tmp_path / "coord.db") + return SubAgentRunner( + ResourceLockManager(SqliteLeaseBackend(db)), + TaskRegistry(db), + session_dir=sd, + policy=None, + ) + + +def _progress_notes(task) -> list[dict]: + return [row["progress"] for row in task.history if "progress" in row] + + +def _iso_ago(seconds: float) -> str: + """Build the ISO timestamp a task that started ``seconds`` ago would carry.""" + return datetime.fromtimestamp(time.time() - seconds, tz=timezone.utc).isoformat() + + +# Bound on every wait paced by the heartbeat driver, so a regression that stops +# the driver fails in seconds instead of hanging the suite. +_HEARTBEAT_BACKSTOP_S = 10.0 + +# Bound on every wait for a worker thread the rollback tests hold a lock in, so +# a regression that never frees it fails instead of hanging the suite. +_ROLLBACK_BACKSTOP_S = 5.0 + +# How long a cancelled write is given to come back before it is called early. +# A write that abandoned its rollback returns on the next loop turn, so this is +# orders of magnitude more than it needs and the assertion still means "it +# returned while the rollback was queued" rather than "the loop was busy". +_RETURNED_EARLY_WINDOW_S = 0.2 + + +async def _await_notes(notes: list[dict], label: str, count: int, *, interval_s: float) -> None: + """Wait until the driver stamping ``label`` has reported ``count`` notes. + + Paces a test on the driver's own reports rather than on elapsed time. A tick + is a timer, so "another interval went by" cannot be asserted from a ``sleep`` + on a runner that may starve the loop for longer than the interval itself; a + note is proof the driver got that tick. A driver that is meant to be silent + is paced the same way, by the notes of a second one kept deliberately noisy. + + Args: + notes (list[dict]): The sink's accumulated notes. + label (str): The ``label`` field the driver of interest stamps. + count (int): Notes bearing ``label`` to wait for. + interval_s (float): The driver's tick interval, used as the poll period. + """ + + async def _reached() -> None: + while sum(1 for note in notes if note.get("label") == label) < count: + await asyncio.sleep(interval_s) + + await asyncio.wait_for(_reached(), timeout=_HEARTBEAT_BACKSTOP_S) + + +async def _await_cancelled(task: asyncio.Task) -> None: + """Await a cancelled task so the caller can inspect leftover state. + + Args: + task (asyncio.Task): Already cancelled; must finish as cancelled. + """ + try: + await task + pytest.fail(f"expected CancelledError; the task ended as {task.exception()!r}") + except asyncio.CancelledError: + # Expected: cancel is the success path; the caller asserts leftover state. + return + + +@pytest.mark.asyncio +async def test_a_task_that_reports_units_leaves_a_trail_on_its_own_row(tmp_path, monkeypatch): + """The heartbeat is what separates a working long task from a hung one.""" + sub = _runner(tmp_path, monkeypatch) + + async def _grid(_ctx) -> dict: + for i in (1, 2, 3): + await report_progress(unit="variant", label=f"v{i}", index=i, total=3) + return {"status": "ok"} + + sub.register_executor("explore", _grid) + task = await sub.tasks.create(kind="explore", params={}, idempotency_key="grid-0") + res = await sub.run_task(task) + + assert res.state == "succeeded" + done = await sub.tasks.get(task.task_id) + assert [note["label"] for note in _progress_notes(done)] == ["v1", "v2", "v3"] + + +@pytest.mark.asyncio +async def test_every_note_names_the_agent_it_vouches_for(tmp_path, monkeypatch): + """Without an owner the heartbeat would excuse whichever agent is quiet.""" + sub = _runner(tmp_path, monkeypatch) + + async def _grid(_ctx) -> dict: + await report_progress(unit="variant", label="v1") + return {"status": "ok"} + + sub.register_executor("explore", _grid) + task = await sub.tasks.create(kind="explore", params={}, idempotency_key="grid-owner") + await sub.run_task(task) + + done = await sub.tasks.get(task.task_id) + assert [note["agent"] for note in _progress_notes(done)] == [PROGRESS_OWNER_AGENT] + + +@pytest.mark.asyncio +async def test_a_heartbeat_leaves_the_running_mark_where_it_was(tmp_path, monkeypatch): + """``updated_at`` says when the task started running, not when it last spoke. + + The lease watchdog, the ``extend_lease`` budget math and the in-flight + projection all measure elapsed runtime from it. + """ + sub = _runner(tmp_path, monkeypatch) + started_iso = _iso_ago(3600) + seen: dict[str, Any] = {} + + async def _slow(ctx) -> dict: + await sub.tasks.db.execute( + "UPDATE tasks SET updated_at=? WHERE task_id=?", + (started_iso, ctx.task.task_id), + ) + await report_progress(unit="baseline_round", label="warmup") + beating = await sub.tasks.get(ctx.task.task_id) + seen["updated_at"] = beating.updated_at + seen["notes"] = len(_progress_notes(beating)) + assert beating.state == "running" + return {"status": "ok"} + + sub.register_executor("baseline", _slow) + task = await sub.tasks.create(kind="baseline", params={}, idempotency_key="baseline-0") + await sub.run_task(task) + + assert seen["updated_at"] == started_iso + assert seen["notes"] == 1 + + +@pytest.mark.asyncio +async def test_a_task_that_heartbeats_all_along_is_still_reclaimed_at_its_lease(tmp_path, monkeypatch): + """The R6 watchdog is a runtime budget, not an inactivity timeout. + + A heartbeat that reset its clock would make the backstop unreachable for + exactly the long-running rows that hold lanes and read as live work. + """ + sub = _runner(tmp_path, monkeypatch) + task = await sub.tasks.create( + kind="roofline", + params={}, + idempotency_key="roofline-lease", + lease_ttl_sec=2700, + ) + await sub.tasks.transition(task.task_id, "running") + await sub.tasks.db.execute( + "UPDATE tasks SET updated_at=? WHERE task_id=?", + (_iso_ago(3106), task.task_id), + ) + for unit in range(3): + await sub.tasks.record_progress(task.task_id, {"unit": "roofline_step", "index": unit}) + + reclaimed = await sub.tasks.reclaim_expired_running(reason="test_watchdog") + + assert reclaimed == [task.task_id] + assert (await sub.tasks.get(task.task_id)).state == "failed" + + +@pytest.mark.asyncio +async def test_a_heartbeat_never_fails_the_work_it_reports_on(tmp_path, monkeypatch): + """A row reaped underneath a running executor must not turn into a task failure.""" + sub = _runner(tmp_path, monkeypatch) + + async def _reported_after_deletion(ctx) -> dict: + async with sub.tasks.db.transaction() as cur: + cur.execute("DELETE FROM tasks WHERE task_id=?", (ctx.task.task_id,)) + await report_progress(unit="variant", label="orphan") + return {"status": "ok"} + + sub.register_executor("explore", _reported_after_deletion) + task = await sub.tasks.create(kind="explore", params={}, idempotency_key="grid-1") + res = await sub.run_task(task) + + assert res.state == "succeeded" + + +@pytest.mark.asyncio +async def test_a_sink_that_raises_is_swallowed_not_propagated(tmp_path, monkeypatch): + """The reporter is an observability path; it owns its own failures.""" + + async def _broken(**_note) -> None: + raise RuntimeError("sink is down") + + with progress_scope(_broken): + await report_progress(unit="variant") + + +@pytest.mark.asyncio +async def test_progress_reported_outside_a_task_is_a_no_op() -> None: + """Executors call the reporter unconditionally, including from unit tests.""" + await report_progress(unit="variant", label="unscoped") + + +@pytest.mark.asyncio +async def test_the_scope_does_not_outlive_the_task_that_opened_it(tmp_path, monkeypatch): + """Otherwise one task's units would land on another task's row.""" + sub = _runner(tmp_path, monkeypatch) + + async def _noop(_ctx) -> dict: + return {"status": "ok"} + + sub.register_executor("explore", _noop) + task = await sub.tasks.create(kind="explore", params={}, idempotency_key="grid-2") + await sub.run_task(task) + + await report_progress(unit="variant", label="after") + done = await sub.tasks.get(task.task_id) + assert _progress_notes(done) == [] + + +@pytest.mark.asyncio +async def test_a_long_step_keeps_reporting_while_its_child_talks() -> None: + """The 55-minute analysis has one await and no completion report to lean on.""" + notes: list[dict] = [] + + async def _sink(**note) -> None: + notes.append(note) + + interval = 0.02 + with progress_scope(_sink): + async with heartbeat_while_output_flows( + unit="kernel_tool", + label="trace_analyze", + interval_s=interval, + ) as activity: + for line in range(1, 4): + activity.note() + await _await_notes(notes, "trace_analyze", line, interval_s=interval) + + assert len(notes) == 3 + assert {n["label"] for n in notes} == {"trace_analyze"} + assert all(n["status"] == "running" for n in notes) + assert [n["output_lines"] for n in notes] == sorted(n["output_lines"] for n in notes) + + +@pytest.mark.asyncio +async def test_a_step_whose_child_went_quiet_is_allowed_to_go_stale() -> None: + """A timer would keep vouching for a wedged process; that is the failure to catch. + + A second heartbeat, kept noisy, paces the quiet stretch: each of its notes is + an interval in which the first driver also had a tick and nothing new to + report. Sleeping for a multiple of the interval instead would assume the loop + was scheduled during it, which is the assumption a 2-vCPU runner breaks. + """ + notes: list[dict] = [] + + async def _sink(**note) -> None: + notes.append(note) + + interval = 0.02 + with progress_scope(_sink): + async with heartbeat_while_output_flows( + unit="kernel_tool", + label="trace_analyze", + interval_s=interval, + ) as activity: + activity.note() + await _await_notes(notes, "trace_analyze", 1, interval_s=interval) + async with heartbeat_while_output_flows(label="pacer", interval_s=interval) as pacer: + for tick in range(1, 4): + pacer.note() + await _await_notes(notes, "pacer", tick, interval_s=interval) + + assert [note["label"] for note in notes] == ["trace_analyze", "pacer", "pacer", "pacer"] + + +@pytest.mark.asyncio +async def test_the_driver_stops_with_the_step_it_watches() -> None: + """A leaked driver task would report a step that already returned. + + The silence after the step returns is paced by a second heartbeat's notes, so + the window a leaked driver would have reported in is three intervals it + actually got rather than three the test hoped had gone by. + """ + notes: list[dict] = [] + + async def _sink(**note) -> None: + notes.append(note) + + interval = 0.02 + with progress_scope(_sink): + async with heartbeat_while_output_flows(label="t", interval_s=interval) as activity: + activity.note() + await _await_notes(notes, "t", 1, interval_s=interval) + activity.note() # the step it belonged to is over; nothing may report this + async with heartbeat_while_output_flows(label="pacer", interval_s=interval) as pacer: + for tick in range(1, 4): + pacer.note() + await _await_notes(notes, "pacer", tick, interval_s=interval) + + assert [note["label"] for note in notes] == ["t", "pacer", "pacer", "pacer"] + + +@pytest.mark.asyncio +async def test_teardown_lets_the_note_in_flight_finish_before_giving_up() -> None: + """A note is a ``tasks`` write; cancelling one mid-write wedges the connection. + + Teardown starts on the sink's own signal that it is mid-write rather than + after a sleep long enough to hope one began, so the note is always in flight + when the grace window opens. + """ + events: list[str] = [] + writing = asyncio.Event() + + async def _slow_sink(**_note) -> None: + events.append("begin") + writing.set() + try: + await asyncio.sleep(0.05) + except asyncio.CancelledError: + events.append("cancelled") + raise + events.append("end") + + interval = 0.01 + with progress_scope(_slow_sink): + async with heartbeat_while_output_flows(label="t", interval_s=interval) as activity: + activity.note() + await asyncio.wait_for(writing.wait(), timeout=_HEARTBEAT_BACKSTOP_S) + + assert events == ["begin", "end"] + + +@pytest.mark.asyncio +async def test_a_wedged_sink_cannot_hold_the_step_open(monkeypatch) -> None: + """Cooperative shutdown is bounded: past the grace the driver is cancelled. + + The step is bounded here because the sink is not: a teardown that waited on + the sink instead of cancelling it would sit inside the ``async with`` for the + hour the sink sleeps, and with no timeout plugin in this suite that blocks + until the CI job is killed rather than failing. Which is the failure mode the + grace window exists to prevent, so the test for it may not have it either. + """ + monkeypatch.setattr(task_progress, "_DRIVER_STOP_GRACE_S", 0.05) + events: list[str] = [] + entered = asyncio.Event() + + async def _wedged_sink(**_note) -> None: + entered.set() + try: + await asyncio.sleep(3600) + except asyncio.CancelledError: + events.append("cancelled") + raise + + interval = 0.01 + + async def _step() -> None: + with progress_scope(_wedged_sink): + async with heartbeat_while_output_flows(label="t", interval_s=interval) as activity: + activity.note() + await entered.wait() + + await asyncio.wait_for(_step(), timeout=_HEARTBEAT_BACKSTOP_S) + + await asyncio.sleep(0) + # The cancellation is the whole claim: a teardown that waited on the sink + # instead would still be inside the ``async with``, not here. + assert events == ["cancelled"] + + +@pytest.mark.asyncio +async def test_a_cancel_landing_in_teardown_still_cancels_the_step() -> None: + """Suppressing the driver's cancellation used to absorb the caller's too.""" + entered = asyncio.Event() + + async def _slow_to_die_sink(**_note) -> None: + entered.set() + try: + await asyncio.sleep(3600) + except asyncio.CancelledError: + await asyncio.sleep(0.05) + raise + + async def _step() -> str: + with progress_scope(_slow_to_die_sink): + async with heartbeat_while_output_flows(label="t", interval_s=0.01) as activity: + activity.note() + await entered.wait() + return "finished" + + step = asyncio.create_task(_step()) + await entered.wait() + await asyncio.sleep(0.02) # the body has returned; teardown is waiting + step.cancel() + await _await_cancelled(step) + + +@pytest.mark.asyncio +async def test_a_cancelled_progress_write_leaves_the_connection_usable(tmp_path, monkeypatch): + """A cancel mid-``BEGIN IMMEDIATE`` must not wedge the shared connection. + + Every heartbeat around a long subprocess ends in a cancel-or-stop of a + coroutine that may be inside a registry write, so a transaction left open + here fails every later write in the session with "cannot start a + transaction within a transaction". + """ + sub = _runner(tmp_path, monkeypatch) + task = await sub.tasks.create(kind="explore", params={}, idempotency_key="wedge") + await sub.tasks.transition(task.task_id, "running") + + begun = threading.Event() + real_begin = sub.tasks.db._begin_immediate + + def _slow_begin(): + """Widen the window between ``BEGIN IMMEDIATE`` and the caller resuming.""" + cur = real_begin() + if not begun.is_set(): + begun.set() + time.sleep(0.2) + return cur + + monkeypatch.setattr(sub.tasks.db, "_begin_immediate", _slow_begin) + writing = asyncio.create_task(sub.tasks.record_progress(task.task_id, {"unit": "variant"})) + await asyncio.to_thread(begun.wait, 5.0) + writing.cancel() + await _await_cancelled(writing) + + assert not sub.tasks.db.raw.in_transaction + await sub.tasks.record_progress(task.task_id, {"unit": "variant", "label": "after"}) + assert [note.get("label") for note in _progress_notes(await sub.tasks.get(task.task_id))] == ["after"] + + +@pytest.mark.asyncio +async def test_the_loop_keeps_running_while_a_cancelled_write_rolls_back(tmp_path, monkeypatch): + """The rollback waits on a lock a worker thread holds; the loop must not wait with it. + + In production that worker is the abandoned ``BEGIN IMMEDIATE``, blocked for + up to ``busy_timeout`` while another writer holds the database and holding + ``_sync_lock`` the whole time. Rolling back from the except handler on the + event-loop thread queues behind it and stops the entire orchestrator — + including the shutdown path that issued the cancel, which is exactly when + this fires. + + The worker here holds the lock until the loop proves it is still ticking + rather than for a wall-clock interval, so the assertion is a count on a + loaded machine as much as an idle one. + """ + sub = _runner(tmp_path, monkeypatch) + task = await sub.tasks.create(kind="explore", params={}, idempotency_key="loop-liveness") + await sub.tasks.transition(task.task_id, "running") + + tick_s = 0.01 + ticks_required = 5 + db = sub.tasks.db + holding = threading.Event() + cancelled = threading.Event() + loop_alive = threading.Event() + real_begin = db._begin_immediate + + def _begin_and_keep_the_lock(): + """Begin, then hold ``_sync_lock`` past the cancel like a contended BEGIN does.""" + with db._sync_lock: + cur = real_begin() + holding.set() + loop_alive.wait(_ROLLBACK_BACKSTOP_S) + return cur + + monkeypatch.setattr(db, "_begin_immediate", _begin_and_keep_the_lock) + + async def _tick_until_the_rollback_may_proceed() -> None: + """Count loop ticks once the cancel has landed, then free the worker's lock.""" + ticks = 0 + while ticks < ticks_required: + await asyncio.sleep(tick_s) + if cancelled.is_set(): + ticks += 1 + loop_alive.set() + + ticker = asyncio.create_task(_tick_until_the_rollback_may_proceed()) + writing = asyncio.create_task(sub.tasks.record_progress(task.task_id, {"unit": "variant"})) + await asyncio.to_thread(holding.wait, _ROLLBACK_BACKSTOP_S) + writing.cancel() + cancelled.set() + await _await_cancelled(writing) + ticker.cancel() + await asyncio.gather(ticker, return_exceptions=True) + + assert loop_alive.is_set(), "the event loop stopped while the rollback waited for the worker's lock" + # And the rollback is awaited, not fired and forgotten: ``transaction()`` + # cannot return while the connection is still inside one, or the next + # ``BEGIN IMMEDIATE`` would fail the way it did before the rollback existed. + assert not db.raw.in_transaction + await sub.tasks.record_progress(task.task_id, {"unit": "variant", "label": "after"}) + + +def _rollback_gated_on(db, entered: threading.Event, release: threading.Event, monkeypatch) -> None: + """Make ``db``'s rollback announce itself and then wait for ``release``. + + Stands in for the rollback queued behind a worker thread that still holds + ``_sync_lock``, which is the state a cancelled ``BEGIN IMMEDIATE`` leaves and + the only state in which anything can land on the rollback's own wait. + + Args: + db (SqliteConnection): Connection whose ``_rollback`` is gated. + entered (threading.Event): Set once the rollback is in flight. + release (threading.Event): Awaited before the rollback actually runs. + monkeypatch: The active monkeypatch fixture. + """ + real_rollback = db._rollback + + def _gated_rollback() -> None: + entered.set() + release.wait(_ROLLBACK_BACKSTOP_S) + real_rollback() + + monkeypatch.setattr(db, "_rollback", _gated_rollback) + + +@pytest.mark.asyncio +async def test_a_cancel_landing_on_the_rollback_does_not_release_the_lock_early(tmp_path, monkeypatch): + """The second cancel must not abandon the wait the first one created. + + Abandoning it releases ``_async_lock`` while the rollback is still queued + behind the worker the first cancel walked away from — fire and forget with + the lock already gone, which is the behaviour this rollback was moved off the + loop to avoid rather than to adopt. The next writer then finds the + connection still inside a transaction and every write in the session fails + with "cannot start a transaction within a transaction". + + Both cancels are ones production delivers: the stop that cancels an + in-flight action, and the escalation that follows when shutdown is not + making progress. + """ + sub = _runner(tmp_path, monkeypatch) + task = await sub.tasks.create(kind="explore", params={}, idempotency_key="second-cancel") + await sub.tasks.transition(task.task_id, "running") + + db = sub.tasks.db + holding = threading.Event() + release = threading.Event() + rolling_back = threading.Event() + real_begin = db._begin_immediate + + def _begin_and_keep_the_lock(): + """Hold ``_sync_lock`` past the cancel, like a contended BEGIN IMMEDIATE.""" + with db._sync_lock: + cur = real_begin() + holding.set() + release.wait(_ROLLBACK_BACKSTOP_S) + return cur + + monkeypatch.setattr(db, "_begin_immediate", _begin_and_keep_the_lock) + _rollback_gated_on(db, rolling_back, release, monkeypatch) + + writing = asyncio.create_task(sub.tasks.record_progress(task.task_id, {"unit": "variant"})) + await asyncio.to_thread(holding.wait, _ROLLBACK_BACKSTOP_S) + writing.cancel() + await asyncio.to_thread(rolling_back.wait, _ROLLBACK_BACKSTOP_S) + writing.cancel() + await asyncio.wait({writing}, timeout=_RETURNED_EARLY_WINDOW_S) + + assert not writing.done(), "the write returned with its rollback still queued behind the abandoned worker" + release.set() + await _await_cancelled(writing) + + assert not db.raw.in_transaction + assert not db._async_lock.locked() + await sub.tasks.record_progress(task.task_id, {"unit": "variant", "label": "after"}) + + +@pytest.mark.asyncio +async def test_a_cancel_arriving_while_the_rollback_runs_is_not_lost(tmp_path, monkeypatch): + """One cancel is enough, and it must not be swallowed by the rollback handler. + + ``record_progress``'s body raises on its own — a ``BEGIN IMMEDIATE`` that + outlasted ``busy_timeout``, a ``history`` column that will not parse — so a + single cancel is all it takes to land on the rollback's wait. Swallowed, it + leaves the caller with the body's exception, which ``report_progress`` drops: + the action then runs on as though it had never been cancelled while the + dispatcher's ``gather`` waits for it to stop. + """ + sub = _runner(tmp_path, monkeypatch) + task = await sub.tasks.create(kind="explore", params={}, idempotency_key="lost-cancel") + await sub.tasks.transition(task.task_id, "running") + await sub.tasks.db.execute( + "UPDATE tasks SET history=? WHERE task_id=?", + ("{ this will not parse", task.task_id), + ) + + db = sub.tasks.db + rolling_back = threading.Event() + release = threading.Event() + _rollback_gated_on(db, rolling_back, release, monkeypatch) + + writing = asyncio.create_task(sub.tasks.record_progress(task.task_id, {"unit": "variant"})) + await asyncio.to_thread(rolling_back.wait, _ROLLBACK_BACKSTOP_S) + assert writing.cancel() + release.set() + await asyncio.wait({writing}) + + assert writing.cancelled(), f"the cancel was lost; the write ended as {writing.exception()!r}" + assert not db.raw.in_transaction + + +@pytest.mark.asyncio +async def test_a_rollback_the_connection_cannot_do_is_logged_not_raised(tmp_path, monkeypatch, caplog): + """A rollback that fails outright must not become the exception the caller sees. + + Teardown closes the connection while writes are still unwinding, and a + rollback that lands after it raises ``ProgrammingError``. Losing the body's + own exception behind that would hide why the write failed in the first + place. + """ + db = SqliteConnection(tmp_path / "coord.db") + + def _rollback_on_a_closed_connection() -> None: + raise sqlite3.ProgrammingError("Cannot operate on a closed database.") + + monkeypatch.setattr(db, "_rollback", _rollback_on_a_closed_connection) + caught = False + try: + with caplog.at_level(logging.WARNING): + try: + async with db.transaction(): + raise ValueError("body failed") + except ValueError: + caught = True + assert caught, "the body's exception was lost behind the rollback" + assert "rollback after a failed transaction did not complete" in caplog.text + assert "Cannot operate on a closed database" in caplog.text + finally: + db.close() + + +def test_the_tally_is_safe_to_advance_from_reader_threads() -> None: + """The pump threads write it; the event loop reads it.""" + activity = OutputActivity() + threads = [threading.Thread(target=lambda: [activity.note() for _ in range(200)]) for _ in range(4)] + for thread in threads: + thread.start() + for thread in threads: + thread.join() + + assert activity.count() == 800 + + +def test_a_counter_reads_as_one_field_in_the_log_line() -> None: + """``3/12`` is what an operator scans for; two separate keys are not.""" + line = _format_progress({"unit": "variant", "label": "v3", "index": 3, "total": 12, "status": None}) + assert "progress=3/12" in line + assert "status" not in line + + assert "progress=2" in _format_progress({"index": 2}) diff --git a/src/hyperloom/inference_optimizer/tests/test_task_registry_history_bound.py b/src/hyperloom/inference_optimizer/tests/test_task_registry_history_bound.py new file mode 100644 index 0000000000..67c5dcbf31 --- /dev/null +++ b/src/hyperloom/inference_optimizer/tests/test_task_registry_history_bound.py @@ -0,0 +1,117 @@ +# SPDX-FileCopyrightText: 2026 Advanced Micro Devices, Inc. +# SPDX-License-Identifier: MIT + +"""What a long task's progress trail is allowed to cost its own row. + +Every note rewrites the whole ``history`` blob inside a transaction on the one +shared connection, so an unbounded trail charges a session for its own length — +and the sessions this heartbeat exists for are the long ones. These tests pin +the bound and the thing the bound must not break: the state transitions +consumers read positionally. +""" + +from __future__ import annotations + +import json + +import pytest + +from hyperloom.orchestrator.bus.storage import SqliteConnection +from hyperloom.orchestrator.state.task_registry import ( + _MAX_PROGRESS_NOTES, + TaskRegistry, +) + + +async def _running_task(tmp_path, name: str) -> tuple[TaskRegistry, str]: + """Create a registry holding one task already in ``running``.""" + registry = TaskRegistry(SqliteConnection(tmp_path / f"{name}.db")) + task = await registry.create(kind="roofline", params={}, idempotency_key=name) + await registry.transition(task.task_id, "running") + return registry, task.task_id + + +async def _report(registry: TaskRegistry, task_id: str, indices: range) -> None: + """Report one progress note per index, shaped like the heartbeat driver's.""" + for index in indices: + await registry.record_progress( + task_id, + {"unit": "roofline_step", "index": index, "agent": "orchestration", "label": f"step-{index}"}, + ) + + +async def _history_bytes(registry: TaskRegistry, task_id: str) -> int: + """Size of the blob ``record_progress`` rewrites on every note.""" + row = await registry.db.fetchone("SELECT history FROM tasks WHERE task_id=?", (task_id,)) + return len(row["history"]) + + +def _notes(history: list[dict]) -> list[dict]: + return [entry["progress"] for entry in history if "progress" in entry] + + +@pytest.mark.asyncio +async def test_the_progress_trail_stops_growing_at_the_bound(tmp_path): + """A 12-hour session at the 60s tick would otherwise leave a 160 KB blob. + + The newest notes are the ones a consumer reads, so the oldest are dropped, + and once the bound is reached each further note costs what one note costs + rather than what the session's whole trail costs. + """ + over = _MAX_PROGRESS_NOTES + 40 + registry, task_id = await _running_task(tmp_path, "bounded") + try: + await _report(registry, task_id, range(over)) + at_bound = await _history_bytes(registry, task_id) + await _report(registry, task_id, range(over, over + 40)) + later = await _history_bytes(registry, task_id) + + history = (await registry.get(task_id)).history + finally: + registry.db.close() + + notes = _notes(history) + assert len(notes) == _MAX_PROGRESS_NOTES + assert notes[0]["index"] == over + 40 - _MAX_PROGRESS_NOTES + assert notes[-1]["index"] == over + 39 + # 40 more notes of this shape add ~4 KB to an uncapped blob; at the bound + # they only shift which ones are held, so the size is steady. + assert later - at_bound < 512 + assert at_bound < 32 * 1024 + + +@pytest.mark.asyncio +async def test_no_number_of_notes_can_bury_a_state_transition(tmp_path): + """Consumers read transitions positionally; dropping one would make them lie. + + The dispatcher's policy-denied lookup scans for the newest + ``queued -> cancelled`` entry, and the enablement path reads a failure class + off the last one, so the cap must only ever retire progress notes. + """ + registry, task_id = await _running_task(tmp_path, "transitions") + try: + await _report(registry, task_id, range(_MAX_PROGRESS_NOTES + 5)) + await registry.transition(task_id, "failed", evidence={"failure_class": "timeout"}) + + history = (await registry.get(task_id)).history + finally: + registry.db.close() + + transitions = [(entry.get("from"), entry.get("to")) for entry in history if "to" in entry] + assert transitions == [("queued", "running"), ("running", "failed")] + assert history[-1]["evidence"]["failure_class"] == "timeout" + + +@pytest.mark.asyncio +async def test_a_note_lands_whole_and_readable_under_the_bound(tmp_path): + """The trail is still a trail: the retained notes keep their own timestamps.""" + registry, task_id = await _running_task(tmp_path, "readable") + try: + await _report(registry, task_id, range(3)) + row = await registry.db.fetchone("SELECT history FROM tasks WHERE task_id=?", (task_id,)) + finally: + registry.db.close() + + notes = [entry for entry in json.loads(row["history"]) if "progress" in entry] + assert [entry["progress"]["label"] for entry in notes] == ["step-0", "step-1", "step-2"] + assert all(entry["ts"] for entry in notes) diff --git a/src/hyperloom/orchestrator/actions/executors/_grid_base.py b/src/hyperloom/orchestrator/actions/executors/_grid_base.py index ae2aba0fbb..63d42af2a6 100644 --- a/src/hyperloom/orchestrator/actions/executors/_grid_base.py +++ b/src/hyperloom/orchestrator/actions/executors/_grid_base.py @@ -4,16 +4,15 @@ """Shared value types and helpers for the ``explore`` executor's grid runs. Holds :class:`GridVariant` / :class:`VariantResult`, the content-fingerprint -delegate, ``extra_envs`` coercion, the Pareto filter, and the shared Magpie -cwd / per-variant timeout defaults. The runner that actually invokes Magpie -and parses ``benchmark_report.json`` lives in :mod:`._grid_runner`. +delegate, ``extra_envs`` coercion, the Pareto filter, and the shared +per-variant timeout default. The runner that actually invokes Magpie and +parses ``benchmark_report.json`` lives in :mod:`._grid_runner`. """ from __future__ import annotations import logging import re -import tempfile from dataclasses import dataclass, field from typing import Any @@ -64,8 +63,6 @@ def variant_fingerprint( ) -_MAGPIE_CWD_DEFAULT = tempfile.gettempdir() - _VARIANT_TIMEOUT_SEC_DEFAULT = 7800 # 130 min; matches BASELINE_DEFAULT_TIMEOUT_SEC diff --git a/src/hyperloom/orchestrator/actions/executors/_grid_runner.py b/src/hyperloom/orchestrator/actions/executors/_grid_runner.py index 72faee03a3..1aceb0ef5b 100644 --- a/src/hyperloom/orchestrator/actions/executors/_grid_runner.py +++ b/src/hyperloom/orchestrator/actions/executors/_grid_runner.py @@ -19,7 +19,7 @@ import subprocess import time from pathlib import Path -from typing import Any +from typing import Any, Callable import yaml @@ -33,6 +33,7 @@ ) from ...roles.robustness_pulse import pulse as _robustness_pulse +from ...trace.task_progress import heartbeat_while_output_flows, report_progress from ._accuracy_gate import materialized_run_eval_disabled from ._subprocess_kill import ( AGENTX_PREFLIGHT_RETURNCODE, @@ -59,7 +60,6 @@ # Re-exported from sibling modules to keep the module namespace intact. from ._grid_base import ( - _MAGPIE_CWD_DEFAULT as _MAGPIE_CWD_DEFAULT, _VARIANT_TIMEOUT_SEC_DEFAULT as _VARIANT_TIMEOUT_SEC_DEFAULT, GridVariant as GridVariant, coerce_extra_envs as coerce_extra_envs, @@ -937,6 +937,7 @@ def _run_magpie( preclean: bool = True, server_already_ready: bool = False, serving_lease: Any = None, + on_output: Callable[[], None] | None = None, ) -> tuple[int, str, str]: """Blocking subprocess wrapper. Returns (rc, stdout, stderr). @@ -966,6 +967,10 @@ def _run_magpie( runs inside the lease's actor — which holds ``num_gpus`` across every round sharing this server — instead of a local subprocess. ``None`` keeps the existing local ``run_with_session_kill`` path unchanged. + on_output: Liveness callback invoked from the reader thread on each + line the benchmark emits, so the caller's heartbeat can keep + reporting across a run that blocks for hours. Ignored on the + ``serving_lease`` path — see the note there. Returns: tuple[int, str, str]: ``(returncode, stdout, stderr)``. @@ -1061,6 +1066,11 @@ def _run_magpie( config_path=ray_config_path, output_dir=output_dir, ) + # ``on_output`` cannot follow the round here: the benchmark runs inside a + # Ray actor in another process (potentially on another node) and only its + # final ``(rc, stdout, stderr)`` comes back, so there is nothing local to + # call per line. A Ray-backed variant therefore reports on entry and then + # goes quiet until it returns — a known gap, not an oversight. return serving_lease.run_session_kill( cmd, env=env, @@ -1086,6 +1096,7 @@ def _run_magpie( soft_deadline_sec=soft_deadline_sec, server_log_path=str(output_dir / "server.log"), server_already_ready=server_already_ready, + on_output=on_output, ) return proc.returncode, proc.stdout or "", proc.stderr or "" @@ -1178,6 +1189,41 @@ def _resolve_mn_effective_server_args( ) +def _variant_progress_note( + grid: list[GridVariant], + results: list[VariantResult], + idx: int, +) -> dict[str, Any]: + """Build the progress note for the variant at ``idx`` from that variant's own row. + + The row is located by index and never taken from the tail of ``results``: a + stop cause that ends the batch records the round it stopped and then a + not-run row for every later variant, so the tail is the last variant in the + grid rather than the one that just ran. Each variant contributes exactly one + row, in order, before it reports, which is what makes ``idx`` where its row + is. The log line beside this note derives from ``idx`` already; the note is + the artefact the heartbeat exists to make honest, and the one a stall signal + reads, so it cannot be the one that names the wrong variant. + + Args: + grid (list[GridVariant]): The variants being run. + results (list[VariantResult]): Rows recorded so far. + idx (int): Zero-based index of the variant being reported. + + Returns: + dict[str, Any]: Keyword note for :func:`report_progress`. + """ + landed = results[idx] if idx < len(results) else None + return { + "unit": "variant", + "label": grid[idx].name, + "index": idx + 1, + "total": len(grid), + "status": getattr(landed, "status", None), + "output_throughput": getattr(landed, "output_throughput", None), + } + + async def run_grid( *, base_yaml_path: Path, @@ -1185,7 +1231,6 @@ async def run_grid( grid: list[GridVariant], output_root: Path, magpie_python: str | None = None, - cwd: str = _MAGPIE_CWD_DEFAULT, variant_timeout_sec: int = _VARIANT_TIMEOUT_SEC_DEFAULT, keep_going_on_failure: bool = True, model_path: str | None = None, @@ -1215,6 +1260,13 @@ async def run_grid( session budget; a variant is skipped once the remaining budget cannot fit another ``variant_timeout_sec`` worst-case run, so a wall-clock timeout stops the grid mid-way and the last variant never overruns the close window. + + Every pass runs with ``output_root`` as its working directory, the way the + baseline arm anchors Magpie to its own output dir. That is what marks the + benchmark subtree as this session's on a shared node: the robustness reactor + only believes a load generator that it can tie to the session, and a grid + launched from the system temp directory carried no such tie, so a server + dying mid-variant read as the idle gap between two variants. """ if not magpie_python: # Backend-aware: bypass uses a plain python3, not Magpie's venv. @@ -1227,6 +1279,11 @@ async def run_grid( warmup_before_measure = _run_grid_warmup_enabled() auto_warmup_requested = bool(warmup_before_measure and server_lifecycle is None) results: list[VariantResult] = [] + # This function names the working directory, so it creates it: callers and + # the per-variant config writer both happen to create it first today, and + # neither is a contract. The old system-temp default never needed one. + output_root.mkdir(parents=True, exist_ok=True) + cwd = str(output_root) # Reap orphaned aiter JIT build locks before booting any server. A prior GPU # process killed mid-``hipcc`` (e.g. an OOM'd co-scheduled server, or a @@ -1268,18 +1325,67 @@ async def run_grid( except Exception as exc: # noqa: BLE001 - reference base is additive; never block the grid log.debug("grid_runner: reference env resolve swallowed: %r", exc) - # Variant-boundary robustness pulse: a bounded tick after every variant so - # a mid-grid leak/crash surfaces between variants. Best-effort. + # Reported on entry, not on completion: ``_pulse_after_variant`` only runs once a + # result has been appended, so a first variant that hangs — or a branch that + # raises before reaching it — would emit nothing at all, which is exactly + # the silence the heartbeat exists to break. + async def _unit_started(idx: int, label: str) -> None: + """Report that a unit of variant ``idx`` is about to start. + + Args: + idx (int): Zero-based index of the variant the unit belongs to. + label (str): Unit name (``"variant"``, ``"warmup"``, ...). + """ + await report_progress( + unit="variant_step", + label=f"{grid[idx].name}:{label}", + index=idx + 1, + total=len(grid), + status="started", + ) + + async def _reported_magpie(idx: int, label: str, **kwargs: Any) -> tuple[int, str, str]: + """Run one Magpie pass, announced on entry and kept alive by its output. + + The entry note covers the wait before the child says anything; the + heartbeat covers the hours after it does. Without the second half a + benchmark could hold the row silent for a whole variant timeout against + a suppression window three orders of magnitude shorter. + + Args: + idx (int): Zero-based index of the variant this pass belongs to. + label (str): Unit name (``"warmup"``, ``"mn_warmup"``, + ``"benchmark"``). + **kwargs (Any): Forwarded to :func:`_run_magpie`. + + Returns: + tuple[int, str, str]: ``(returncode, stdout, stderr)``. + """ + await _unit_started(idx, label) + async with heartbeat_while_output_flows( + unit="variant_step", + label=f"{grid[idx].name}:{label}", + index=idx + 1, + total=len(grid), + ) as activity: + return await asyncio.to_thread(_run_magpie, on_output=activity.note, **kwargs) + + # Variant boundary: a bounded robustness tick so a mid-grid leak/crash + # surfaces between variants, plus a progress heartbeat so a grid that runs + # for hours is distinguishable from one that hung on its first variant. + # Both best-effort. async def _pulse_after_variant(idx: int) -> None: - """Run a best-effort robustness pulse after a variant completes. + """Report the finished variant and run a best-effort robustness pulse. - Exceptions from the pulse are swallowed (logged at debug) so a pulse - failure never aborts the grid. + Called once the variant's result has been appended, so the progress + note carries what actually landed. Exceptions from the pulse are + swallowed (logged at debug) so a pulse failure never aborts the grid. Args: idx (int): Zero-based index of the just-finished variant, passed through as the pulse ``tick_index``. """ + await report_progress(**_variant_progress_note(grid, results, idx)) try: await _robustness_pulse(tick_index=idx) except Exception as exc: # noqa: BLE001 @@ -1303,6 +1409,7 @@ async def _pulse_after_variant(idx: int) -> None: for skipped_variant in grid[i:]: results.append(_session_deadline_skip_result(skipped_variant)) break + await _unit_started(i, "variant") slot = output_root / f"variant_{i:02d}_{_safe(variant.name)}" server_log = slot / "server.log" # Capability fast-fail: drop a variant whose env flag the build cannot @@ -1481,8 +1588,9 @@ async def _pulse_after_variant(idx: int) -> None: warmup_workspaces_before = snapshot_workspaces(warmup_slot) warmup_started_unix = time.time() try: - warmup_rc, warmup_stdout, warmup_stderr = await asyncio.to_thread( - _run_magpie, + warmup_rc, warmup_stdout, warmup_stderr = await _reported_magpie( + i, + "warmup", magpie_python=magpie_python, config_path=warmup_cfg_path, output_dir=warmup_slot, @@ -1683,6 +1791,7 @@ async def _pulse_after_variant(idx: int) -> None: note=variant.note, ) ) + await _pulse_after_variant(i) if not keep_going_on_failure: break continue @@ -1700,8 +1809,9 @@ async def _pulse_after_variant(idx: int) -> None: if _mn_imn() and _mn_warm(): _mn_warm_slot = slot / "mn_warmup" try: - await asyncio.to_thread( - _run_magpie, + await _reported_magpie( + i, + "mn_warmup", magpie_python=magpie_python, config_path=cfg_path, output_dir=_mn_warm_slot, @@ -1730,8 +1840,9 @@ async def _pulse_after_variant(idx: int) -> None: slot_workspaces_before = snapshot_workspaces(slot) variant_started_unix = time.time() try: - rc, stdout, stderr = await asyncio.to_thread( - _run_magpie, + rc, stdout, stderr = await _reported_magpie( + i, + "benchmark", magpie_python=magpie_python, config_path=cfg_path, output_dir=slot, diff --git a/src/hyperloom/orchestrator/actions/executors/_subprocess_kill.py b/src/hyperloom/orchestrator/actions/executors/_subprocess_kill.py index 203cbe1a85..90f1b71640 100644 --- a/src/hyperloom/orchestrator/actions/executors/_subprocess_kill.py +++ b/src/hyperloom/orchestrator/actions/executors/_subprocess_kill.py @@ -24,6 +24,9 @@ import threading import time from pathlib import Path +from typing import Callable, NamedTuple + +from .bypass_analysis import parse_server_log_throughput log = logging.getLogger(__name__) @@ -260,15 +263,6 @@ def kill_my_spawned_server( "The server is fired up and ready to roll", ) -# Generation-progress markers: the periodic decode-throughput lines. Scanned and -# returned by ``_scan_logs_increment`` but currently unconsumed — the stall gate -# keys on raw log activity (any new bytes); see -# :func:`_communicate_with_soft_deadline`. -_SERVER_PROGRESS_MARKERS: tuple[str, ...] = ( - "gen throughput (token/s):", # sglang - "Avg generation throughput:", # vLLM -) - # Accuracy-eval start markers: their appearance means the benchmark phase of the # run is over and the accuracy eval has begun. The soft deadline measures # throughput only, so it stops being enforced from this point on — eval duration @@ -279,8 +273,10 @@ def kill_my_spawned_server( "[magpie_bench_remote_compat] lm_eval cmd:", ) -# The patcher echoes the eval-start marker to stderr, which Magpie redirects -# here rather than into ``server.log``; scanned alongside it. +# The benchmark body's own stderr: Magpie redirects it here rather than into +# ``server.log`` or the parent's pipe, so it is both where the eval-start marker +# lands and the one resolved log whose growth is output of the very child this +# module is waiting on. _EVAL_LOG_NAME: str = "benchmark_stderr.log" # Default grace: how long after the server reports ready it may emit no log @@ -293,14 +289,24 @@ def kill_my_spawned_server( class _StreamCapture: """Capture child output while mirroring each line to the parent stream.""" - def __init__(self, proc: subprocess.Popen, *, text: bool) -> None: + def __init__( + self, + proc: subprocess.Popen, + *, + text: bool, + on_output: Callable[[], None] | None = None, + ) -> None: """Set up capture/mirror threads for a child's stdout and stderr. Args: proc: The child process whose pipes should be captured. text: Whether the pipes are in text (``str``) or bytes mode. + on_output: Called once per observed unit of child output, from the + pump thread. Used as liveness evidence by callers that report + progress for a long step. """ self._text = text + self._on_output = on_output self._stdout_chunks: list[str | bytes] = [] self._stderr_chunks: list[str | bytes] = [] self._threads: list[threading.Thread] = [] @@ -344,6 +350,15 @@ def finish(self, timeout: float = 2.0) -> tuple[str | bytes, str | bytes]: self._join(self._stderr_chunks) if self._stderr_chunks else empty, ) + def note_output(self) -> None: + """Report one unit of child output to the caller's liveness callback.""" + if self._on_output is None: + return + try: + self._on_output() + except Exception: # noqa: BLE001 - liveness reporting never breaks capture + pass + def _join(self, chunks: list[str | bytes]) -> str | bytes: """Concatenate captured chunks using the appropriate empty separator. @@ -370,6 +385,7 @@ def _pump(self, pipe, chunks: list[str | bytes], mirror) -> None: break chunks.append(chunk) self._mirror(chunk, mirror) + self.note_output() finally: try: pipe.close() @@ -548,7 +564,29 @@ def _resolve_scan_logs(server_log_path: str) -> list[str]: return out -def _scan_logs_increment(server_log_path: str, offsets: dict[str, int]) -> tuple[bool, bool, bool, bool]: +class _LogScan(NamedTuple): + """What one pass over the resolved logs found in the bytes appended since the last. + + Attributes: + saw_ready: A server-ready marker appeared. + saw_progress: A periodic decode-throughput line reported a non-zero + rate, so tokens were being produced during the interval whoever + logged them. + saw_eval_start: The accuracy eval announced itself. + grew: Some resolved log got longer, from any writer at all. + child_spoke: The benchmark body's own redirected stderr got longer, + which is output of the child being waited on that never reaches its + pipe. + """ + + saw_ready: bool + saw_progress: bool + saw_eval_start: bool + grew: bool + child_spoke: bool + + +def _scan_logs_increment(server_log_path: str, offsets: dict[str, int]) -> _LogScan: """Scan every resolved log for markers, advancing ``offsets`` in place. Args: @@ -556,10 +594,10 @@ def _scan_logs_increment(server_log_path: str, offsets: dict[str, int]) -> tuple offsets: Per-path byte offsets already consumed; mutated in place. Returns: - ``(saw_ready, saw_progress, saw_eval_start, grew)`` — the markers seen - in the newly appended bytes, and whether any log grew (liveness). + _LogScan: The markers seen in the newly appended bytes, plus who — if + anyone — did the appending. """ - saw_ready = saw_progress = saw_eval_start = grew = False + saw_ready = saw_progress = saw_eval_start = grew = child_spoke = False for path in _resolve_scan_logs(server_log_path): prev = offsets.get(path, 0) new_offset, ready, progress, eval_start = _scan_server_log_increment(path, prev) @@ -567,8 +605,10 @@ def _scan_logs_increment(server_log_path: str, offsets: dict[str, int]) -> tuple saw_ready = saw_ready or ready saw_progress = saw_progress or progress saw_eval_start = saw_eval_start or eval_start - grew = grew or new_offset > prev - return saw_ready, saw_progress, saw_eval_start, grew + if new_offset > prev: + grew = True + child_spoke = child_spoke or Path(path).name == _EVAL_LOG_NAME + return _LogScan(saw_ready, saw_progress, saw_eval_start, grew, child_spoke) def _scan_server_log_increment(path: str, from_offset: int) -> tuple[int, bool, bool, bool]: @@ -590,8 +630,8 @@ def _scan_server_log_increment(path: str, from_offset: int) -> tuple[int, bool, Returns: ``(new_offset, saw_ready, saw_progress, saw_eval_start)`` — the advanced - offset plus whether a ready / progress / eval-start marker appeared in - the newly read bytes. + offset plus whether the newly read bytes carried a ready marker, a + non-zero generation-throughput rate, or the eval-start marker. """ try: size = os.path.getsize(path) @@ -609,7 +649,19 @@ def _scan_server_log_increment(path: str, from_offset: int) -> tuple[int, bool, except (OSError, ValueError): return from_offset, False, False, False saw_ready = any(marker in chunk for marker in _SERVER_READY_MARKERS) - saw_progress = any(marker in chunk for marker in _SERVER_PROGRESS_MARKERS) + # Progress is the rate on the periodic decode-throughput line, not the + # line's presence: some vLLM builds log ``Avg generation throughput: 0.0 + # tokens/s`` on an idle engine, and an engine goes idle precisely when the + # client driving it wedges, so the marker alone lets the server vouch for + # the client that stopped asking it for tokens. Reusing the post-mortem + # estimator's parse keeps the frameworks the two recognise from drifting + # apart. A line whose rate it cannot read counts as no progress: this + # evidence only ever suppresses a stall accusation, and one suppressed by + # mistake is invisible, where a missing one is visible and answerable from + # the child's own redirected stderr. The stall gate is deliberately broader + # and keys on raw log activity (any new bytes); see + # :func:`_communicate_with_soft_deadline`. + saw_progress = bool(parse_server_log_throughput(chunk)) saw_eval_start = any(marker in chunk for marker in _EVAL_START_MARKERS) return size, saw_ready, saw_progress, saw_eval_start @@ -626,8 +678,15 @@ def run_with_session_kill( server_dead_grace_sec: float | None = None, detok_stall_grace_sec: float | None = None, server_already_ready: bool = False, + on_output: Callable[[], None] | None = None, ) -> subprocess.CompletedProcess: - """Run a subprocess in its own session and reap descendants on every exit path.""" + """Run a subprocess in its own session and reap descendants on every exit path. + + Args: + on_output: Called from a reader thread each time the child produces + output, so a caller can report a long step alive on the child's own + activity rather than on a timer. + """ if server_dead_grace_sec is None: try: server_dead_grace_sec = float( @@ -660,7 +719,7 @@ def run_with_session_kill( cwd=cwd, **new_session_kwargs(), ) - capture = _StreamCapture(proc, text=text) + capture = _StreamCapture(proc, text=text, on_output=on_output) capture.start() try: stdout, stderr = _communicate_with_soft_deadline( @@ -887,14 +946,14 @@ def _communicate_with_soft_deadline( # Advance the log scan, latching the server-ready, last-activity # and eval-start signals. if scan_active: - saw_ready, _saw_progress, saw_eval_start, grew = _scan_logs_increment( + scan = _scan_logs_increment( server_log_path, # type: ignore[arg-type] scan_offsets, ) - if saw_ready and server_ready_since is None: + if scan.saw_ready and server_ready_since is None: server_ready_since = now last_activity_at = now # start the silence clock at ready - if saw_eval_start and not soft_deadline_suspended: + if scan.saw_eval_start and not soft_deadline_suspended: soft_deadline_suspended = True log.info( "_subprocess_kill: accuracy eval started; soft_deadline_sec=%.1fs no longer enforced " @@ -903,8 +962,19 @@ def _communicate_with_soft_deadline( ) # Any new bytes count as liveness; only total silence trips the # stall gate. - if grew: + if scan.grew: last_activity_at = now + # The liveness callback makes a narrower claim than the stall gate — + # that this child is working, not that something on the box is — so + # it takes narrower evidence: tokens flowing, or the child's own + # redirected stderr growing. A ``server.log`` that grew is neither. + # The server keeps logging while its benchmark client is wedged, and + # both vLLM and sglang write an access line per request, including + # the health probe the robustness agent issues on its own tick — + # which would let the monitor manufacture the evidence that + # suppresses its own stall accusation. + if capture is not None and (scan.saw_progress or scan.child_spoke): + capture.note_output() # Soft deadline. With ``soft_from_ready`` the overtime clock is measured # from the server-ready marker and stays dormant until ready; otherwise # it is the from-spawn elapsed. diff --git a/src/hyperloom/orchestrator/actions/executors/baseline.py b/src/hyperloom/orchestrator/actions/executors/baseline.py index 334b72e10d..1181a50cff 100644 --- a/src/hyperloom/orchestrator/actions/executors/baseline.py +++ b/src/hyperloom/orchestrator/actions/executors/baseline.py @@ -34,6 +34,7 @@ from hyperloom.common.git_safety import safe_directory_args from hyperloom.inference_optimizer.session.session_paths import runs_dir from ...loop.sub_agent_runner import RunnerContext +from ...trace.task_progress import heartbeat_while_output_flows, report_progress from . import _server_lifecycle as _lifecycle from ._file_lock import best_effort_file_lock from ._aiter_jit import ( @@ -2899,7 +2900,8 @@ def _persist_recipe_snapshot(manifest: dict[str, Any]) -> bool: lifecycle["reason"], ) try: - result = await self._run_single_benchmark( + result = await self._run_reported_round( + label="single", config_path=config_path, output_dir=output_dir, **common, @@ -2957,7 +2959,8 @@ def _persist_recipe_snapshot(manifest: dict[str, Any]) -> bool: "baseline_executor: cold-start guard — warmup round (discarded, boots persistent server) in %s", warmup_dir, ) - warmup_result = await self._run_single_benchmark( + warmup_result = await self._run_reported_round( + label="warmup", config_path=warmup_cfg, output_dir=warmup_dir, **common, @@ -2989,6 +2992,15 @@ def _persist_recipe_snapshot(manifest: dict[str, Any]) -> bool: return warmup_result warmup_tput = warmup_result.get("output_throughput") warmup_runtime = warmup_result.get("subprocess_runtime_sec") + await report_progress( + unit="baseline_round", + label="warmup", + index=1, + total=2, + status="succeeded", + output_throughput=warmup_tput, + runtime_sec=warmup_runtime, + ) # Round 2 (measured): re-attach to the hot server (client only). # Warm re-attach is intentional — all comparison points (baseline, @@ -3015,7 +3027,8 @@ def _persist_recipe_snapshot(manifest: dict[str, Any]) -> bool: measure_dir, warmup_tput or 0.0, ) - result = await self._run_single_benchmark( + result = await self._run_reported_round( + label="measure", config_path=measure_cfg, output_dir=measure_dir, **common, @@ -3089,7 +3102,8 @@ def _persist_recipe_snapshot(manifest: dict[str, Any]) -> bool: ) except (TypeError, ValueError): accuracy_timeout_sec = timeout_sec - accuracy_result = await self._run_single_benchmark( + accuracy_result = await self._run_reported_round( + label="accuracy", config_path=accuracy_cfg, output_dir=accuracy_dir, **{ @@ -3356,6 +3370,37 @@ def _teardown_lifecycle_server( port=port, ) + async def _run_reported_round( + self, + *, + label: str, + config_path: Path, + output_dir: Path, + **common: Any, + ) -> dict[str, Any]: + """Announce a benchmark round before it blocks, then run it. + + Reported on entry, not on completion: a round can boot a server, warm + JIT and bench for the better part of an hour, and one that never + returns is exactly the case the heartbeat has to be able to show. + + Args: + label (str): Round name carried on the progress note + (``"single"``, ``"warmup"``, ``"measure"``, ``"accuracy"``). + config_path (Path): The materialized Magpie YAML for this round. + output_dir (Path): The per-round workspace slot. + **common (Any): Remaining :meth:`_run_single_benchmark` arguments. + + Returns: + dict[str, Any]: The round's benchmark result, unchanged. + """ + await report_progress(unit="baseline_round", label=label, status="started") + return await self._run_single_benchmark( + config_path=config_path, + output_dir=output_dir, + **common, + ) + async def _run_single_benchmark( self, *, @@ -3549,14 +3594,19 @@ async def _run_single_benchmark( _mn_warm_env["EVAL_RESULT_DIR"] = str(_mn_warm_dir / "eval_output") _mn_warm_env["SERVER_LOG"] = str(_mn_warm_dir / "server.log") _mn_warm_env["GPU_METRICS_CSV"] = str(_mn_warm_dir / "gpu_metrics.csv") - await asyncio.to_thread( - run_with_session_kill, - _mn_warm_cmd, - env=_mn_warm_env, - cwd=str(_mn_warm_dir), - timeout=timeout_sec, - server_log_path=_watchdog_server_log_path(_mn_warm_dir, framework), - ) + async with heartbeat_while_output_flows( + unit="baseline_round", + label="mn_warmup", + ) as _mn_warm_activity: + await asyncio.to_thread( + run_with_session_kill, + _mn_warm_cmd, + env=_mn_warm_env, + cwd=str(_mn_warm_dir), + timeout=timeout_sec, + server_log_path=_watchdog_server_log_path(_mn_warm_dir, framework), + on_output=_mn_warm_activity.note, + ) log.info("baseline_executor: MN warmup pass done (discarded)") except Exception as exc: # noqa: BLE001 - warmup is best-effort log.warning("baseline_executor: MN warmup pass failed (ignored): %r", exc) @@ -3597,6 +3647,12 @@ async def _run_single_benchmark( config_path=ray_config_path, output_dir=output_dir, ) + # No liveness callback is possible here: the round runs inside a + # Ray actor in another process (potentially on another node) and + # only its final ``(rc, stdout, stderr)`` crosses back, so there + # is nothing local to call per line of child output. A Ray-backed + # round reports on entry and then goes quiet until it returns — a + # known gap, not an oversight. proc_returncode, proc_stdout, proc_stderr = await asyncio.to_thread( serving_lease.run_session_kill, ray_cmd, @@ -3607,14 +3663,19 @@ async def _run_single_benchmark( ) subprocess_runtime_sec = max(0.0, time.time() - subprocess_started_unix) else: - proc = await asyncio.to_thread( - run_with_session_kill, - cmd, - env=env, - cwd=str(output_dir), - timeout=timeout_sec, - server_log_path=watchdog_server_log, - ) + async with heartbeat_while_output_flows( + unit="baseline_round", + label="benchmark", + ) as activity: + proc = await asyncio.to_thread( + run_with_session_kill, + cmd, + env=env, + cwd=str(output_dir), + timeout=timeout_sec, + server_log_path=watchdog_server_log, + on_output=activity.note, + ) subprocess_runtime_sec = max( 0.0, time.time() - subprocess_started_unix, diff --git a/src/hyperloom/orchestrator/actions/executors/roofline.py b/src/hyperloom/orchestrator/actions/executors/roofline.py index b4ff9c00f9..2bd5544b44 100644 --- a/src/hyperloom/orchestrator/actions/executors/roofline.py +++ b/src/hyperloom/orchestrator/actions/executors/roofline.py @@ -28,10 +28,11 @@ import os import time from pathlib import Path -from typing import Any +from typing import Any, Awaitable, Callable from hyperloom.common.timeutil import now_iso from ...loop.sub_agent_runner import RunnerContext +from ...trace.task_progress import report_progress from ._multi_node_env import is_multi_node log = logging.getLogger(__name__) @@ -257,6 +258,34 @@ async def __call__(self, ctx: RunnerContext) -> dict[str, Any]: from ...kernel.request_handlers import trace_analyze_handler from .profile import profile_executor + # Every sub-step below goes through this, so a call site added later + # cannot silently be the one that reports nothing. Reported on entry, + # not on completion: a sub-step that never returns is exactly the case + # the heartbeat has to be able to show. + async def _reported( + label: str, + start: Callable[[], Awaitable[Any]], + **fields: Any, + ) -> Any: + """Announce a roofline sub-step, then await it. + + Args: + label (str): Sub-step name carried on the progress note. + start (Callable[[], Awaitable[Any]]): Zero-argument factory + returning the sub-step awaitable. + **fields (Any): Extra note fields, e.g. ``index`` / ``total``. + + Returns: + Any: Whatever the sub-step returned, unchanged. + """ + await report_progress( + unit="roofline_step", + label=label, + status="started", + **fields, + ) + return await start() + session_dir = self._resolve_session_dir(ctx) # Time the composite so the END lifecycle event reports its duration. _lc_t0 = time.monotonic() @@ -310,7 +339,12 @@ async def __call__(self, ctx: RunnerContext) -> dict[str, Any]: framework=framework, ) try: - profile_result = await profile_executor(profile_ctx) + profile_result = await _reported( + "profile", + lambda: profile_executor(profile_ctx), + index=attempt, + total=_PROFILE_MAX_ATTEMPTS, + ) except Exception as exc: # noqa: BLE001 last_phase = "profile" last_error = f"profile_executor raised: {exc!r}" @@ -493,9 +527,9 @@ async def __call__(self, ctx: RunnerContext) -> dict[str, Any]: if roofline_output_name: ta_payload["roofline_output_name"] = roofline_output_name try: - ta_result = await trace_analyze_handler( - ta_payload, - session_dir=session_dir, + ta_result = await _reported( + "trace_analyze", + lambda: trace_analyze_handler(ta_payload, session_dir=session_dir), ) except Exception as exc: # noqa: BLE001 # Clear the cache so the prompt shows no snapshot rather than advice @@ -550,9 +584,9 @@ async def __call__(self, ctx: RunnerContext) -> dict[str, Any]: if roofline_output_name: ta_payload_retry["roofline_output_name"] = roofline_output_name try: - ta_result = await trace_analyze_handler( - ta_payload_retry, - session_dir=session_dir, + ta_result = await _reported( + "trace_analyze_n26_retry", + lambda: trace_analyze_handler(ta_payload_retry, session_dir=session_dir), ) except Exception as exc: # noqa: BLE001 self.shared_state.last_trace_analyze = {} @@ -664,7 +698,10 @@ async def __call__(self, ctx: RunnerContext) -> dict[str, Any]: os.environ[_COMPUTE_BOUND_PROFILE_ENV] = "1" try: cb_ctx = self._wrap_profile_ctx(ctx, framework=framework) - cb_profile = await profile_executor(cb_ctx) + cb_profile = await _reported( + "profile_compute_bound", + lambda: profile_executor(cb_ctx), + ) cb_trace = _extract_trace_path(cb_profile) if isinstance(cb_profile, dict) else "" if cb_trace: cb_payload: dict[str, Any] = { @@ -675,7 +712,10 @@ async def __call__(self, ctx: RunnerContext) -> dict[str, Any]: cb_payload["roofline_arm"] = roofline_arm if roofline_output_name: cb_payload["roofline_output_name"] = roofline_output_name - cb_ta = await trace_analyze_handler(cb_payload, session_dir=session_dir) + cb_ta = await _reported( + "trace_analyze_compute_bound", + lambda: trace_analyze_handler(cb_payload, session_dir=session_dir), + ) if isinstance(cb_ta, dict) and cb_ta.get("status") == "ok": cb_hot = cb_ta.get("hot_kernels_top15") or cb_ta.get("hot_kernels") or [] if cb_hot: diff --git a/src/hyperloom/orchestrator/bus/storage/connection.py b/src/hyperloom/orchestrator/bus/storage/connection.py index 4d561fefcf..a41c90055b 100644 --- a/src/hyperloom/orchestrator/bus/storage/connection.py +++ b/src/hyperloom/orchestrator/bus/storage/connection.py @@ -12,6 +12,7 @@ import asyncio import contextlib +import logging import os import sqlite3 import threading @@ -22,6 +23,9 @@ from .schema import ensure_schema +log = logging.getLogger(__name__) + + # Journal mode is env-overridable; WAL default. On networked filesystems # (WekaFS / NFS) WAL's ``-shm`` mapping can corrupt the DB, so set # ``INFERENCE_OPTIMIZER_SQLITE_JOURNAL_MODE=DELETE`` on such mounts. @@ -208,19 +212,30 @@ async def transaction(self) -> AsyncIterator[sqlite3.Cursor]: Yields: An open cursor inside the immediate write transaction; the - transaction commits on clean exit and rolls back on exception. + transaction commits on clean exit and rolls back on any exception, + cancellation included. """ await self._async_lock.acquire() + cur: sqlite3.Cursor | None = None try: - cur = await asyncio.to_thread(self._begin_immediate) try: + cur = await asyncio.to_thread(self._begin_immediate) yield cur await asyncio.to_thread(self._commit) - except Exception: - await asyncio.to_thread(self._rollback) + except BaseException: + # ``BaseException``, not ``Exception``: ``CancelledError`` is + # not an ``Exception``, and a cancel landing on any of the + # ``to_thread`` hops here — including the one that returns the + # cursor, after ``BEGIN IMMEDIATE`` already ran in the worker + # thread — would otherwise skip the rollback. The shared + # connection then stays inside a transaction for the rest of + # the session and every later write fails with "cannot start a + # transaction within a transaction". + await self._rollback_off_loop() raise finally: - await asyncio.to_thread(cur.close) + if cur is not None: + await asyncio.to_thread(cur.close) finally: self._async_lock.release() @@ -246,6 +261,51 @@ def _rollback(self) -> None: with self._sync_lock: self._conn.rollback() + async def _rollback_off_loop(self) -> None: + """Roll back a failed transaction on a worker thread, uncancellably. + + Three constraints meet here. The rollback must not run on the event-loop + thread, because it takes ``_sync_lock``, and when the failure was a + cancellation the worker that cancel abandoned still holds that lock — + parked inside its own ``BEGIN IMMEDIATE`` for as long as another writer + holds the database, up to ``busy_timeout``. An inline rollback queues + behind it and stops the whole loop for that window, which is the + shutdown or budget-exhaustion window that issued the cancel. The + rollback must not itself be cancellable, because a bare ``await`` in a + handler for this task's own cancellation is the way the connection stays + wedged inside a transaction for the rest of the session. And the + connection must be out of that transaction *before* ``_async_lock`` is + released, or a later writer finds it still open and fails with "cannot + start a transaction within a transaction". + + :func:`asyncio.shield` keeps the worker running whatever happens to this + task, but it protects the rollback, not the wait on it: a cancel landing + on the wait raises here. Abandoning the wait at that point releases + ``_async_lock`` with the rollback still queued behind the parked worker, + which is fire-and-forget with the lock already gone — so every cancel is + absorbed and the wait resumed until the rollback is done. The last one + absorbed is then re-raised, because a cancelled caller that returns + normally keeps running as though it had never been cancelled. + + A rollback that fails outright — a statement error, a connection already + closed by teardown, an executor that will accept no more work — is + logged and never masks the caller's original exception. + """ + rolling_back = asyncio.ensure_future(asyncio.to_thread(self._rollback)) + cancel: asyncio.CancelledError | None = None + while not rolling_back.done(): + try: + await asyncio.shield(rolling_back) + except asyncio.CancelledError as exc: + cancel = exc + except (sqlite3.Error, RuntimeError) as exc: + # The rollback itself failed: a statement error, or the loop's + # executor refusing new work during teardown. Anything else is + # a bug worth surfacing rather than logging. + log.warning("rollback after a failed transaction did not complete: %r", exc) + if cancel is not None: + raise cancel + def close(self) -> None: """Close the underlying connection under the sync lock.""" with self._sync_lock: diff --git a/src/hyperloom/orchestrator/kernel/request_handlers.py b/src/hyperloom/orchestrator/kernel/request_handlers.py index b48c60db79..0b745da103 100644 --- a/src/hyperloom/orchestrator/kernel/request_handlers.py +++ b/src/hyperloom/orchestrator/kernel/request_handlers.py @@ -43,6 +43,7 @@ async def handler(payload: dict, *, session_dir: Path) -> dict: ) from ..trace.llm_trace import LLMCallRecord, append_llm_call +from ..trace.task_progress import heartbeat_while_output_flows from ..trace.parse_usage import ( parse_forge_steps, parse_forge_usage, @@ -1578,6 +1579,22 @@ def _resolve_integrate_payload(payload: dict, *, session_dir: Path) -> tuple[dic return resolved, None +def _tool_label(cmd: list[str]) -> str: + """Name the tool a command runs, for the progress note. + + Args: + cmd (list[str]): The command and arguments. + + Returns: + str: The first ``.py`` argument's stem, else the executable's name. + """ + for arg in cmd: + text = str(arg) + if text.endswith(".py"): + return Path(text).stem + return Path(str(cmd[0])).name if cmd else "subprocess" + + async def _run_subprocess( cmd: list[str], *, @@ -1599,7 +1616,8 @@ async def _run_subprocess( or timeout_sec <= 0 ): raise ValueError("timeout_sec must be finite and positive") - def _run() -> tuple[int, str, str]: + + def _run(on_output: Callable[[], None]) -> tuple[int, str, str]: """Run the command synchronously in a worker thread. Copies the environment, injects the Ray GCS address in multi-node mode, @@ -1608,6 +1626,9 @@ def _run() -> tuple[int, str, str]: grandchild dies with the wrapper. Mirrors ``subprocess.run``: captures stdout/stderr and re-raises ``TimeoutExpired``. + Args: + on_output: Liveness callback invoked per line the child emits. + Returns: tuple[int, str, str]: ``(returncode, stdout, stderr)``. @@ -1633,15 +1654,22 @@ def _run() -> tuple[int, str, str]: if addr: env.setdefault("RAY_ADDRESS", addr) env["PATH"] = f"/opt/venv/bin:{env.get('PATH', '')}" + # The heartbeat around this call is only as honest as the child's + # flushing: block-buffered on a pipe, it looks dead between flushes. + # ``setdefault`` so an operator who set this deliberately still wins. + env.setdefault("PYTHONUNBUFFERED", "1") + # run_with_session_kill reaps the whole descendant tree on every exit path. cp = run_with_session_kill( cmd, env=env, timeout=timeout_sec, text=True, + on_output=on_output, ) return cp.returncode, cp.stdout or "", cp.stderr or "" - return await asyncio.to_thread(_run) + async with heartbeat_while_output_flows(unit="kernel_tool", label=_tool_label(cmd)) as activity: + return await asyncio.to_thread(_run, activity.note) def _normalize_precision(value: Any) -> str: diff --git a/src/hyperloom/orchestrator/loop/sub_agent_runner.py b/src/hyperloom/orchestrator/loop/sub_agent_runner.py index c997c79366..de1bef9ebc 100644 --- a/src/hyperloom/orchestrator/loop/sub_agent_runner.py +++ b/src/hyperloom/orchestrator/loop/sub_agent_runner.py @@ -13,7 +13,7 @@ from dataclasses import dataclass, field from pathlib import Path -from typing import TYPE_CHECKING, Awaitable, Callable +from typing import TYPE_CHECKING, Any, Awaitable, Callable import logging @@ -21,6 +21,7 @@ from ..bus.resource_lock import Lease, ResourceLockManager from ..policy.gate import PolicyDenied from ..state.task_registry import IllegalTransition, Task, TaskNotFound, TaskRegistry +from ..trace.task_progress import ProgressReporter, progress_scope if TYPE_CHECKING: from ..policy.gate import PolicyGate @@ -28,6 +29,14 @@ log = logging.getLogger(__name__) +# Every ``tasks`` row is dispatched and awaited by the Coordinator's +# orchestration loop, and the table carries no requester column, so a heartbeat +# can only ever attest to this one agent. Widening that — letting any running +# task vouch for whoever happens to be quiet — is what allowed a single busy +# task to silence stall detection for the whole session. +PROGRESS_OWNER_AGENT = "orchestration" + + @dataclass class RunnerContext: """Per-task context handed to an :data:`ExecutorFn`. @@ -282,7 +291,8 @@ async def run_task( extra.update(dict(extra_context)) ctx = RunnerContext(task=task, lease=lease, extra=extra) try: - result_payload = await runner(ctx) + with progress_scope(self._progress_reporter(task.task_id)): + result_payload = await runner(ctx) except Exception as exc: # noqa: BLE001 — surface to task.history await self._transition_resilient( task.task_id, @@ -314,5 +324,51 @@ async def run_task( if lease is not None: await self.locks.release(lease) + def _progress_reporter(self, task_id: str) -> ProgressReporter: + """Build the ambient progress sink for one task's executor. + + Composite actions call :func:`~...trace.task_progress.report_progress` + as each internal unit lands, which reaches this sink and lands on the + task row as a heartbeat instead of the row going dark for the whole + run. Each note is stamped with :data:`PROGRESS_OWNER_AGENT` so a + consumer can tell whose silence the heartbeat actually excuses. + + Args: + task_id (str): Task the returned sink reports for. + + Returns: + ProgressReporter: ``async (**note) -> None``. + """ + + async def sink(**note: Any) -> None: + note.setdefault("agent", PROGRESS_OWNER_AGENT) + log.info("task_progress: task=%s %s", task_id, _format_progress(note)) + await self.tasks.record_progress(task_id, note) + + return sink + -__all__ = ["RunnerContext", "ExecutorFn", "SubAgentResult", "SubAgentRunner"] +def _format_progress(note: dict[str, Any]) -> str: + """Render a progress note as one greppable ``key=value`` log line. + + Args: + note (dict[str, Any]): The reported note; ``index``/``total`` collapse + into a single ``3/12`` counter and empty values are dropped. + + Returns: + str: Space-separated ``key=value`` pairs. + """ + index, total = note.get("index"), note.get("total") + parts = [f"{k}={v}" for k, v in note.items() if k not in ("index", "total") and v not in (None, "")] + if index is not None: + parts.append(f"progress={index}/{total}" if total is not None else f"progress={index}") + return " ".join(parts) + + +__all__ = [ + "PROGRESS_OWNER_AGENT", + "RunnerContext", + "ExecutorFn", + "SubAgentResult", + "SubAgentRunner", +] diff --git a/src/hyperloom/orchestrator/state/task_registry.py b/src/hyperloom/orchestrator/state/task_registry.py index 253b08f8ac..0a1ebe44b5 100644 --- a/src/hyperloom/orchestrator/state/task_registry.py +++ b/src/hyperloom/orchestrator/state/task_registry.py @@ -46,6 +46,19 @@ TERMINAL_STATES = frozenset({"succeeded", "cancelled"}) +# Progress notes a task's ``history`` retains, oldest dropped first. +# ``record_progress`` re-reads and rewrites the whole blob inside a +# ``BEGIN IMMEDIATE`` on the one connection every other writer serialises +# behind, and the robustness probe re-parses it for every running task on every +# tick, so an uncapped trail makes both costs grow with the session: 12 hours at +# the 60s heartbeat is 720 notes, a blob measured between 100 and 160 KB +# depending on the note, and tens of MB of cumulative row rewrites. 120 notes +# hold two hours of trail — longer than the longest measured single work unit, a +# 3941s warmup — for a blob under 20 KB, which turns the growth from quadratic +# in the session's length into linear at a bounded rate. The only consumer that +# reads the notes wants the newest one. +_MAX_PROGRESS_NOTES = 120 + # microseconds + ``+00:00`` (canonical helper; kept importable for callers). _now_iso = now_iso @@ -65,7 +78,9 @@ class Task: allowed_tools (list[str]): Tool whitelist for the task. side_effects (list[str]): Declared side effects. lease_ttl_sec (int): Lease TTL in seconds. - history (list[dict]): Recorded state-transition history. + history (list[dict]): Recorded state transitions, plus the newest + progress notes a running task reported (bounded by + :data:`_MAX_PROGRESS_NOTES`). created_at (str): ISO creation timestamp. updated_at (str): ISO last-update timestamp. """ @@ -122,6 +137,49 @@ class TaskNotFound(RuntimeError): pass +def _is_progress_note(entry: Any) -> bool: + """Report whether a ``history`` entry is a progress note. + + A note carries a ``progress`` payload where a transition carries + ``from``/``to``; the robustness probe keys on the same field. + + Args: + entry (Any): One decoded ``history`` entry. + + Returns: + bool: ``True`` for a progress note. + """ + return isinstance(entry, dict) and "progress" in entry + + +def _drop_oldest_progress_notes(history: list[Any], keep: int) -> list[Any]: + """Retain the newest ``keep`` progress notes and every other entry. + + Transitions are never dropped: consumers read them positionally — the last + entry for a failure class, the newest ``queued -> cancelled`` for a policy + denial — and losing one would make a task's state history lie. Notes are + only ever read newest-first, so the oldest are the ones that can go. + + Args: + history (list[Any]): The task's decoded ``history``. + keep (int): Progress notes to retain. + + Returns: + list[Any]: ``history`` itself when it is already within the bound, + otherwise a copy with the oldest surplus notes removed. + """ + surplus = sum(1 for entry in history if _is_progress_note(entry)) - keep + if surplus <= 0: + return history + kept: list[Any] = [] + for entry in history: + if surplus > 0 and _is_progress_note(entry): + surplus -= 1 + continue + kept.append(entry) + return kept + + class TaskRegistry: """State machine + persistence layer for delegated tasks. @@ -318,6 +376,54 @@ async def transition( ) return await self.get(task_id) + async def record_progress( + self, + task_id: str, + note: dict[str, Any] | None = None, + ) -> None: + """Record that a running task made progress, without changing its state. + + A composite action — an explore grid, a baseline double-run, a profile + and its analysis — is one task that internally completes many units of + work over hours. Until it returns, its row looks identical to a task + that hung at second one, which is why a healthy 80-minute analysis and + a wedged Coordinator produce the same stall evidence. The note carries + the difference: it lands on ``history`` with its own timestamp, and a + consumer that wants freshness reads the notes. + + ``updated_at`` is deliberately left alone. It marks when the task + entered ``running``, and the R6 lease watchdog, the ``extend_lease`` + remaining-budget math and the "Tasks in flight" projection all measure + elapsed runtime from it; moving it would turn a cumulative budget into + an inactivity timeout and make an 80-minute task render as seconds old. + + Only the newest :data:`_MAX_PROGRESS_NOTES` notes are retained. Each + note costs a rewrite of the whole ``history`` blob, so an unbounded + trail charges a session for its own length in exactly the runs this + feature exists for; the notes are read newest-first, and transitions are + kept whatever the bound. + + Best-effort: a task that vanished under a reaper must not take its + executor down over a progress note. + + Args: + task_id (str): The running task reporting progress. + note (dict[str, Any] | None): Structured detail (unit name, index, + outcome) recorded on the task's history. + """ + async with self.db.transaction() as cur: + cur.execute("SELECT history FROM tasks WHERE task_id=?", (task_id,)) + row = cur.fetchone() + if row is None: + return + history = json.loads(row["history"]) + history.append({"progress": note or {}, "ts": _now_iso()}) + history = _drop_oldest_progress_notes(history, _MAX_PROGRESS_NOTES) + cur.execute( + "UPDATE tasks SET history=? WHERE task_id=?", + (json.dumps(history), task_id), + ) + async def queued(self) -> list[Task]: """Return all queued tasks ordered oldest-first. diff --git a/src/hyperloom/orchestrator/trace/__init__.py b/src/hyperloom/orchestrator/trace/__init__.py index 0785f2c202..4a01e144bc 100644 --- a/src/hyperloom/orchestrator/trace/__init__.py +++ b/src/hyperloom/orchestrator/trace/__init__.py @@ -25,6 +25,8 @@ * :mod:`langfuse_mapping` — projection of local rows onto Langfuse traces / spans / generations / scores. * :mod:`trace_env` — the env-var knobs and credential resolution. +* :mod:`task_progress` — the ambient heartbeat a long composite action reports + its internal units through (:func:`progress_scope`, :func:`report_progress`). The collector that joins this ledger with the decision streams lives in ``src/hyperloom/inference_optimizer/breakdown/collectors/decision.py`` (``collect_decision_trace``). @@ -51,6 +53,7 @@ parse_codex_jsonl_error, parse_codex_jsonl_usage, ) +from .task_progress import progress_scope, report_progress from .trace_env import langfuse_live_enabled __all__ = [ @@ -67,6 +70,8 @@ "parse_claude_stream_json_usage", "parse_codex_jsonl_error", "parse_codex_jsonl_usage", + "progress_scope", "redact_secrets", + "report_progress", "write_mcp_setup_once", ] diff --git a/src/hyperloom/orchestrator/trace/task_progress.py b/src/hyperloom/orchestrator/trace/task_progress.py new file mode 100644 index 0000000000..3c09cbcd11 --- /dev/null +++ b/src/hyperloom/orchestrator/trace/task_progress.py @@ -0,0 +1,215 @@ +# SPDX-FileCopyrightText: 2026 Advanced Micro Devices, Inc. +# SPDX-License-Identifier: MIT + +"""Ambient progress heartbeat for long-running tasks. + +A composite action — an explore grid over a dozen variants, a baseline +double-run, a profile plus its analysis — is a single ``tasks`` row that +internally completes many units of work over hours. Between dispatch and +return it emits nothing durable, so a healthy 80-minute run and a wedged one +leave identical evidence, and every consumer downstream (stall detection, the +journal, an operator reading the session) is blind for the duration. + +The reporter is ambient rather than a parameter because the emitters sit deep +inside call chains that already carry a dozen arguments — the grid runner is +eight frames below the executor entry point, reached through several call +sites that have no business knowing about task bookkeeping. A +:class:`~contextvars.ContextVar` set once at the task boundary reaches all of +them, follows ``asyncio.create_task`` and ``asyncio.to_thread``, and stays +correctly scoped when tasks run concurrently. + +Emitters call :func:`report_progress` unconditionally. Outside a scope — a +unit test, a CLI entry point driving an executor directly — it is a no-op. +""" + +from __future__ import annotations + +import asyncio +import threading +from contextlib import asynccontextmanager, contextmanager, suppress +from contextvars import ContextVar +from typing import Any, AsyncIterator, Awaitable, Callable, Iterator + +import logging + +log = logging.getLogger(__name__) + +# Well below the 300s a consumer waits before calling an agent silent, so a +# step that is genuinely working is never one missed tick away from an +# accusation. +_OUTPUT_HEARTBEAT_INTERVAL_S: float = 60.0 + +# How long teardown waits for the driver to finish the note it is in. A note is +# one small SQLite write, so anything near this bound means the sink is wedged +# — at which point the executor's own exit matters more than the last heartbeat. +_DRIVER_STOP_GRACE_S: float = 5.0 + +ProgressReporter = Callable[..., Awaitable[None]] + +_REPORTER: ContextVar[ProgressReporter | None] = ContextVar( + "hyperloom_task_progress_reporter", + default=None, +) + + +@contextmanager +def progress_scope(reporter: ProgressReporter | None) -> Iterator[None]: + """Bind ``reporter`` as the ambient progress sink for the enclosed work. + + Args: + reporter (ProgressReporter | None): ``async (**note) -> None`` sink, + typically bound to one task row. ``None`` clears any outer scope, + which is what nested execution of an unrelated task wants. + + Yields: + None: For the duration of the ``with`` block. + """ + token = _REPORTER.set(reporter) + try: + yield + finally: + _REPORTER.reset(token) + + +async def report_progress(**note: Any) -> None: + """Report that the enclosing task finished a unit of work. + + Best-effort in every direction: no scope, a sink that raises, a task row + reaped underneath — none of it is worth failing the work being reported. + + Args: + **note (Any): Structured detail for the unit that landed. ``unit`` + (e.g. ``"variant"``, ``"baseline_round"``) and a human-readable + ``label`` are the conventional keys; consumers treat the rest as + opaque. + """ + reporter = _REPORTER.get() + if reporter is None: + return + try: + await reporter(**note) + except Exception as exc: # noqa: BLE001 — a heartbeat never breaks its caller + log.debug("task progress note dropped: %r", exc) + + +class OutputActivity: + """Thread-safe tally of the output a child process has produced. + + The reader lives in a subprocess pump thread while the heartbeat lives on + the event loop, so the two sides share nothing but this counter. + """ + + def __init__(self) -> None: + self._lines = 0 + self._lock = threading.Lock() + + def note(self) -> None: + """Record one more line of child output. Callable from any thread.""" + with self._lock: + self._lines += 1 + + def count(self) -> int: + """Read the tally. + + Returns: + int: Lines recorded so far; never decreases. + """ + with self._lock: + return self._lines + + +@asynccontextmanager +async def heartbeat_while_output_flows( + *, + interval_s: float | None = None, + **note: Any, +) -> AsyncIterator[OutputActivity]: + """Keep reporting a long step alive for as long as its child keeps talking. + + Never a bare timer: a tick that saw no new output reports nothing, so a + wedged child falls silent here too and stays accusable. Faking the + heartbeat would disarm the very signal it feeds. + + Args: + interval_s (float | None): Seconds between ticks; + :data:`_OUTPUT_HEARTBEAT_INTERVAL_S` when ``None``. + **note (Any): Fields stamped on every heartbeat, e.g. ``unit`` and + ``label``. + + Yields: + OutputActivity: Handle the subprocess reader calls :meth:`note` on. + """ + activity = OutputActivity() + stop = asyncio.Event() + tick_s = _OUTPUT_HEARTBEAT_INTERVAL_S if interval_s is None else interval_s + driver = asyncio.create_task(_report_new_output(activity, tick_s, stop, note)) + try: + yield activity + finally: + await _stop_driver(driver, stop) + + +async def _stop_driver(driver: asyncio.Task, stop: asyncio.Event) -> None: + """Stop the heartbeat driver cooperatively, cancelling only if it overruns. + + A hard cancel is the wrong first move: the driver spends its ticks inside a + ``tasks`` row write, and a cancel landing mid-write used to leave the shared + connection inside an open transaction. Setting the flag lets the driver + finish the note it is in. The wait is bounded so a wedged sink delays the + executor by the grace window and no more. + + Nothing here catches :class:`asyncio.CancelledError`: an outer cancel + arriving during teardown belongs to the enclosing task, and swallowing it + would let a cancelled step return as though it had finished. + + Args: + driver (asyncio.Task): The running :func:`_report_new_output` task. + stop (asyncio.Event): The flag it polls between ticks. + """ + stop.set() + try: + done, _pending = await asyncio.wait({driver}, timeout=_DRIVER_STOP_GRACE_S) + except asyncio.CancelledError: + driver.cancel() + raise + if not done: + # Deliberately not awaited: the driver is stuck in a sink that already + # overran its grace, and the step it was reporting for has returned. + driver.cancel() + + +async def _report_new_output( + activity: OutputActivity, + interval_s: float, + stop: asyncio.Event, + note: dict[str, Any], +) -> None: + """Report one heartbeat per interval in which new output arrived. + + Args: + activity (OutputActivity): Counter the reader thread advances. + interval_s (float): Seconds between ticks. + stop (asyncio.Event): Set by teardown; ends the loop at the next tick + boundary instead of the driver being cancelled mid-write. + note (dict[str, Any]): Fields stamped on every heartbeat. + """ + seen = 0 + while True: + with suppress(asyncio.TimeoutError): + await asyncio.wait_for(stop.wait(), timeout=interval_s) + if stop.is_set(): + return + current = activity.count() + if current == seen: + continue + seen = current + await report_progress(status="running", output_lines=current, **note) + + +__all__ = [ + "OutputActivity", + "ProgressReporter", + "heartbeat_while_output_flows", + "progress_scope", + "report_progress", +]