fix(stella-tools): decline a blind wait before the spawn, and give the re-measurement an instrument - #6501
Conversation
…aming it after `bash` has an advisory that fires when a call spends a long time in `sleep`. It is appended to the result of the call it fires on, so the whole interval is already spent by the time the model reads the remedy. On the run #3753 measures, the two calls it would have named ran 489.5s and 280.4s. The note arrived after both, and neither trial got the time back. That is the same thing `shell_write_audit` says about itself two lines above the spawn: a refusal that arrives after the process has run is a report, not a fence. So the sleep check becomes a ladder. Past SLEEP_ADVISORY_THRESHOLD_SECS (30s, unchanged) the call runs and the note names the wait. Past SLEEP_REFUSAL_THRESHOLD_SECS the call does not start, and the model answers a refusal that names the poll-loop remedy. The upper bound is DEFAULT_TIMEOUT_SECS, a constant the tool already has: 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, so every bound between the poll loop and the blind waits declines the same two calls. A polling loop survives by construction, because blocking_sleep_seconds reads one sleep per segment and so reports one pass rather than the worst case. The same match measured that loop at 20.9s against the 280.4s of the blind wait it replaces. The two rungs move to bash/wait.rs beside bash/words.rs, because bash.rs was at the 1500-line ceiling and a wait is its own subject. Refs #3753
The refusal that never fires is the cheapest one. The schema already names what bash refuses before it runs — a write outside the session's directories — so the blind-wait rung belongs in the same sentence rather than only in the refusal a model reads after it has already written the call. docs/tools/bash.toml regenerated by `make tool-docs-update`; the description sentence is the whole diff. Refs #3753
…rument #3753's remaining boxes both need a panel run nobody has paid for. The second one asks whether the blind-wait share fell, "using the same tool_start → tool_result join". That join lives in bench/trace_triage; the question did not. This adds it, so the answer is one command rather than a fresh script whose method nobody can compare to the last one. waits.py mirrors blocking_sleep_seconds from stella-core. The mirror was checked against the Rust on the five commands the recorded match actually sent, and the two agree on all five, including the two disagreements a looser parser gets wrong: a backgrounded install is not part of the wait, and `do sleep 20;` reads as no sleep because the loop keyword shares the segment. That second one is the predicate under-reading a poll loop, which is the safe direction — a wait the rung cannot see is a wait it never declines. Run against the trace #3753 cites, the detector finds three waits past the bound rather than the two a tool-time census sees: 490s and 280s that returned, and a 580s wait in rstan-to-pystan that never produced a tool_result at all. The third is invisible to any measure built on the join, which is worth knowing before the next panel is scored. ReportOnly, not Banned. The before/after this exists to measure runs the pre-rung build as its control arm, and a first-trial trip would abort the control. Also removes an unused import in tests/test_postmortem.py that fails `ruff check` on main. Refs #3753
There was a problem hiding this comment.
Sorry @macanderson, you've used your own review budget of 250,000 diff characters for the last 7 days.
You can request another review in 2 days and 4 hours by commenting @sourcery-ai review. Upgrade to get a review now.
Reviewer's GuideThe PR turns long bash sleeps into a two-rung policy: waits over 30 seconds still run with polling guidance, while waits at or above the 120-second default timeout are refused before spawning. It also adds a comparable, report-only trace detector and parser to remeasure blind waits, updates tool documentation, and expands witness coverage. Sequence diagram for bash sleep policy evaluationsequenceDiagram
participant Model
participant Bash as BashTool
participant WaitPolicy as wait.rs
participant Shell as ShellProcess
Model->>Bash: execute(command)
Bash->>WaitPolicy: blocking_wait_refusal(command)
alt sleep >= 120s
WaitPolicy-->>Bash: RefusedByPolicy
Bash-->>Model: refusal with poll-loop remedy
else sleep < 120s
Bash->>Shell: spawn(command)
Shell-->>Bash: ToolOutput
opt sleep >= 30s
Bash->>WaitPolicy: sleep_advisory(command)
WaitPolicy-->>Bash: advisory with polling guidance
end
Bash-->>Model: result
end
Flow diagram for the two-rung sleep policyflowchart TD
A["bash command"] --> B{"blocking_sleep_seconds"}
B -->|"no foreground sleep or under 30s"| C["spawn normally"]
B -->|"30s to under 120s"| D["spawn and append sleep advisory"]
B -->|"120s or more"| E["refuse before spawn"]
D --> F["model uses a bounded poll loop"]
E --> F
File-Level Changes
Tips and commandsInteracting with Sourcery
Customizing Your ExperienceAccess your dashboard to:
Getting Help
|
`--pipeline` has taken several plugin ids separated by commas since #4094, in the order the user writes them, and `run.mdx` documented one variant. The composition is the whole deliverable of that issue, and a reader of the reference page had no way to learn it exists: nothing under `docs/` or `website/` contained the comma form at all. The card now names the ordering, the per-member host plane that keeps one member out of another's declared role, and the two selections that are refused — a repeated id and an empty entry — which `bind_installed` already rejects with its own message. Refs #4029
Picks up #6497, which carried stella-time's Cargo.lock entry to 0.9.417. The base this branch was cut from had the broken lock, so every --locked job on this PR failed for a reason in main rather than in the branch.
… bands.py The registry table gained a row. The sentence under it said "the last two read their thresholds from bands.py", and that had already stopped being true: the last two rows are `repeated-file-read` and `grep-ere-false-negative`, while the bands readers are `cache-collapse` and `repeated-file-read`. A row appended after the sentence was written silently moved what it pointed at. Naming the two detectors removes the failure mode rather than re-counting. Refs #3753
|
SCR-003 DoD check waived by the |
`clippy, no default features, all targets` fails on `wait.rs`, so the PR cannot merge. Two mechanical errors, both in the new file. **A duplicated `#[test]`.** One sat above the doc comment and one below it, so the attribute appeared twice on `a_wait_longer_than_a_whole_command_never_starts`. Removed the stray upper copy; the doc comment now precedes the attribute, which is the conventional order and is where the other tests in the file keep it. **`assertions_on_constants` on the rung ordering.** The test asserted `SLEEP_ADVISORY_THRESHOLD_SECS < SLEEP_REFUSAL_THRESHOLD_SECS` at runtime. Both sides are constants, so that assert can never fail a run that compiled, which is exactly clippy's objection and it is correct. Moved to `const _: () = assert!(...)` beside the constants. That is strictly stronger: the ordering is a compile-time fact, and this fails the build rather than a test. It also guards a real drift path — the refusal threshold is defined as `super::DEFAULT_TIMEOUT_SECS`, so lowering the default timeout could cross the advisory with nobody editing this file. Verified: cargo clippy -p stella-tools --no-default-features --all-targets -> clean cargo test -p stella-tools --no-default-features --lib bash::wait -> 7 passed The witness `a_wait_longer_than_a_whole_command_never_starts` and `the_advisory_and_the_refusal_are_two_rungs` both still pass, so neither fix weakened what they check.
|
Pushed a fix for the two clippy errors that were blocking this, since the branch had been idle seven hours and the PR could not merge past them. Both were in
Verified locally: The witness test and One other note: the |
|
Added The PR body carries
|
… what it says about the 75% (#6503) ## What & why `#3753`'s remaining definition of done asks for the tool-execution share of wall clock "on the same clean-basis method" as the 75% in its body. That method was an uncommitted `jq` incantation. `bench/trace_triage/census.py` is the method written down, so the next panel produces a figure a reader can hold against this one. Wall clock is the first event to the last, per trial. Tool time is `tool_result.duration_ms` over the join `run_trace` already performs. A share is a ratio of two sums over one named trial set, never a mean of ratios. ## Calibration Run against the match `#3753` cites, the committed module answers **52.0%** over 12 trials. The figure already published on that issue from the same match, by a separate hand-written join, is **51.8%** (6,578s wall, 3,406s tool). The wall clocks are identical and the tool totals differ by 13s. I did not establish what that 13s is — the other join is not in the tree — so it is stated as an unexplained residual rather than attributed. ``` $ python3 bench/trace_triage/census.py ~/.arenabench/matches/13f7f2bb533d match 13f7f2bb533d: 12 trials with a wall clock over the 12 trials that carry a clock: wall clock 1.83h tool execution 0.95h 52.0% of wall clock model 0.46h 25.0% of wall clock over all 12 trials, which needs no clock: bash 0.95h over 191 bash calls of 216 tool calls killed by the timeout 0.38h 40.4% of bash killed and tried again 0.18h 19.3% of bash ...of which run verbatim 0.00h ``` ## What it says about the 75% Pointed at every ArenaBench match on this machine — 294 matches, 341 Stella trials that carry a wall clock — the share is not 75% and not 52%: | trial set | trials | tool share | model share | | --- | --- | --- | --- | | `#3753`'s body, clean basis of 9 | 9 | 75% | 31% | | `#3753`'s later comment, same match | 12 | 51.8% | — | | every match on this machine | 341 | **15.5%** | **56.6%** | **Labelled as a measurement, not a panel.** These are the matches that happen to be on disk, run against many configurations over months, not a controlled panel. What it establishes is narrow and worth having: the 75% is a property of an install-heavy task mix, not of the harness. On the corpus the model is the larger consumer by a wide margin. The practical consequence: a panel reporting a lower number than 75% has probably changed task mix, and the census makes that visible because the trial count travels with the share. It does not discharge either remaining box on `#3753`. Both still need a funded panel. ## The second cost inside shell time `#6440` and `#6501` are both aimed at blind waiting. The census names a larger bucket beside it, over 24.48h of `bash` wall clock in 13,245 bash calls: | | hours | share of bash | | --- | --- | --- | | killed by the tool timeout | 5.70 | 23.3% | | killed, and the command came back later | 3.14 | 12.8% | The second row is time that bought nothing at all: the call was killed, and a later call in the same trial re-ran it. That is the shape `pytorch-model-cli` died in — `pip install torch` killed at 120s, the same install killed again at 300s, then a third attempt that ran. 420s of its 984s went into the two attempts that were thrown away, before the 490s blind wait `#6501` declines. No fix here. The remedy is backgrounding, which `#6501` argues is a body of work rather than a session, and which `#3753` already tracks as its unbuilt direction two. The number is here so whoever sizes that work has it. ## Three trial kinds kept apart, and two bases kept apart Each of these was a wrong number before it was a distinction: - **A trace from before the event schema carried `ts`** has tool durations and no wall clock. It stays out of the numerator as well as the denominator, instead of entering as a zero that deflates the share. 180 of the traces here are this. - **A trial that recorded nothing** is counted separately. A credential that never authenticated writes empty traces, and folding them in reports a broken run as an old one — the separation `postmortem` puts first, for the same reason. - **A task directory with no `stella-events.jsonl`** is the other contestant's seat. Walking on the `agent/` directory alone read 16 opposing trials on `13f7f2bb533d` as trials of ours that died. The render also prints the shell figures under their own heading. A share needs a clock and is held to the trials that carry one; a duration does not, so a trace on the older schema still contributes its shell time. Printed as one block, the smaller tool figure read as though it contained the larger shell one. `1aabe7c76` is that fix, and it followed me publishing the misreading on `#3753` — the bash hours were right and the call count beside them was every tool's. ## The witness - [x] This PR includes witness tests (fail on `main`, pass here). `bench/trace_triage/tests/test_census.py`: - `test_a_trial_without_a_timestamp_stays_out_of_every_share` — the 600s an untimed trial spent is absent from the share and still visible in `bash_ms`. - `test_a_killed_call_whose_command_comes_back_is_paid_for_twice` — the commands `pytorch-model-cli` actually sent, verbatim. - `test_a_run_that_never_timed_out_reports_no_waste` — quiet on a healthy run. - `test_the_rendered_census_names_the_basis_of_its_share` and `test_a_share_with_no_wall_clock_behind_it_is_absent_rather_than_zero`. - `test_a_trial_that_recorded_nothing_is_not_reported_as_an_old_schema`. - `test_the_other_contestants_seat_is_not_a_trial_that_recorded_nothing`. Offline by construction: every trace is written, never fetched. ## The gate - [x] `pytest bench/trace_triage/tests/test_census.py` — 7 passed - [x] `ruff check` and `ruff format --check` on both new files - [x] `make prose`, `make line-citations`, `scripts/check-file-size.sh` `bench.yml` runs `pytest bench/trace_triage/tests` on every pull request and its scope filter names `bench/`, so this suite is gated in CI rather than only here. No workspace build was run locally, per SCR-001. ## Conflict surface Two new files, nothing shared touched. `#6501` adds `bench/trace_triage/waits.py` for blind waits and edits `detectors.py` and `tests/test_postmortem.py`; this branch touches none of those, so the two can land in either order. Refs #3753
`check-prose.py` failed this PR: `wait.rs` went from grade 6.00 to 6.06, and the sentences that pushed it over were mine, added with the compile-time assertion in the previous commit. Rewritten in shorter sentences and plainer words. Nothing about what the assertion does or why it is a compile-time check has been dropped — the long clauses were carrying no meaning the short ones do not. Verified: python3 ./scripts/check-prose.py -> OK cargo clippy -p stella-tools --no-default-features --all-targets -> clean cargo test -p stella-tools --no-default-features --lib bash::wait -> 7 passed
What & why
bashhas an advisory that fires when a call spends a long time insleep. It isappended to the result of the call it fires on, so the whole interval is already
spent by the time the model reads the remedy. It can never save the call it rides
on. Two lines above the spawn,
shell_write_auditsays exactly this about itself:a refusal that arrives after the process has run is a report, not a fence.
This turns the sleep check into a ladder. Past
SLEEP_ADVISORY_THRESHOLD_SECS(30s, unchanged) the call runs and the note names the wait. Past
SLEEP_REFUSAL_THRESHOLD_SECSthe call does not start, and the model answers arefusal naming the poll-loop remedy instead of sitting through the wait.
The upper bound is
DEFAULT_TIMEOUT_SECS, a constant the tool already has: a waitthat outlasts the default limit for a whole command is the command. It is not a
number fitted to the corpus — in arenabench match
13f7f2bb533dthe calls thatsleep at all wait 2s, 20s, 280s and 490s, so every bound between the poll loop and
the blind waits declines the same two calls.
The schema now states the rule too, beside the write-refusal sentence it already
carried. A refusal the model never triggers is cheaper than one it answers.
Why not candidate direction 2
#3753opened with three directions. Two shipped (#6440,#6466). The third,backgrounding a long command, would rebuild the
read_output/wait_forfamilythat
#3244deleted, and#3244notes that a future command-running tool has torebuild the approval chain that went with it. That is a body of work, not a
session, and it is not what the measurement points at. What the trace shows is an
agent hand-rolling backgrounding with
&and then blocking on a guessed number.Declining the guess is the smaller change that removes the same cost.
Numbers
Profiled independently from the recorded trace, reproducing the figures already on
the issue: 6,578s wall clock, 3,406s tool execution (51.8%), 792s of foreground
sleep.The two calls this rung declines ran 489.5s and 280.4s. Replayed over the same
trace, with the substitute priced at the poll loop the same match measured
(20.9s) plus that match's median model call (5.3s):
Labelled as a replay, not a measurement. This is arithmetic over a recorded
trace, not a new run. It assumes the model answers the refusal with a poll loop,
which is the thing a panel has to establish.
pytorch-model-clitimed out at the900s budget having spent 489.5s in one of these calls; without it that trial lands
around 628s, which says the wall it hit is no longer hit by this cause and says
nothing about whether it would have passed.
The saving is a floor. The new detector finds a third wait past the bound in
rstan-to-pystan—sleep 580, the call that trial died inside. It produced notool_result, so it never entered the tool-time denominator and is absent fromthe table above.
The instrument
#3753's remaining boxes both need a funded panel. The second asks whether theblind-wait share fell "using the same
tool_start→tool_resultjoin". That joinlives in
bench/trace_triage; the question did not.waits.pyand theblind-waitdetector add it, so the re-measurement is one command with a method comparable to
this one rather than a fresh script.
waits.pymirrorsblocking_sleep_secondsfromstella-core, and the mirror waschecked against the Rust on the five commands the match actually sent. They agree on
all five, including the two a looser parser gets wrong: a backgrounded install is not
part of the wait, and
do sleep 20;reads as no sleep because the loop keyword sharesthe segment. That second one is the predicate under-reading a poll loop, which is the
safe direction here — a wait the rung cannot see is a wait it never declines. An
earlier draft of this PR claimed that case read as 20s; the Rust says
None, and thedoc comment was corrected to what the code does.
The detector is
ReportOnly. The before/after it exists to serve runs the pre-rungbuild as its control arm, and a first-trial trip would abort the control.
Exemplar
The pre-spawn text audit follows
shell_write_auditin the same file — same seam,same
RefusedByPolicyclass, same "read the text before the spawn" rationale. Thesubmodule split follows
bash/words.rs, whose own header gives the same two reasons(the 1500-line ceiling, and a concern the tool's spawn/timeout body is not).
The witness
main, pass here).crates/stella-tools/src/bash/wait.rs:a_wait_longer_than_a_whole_command_never_starts— the two recorded commands, verbatim, are declined.a_poll_loop_and_a_short_wait_still_run— the cheap shapes are untouched.the_advisory_and_the_refusal_are_two_rungs— both rungs reachable, ordered.crates/stella-tools/src/bash.rs:a_declined_wait_returns_at_once_and_never_spawns—executeanswers in under 2sfor a
sleep 300, so the elapsed time proves the shell never ran.bench/trace_triage/tests/test_waits.py— six tests over the real command text.The "before" is not synthetic: the identical commands ran 489.5s and 280.4s in the
recorded match.
The gate
cargo fmt --check(stella-tools,stella-core)cargo clippy -p stella-tools --all-targets— zero warningscargo test -p stella-tools --lib bash::— 48 passedpytest bench/trace_triage/tests— 110 passedmake prose,make line-citations,make doc-links,check-file-size.sh,check-bench-suites.shmake tool-docs-update—docs/tools/bash.tomlregenerated, the description sentence is the whole diffbashschema states the ruleThe whole-workspace suite was not run locally. Per this repo's standing rule
(SCR-001) a session builds and tests only the crates its change touches, and CI
owns the full gate.
Fix over file
Two, both unrelated to the rest of this PR.
bench/trace_triage/tests/test_postmortem.pyimportedcohort_ofand never usedit, failing
ruff checkonmain. Removed.bench/trace_triage/README.mdsaid "the last two read their thresholds frombands.py" under the detector table, and that had already stopped being true: thelast two rows are
repeated-file-readandgrep-ere-false-negative, while thebands readers are
cache-collapseandrepeated-file-read. A row appended afterthe sentence was written moved what it pointed at, silently. The two are named now
rather than counted, which is the failure mode
doc:prose-guidelineswarns about.Merge note
The base this branch was cut from carried the broken
Cargo.lockthat #6495tracks, so the first CI run failed every
--lockedjob for a reason inmain.origin/mainis merged in, which picks up #6497's fix. Themain is not known-brokencheck stays red until the canarycloses #6495on its own.Scope note
bash.rswas 1,375 lines and this change took it past the 1,500-line ceiling. Nobaseline entry was added; the two sleep rungs moved to
bash/wait.rsinstead.Refs #3753
Summary by Sourcery
Prevent excessively long bash sleeps from starting and instrument trace analysis to measure blind waits consistently.
New Features:
Bug Fixes:
Enhancements:
Documentation:
Tests:
Chores:
Edit:
closes #6495above is now in inline code. As bare prose the definition-of-done gate read it as this PR closing that issue, then failed the PR against that issue's checklist, and thecloses-nothinglabel waived nothing because the gate believed the PR closed something. The sentence was accurate narration about what the canary does; GitHub and the gate do not distinguish narration from intent.That is the third time today, across three PRs: a commit message in oxagen#2865 reading "the claim that it
closes #2559" actually closed it, oxagen#2870 was written to record that lesson and reproduced it in its own body, and this is the third. Reserve the verb for a trailer, in bodies and commit messages alike; put it in backticks anywhere else.