Skip to content

Commit 1da5809

Browse files
fix(run): bound child output capture and reaper threads (#340)
* fix(run): bound child output capture and reaper threads (#339) The shell-out helpers redirected child stdout/stderr to tempfiles but then read both streams fully into heap Vecs, so peak RSS scaled 1:1 with child output volume and summed across concurrent calls (measured: 128 MiB child output -> +128 MiB RSS; 8 concurrent captures sum). The doc comments claimed bounded capture; nothing bounded it. - Diagnostics capture is now capped at 256 KiB per stream, tail-preserving (the last bytes are what error messages need), with a diagnostic line on truncation. - `pty list --json` moves to an explicit full-stdout variant: parsed structured output must be whole; stdout is intentionally uncapped there. - One shared reaper thread replaces detached thread-per-timed-out-child, which accumulated without bound under timeout storms. - Eval run steps stream child output straight into their capture files and combined logs instead of buffering whole outputs; agent log dumps stream scrollback to file without materializing it; the bash judge uses null stdio instead of undrained pipes that could deadlock on chatty judges. Decision record: docs/vrs/.decisions/0007. agent-identity: unknown agent-persona: generalist agent-supervisor: unavailable agent-tool: OMP agent-tool-version: 18.0.3 agent-runtime: OMP 18.0.3 tooling-profile: dotfiles@ffce621 * docs(vrs): carry the bounded child-capture contract (R34) Decision 0007 landed with the fix, but the requirement and spec did not state the bound. R32's reaper clause already covered teardown ownership; R34 now requires capture memory to be cap-bounded, tail-preserving, and observable, with unbounded reads opt-in at the call site. The supervision spec gains a child-process execution section pointing at D0007. agent-identity: unknown agent-persona: generalist agent-supervisor: unavailable agent-tool: OMP agent-tool-version: 18.0.3 agent-runtime: OMP 18.0.3 tooling-profile: dotfiles@ffce621
1 parent 55efd31 commit 1da5809

6 files changed

Lines changed: 403 additions & 55 deletions

File tree

Lines changed: 58 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,58 @@
1+
# Child process output capture is bounded and tail-preserving
2+
3+
Status: accepted
4+
5+
Decision made by Johannes on 2026-08-25 (issue #339, independently reproduced
6+
measurements in the session record; option A of three, cap size 256 KiB).
7+
8+
## Context
9+
10+
The supervisor shell-out helpers (`src/run.rs`
11+
`output_with_input_timeout_observed`, `src/ding/mod.rs` `output_with_timeout`)
12+
redirect child stdout/stderr to tempfiles — sound, because files keep an
13+
escaped descendant from blocking cleanup and make bounded read-back
14+
deadlock-free — then unconditionally rewind both streams and `read_to_end`
15+
them into fresh heap buffers. Measured peak RSS scales 1:1 with child output
16+
(16 MiB child → +16.2 MiB RSS; 8 concurrent × 16 MiB → +103 MiB) despite doc
17+
comments claiming "bounded output capture". No spec or invariant defined a
18+
bound; the comment described aspiration, not behavior.
19+
20+
Consumer inventory: only `pty list --json` (parsed JSON, naturally bounded by
21+
catalog size) and `pty peek` (terminal screen text, consumed for composer
22+
matching where the tail is what matters) need complete stdout. Every other
23+
call site uses stderr only trimmed inside error strings. The same audit found
24+
two sibling hazards: detached reaper threads accumulate without bound under
25+
timeout storms, and `src/eval_run.rs` holds whole step output plus full
26+
scrollback in memory before writing log files, with an undrained pipe pair in
27+
the bash judge that can deadlock.
28+
29+
## Decision
30+
31+
1. **Diagnostics capture is capped at 256 KiB per stream and tail-preserving.**
32+
When a stream exceeds the cap, the last `CAPTURE_CAP_BYTES` bytes are kept;
33+
the head is dropped. Truncation emits one diagnostic line naming the
34+
command, stream, kept/total bytes, and cap.
35+
2. **Payload capture stays complete and explicit.** Callers that parse
36+
structured data (`pty list --json`) use a distinctly named
37+
full-stdout variant whose doc comment states that stdout is intentionally
38+
uncapped and why. Bounded-tail remains the default so an uncapped read is
39+
always a visible, deliberate choice at the call site.
40+
3. **One shared reaper thread** drains killed children over a channel,
41+
replacing per-timeout detached threads.
42+
4. **Eval run steps stream to their log files** instead of buffering, and the
43+
bash judge uses null stdio (only its exit status is consumed).
44+
45+
Rejected alternatives: disk spill references for oversized diagnostics
46+
(spill-file lifecycle for no demonstrated consumer) and streaming every
47+
shell-out to log files exec-backend style (changes every error path; revisit
48+
only if a consumer needs full oversized diagnostics).
49+
50+
## Consequences
51+
52+
- Peak supervisor RSS no longer scales with child output volume; worst case
53+
is bounded by calls × 512 KiB regardless of child behavior.
54+
- Diagnostics for oversized children lose their head. Error messages built
55+
from stderr keep their tail, which is where failure text lives.
56+
- The tempfile redirection is now load-bearing for more than cleanup: it is
57+
what makes the bounded read-back deadlock-free. Any future move back to
58+
pipes must preserve a bound on buffered bytes.

docs/vrs/requirements.md

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -72,6 +72,13 @@ accepted.
7272
that outlive that child. st2 either reaps the direct child before returning or
7373
transfers wait ownership to a background reaper; the failure remains bounded
7474
and reports its originating input error or timeout.
75+
- **R34 Bounded helper output capture:** Capturing a spawned non-interactive
76+
helper's stdout/stderr consumes memory bounded by a fixed per-stream cap
77+
independent of the child's output volume and of how many captures run
78+
concurrently. When a stream exceeds the cap, the retained bytes are that
79+
stream's tail, and truncation is observable. A caller that must consume a
80+
stream whole (structured data for parsing) opts in through an explicitly
81+
named capture path, so an unbounded read is always visible at its call site.
7582
- **R22 Quiet coordination after events:** A network with minimal or default
7683
personas stays quiet while useful work continues. Agents coordinate only after
7784
an inbox DING, a durable failure, a real blocker, a completion or decision

docs/vrs/spec.md

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -710,6 +710,26 @@ validate ──► materialize ──► host-local st2 scheduler/reconciler
710710
closed instead of hanging reconciliation. The deadline is containment, not
711711
the mechanism for admitting a larger fleet.
712712

713+
### Child-process execution (R32, R34)
714+
715+
Non-interactive helper shells-outs (`src/run.rs`, `src/ding/mod.rs`) share one
716+
shape: the child is `setsid` so its pid is its process group, stdout/stderr go
717+
to unlinked tempfiles (an escaped descendant that inherited them cannot block
718+
cleanup), and deadline expiry kills the whole group. Wait ownership for a
719+
killed child transfers to one shared reaper thread draining a channel — never
720+
one detached thread per timed-out child, which accumulates without bound under
721+
timeout storms.
722+
723+
Read-back is tail-capped at `CAPTURE_CAP_BYTES` (256 KiB) per stream: over-cap
724+
streams keep their last 256 KiB and emit one diagnostic line naming the
725+
command, stream, kept/total bytes, and cap. Memory per capture is therefore
726+
bounded by calls × 2 × cap regardless of child behavior. `pty list --json`
727+
parses structured output that must be whole, so it uses the explicitly named
728+
full-stdout variant; that read is intentionally uncapped and visible at its
729+
call site. Eval run steps and agent log dumps stream child output straight to
730+
their catalog log files without buffering it. Rationale and rejected
731+
alternatives: [decision 0007](.decisions/0007-child-output-capture-is-bounded-and-tail-preserving.md).
732+
713733
## Message lifecycle
714734

715735
```text

src/ding/mod.rs

Lines changed: 24 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,6 @@
1414
//! work into one generic recovery DING. `busy` never suppresses a notification; fresh `dnd` does.
1515
1616
use std::collections::{HashSet, VecDeque};
17-
use std::io::{Read as _, Seek as _};
1817
use std::os::unix::process::CommandExt as _;
1918
use std::path::{Path, PathBuf};
2019
use std::process::{Command, Output, Stdio};
@@ -27,7 +26,9 @@ mod composer;
2726
mod harness;
2827

2928
use crate::message::{self, Message};
29+
use crate::run::{CAPTURE_CAP_BYTES, reap_detached, read_bounded_tail};
3030
use crate::status;
31+
3132
use composer::{ComposerState, classify_composer, classify_receipt};
3233
use harness::ReceiptState;
3334

@@ -329,6 +330,9 @@ impl PtyPoker {
329330
Ok(())
330331
}
331332

333+
/// Reads the terminal screen of the session. Output capture is tail-capped at
334+
/// [`crate::run::CAPTURE_CAP_BYTES`]; semantics are preserved because a terminal screen is
335+
/// far below that bound.
332336
fn peek(&self) -> anyhow::Result<String> {
333337
let out = output_with_timeout(
334338
Command::new(&self.bin).args(["peek", self.session.as_str()]),
@@ -391,8 +395,10 @@ impl Poker for PtyPoker {
391395
}
392396
}
393397

394-
/// Run a non-interactive child with bounded output capture. Temporary files keep an escaped
395-
/// descendant that inherited stdout/stderr from blocking cleanup after the direct child times out.
398+
/// Run a non-interactive child with bounded output capture: each stream keeps at most its last
399+
/// [`crate::run::CAPTURE_CAP_BYTES`] bytes (tail-preserving, with a diagnostic line on
400+
/// truncation). Temporary files keep an escaped descendant that inherited stdout/stderr from
401+
/// blocking cleanup after the direct child times out.
396402
fn output_with_timeout(command: &mut Command, timeout: Duration) -> anyhow::Result<Output> {
397403
let mut stdout = tempfile::tempfile()?;
398404
let mut stderr = tempfile::tempfile()?;
@@ -421,23 +427,27 @@ fn output_with_timeout(command: &mut Command, timeout: Duration) -> anyhow::Resu
421427
libc::kill(-pid, libc::SIGKILL);
422428
}
423429
let _ = child.kill();
424-
thread::spawn(move || {
425-
let _ = child.wait();
426-
});
430+
reap_detached(child);
427431
anyhow::bail!("timed out after {:.1}s", timeout.as_secs_f64());
428432
}
429433
thread::sleep(Duration::from_millis(10));
430434
};
431-
stdout.rewind()?;
432-
stderr.rewind()?;
433-
let mut stdout_bytes = Vec::new();
434-
let mut stderr_bytes = Vec::new();
435-
stdout.read_to_end(&mut stdout_bytes)?;
436-
stderr.read_to_end(&mut stderr_bytes)?;
435+
let stdout_stream = read_bounded_tail(&mut stdout, CAPTURE_CAP_BYTES)?;
436+
let stderr_stream = read_bounded_tail(&mut stderr, CAPTURE_CAP_BYTES)?;
437+
let program = command.get_program().to_string_lossy();
438+
for (stream, name) in [(&stdout_stream, "stdout"), (&stderr_stream, "stderr")] {
439+
if stream.truncated() {
440+
eprintln!(
441+
"st2: truncated {name} capture of `{program}`: keeping last {} of {} bytes (cap {CAPTURE_CAP_BYTES})",
442+
stream.bytes.len(),
443+
stream.total,
444+
);
445+
}
446+
}
437447
Ok(Output {
438448
status,
439-
stdout: stdout_bytes,
440-
stderr: stderr_bytes,
449+
stdout: stdout_stream.bytes,
450+
stderr: stderr_stream.bytes,
441451
})
442452
}
443453

src/eval_run.rs

Lines changed: 95 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -911,7 +911,7 @@ fn run_steps(
911911
catalog: &Path,
912912
top_env: &BTreeMap<String, String>,
913913
) -> (Vec<JudgeResult>, BTreeMap<String, String>) {
914-
use std::process::Command;
914+
use std::process::{Command, Stdio};
915915
let mut results = Vec::new();
916916
// The env the JUDGES also get: $RUNS_DIR + each step's $RUN_<id>_EXIT (so a bash judge can read the
917917
// captures). Empty when there are no run steps.
@@ -947,7 +947,8 @@ fn run_steps(
947947
.unwrap_or((1, Duration::ZERO));
948948

949949
let mut exit = -1;
950-
let (mut out, mut err) = (Vec::new(), Vec::new());
950+
let out_path = runs_dir.join(format!("{}.out", step.id));
951+
let err_path = runs_dir.join(format!("{}.err", step.id));
951952
for attempt in 0..attempts {
952953
let mut cmd = Command::new("sh");
953954
cmd.arg("-c")
@@ -961,15 +962,22 @@ fn run_steps(
961962
for (k, v) in &runtime {
962963
cmd.env(k, v);
963964
}
964-
match cmd.output() {
965-
Ok(o) => {
966-
exit = o.status.code().unwrap_or(-1);
967-
out = o.stdout;
968-
err = o.stderr;
969-
}
965+
// The child's stdout/stderr stream STRAIGHT into the capture files: a run step can emit
966+
// arbitrarily much output and it must never be buffered wholesale in this process. Each
967+
// attempt re-truncates, so the files hold the LAST attempt's output — the same bytes the
968+
// old buffer-then-write path produced.
969+
let attempt_exit = (|| -> std::io::Result<i32> {
970+
let out_file = std::fs::File::create(&out_path)?;
971+
let err_file = std::fs::File::create(&err_path)?;
972+
cmd.stdout(Stdio::from(out_file))
973+
.stderr(Stdio::from(err_file));
974+
Ok(cmd.status()?.code().unwrap_or(-1))
975+
})();
976+
match attempt_exit {
977+
Ok(code) => exit = code,
970978
Err(e) => {
971979
exit = -1;
972-
err = format!("run step spawn failed: {e}").into_bytes();
980+
let _ = std::fs::write(&err_path, format!("run step spawn failed: {e}"));
973981
}
974982
}
975983
if exit == 0 {
@@ -980,13 +988,19 @@ fn run_steps(
980988
}
981989
}
982990

983-
let _ = std::fs::write(runs_dir.join(format!("{}.out", step.id)), &out);
984-
let _ = std::fs::write(runs_dir.join(format!("{}.err", step.id)), &err);
985-
let _ = std::fs::write(runs_dir.join(format!("{}.exit", step.id)), exit.to_string());
986-
// Also a unified, judge-greppable combined log (stdout then stderr) named after the run label.
987-
let mut combined = out.clone();
988-
combined.extend_from_slice(&err);
989-
let _ = std::fs::write(logs_dir.join(format!("{}.log", step.id)), &combined);
991+
let _ =
992+
std::fs::write(runs_dir.join(format!("{}.exit", step.id)), exit.to_string());
993+
// Also a unified, judge-greppable combined log (stdout then stderr), copied from the two
994+
// capture files so neither ever has to fit in memory.
995+
let combined_path = logs_dir.join(format!("{}.log", step.id));
996+
let _ = (|| -> std::io::Result<()> {
997+
let mut log = std::fs::File::create(&combined_path)?;
998+
let mut out = std::fs::File::open(&out_path)?;
999+
std::io::copy(&mut out, &mut log)?;
1000+
let mut err = std::fs::File::open(&err_path)?;
1001+
std::io::copy(&mut err, &mut log)?;
1002+
Ok(())
1003+
})();
9901004
runtime.insert(format!("RUN_{}_EXIT", env_key(&step.id)), exit.to_string());
9911005
eval_log!(
9921006
"== run step {} → exit {}{} ==",
@@ -1020,22 +1034,32 @@ fn run_steps(
10201034
/// continuous plain-text log, so this is the scrollback captured at judge time — enough to inspect a
10211035
/// wedged/finished agent's history. A truly continuous agent log would need a `pty` feature.
10221036
fn dump_agent_logs(pty_task_ids: &[String], catalog: &Path) {
1037+
use std::process::Stdio;
10231038
if pty_task_ids.is_empty() {
10241039
return;
10251040
}
10261041
let logs_dir = catalog.join("logs");
10271042
let _ = std::fs::create_dir_all(&logs_dir);
10281043
let pty_root = crate::run::effective_pty_root(catalog);
10291044
for task_id in pty_task_ids {
1030-
let out = std::process::Command::new("pty")
1031-
.args(["peek", "--full", "--plain", task_id])
1032-
.env("PTY_ROOT", &pty_root)
1033-
.output();
1034-
if let Ok(o) = out
1035-
&& o.status.success()
1036-
&& !o.stdout.is_empty()
1037-
{
1038-
let _ = std::fs::write(logs_dir.join(format!("{task_id}.log")), &o.stdout);
1045+
let log_path = logs_dir.join(format!("{task_id}.log"));
1046+
// Stream the peek's stdout straight into the log file: the full scrollback can be large and
1047+
// must never be buffered wholesale in this process. The old contract — keep the log only
1048+
// when the peek succeeded AND produced output — is kept by deleting the (possibly empty)
1049+
// file otherwise.
1050+
let dumped = (|| -> std::io::Result<bool> {
1051+
let mut child = std::process::Command::new("pty")
1052+
.args(["peek", "--full", "--plain", task_id])
1053+
.env("PTY_ROOT", &pty_root)
1054+
.stdout(Stdio::from(std::fs::File::create(&log_path)?))
1055+
.stderr(Stdio::null())
1056+
.spawn()?;
1057+
child.wait().map(|s| s.success())
1058+
})();
1059+
let keep =
1060+
dumped.unwrap_or(false) && std::fs::metadata(&log_path).is_ok_and(|m| m.len() > 0);
1061+
if !keep {
1062+
let _ = std::fs::remove_file(&log_path);
10391063
}
10401064
}
10411065
}
@@ -1552,8 +1576,11 @@ fn run_bash_judge(
15521576
.env("CATALOG", catalog)
15531577
.env("ST_ROOT", bus)
15541578
.env("SPEC_DIR", &physical_spec_dir)
1555-
.stdout(Stdio::piped())
1556-
.stderr(Stdio::piped());
1579+
// Only the status/exit detail is consumed. Piping stdout/stderr and never draining them
1580+
// deadlocks a chatty judge: once its pipe buffers fill, the child blocks forever while the
1581+
// parent keeps polling try_wait.
1582+
.stdout(Stdio::null())
1583+
.stderr(Stdio::null());
15571584
// $RUNS_DIR + each $RUN_<id>_EXIT, so a judge can read the run steps' captured stdout/stderr/exit.
15581585
for (k, v) in run_env {
15591586
command.env(k, v);
@@ -2930,6 +2957,47 @@ agent "worker" { identity "worker"; host "evalhost"; argv "true" }
29302957
assert!(!run_declarative(&missing, cat.path()).0);
29312958
}
29322959

2960+
#[test]
2961+
fn run_steps_streams_large_step_output_to_files_without_corruption() {
2962+
let catalog = tempfile::tempdir().unwrap();
2963+
let cat = catalog.path();
2964+
// ~64 KiB each of stdout and stderr — far beyond any pipe buffer. This round-trips byte
2965+
// for byte only if the child streams straight into the capture files, and the combined log
2966+
// keeps the stdout-then-stderr ordering.
2967+
let marker_out = "O".repeat(64 * 1024);
2968+
let marker_err = "E".repeat(64 * 1024);
2969+
let step = RunStep {
2970+
id: "big".into(),
2971+
workspace: None,
2972+
command: "printf '%s' \"$BIG_OUT\"; printf '%s' \"$BIG_ERR\" >&2".into(),
2973+
env: BTreeMap::from([
2974+
("BIG_OUT".to_string(), marker_out.clone()),
2975+
("BIG_ERR".to_string(), marker_err.clone()),
2976+
]),
2977+
unset: vec![],
2978+
retry: None,
2979+
allow_nonzero: false,
2980+
};
2981+
let (results, judge_env) = run_steps(&[step], cat, &BTreeMap::new());
2982+
assert_eq!(results.len(), 1);
2983+
assert!(results[0].passed);
2984+
assert_eq!(judge_env.get("RUN_big_EXIT").map(String::as_str), Some("0"));
2985+
let runs = cat.join(".runs");
2986+
assert_eq!(
2987+
std::fs::read(runs.join("big.out")).unwrap(),
2988+
marker_out.as_bytes()
2989+
);
2990+
assert_eq!(
2991+
std::fs::read(runs.join("big.err")).unwrap(),
2992+
marker_err.as_bytes()
2993+
);
2994+
assert_eq!(std::fs::read_to_string(runs.join("big.exit")).unwrap(), "0");
2995+
// Combined log = stdout fully followed by stderr.
2996+
let mut expected = marker_out.into_bytes();
2997+
expected.extend_from_slice(marker_err.as_bytes());
2998+
assert_eq!(std::fs::read(cat.join("logs/big.log")).unwrap(), expected);
2999+
}
3000+
29333001
#[test]
29343002
fn bash_judge_exit_code_and_timeout() {
29353003
let spec = tempfile::tempdir().unwrap();

0 commit comments

Comments
 (0)