diff --git a/bench/trace_triage/README.md b/bench/trace_triage/README.md index eea82a9c52..35d874d14e 100644 --- a/bench/trace_triage/README.md +++ b/bench/trace_triage/README.md @@ -112,11 +112,12 @@ Delete `posture` later and the record is still true. | `cache-collapse` | pooled prompt cache hit below the floor measured across nine arms | | `repeated-file-read` | one path named by five or more read-shaped calls in one trial | | `grep-ere-false-negative` | a `grep` zero-match on an ERE pattern with none of the POSIX-fallback disclosure #2989 attaches | +| `blind-wait` | a `bash` call whose text waits in `sleep` past the bound `bash/wait.rs` declines at | `--list-detectors` prints the live registry. -The last two read their thresholds from [`bands.py`](bands.py), which records -the nine-arm survey they were measured off — and which is also where a metric +`cache-collapse` and `repeated-file-read` read their thresholds from +[`bands.py`](bands.py), which records the nine-arm survey they were measured off — and which is also where a metric that *cannot* separate a healthy arm from a broken one is marked as such, so it is reported and never concluded from. diff --git a/bench/trace_triage/banned.py b/bench/trace_triage/banned.py index 9fd6651bb7..546d16ef71 100644 --- a/bench/trace_triage/banned.py +++ b/bench/trace_triage/banned.py @@ -275,6 +275,19 @@ class ReportOnly: "worth reading, not worth killing." ) ), + "blind-wait": ReportOnly( + reason=( + "a build carrying the rung in `crates/stella-tools/src/bash/wait.rs` " + "declines these before the spawn, so on a current binary this is close " + "to the `FIXED_REGRESSION` shape. It stays report-only for two reasons. " + "The before/after this detector exists to measure (`#3753`) runs the " + "pre-rung build as its control arm, and a first-trial trip would abort " + "the control. And a finding is not proof the fix is absent: the rung " + "covers `bash`, and the predicate cannot see a duration reached through " + "a variable, so both a false positive and a false negative are " + "reachable. It describes an agent waiting badly, which is a result." + ) + ), "repeated-file-read": ReportOnly( reason=( "same shape as the band metrics above — 2 of 20 trials on s5b2. It " diff --git a/bench/trace_triage/detectors.py b/bench/trace_triage/detectors.py index 86b532bfc0..551755fa6e 100644 --- a/bench/trace_triage/detectors.py +++ b/bench/trace_triage/detectors.py @@ -53,6 +53,7 @@ def _my_shape(run: Run) -> list[Finding]: import bands from fingerprint import Fingerprint, fingerprint_of from run_trace import Run, Trial +from waits import REFUSAL_BOUND_SECS, waits_in # A `bash` error envelope whose message is at least this long, and this many # lines, before its `[exit code: N]` trailer is carrying real output that the @@ -1278,3 +1279,74 @@ def _graded_void_trial(run: Run) -> list[Finding]: ], ) ] + + + +@detector( + code="blind-wait", + title="a bash call sat in `sleep` for longer than a whole command's default limit", + site="crates/stella-tools/src/bash/wait.rs", + search_terms=("blind sleep tool time", "sleep instead of polling"), +) +def _blind_wait(run: Run) -> list[Finding]: + """`bash` calls that wait on a fixed number past the rung. + + The measurement behind `#3753`. A blind `sleep N` costs N. A poll loop + costs one pass. Both look like a wait. Elapsed time tells them apart. So + each row carries the seconds asked for and the seconds spent. + """ + occurrences = [] + total_declared = 0 + total_elapsed = 0.0 + for trial in run.trials: + for wait in waits_in(trial): + if not wait.declined_by_the_shipped_rung: + continue + total_declared += wait.declared_sleep_secs + total_elapsed += wait.elapsed_secs or 0.0 + spent = ( + f"{wait.elapsed_secs:.1f}s spent" + if wait.elapsed_secs is not None + else "no result recorded" + ) + occurrences.append( + Occurrence( + trial_uuid=trial.trial_uuid, + task_id=trial.task_id, + s3_key=trial.s3_key(), + location=( + f"bash call `{wait.call_id}` — {wait.declared_sleep_secs}s of " + f"`sleep` asked for, {spent}" + ), + excerpt=wait.command[:800], + ) + ) + if not occurrences: + return [] + return [ + Finding( + detector="blind-wait", + site="crates/stella-tools/src/bash/wait.rs", + variant_source=f"foreground sleep over {REFUSAL_BOUND_SECS}s", + title="a bash call waited on a number of seconds instead of on the thing", + summary=( + f"These calls asked for {total_declared}s of `sleep`. They spent " + f"{total_elapsed:.0f}s. The turn pays the whole wait. It pays it even " + "when the thing arrives early. A poll loop returns when it is ready. " + "A build with the rung in `bash/wait.rs` declines these before the " + "spawn. So on a new build the count is the finding, not the seconds." + ), + occurrences=occurrences, + denominator=len(run.trials), + search_terms=("blind sleep tool time", "sleep instead of polling"), + caveats=[ + "This reads the command text, never a measured wait. A `sleep` " + "reached through a variable is invisible. So it is a floor on the " + "blind waiting in a run, not a census.", + f"The {REFUSAL_BOUND_SECS}s bound is the shipped one. An old trace is " + "scored against a rule its binary never ran. That is what makes a " + "before and an after line up. It is not a claim about what the old " + "build refused.", + ], + ) + ] diff --git a/bench/trace_triage/tests/test_postmortem.py b/bench/trace_triage/tests/test_postmortem.py index ec1573074c..4698a79ef8 100644 --- a/bench/trace_triage/tests/test_postmortem.py +++ b/bench/trace_triage/tests/test_postmortem.py @@ -21,7 +21,7 @@ from bands import arm_metrics, trial_metrics from fixtures import event, ok, tool_pair, write_run -from postmortem import build_report, cohort_of, render_markdown, write_report +from postmortem import build_report, render_markdown, write_report from run_trace import load_run # -------------------------------------------------------------------------- diff --git a/bench/trace_triage/tests/test_waits.py b/bench/trace_triage/tests/test_waits.py new file mode 100644 index 0000000000..25a9dcd638 --- /dev/null +++ b/bench/trace_triage/tests/test_waits.py @@ -0,0 +1,126 @@ +"""The wait parser and the `blind-wait` detector, against real command text. + +Every command string below was sent by a trial in arenabench match +`13f7f2bb533d`. They are kept verbatim because the discrimination this code +has to make is between two shapes that look alike and cost 13x differently: +a blind `sleep N`, which always costs N, and a poll loop, which costs one pass +when the check passes early. That match measured the loop at 20.9s and the +blind wait beside it at 280.4s. +""" + +from __future__ import annotations + +from detectors import run_all +from fixtures import ok, write_run +from run_trace import load_run +from waits import ADVISORY_BOUND_SECS, REFUSAL_BOUND_SECS, blocking_sleep_seconds + +# The two calls that dominated the panel's tool time. +BACKGROUNDED_INSTALL = ( + "timeout 500 pip install --quiet torch --index-url " + "https://download.pytorch.org/whl/cpu 2>&1 | tail -30 &\n" + "BGPID=$!\nsleep 490\nwait $BGPID 2>/dev/null\necho done" +) +BLIND_POLL = "sleep 280; tail -30 /tmp/apt_install.log; echo ---; ps aux|grep apt" + +# The same agent, in the same trial, getting it right. +POLL_LOOP = ( + 'for i in $(seq 1 25); do sleep 20; if ! ps aux | grep -q "[a]pt-get install"; ' + "then echo DONE; break; fi; echo waiting $i; done; which g++ gcc" +) +NOHUP_START = ( + "nohup apt-get install -y g++ > /tmp/apt_install.log 2>&1 & sleep 2; echo started" +) +# The shape the advisory's own remedy text recommends. +CHECK_FIRST_LOOP = "for i in $(seq 30); do curl -sf http://localhost:8080 && break; sleep 1; done" + + +def test_a_backgrounded_install_is_not_part_of_the_wait(): + """The install runs beside the wait; only the `sleep` is the wait.""" + assert blocking_sleep_seconds(BACKGROUNDED_INSTALL) == 490 + assert blocking_sleep_seconds(BLIND_POLL) == 280 + + +def test_a_poll_loop_is_read_as_a_pass_or_not_at_all(): + """Neither reading of a poll loop reaches the bound. + + A segment counts only when it is exactly `sleep N`. `do sleep 20;` keeps + the loop keyword in the segment, so it reads as no sleep; the same loop + written `…; sleep 1; done` reads as one second, which is one pass rather + than the worst case. Both are far under the bound, so the cheap pattern is + never declined. The seconds this predicate cannot see are checked against + the Rust it mirrors in `crates/stella-core/src/shell_text.rs`. + """ + assert blocking_sleep_seconds(POLL_LOOP) is None + assert blocking_sleep_seconds(CHECK_FIRST_LOOP) == 1 + assert blocking_sleep_seconds(NOHUP_START) == 2 + + +def test_the_bounds_separate_the_two_shapes(): + assert ADVISORY_BOUND_SECS < REFUSAL_BOUND_SECS + for command in (BACKGROUNDED_INSTALL, BLIND_POLL): + assert blocking_sleep_seconds(command) >= REFUSAL_BOUND_SECS, command + for command in (POLL_LOOP, CHECK_FIRST_LOOP, NOHUP_START): + assert (blocking_sleep_seconds(command) or 0) < REFUSAL_BOUND_SECS, command + + +def test_a_command_that_never_sleeps_reports_nothing(): + assert blocking_sleep_seconds("grep sleep /app/main.c") is None + assert blocking_sleep_seconds("cargo build --release") is None + # A duration this parser cannot read is not a wait it may invent. + assert blocking_sleep_seconds("sleep $DELAY") is None + + +def _bash_call(call_id: str, command: str, *, started_ms: int, ended_ms: int): + return [ + { + "ts": started_ms, + "type": "tool_start", + "call": {"call_id": call_id, "name": "bash", "input": {"command": command}}, + }, + {"ts": ended_ms, "type": "tool_result", "call_id": call_id, "output": ok("done")}, + ] + + +def test_the_detector_fires_on_the_blind_wait_and_leaves_the_poll_loop_alone(tmp_path): + write_run( + tmp_path, + [ + { + "task": "rstan-to-pystan__AAA", + "reward": 0, + "events": [ + *_bash_call("blind", BLIND_POLL, started_ms=0, ended_ms=280_400), + *_bash_call("loop", POLL_LOOP, started_ms=300_000, ended_ms=320_900), + {"ts": 1, "type": "step_usage", "role": "worker", "model": "m"}, + ], + } + ], + ) + findings = [f for f in run_all(load_run(tmp_path, "testrun")) if f.detector == "blind-wait"] + assert len(findings) == 1 + finding = findings[0] + assert finding.count == 1, "the poll loop is not a blind wait" + only = finding.occurrences[0] + assert "280s of `sleep` asked for" in only.location + assert "280.4s spent" in only.location + assert "sleep 280" in only.excerpt + + +def test_the_detector_is_silent_when_nothing_waits(tmp_path): + write_run( + tmp_path, + [ + { + "task": "alpha__AAA", + "reward": 1, + "events": [ + *_bash_call("build", "cargo build", started_ms=0, ended_ms=4_000), + {"ts": 1, "type": "step_usage", "role": "worker", "model": "m"}, + ], + } + ], + ) + assert not [ + f for f in run_all(load_run(tmp_path, "testrun")) if f.detector == "blind-wait" + ] diff --git a/bench/trace_triage/waits.py b/bench/trace_triage/waits.py new file mode 100644 index 0000000000..52f02c34f5 --- /dev/null +++ b/bench/trace_triage/waits.py @@ -0,0 +1,141 @@ +"""What a trial spent waiting: the `sleep` seconds a command committed to. + +This mirrors `blocking_sleep_seconds` in `crates/stella-core/src/shell_text.rs`, +which is the predicate the shipped `bash` rungs ask. A trace read with a +different predicate than the binary used would report a share the binary never +acted on. + +The mirror is close, not exact. Rust uses a quote-aware `shell_words`. Here +the split is on whitespace, once the operators are cut out. So a `sleep` in a +quoted string is a sleep here and data there. No trace this has run against +has that shape. If one turns up, fix the parser rather than explain the +number. + +Both sides share the segment rule, and it is strict. A segment counts only +when it is exactly `sleep N`. So `…; sleep 1; done` reads as one second. +`do sleep 20;` reads as no sleep, because the loop keyword is in the segment. +The predicate under-reads a poll loop. That is why a poll loop is never +declined. +""" + +from __future__ import annotations + +import re +from dataclasses import dataclass + +#: The `sleep` seconds past which `bash` declines a call before it spawns. +#: This is `SLEEP_REFUSAL_THRESHOLD_SECS` in +#: `crates/stella-tools/src/bash/wait.rs`, which is that tool's +#: `DEFAULT_TIMEOUT_SECS`. It lives here so an old trace and a new one are +#: scored against one bound. +REFUSAL_BOUND_SECS = 120 + +#: The seconds past which the call still runs and the result names the wait — +#: `SLEEP_ADVISORY_THRESHOLD_SECS` in the same file. +ADVISORY_BOUND_SECS = 30 + +_OPERATORS = frozenset({";", "&&", "||", "|", "&", "\n"}) +_UNITS = {"s": 1.0, "m": 60.0, "h": 3600.0, "d": 86400.0} + +#: Longest first, so `&&` is one token and not two. The separator is captured +#: and kept. `shell_words` does the same: an operator is its own word, even +#: glued to one. +_SPLIT = re.compile(r"(&&|\|\||;|\||&|\n)") + + +def _words(command: str) -> list[str]: + out: list[str] = [] + for piece in _SPLIT.split(command): + if piece in _OPERATORS: + out.append(piece) + else: + out.extend(piece.split()) + return out + + +def _arg_seconds(arg: str) -> float | None: + digits, per_unit = arg, 1.0 + if arg and arg[-1] in _UNITS: + digits, per_unit = arg[:-1], _UNITS[arg[-1]] + try: + return float(digits) * per_unit + except ValueError: + return None + + +def blocking_sleep_seconds(command: str) -> int | None: + """Seconds this command waits in a foreground `sleep`, or `None` for none. + + A segment the shell backgrounds is skipped, as the Rust walk skips it. + `pip install … & sleep 490` waits 490 seconds. The install is not part of + the wait. + """ + words = _words(command) + total = 0.0 + saw_sleep = False + start = 0 + for end in range(len(words) + 1): + separator = words[end] if end < len(words) and words[end] in _OPERATORS else None + if end < len(words) and separator is None: + continue + segment = words[start:end] + start = end + 1 + if separator == "&": + continue + if len(segment) == 2 and segment[0] == "sleep": + secs = _arg_seconds(segment[1]) + if secs is not None: + total += secs + saw_sleep = True + return round(total) if saw_sleep else None + + +@dataclass(frozen=True) +class Wait: + """One `bash` call that committed to a wait, with what it actually cost.""" + + call_id: str + command: str + declared_sleep_secs: int + elapsed_secs: float | None + + @property + def declined_by_the_shipped_rung(self) -> bool: + return self.declared_sleep_secs >= REFUSAL_BOUND_SECS + + +def waits_in(trial) -> list[Wait]: # noqa: ANN001 — `run_trace.Trial`, imported by its user + """Every `bash` call in `trial` whose text commits to a foreground sleep. + + `elapsed_secs` joins `tool_start` to `tool_result` by `call_id`. It is the + wall clock the call took, not the seconds it asked for. The two agree on a + blind wait and part on anything that exits early, so both are carried. + """ + # `start_index` is a line number, not an index into `events`. So the start + # stamp comes from the `tool_start` event itself. + starts = { + str(e.get("call", {}).get("call_id") or ""): e.get("ts") + for e in trial.of_type("tool_start") + } + found: list[Wait] = [] + for call in trial.tool_calls: + command = call.input.get("command") + if call.name != "bash" or not isinstance(command, str): + continue + secs = blocking_sleep_seconds(command) + if secs is None: + continue + elapsed = None + started = starts.get(call.call_id) + ended = call.result.get("ts") if call.result else None + if isinstance(started, int | float) and isinstance(ended, int | float): + elapsed = (ended - started) / 1000.0 + found.append( + Wait( + call_id=call.call_id, + command=command, + declared_sleep_secs=secs, + elapsed_secs=elapsed, + ) + ) + return found diff --git a/crates/stella-tools/src/bash.rs b/crates/stella-tools/src/bash.rs index 19a6f8a274..fc81fe1630 100644 --- a/crates/stella-tools/src/bash.rs +++ b/crates/stella-tools/src/bash.rs @@ -67,9 +67,10 @@ use stella_protocol::tool::{ToolOutput, ToolSchema}; use crate::registry::Tool; +mod wait; mod words; -use stella_core::shell_text::blocking_sleep_seconds; +use wait::{blocking_wait_refusal, sleep_advisory}; use words::{cd_escape_target, shell_words}; const DEFAULT_TIMEOUT_SECS: u64 = 120; @@ -377,58 +378,6 @@ fn drift_advisory(command: &str, root: &Path) -> Option { None } -/// The per-call half of #2022: a `sleep` long enough to be worth naming in -/// the result the model reads. -/// -/// The cheap rung, and a low one — 30s catches the shape on the very call -/// that made it, before any accumulation. What it cannot see is the *turn*: -/// loop detection reads interleaved calls as progress and the budget guard is -/// spend-based, so idling costs $0. That blind spot is the engine's to close, -/// over the seconds a whole turn has asked for (`stella_core`'s stall rung, -/// `driver::loop_escalation`), and this advisory is not it. -/// -/// The threshold is also what keeps a retry backoff quiet, now that -/// [`blocking_sleep_seconds`] counts a sleep beside real work. A `sleep 2 && -/// curl` reports two seconds and is ignored here; a `sleep 490` next to a -/// backgrounded install reports 490 and is named. -/// -/// Honest visibility, not a refusal, on either rung: a static text-shape check -/// on the command ([`blocking_sleep_seconds`]), never a measured elapsed time, -/// so it stays deterministic for the loop detector. A timing in -/// [`stella_protocol::tool::ToolOutput`] makes identical calls look distinct -/// and defeats that detector, which is why none is embedded here. -const SLEEP_ADVISORY_THRESHOLD_SECS: u64 = 30; - -/// A footer naming a `sleep` that crossed the advisory threshold, and a -/// remedy the agent can actually perform. -/// -/// **The remedy has to name a tool that exists.** This advisory shipped for a -/// while pointing at `read_output`/`wait_for` — the managed-process family, -/// which #3244 deleted and the tool restore did not bring back. Every long -/// `sleep` therefore handed the model a directive with no tool behind it, -/// which is worse than the silence it replaced: an instruction that cannot be -/// followed teaches the model to discount the next one too. The text was -/// restored verbatim along with the rest of `bash`, and the stale half was -/// only caught by an issue sweep afterwards. -/// -/// So the wording now stays inside what the surface offers: a short poll in a -/// loop, which `bash` can do on its own, and which returns as soon as the -/// condition holds instead of blocking the whole interval. -fn sleep_advisory(command: &str) -> Option { - let secs = blocking_sleep_seconds(command)?; - if secs < SLEEP_ADVISORY_THRESHOLD_SECS { - return None; - } - Some(format!( - "\n\nnote: this call spent {secs}s inside `sleep`, and the whole interval was charged \ - to the turn whether or not the thing you are waiting for finished early. If you are \ - waiting on something, poll for the condition instead of sleeping through it — a \ - bounded retry loop that checks and exits as soon as the check passes (for example \ - `for i in $(seq 30); do && break; sleep 1; done`) costs a fraction of a blind \ - wait." - )) -} - /// How long this call may run: the model's `timeout_secs`, clamped to /// [`crate::exec::MAX_TIMEOUT_SECS`], or the default when it asked for /// nothing usable. @@ -516,7 +465,10 @@ impl Tool for Bash { lose the record for every one of them. You can only CHANGE things inside this \ session's directories (get_environment reports the workspace root), so a \ command that creates, edits, deletes or moves a file elsewhere is refused \ - before it runs. Prefer write_file/edit_file/delete_file over shell equivalents \ + before it runs. A command that would sit in sleep for longer than the default \ + timeout is refused before it runs too: poll for what you are waiting on in a \ + short loop, so the call returns when the thing is ready instead of costing you \ + however long you guessed. Prefer write_file/edit_file/delete_file over shell equivalents \ for files in the workspace: their changes are what this turn's diff and \ verification are computed from.{scratch}" ), @@ -552,6 +504,17 @@ impl Tool for Bash { refusal, ); } + // The same moment, for the same reason. `sleep_advisory` below names a + // long wait in the result, by which time the turn has already paid for + // it; past `SLEEP_REFUSAL_THRESHOLD_SECS` the wait is declined here + // instead, and the model answers at the cost of one model call rather + // than the interval it asked to sit through (#3753). + if let Some(refusal) = blocking_wait_refusal(command) { + return ToolOutput::classified_error( + stella_protocol::ErrorClass::RefusedByPolicy, + refusal, + ); + } let timeout_secs = effective_timeout(input).as_secs(); // trace: true prefixes `set -x` so every executed line echoes to @@ -1084,89 +1047,31 @@ mod tests { } } - /// #2022 witness: the exact observed pathological shape - /// (`sleep 300; echo done`, `sleep 120` alone) is caught and its - /// accumulated seconds are named, so the advisory can fire on it. - #[test] - fn a_sleep_is_detected_and_summed() { - assert_eq!(blocking_sleep_seconds("sleep 300; echo done"), Some(300)); - assert_eq!(blocking_sleep_seconds("sleep 120"), Some(120)); - assert_eq!(blocking_sleep_seconds("sleep 60"), Some(60)); - // Several sleeps in one call accumulate. - assert_eq!( - blocking_sleep_seconds("sleep 30 && sleep 30"), - Some(60), - "accumulated sleep across the whole call, not just the last segment" - ); - assert_eq!( - blocking_sleep_seconds("sleep 2.5"), - Some(3), - "rounds to the nearest second" - ); - } - - /// A short wait stays unflagged, and the threshold is what keeps it that - /// way. A retry backoff and a five-second pause before a `tail` both - /// report their seconds; neither crosses the line. - #[test] - fn a_short_sleep_beside_real_work_is_not_flagged() { - for command in [ - "sleep 2 && curl -s http://localhost:8080", - "sleep 5; tail -f build.log", - "echo waiting; sleep 5; ls", - "for i in $(seq 30); do curl -sf http://localhost:8080 && break; sleep 1; done", - ] { - assert_eq!( - sleep_advisory(command), - None, - "advice was appended for `{command}`" - ); - } - // A command that never calls `sleep` has nothing to report at all. - assert_eq!(blocking_sleep_seconds("grep sleep /app/main.c"), None); - } - - /// The two waits that cost `13f7f2bb533d` most of a quarter of its - /// measured tool time. Both sit beside real work, so both were silent - /// while the predicate demanded a command made of nothing but sleeps. - /// - /// `pytorch-model-cli` backgrounded a `pip install torch` and then blocked - /// on a fixed 490s wait instead of on the install; `rstan-to-pystan` slept - /// 280s and then tailed the apt log it was waiting for. Each one is what - /// the advisory's own remedy describes — poll for the condition — and - /// neither was ever told. - #[test] - fn a_long_sleep_beside_real_work_is_named() { - let backgrounded_install = "timeout 500 pip install --quiet torch &\nBGPID=$!\nsleep 490\nwait $BGPID 2>/dev/null\necho DONE"; - let note = sleep_advisory(backgrounded_install).expect("over threshold"); - assert!(note.contains("490s"), "{note}"); - - let blind_poll = "sleep 280; tail -30 apt_install.log; ps aux | grep apt"; - let note = sleep_advisory(blind_poll).expect("over threshold"); - assert!(note.contains("280s"), "{note}"); - assert!(note.contains("poll"), "{note}"); - } - - #[test] - fn the_sleep_advisory_only_fires_past_the_threshold() { + /// The refusal is what the tool returns, not just what the predicate + /// says: `execute` answers immediately and never spawns the shell. A + /// `sleep 300` that ran would take five minutes, so the elapsed time is + /// the proof that it did not. + #[tokio::test] + async fn a_declined_wait_returns_at_once_and_never_spawns() { + let dir = std::env::temp_dir(); + let started = std::time::Instant::now(); + let out = Bash::new(None) + .execute( + &serde_json::json!({"command": "sleep 300; echo woke", "timeout_secs": 400}), + &cx(&dir), + ) + .await; + let elapsed = started.elapsed(); + let ToolOutput::Error { message, class, .. } = out else { + panic!("a 300s wait must be declined, got: {out:?}"); + }; + assert_eq!(class, Some(stella_protocol::ErrorClass::RefusedByPolicy)); + assert!(message.contains("300s"), "{message}"); + assert!(!message.contains("woke"), "the shell ran: {message}"); assert!( - sleep_advisory("sleep 5").is_none(), - "under threshold, no nudge" + elapsed < std::time::Duration::from_secs(2), + "the wait was spent rather than declined: {elapsed:?}" ); - let note = sleep_advisory("sleep 300; echo done").expect("over threshold"); - assert!(note.contains("300s")); - // The remedy must be one the agent can actually perform. This - // assertion used to require the string `read_output` — a tool #3244 - // deleted — so it kept a directive with no tool behind it green for - // as long as it existed. Now it pins that the note names polling, - // and that it names NO tool the catalog does not carry. - assert!(note.contains("poll"), "{note}"); - for gone in ["read_output", "wait_for", "start_process"] { - assert!( - !note.contains(gone), - "the advisory names `{gone}`, which is not on the tool surface: {note}" - ); - } } #[tokio::test] diff --git a/crates/stella-tools/src/bash/wait.rs b/crates/stella-tools/src/bash/wait.rs new file mode 100644 index 0000000000..618b682684 --- /dev/null +++ b/crates/stella-tools/src/bash/wait.rs @@ -0,0 +1,278 @@ +// SPDX-License-Identifier: AGPL-3.0-only +// Copyright (c) 2026 Oxagen, Inc. Commercial licensing: licensing@oxagen.sh + +//! What `bash` does about a command that waits. +//! +//! Two rungs read a `sleep` out of the command text before anything runs. +//! Past [`SLEEP_ADVISORY_THRESHOLD_SECS`] the call runs, and +//! [`sleep_advisory`] names the wait in the result. Past +//! [`SLEEP_REFUSAL_THRESHOLD_SECS`] the call does not start at all. +//! [`blocking_wait_refusal`] declines it and no shell is spawned. +//! +//! Both rungs ask [`blocking_sleep_seconds`] the same question. They differ +//! in what the answer buys. +//! +//! The upper rung exists because the lower one cannot save its own call. That +//! note rides the result of the call it fires on. By the time the model reads +//! it, the wait is paid for (`#3753`). +//! +//! This sits beside [`super`] for the reason [`super::words`] does. `bash.rs` +//! is at the 1500-line ceiling. A wait is also its own subject, apart from +//! the tool's spawn, timeout and policy body. + +use stella_core::shell_text::blocking_sleep_seconds; + +/// The per-call rung (`#2022`): a `sleep` this long is named in the result +/// the model reads. +/// +/// The bound is low on purpose. It catches the shape on the call that made +/// it, before any accumulation. +/// +/// It cannot see the turn. Loop detection reads interleaved calls as +/// progress. The budget guard counts spend, and idling costs $0. Closing that +/// gap is the engine's job, over the seconds a whole turn asked for +/// (`stella_core`'s stall rung, `driver::loop_escalation`). +/// +/// The bound also keeps a retry backoff quiet. [`blocking_sleep_seconds`] +/// counts a sleep beside real work. So `sleep 2 && curl` reports two seconds +/// and is ignored. A `sleep 490` next to a backgrounded install reports 490 +/// and is named. +/// +/// A wait this short is named and still runs. +/// +/// Both rungs read the command text and never a measured elapsed time. That +/// keeps them deterministic for the loop detector. A timing in +/// [`stella_protocol::tool::ToolOutput`] would make identical calls look +/// distinct and defeat it, so none is embedded here. +const SLEEP_ADVISORY_THRESHOLD_SECS: u64 = 30; + +/// A footer naming a `sleep` past the advisory bound, with a remedy the agent +/// can perform. +/// +/// **The remedy has to name a tool that exists.** This note once pointed at +/// `read_output` and `wait_for`. Those went with the cut to twelve built-in +/// tools (`#3244`), and the restore left them out. Every long `sleep` then +/// handed the model a directive with no tool behind it. That is worse than +/// silence. An instruction nobody can follow teaches the model to discount +/// the next one. +/// +/// The wording now stays inside what the surface offers. A short poll in a +/// loop is something `bash` can do on its own, and it returns as soon as the +/// condition holds. +pub(super) fn sleep_advisory(command: &str) -> Option { + let secs = blocking_sleep_seconds(command)?; + if secs < SLEEP_ADVISORY_THRESHOLD_SECS { + return None; + } + Some(format!( + "\n\nnote: this call spent {secs}s inside `sleep`, and the whole interval was charged \ + to the turn whether or not the thing you are waiting for finished early. If you are \ + waiting on something, poll for the condition instead of sleeping through it — a \ + bounded retry loop that checks and exits as soon as the check passes (for example \ + `for i in $(seq 30); do && break; sleep 1; done`) costs a fraction of a blind \ + wait." + )) +} + +/// How long a `sleep` may be before the call is declined rather than named. +/// See [`blocking_wait_refusal`] for why the bound is +/// [`super::DEFAULT_TIMEOUT_SECS`]. +const SLEEP_REFUSAL_THRESHOLD_SECS: u64 = super::DEFAULT_TIMEOUT_SECS; + +/// The rungs must stay in order. A call is advised first and refused second. +/// +/// The refusal bound is `DEFAULT_TIMEOUT_SECS`. Lower that and it could drop +/// under the advisory, and no one would edit this file. +/// +/// This is checked when the code builds, not when tests run. Both sides are +/// constants, so a plain `assert!` could never fail a build that compiled. +/// Clippy says as much. This form breaks the build instead. +const _: () = assert!(SLEEP_ADVISORY_THRESHOLD_SECS < SLEEP_REFUSAL_THRESHOLD_SECS); + +/// The rung above the advisory. A `sleep` this long is the command, not part +/// of one, so the call is declined before the spawn. +/// +/// [`sleep_advisory`] rides the result of the call it fires on. The wait is +/// paid for by the time the model reads the remedy. On the run this rule was +/// measured against, it never saved a second. The two calls it would have +/// named ran 489.5s and 280.4s, and the note arrived after both. +/// +/// A refusal that arrives once the process has run is a report, not a fence. +/// [`super::shell_write_audit`] reads the text before the spawn for that +/// reason, and so does this (`#3753`). +/// +/// The bound is [`super::DEFAULT_TIMEOUT_SECS`]. A wait that outlasts the +/// default limit for a whole command is the command. In arenabench match +/// `13f7f2bb533d` the calls that sleep at all wait 2s, 20s, 280s and 490s. +/// Any bound between the poll loop and the blind waits declines the same two +/// calls. This one is a constant the tool already has, not a number fitted to +/// that gap. +/// +/// A polling loop survives the rung. [`blocking_sleep_seconds`] reads a +/// segment of exactly `sleep N`, so it sees one pass of +/// `…; && break; sleep 1; done` and answers one second, not the +/// thirty of the worst case. Where the loop keyword shares the segment, as in +/// `do sleep 20;`, it sees no sleep at all. Both readings fall under the +/// bound, so neither shape is declined. The same panel measured such a loop +/// at 20.9s, against 280.4s for the blind wait it replaces. +/// +/// That second reading is the predicate under-reading, and the direction is +/// the safe one here: a wait this rung cannot see is a wait it never +/// declines. It costs the advisory below, which stays silent on the same +/// shape. +pub(super) fn blocking_wait_refusal(command: &str) -> Option { + let secs = blocking_sleep_seconds(command)?; + if secs < SLEEP_REFUSAL_THRESHOLD_SECS { + return None; + } + Some(format!( + "not executed — this call would spend {secs}s inside `sleep`, and the whole interval is \ + charged to this turn whether or not the thing you are waiting for finishes early. Poll \ + for the condition instead: a bounded retry loop that checks and exits as soon as the \ + check passes (for example `for i in $(seq 30); do && break; sleep 10; done`) \ + returns the moment the thing is ready and costs a fraction of a blind wait. If you are \ + waiting on something you started in the background, poll for the evidence that it \ + finished — its log, its process, its output file — rather than sleeping for how long \ + you expect it to take." + )) +} + +#[cfg(test)] +mod tests { + use super::*; + + /// The `#2022` witness: the exact observed pathological shape + /// (`sleep 300; echo done`, `sleep 120` alone) is caught and its + /// accumulated seconds are named, so the advisory can fire on it. + #[test] + fn a_sleep_is_detected_and_summed() { + assert_eq!(blocking_sleep_seconds("sleep 300; echo done"), Some(300)); + assert_eq!(blocking_sleep_seconds("sleep 120"), Some(120)); + assert_eq!(blocking_sleep_seconds("sleep 60"), Some(60)); + // Several sleeps in one call accumulate. + assert_eq!( + blocking_sleep_seconds("sleep 30 && sleep 30"), + Some(60), + "accumulated sleep across the whole call, not just the last segment" + ); + assert_eq!( + blocking_sleep_seconds("sleep 2.5"), + Some(3), + "rounds to the nearest second" + ); + } + + /// A short wait stays unflagged, and the threshold is what keeps it that + /// way. A retry backoff and a five-second pause before a `tail` both + /// report their seconds; neither crosses the line. + #[test] + fn a_short_sleep_beside_real_work_is_not_flagged() { + for command in [ + "sleep 2 && curl -s http://localhost:8080", + "sleep 5; tail -f build.log", + "echo waiting; sleep 5; ls", + "for i in $(seq 30); do curl -sf http://localhost:8080 && break; sleep 1; done", + ] { + assert_eq!( + sleep_advisory(command), + None, + "advice was appended for `{command}`" + ); + } + // A command that never calls `sleep` has nothing to report at all. + assert_eq!(blocking_sleep_seconds("grep sleep /app/main.c"), None); + } + + /// The two waits that cost `13f7f2bb533d` most of a quarter of its + /// measured tool time. Both sit beside real work, so both were silent + /// while the predicate demanded a command made of nothing but sleeps. + /// + /// `pytorch-model-cli` backgrounded a `pip install torch` and then blocked + /// on a fixed 490s wait instead of on the install; `rstan-to-pystan` slept + /// 280s and then tailed the apt log it was waiting for. Each one is what + /// the advisory's own remedy describes — poll for the condition — and + /// neither was ever told. + #[test] + fn a_long_sleep_beside_real_work_is_named() { + let backgrounded_install = "timeout 500 pip install --quiet torch &\nBGPID=$!\nsleep 490\nwait $BGPID 2>/dev/null\necho DONE"; + let note = sleep_advisory(backgrounded_install).expect("over threshold"); + assert!(note.contains("490s"), "{note}"); + + let blind_poll = "sleep 280; tail -30 apt_install.log; ps aux | grep apt"; + let note = sleep_advisory(blind_poll).expect("over threshold"); + assert!(note.contains("280s"), "{note}"); + assert!(note.contains("poll"), "{note}"); + } + + #[test] + fn the_sleep_advisory_only_fires_past_the_threshold() { + assert!( + sleep_advisory("sleep 5").is_none(), + "under threshold, no nudge" + ); + let note = sleep_advisory("sleep 300; echo done").expect("over threshold"); + assert!(note.contains("300s")); + // The remedy must be one the agent can actually perform, so this + // pins that the note names polling and names NO tool the catalog does + // not carry. `read_output` and `wait_for` went with the reduction to + // twelve built-in tools (`#3244`) and the restore left them out. + assert!(note.contains("poll"), "{note}"); + for gone in ["read_output", "wait_for", "start_process"] { + assert!( + !note.contains(gone), + "the advisory names `{gone}`, which is not on the tool surface: {note}" + ); + } + } + + /// **The witness for `#3753`.** The two calls that dominated the panel's + /// tool time are declined before they spawn. Both command strings are the + /// ones the trials sent — arenabench match `13f7f2bb533d`, + /// `pytorch-model-cli` and `rstan-to-pystan` — and between them they ran + /// 770 of the 3,406 seconds of tool execution that match recorded. The + /// advisory named them and could not save them: it is appended to the + /// result of the call it fires on. + #[test] + fn a_wait_longer_than_a_whole_command_never_starts() { + let backgrounded_install = "timeout 500 pip install --quiet torch &\nBGPID=$!\nsleep 490\nwait $BGPID 2>/dev/null\necho DONE"; + let refusal = blocking_wait_refusal(backgrounded_install).expect("490s is over the bound"); + assert!(refusal.starts_with("not executed"), "{refusal}"); + assert!(refusal.contains("490s"), "{refusal}"); + assert!(refusal.contains("Poll for the condition"), "{refusal}"); + + let blind_poll = "sleep 280; tail -30 apt_install.log; ps aux | grep apt"; + let refusal = blocking_wait_refusal(blind_poll).expect("280s is over the bound"); + assert!(refusal.contains("280s"), "{refusal}"); + } + + /// The rung leaves the cheap pattern alone. A poll loop reports the + /// seconds of one iteration, so it stays admissible however many + /// iterations it is willing to run — the same match measured that loop at + /// 20.9s against the 280.4s of the blind wait it replaces. The other + /// waits below the bound keep running too. + #[test] + fn a_poll_loop_and_a_short_wait_still_run() { + for command in [ + "for i in $(seq 1 25); do sleep 20; if ! ps aux | grep -q \"[a]pt-get install\"; then echo DONE; break; fi; done", + "nohup apt-get install -y g++ > apt_install.log 2>&1 &\nsleep 2\necho started", + "sleep 2 && curl -s http://localhost:8080", + "echo waiting; sleep 5; ls", + "grep sleep /app/main.c", + ] { + assert_eq!( + blocking_wait_refusal(command), + None, + "{command} is below the bound and must still run" + ); + } + } + + /// Two rungs, ordered, both reachable: a wait between them is named and + /// still runs, and only the upper one declines. + #[test] + fn the_advisory_and_the_refusal_are_two_rungs() { + let between = "sleep 60; echo done"; + assert!(sleep_advisory(between).is_some(), "named at the lower rung"); + assert_eq!(blocking_wait_refusal(between), None, "and still runs"); + } +} diff --git a/docs/tools/bash.toml b/docs/tools/bash.toml index 9a7ab77813..39d88750c5 100644 --- a/docs/tools/bash.toml +++ b/docs/tools/bash.toml @@ -27,7 +27,7 @@ available_for_speculation = false risk_level = "high" description = ''' -Run a shell command in the workspace root. Returns stdout+stderr with a timeout backstop. You can READ anything on this machine — system headers, the toolchain, a dependency's source. To see a file in the workspace, use read_file rather than cat, sed -n, head or tail: read_file records what you were shown, and edit_file needs that record to tell a stale needle from a file that changed underneath you. Several files, or several ranges, go in ONE read_file call through its files argument — reach for a chain of sed and you lose the record for every one of them. You can only CHANGE things inside this session's directories (get_environment reports the workspace root), so a command that creates, edits, deletes or moves a file elsewhere is refused before it runs. Prefer write_file/edit_file/delete_file over shell equivalents for files in the workspace: their changes are what this turn's diff and verification are computed from. Redirect working files that are NOT deliverables — a captured log, a compiled shim, a scratch script — to $STELLA_SCRATCH, which is already exported into your shell: `apt-get update > $STELLA_SCRATCH/apt.log` needs no lookup. It is writable, nothing there lands in this turn's diff, and it is deleted when the session ends. (get_environment reports its absolute path if a file tool needs one.) +Run a shell command in the workspace root. Returns stdout+stderr with a timeout backstop. You can READ anything on this machine — system headers, the toolchain, a dependency's source. To see a file in the workspace, use read_file rather than cat, sed -n, head or tail: read_file records what you were shown, and edit_file needs that record to tell a stale needle from a file that changed underneath you. Several files, or several ranges, go in ONE read_file call through its files argument — reach for a chain of sed and you lose the record for every one of them. You can only CHANGE things inside this session's directories (get_environment reports the workspace root), so a command that creates, edits, deletes or moves a file elsewhere is refused before it runs. A command that would sit in sleep for longer than the default timeout is refused before it runs too: poll for what you are waiting on in a short loop, so the call returns when the thing is ready instead of costing you however long you guessed. Prefer write_file/edit_file/delete_file over shell equivalents for files in the workspace: their changes are what this turn's diff and verification are computed from. Redirect working files that are NOT deliverables — a captured log, a compiled shim, a scratch script — to $STELLA_SCRATCH, which is already exported into your shell: `apt-get update > $STELLA_SCRATCH/apt.log` needs no lookup. It is writable, nothing there lands in this turn's diff, and it is deleted when the session ends. (get_environment reports its absolute path if a file tool needs one.) ''' # The JSON Schema the model is handed for this tool's arguments, verbatim. diff --git a/website/content/docs/commands/run.mdx b/website/content/docs/commands/run.mdx index 9d2e810284..f2f8accfd2 100644 --- a/website/content/docs/commands/run.mdx +++ b/website/content/docs/commands/run.mdx @@ -15,7 +15,7 @@ stella run [--pipeline ] [--test-command ] [global flags] By default, `stella run` sends your prompt through the **raw step loop**. Here's how that works: the model suggests a tool to run, stella runs it, the result goes back to the model, and this repeats until the model has nothing more to do. There's no interactive prompt window, and stella never asks you for more input. It's the non-interactive version of [`stella chat`](/docs/commands/chat). -Use `--pipeline ` to run the turn through an installed [wrapper plugin](/docs/plugins) instead. The plugin can add context before the turn starts and reports its own results after it ends. +Use `--pipeline ` to run the turn through an installed [wrapper plugin](/docs/plugins) instead. The plugin can add context before the turn starts and reports its own results after it ends. You can name more than one. Separate the ids with commas. They run in the order you give. Because `stella run` is non-interactive, it works well with `--output-format json` or `--output-format stream-json` for automated scripts, and with `--spend-limit` to set a hard cap on spending. @@ -37,6 +37,12 @@ A run you start in a terminal is [supervised](/docs/commands/daemon): it keeps g declared at install time to decide whether another turn should run. The variant id is saved with the run, so you can compare two variants later. If you leave this out, the raw step loop runs on its own. + + **Several plugins at once.** Separate the ids with commas. They run in the order you + write them. So `--pipeline research-v1,plan-v1` grounds first and plans second. The + order is yours to set. No manifest states it. Each plugin gets its own host plane. So + one member cannot reach a role that another member declared. An id named twice is + refused as a typo. So is an empty entry. The test command that an installed verification plugin's own `[oracle]` runs, for