diff --git a/bots/panicbot/Cargo.lock b/bots/panicbot/Cargo.lock index 4bae9c94..e03d1c8f 100644 --- a/bots/panicbot/Cargo.lock +++ b/bots/panicbot/Cargo.lock @@ -590,6 +590,7 @@ dependencies = [ "chrono", "clap", "gitbot-shared-context", + "rustix", "serde", "serde_json", "tempfile", diff --git a/bots/panicbot/Cargo.toml b/bots/panicbot/Cargo.toml index 1dc5c894..c3ba4e7d 100644 --- a/bots/panicbot/Cargo.toml +++ b/bots/panicbot/Cargo.toml @@ -28,6 +28,7 @@ toml = "1.1.2" # Error handling anyhow = "1.0.102" +rustix = { version = "1.1.4", default-features = false, features = ["process", "std"] } # Logging tracing = "0.1.44" diff --git a/bots/panicbot/src/fleet.rs b/bots/panicbot/src/fleet.rs index 5f4d16b7..d533a300 100644 --- a/bots/panicbot/src/fleet.rs +++ b/bots/panicbot/src/fleet.rs @@ -13,7 +13,6 @@ use crate::a2ml_writer; use crate::directives; -use crate::scanner; use crate::suite::{self, SuiteOptions, SuiteRun}; use crate::translator; use gitbot_shared_context::bot::{BotExecution, BotId, BotInfo}; @@ -113,10 +112,9 @@ pub fn run_fleet_suite( .map(|n| n.to_string_lossy().to_string()) .unwrap_or_else(|| "unknown".to_string()); - // Try to get panic-attack version for A2ML metadata - let pa_version = scanner::run_diagnostics(config.timeout) - .map(|d| d.version) - .unwrap_or_else(|_| "unknown".to_string()); + // The version for the A2ML metadata comes from the suite's own diagnostics + // part: no second, separately-timed diagnostics run. + let pa_version = run.diagnostics_version().unwrap_or("unknown").to_string(); if !unfixable.is_empty() || !fixable.is_empty() { let a2ml_doc = a2ml_writer::generate_a2ml( diff --git a/bots/panicbot/src/main.rs b/bots/panicbot/src/main.rs index 30bee570..56b931a7 100644 --- a/bots/panicbot/src/main.rs +++ b/bots/panicbot/src/main.rs @@ -96,8 +96,23 @@ fn cmd_scan( match format { OutputFormat::Text => { + // "No issues found." only for a run that really analysed the repo. + // A part error or an empty run is stated as such (and exits 3/4). + if let Some(summary) = &part_error { + println!("Scan INCOMPLETE: {summary}"); + if !findings.is_empty() { + println!( + "({} finding(s) from the parts that ran follow)\n", + findings.len() + ); + } + } else if !run.analysed() { + println!("Scan NOT RUN: {NOTHING_RAN}"); + } if findings.is_empty() { - println!("No issues found."); + if part_error.is_none() && run.analysed() { + println!("No issues found."); + } } else { println!("Found {} issue(s):\n", findings.len()); for finding in &findings { diff --git a/bots/panicbot/src/scanner.rs b/bots/panicbot/src/scanner.rs index 42f4f727..8a720818 100644 --- a/bots/panicbot/src/scanner.rs +++ b/bots/panicbot/src/scanner.rs @@ -318,8 +318,22 @@ pub fn run_diagnostics(timeout: Duration) -> Result { // Fail early, and clearly, when the binary is not there at all. find_panic_attack_binary()?; + // One deadline for the whole preflight: `--version` and `diagnostics` share + // `timeout` rather than each getting a full one (which would double it). + let deadline = std::time::Instant::now() + timeout; + let left = |what: &str| -> Result { + let d = deadline.saturating_duration_since(std::time::Instant::now()); + if d.is_zero() { + bail!( + "panic-attack preflight exhausted its {}s budget before {what}", + timeout.as_secs() + ); + } + Ok(d) + }; + // `--version` is the lightweight health check. Timed like every other invocation: a hung binary must not hang the lane. - let version_run = run_panic_attack_plain(&["--version"], timeout) + let version_run = run_panic_attack_plain(&["--version"], left("--version")?) .context("Failed to execute panic-attack --version")?; // First line only, bounded: this ends up in a part's detail. @@ -342,7 +356,7 @@ pub fn run_diagnostics(timeout: Duration) -> Result { // human-readable self-check of its own source tree (plain text, exit 1 in // any other directory), not a machine report, so a clean exit whose output // is not a diagnostics JSON document falls back to the `--version` check. - let diag = run_panic_attack_raw(&["diagnostics"], timeout) + let diag = run_panic_attack_raw(&["diagnostics"], left("diagnostics")?) .context("Failed to execute panic-attack diagnostics")?; if diag.status.code().is_none() { bail!( @@ -534,7 +548,8 @@ pub struct DynamicReport { /// A verdict from `panic-attack adjudicate` (the real 2.5 report shape). #[derive(Debug, Clone, Serialize, Deserialize)] pub struct AdjudicateVerdict { - /// `pass`, `warn` or `fail`. + /// `pass`, `warn` or `fail`. Newer panic-attack may write `error`, which + /// [`parse_adjudicate_verdict`] turns into an error. pub verdict: String, /// Reports it understood. pub processed_reports: usize, @@ -563,32 +578,47 @@ pub struct AdjudicatePriority { /// Any non-zero exit, a timeout, a missing report file or a report that is not /// JSON is an error: a part never reads as clean because it printed nothing. fn run_to_report(args: &[&str], scratch: &Scratch, timeout: Duration) -> Result { + run_to_report_accepting(args, scratch, timeout, &[0]).map(|(_, v)| v) +} + +/// [`run_to_report`] for a subcommand whose exit code carries a verdict: each +/// code in `accepted` is a complete run whose report is still read and parsed, +/// and is returned with it. Any other exit is an error, so a crash or an +/// incomplete run never reads as a result. +fn run_to_report_accepting( + args: &[&str], + scratch: &Scratch, + timeout: Duration, + accepted: &[i32], +) -> Result<(i32, serde_json::Value)> { let out = scratch.path().join("report.json"); let out_s = out.display().to_string(); let mut full: Vec<&str> = args.to_vec(); full.push("-o"); full.push(&out_s); let run = run_panic_attack_raw_in(&full, timeout, Some(scratch.path()))?; - if !run.status.success() { - bail!( + let code = match run.status.code() { + Some(c) if accepted.contains(&c) => c, + _ => bail!( "panic-attack {} exited with {}: {}", args.first().copied().unwrap_or("?"), run.status, first_diagnostic(&run.stderr) - ); - } + ), + }; let raw = std::fs::read_to_string(&out).with_context(|| { format!( - "panic-attack {} exited 0 without writing its report", + "panic-attack {} exited {code} without writing its report", args.first().copied().unwrap_or("?") ) })?; - serde_json::from_str(extract_json(&raw)).with_context(|| { + let value = serde_json::from_str(extract_json(&raw)).with_context(|| { format!( "panic-attack {} wrote a report that is not JSON", args.first().copied().unwrap_or("?") ) - }) + })?; + Ok((code, value)) } /// Resolve a path argument to an absolute, symlink-free string. @@ -668,9 +698,15 @@ pub fn parse_dynamic_report(value: serde_json::Value) -> Result { /// Run `panic-attack adjudicate` over dynamic-mode reports and return its /// verdict. /// -/// panic-attack 2.5.5 prints `pass (processed 0, failed 1)` and exits 0 for a -/// missing or unrecognised report, so exit status is not evidence of a verdict: -/// [`parse_adjudicate_verdict`] requires every input to have been processed. +/// Exit contract (panic-attack #292, not yet released): 0 is a complete run +/// with verdict pass or warn, 1 a complete run with verdict fail, 2 an +/// incomplete run (no report processed, or one failed to load) whatever the +/// verdict. Exit 0 and 1 are valid runs and the report is read; exit 2 is an +/// error. The pinned panic-attack (410a8f82) predates that contract and exits +/// 0 for every verdict, `fail` and a bad input (`pass (processed 0, failed 1)`) +/// included, so exit status alone is never evidence: +/// [`parse_adjudicate_verdict`] still requires every input to have been +/// processed, and an exit 1 must agree with a `fail` verdict. pub fn run_adjudicate_verdict(reports: &[PathBuf], timeout: Duration) -> Result { let scratch = Scratch::new()?; let mut args: Vec = vec!["adjudicate".to_string()]; @@ -678,8 +714,15 @@ pub fn run_adjudicate_verdict(reports: &[PathBuf], timeout: Duration) -> Result< args.push(absolute(r)?); } let arg_refs: Vec<&str> = args.iter().map(String::as_str).collect(); - let value = run_to_report(&arg_refs, &scratch, timeout)?; - parse_adjudicate_verdict(value, reports.len()) + let (code, value) = run_to_report_accepting(&arg_refs, &scratch, timeout, &[0, 1])?; + let v = parse_adjudicate_verdict(value, reports.len())?; + if code == 1 && v.verdict != "fail" { + bail!( + "panic-attack adjudicate exited 1 but wrote verdict {:?}, not 'fail'", + v.verdict + ); + } + Ok(v) } /// Validate and parse an `adjudicate` report for `expected` inputs. @@ -702,6 +745,11 @@ pub fn parse_adjudicate_verdict( v.verdict ); } + if v.verdict == "error" { + bail!( + "panic-attack adjudicate reported verdict 'error' (the run was incomplete or failed)" + ); + } if !matches!(v.verdict.as_str(), "pass" | "warn" | "fail") { bail!( "panic-attack adjudicate wrote unknown verdict {:?}", @@ -711,10 +759,24 @@ pub fn parse_adjudicate_verdict( Ok(v) } -/// Locate the `panic-attack` binary on PATH. +/// Locate the `panic-attack` binary on PATH and return an ABSOLUTE path. /// -/// Returns the path to the binary, or an error if not found. +/// The scan spawns panic-attack with a different working directory (the +/// scratch dir for `assay`/`adjudicate`), so a relative `PATH` entry would +/// otherwise resolve against the wrong directory (not found, or a binary the +/// scanned tree supplies). Canonicalised here, before any `current_dir`. fn find_panic_attack_binary() -> Result { + let found = locate_panic_attack_binary()?; + std::fs::canonicalize(&found).with_context(|| { + format!( + "cannot resolve the panic-attack executable {} to an absolute path", + found.display() + ) + }) +} + +/// Search PATH, then the common install locations. May return a relative path. +fn locate_panic_attack_binary() -> Result { // Check PATH via `which` let which_output = Command::new("which") .arg("panic-attack") @@ -786,6 +848,7 @@ fn run_panic_attack_cmd( json: bool, ) -> Result { use std::io::Read; + use std::os::unix::process::CommandExt; let binary = find_panic_attack_binary()?; @@ -808,50 +871,73 @@ fn run_panic_attack_cmd( cmd.stdout(std::process::Stdio::piped()); cmd.stderr(std::process::Stdio::piped()); + // Own process group: on a timeout `Child::kill` reaches only panic-attack, + // so a dynamic target and its descendants would survive and could hold the + // output pipes open. The group is killed as a whole instead. + cmd.process_group(0); + let mut child = cmd .spawn() .with_context(|| format!("Failed to spawn panic-attack at {}", binary.display()))?; // Drain both pipes on threads so a large report cannot fill a pipe and - // block the child while this thread waits on the deadline. + // block the child while this thread waits on the deadline. Each reader + // hands its bytes back over a channel so the join can be bounded. let (Some(mut out_pipe), Some(mut err_pipe)) = (child.stdout.take(), child.stderr.take()) else { - let _ = child.kill(); - let _ = child.wait(); - anyhow::bail!("panic-attack stdout/stderr pipes were not captured"); + let k = kill_note(kill_group(&mut child)); + anyhow::bail!("panic-attack stdout/stderr pipes were not captured{k}"); }; - let out_t = std::thread::spawn(move || { + let (out_tx, out_rx) = std::sync::mpsc::channel(); + let (err_tx, err_rx) = std::sync::mpsc::channel(); + std::thread::spawn(move || { let mut b = Vec::new(); let _ = out_pipe.read_to_end(&mut b); - b + let _ = out_tx.send(b); }); - let err_t = std::thread::spawn(move || { + std::thread::spawn(move || { let mut b = Vec::new(); let _ = err_pipe.read_to_end(&mut b); - b + let _ = err_tx.send(b); }); let deadline = std::time::Instant::now() + timeout; let status = loop { - match child - .try_wait() - .context("Failed to wait for panic-attack subprocess")? - { - Some(s) => break s, - None if std::time::Instant::now() >= deadline => { - let _ = child.kill(); - let _ = child.wait(); + match child.try_wait() { + Ok(Some(s)) => break s, + Ok(None) if std::time::Instant::now() >= deadline => { + let k = kill_note(kill_group(&mut child)); bail!( - "panic-attack did not finish within {}s (timed out and killed)", + "panic-attack did not finish within {}s (timed out and killed){k}", timeout.as_secs() ); } - None => std::thread::sleep(Duration::from_millis(20)), + Ok(None) => std::thread::sleep(Duration::from_millis(20)), + Err(e) => { + let k = kill_note(kill_group(&mut child)); + return Err(e).context(format!("Failed to wait for panic-attack subprocess{k}")); + } } }; - let stdout = String::from_utf8_lossy(&out_t.join().unwrap_or_default()).to_string(); - let stderr = String::from_utf8_lossy(&err_t.join().unwrap_or_default()).to_string(); + // panic-attack has exited, but a descendant may still hold the pipes: + // bound the read by the same deadline, then take the whole group down. + let left = || deadline.saturating_duration_since(std::time::Instant::now()); + // Recompute for each read: the first may use up most of the allowance. + let (stdout, stderr) = match (out_rx.recv_timeout(left()), err_rx.recv_timeout(left())) { + (Ok(o), Ok(e)) => ( + String::from_utf8_lossy(&o).to_string(), + String::from_utf8_lossy(&e).to_string(), + ), + _ => { + let k = kill_note(kill_pgid(&child)); + bail!( + "panic-attack left output pipes open past the {}s deadline \ + (a descendant process is still running; killed){k}", + timeout.as_secs() + ); + } + }; if !stderr.is_empty() { tracing::debug!("panic-attack stderr: {}", stderr.trim()); } @@ -862,6 +948,32 @@ fn run_panic_attack_cmd( }) } +/// SIGKILL the whole process group led by `child`. The child was started with +/// `process_group(0)`, so its pid is the group id. ESRCH (the group is already +/// gone) is the desired end state, not an error. +fn kill_pgid(child: &std::process::Child) -> std::result::Result<(), String> { + let pid = rustix::process::Pid::from_child(child); + let pgid = pid.as_raw_nonzero(); + match rustix::process::kill_process_group(pid, rustix::process::Signal::KILL) { + Ok(()) | Err(rustix::io::Errno::SRCH) => Ok(()), + Err(e) => Err(format!("could not kill process group {pgid}: {e}")), + } +} + +/// Kill the child's group, then the child itself, and reap it. Returns the +/// group-kill failure, if any, after the child has been killed and reaped. +fn kill_group(child: &mut std::process::Child) -> std::result::Result<(), String> { + let group = kill_pgid(child); + let _ = child.kill(); + let _ = child.wait(); + group +} + +/// Suffix for an error message when the group kill itself failed. +fn kill_note(r: std::result::Result<(), String>) -> String { + r.err().map(|e| format!(" ({e})")).unwrap_or_default() +} + /// Invoke `panic-attack` for the subcommands other than `assail`. /// /// Non-zero exit with output is tolerated here (diagnostics and some report diff --git a/bots/panicbot/src/suite.rs b/bots/panicbot/src/suite.rs index 23b31c0e..b7687360 100644 --- a/bots/panicbot/src/suite.rs +++ b/bots/panicbot/src/suite.rs @@ -147,6 +147,17 @@ pub struct SuiteRun { } impl SuiteRun { + /// The panic-attack version the suite's own `diagnostics` part reported, + /// when that part ran. Callers reuse it instead of running a second, + /// separately-timed diagnostics. + pub fn diagnostics_version(&self) -> Option<&str> { + self.parts + .iter() + .find(|p| p.command == Subcommand::Diagnostics && p.status == PartStatus::Ran) + .map(|p| p.detail.as_str()) + .filter(|v| !v.is_empty()) + } + /// The parts that ended in `error`. pub fn errored(&self) -> Vec<&Part> { self.parts diff --git a/bots/panicbot/tests/diagnostics_deadline_test.rs b/bots/panicbot/tests/diagnostics_deadline_test.rs new file mode 100644 index 00000000..012ece81 --- /dev/null +++ b/bots/panicbot/tests/diagnostics_deadline_test.rs @@ -0,0 +1,32 @@ +// SPDX-License-Identifier: MPL-2.0 +//! `--version` and `diagnostics` share ONE deadline: a preflight given `t` +//! seconds must not take up to `2t`. Own test file (own process) because it +//! sets `PATH`. + +use panicbot::scanner; +use std::fs; +use std::os::unix::fs::PermissionsExt; +use std::time::{Duration, Instant}; +use tempfile::TempDir; + +#[test] +fn version_and_diagnostics_share_one_deadline() { + let bin = TempDir::new().unwrap(); + let p = bin.path().join("panic-attack"); + fs::write( + &p, + "#!/usr/bin/env bash\ncase \"$1\" in --version) sleep 2; echo 'panic-attack 2.5.5' ;; *) sleep 20 ;; esac\n", + ) + .unwrap(); + fs::set_permissions(&p, fs::Permissions::from_mode(0o755)).unwrap(); + std::env::set_var("PATH", format!("{}:/usr/bin:/bin", bin.path().display())); + + let t = Instant::now(); + let r = scanner::run_diagnostics(Duration::from_secs(3)); + let took = t.elapsed(); + assert!(r.is_err(), "diagnostics hangs, so the preflight must fail"); + assert!( + took < Duration::from_millis(4200), + "the two invocations must share one 3s deadline, took {took:?}" + ); +} diff --git a/bots/panicbot/tests/envelope_parity_test.rs b/bots/panicbot/tests/envelope_parity_test.rs index 680a9b58..ce35a5d6 100644 --- a/bots/panicbot/tests/envelope_parity_test.rs +++ b/bots/panicbot/tests/envelope_parity_test.rs @@ -430,6 +430,227 @@ fn a_crashed_diagnostics_is_an_error_part() { && p["detail"].as_str().unwrap().contains("signal"))); } +/// On a timeout the whole process group dies. Killing only panic-attack would +/// leave the backgrounded `sleep` holding the output pipes, so the scan would +/// block until it ended. +#[test] +fn timeout_kills_descendants_and_returns_within_the_timeout() { + let bin = TempDir::new().unwrap(); + let pidfile = bin.path().join("child.pid"); + stub( + bin.path(), + &format!("sleep 25 &\necho $! > {}\nwait", pidfile.display()), + ); + let t = std::time::Instant::now(); + let o = scan(bin.path(), tree_with_timeout(Some(1)).path()); + assert!( + t.elapsed().as_secs() < 12, + "a descendant holding the pipes must not outlast the timeout" + ); + assert_not_a_run(&o, "did not finish within 1s"); + let pid = fs::read_to_string(&pidfile).unwrap().trim().to_string(); + let mut gone = false; + for _ in 0..50 { + let stat = fs::read_to_string(format!("/proc/{pid}/stat")); + if stat.map(|s| s.contains(") Z ")).unwrap_or(true) { + gone = true; + break; + } + std::thread::sleep(std::time::Duration::from_millis(100)); + } + assert!( + gone, + "the backgrounded descendant {pid} survived the timeout" + ); +} + +/// A relative `PATH` entry must be made absolute before `assay` changes the +/// working directory to its scratch dir. +#[test] +fn a_relative_path_entry_is_resolved_before_the_cwd_changes() { + let root = TempDir::new().unwrap(); + let bin = root.path().join("bin"); + fs::create_dir(&bin).unwrap(); + stub(&bin, &full_stub_body(ASSAY_NONE)); + let tree = tree_with_timeout(None); + let home = TempDir::new().unwrap(); + let o = Command::new(env!("CARGO_BIN_EXE_panicbot")) + .env_clear() + .current_dir(root.path()) + .env("PATH", "bin:/usr/bin:/bin") + .env("HOME", home.path()) + .env("RUST_LOG", "off") + .args(["--format", "json", "scan"]) + .arg(tree.path()) + .output() + .unwrap(); + assert!( + o.status.success(), + "stderr: {}", + String::from_utf8_lossy(&o.stderr) + ); + let v: serde_json::Value = serde_json::from_slice(&o.stdout).expect("a findings array"); + assert!(v.is_array(), "{v}"); +} + +fn scan_text(bin_dir: &Path, tree: &Path) -> Output { + let home = TempDir::new().unwrap(); + Command::new(env!("CARGO_BIN_EXE_panicbot")) + .env_clear() + .env("PATH", format!("{}:/usr/bin:/bin", bin_dir.display())) + .env("HOME", home.path()) + .env("RUST_LOG", "off") + .args(["--format", "text", "scan"]) + .arg(tree) + .output() + .unwrap() +} + +/// Text mode must not print "No issues found." for a run that errored or in +/// which nothing ran. +#[test] +fn text_mode_never_says_no_issues_for_an_incomplete_run() { + // assail fails: a part error (exit 3). + let bin = TempDir::new().unwrap(); + stub(bin.path(), "echo 'panic-attack: boom' >&2\nexit 3"); + let o = scan_text(bin.path(), tree_with_timeout(None).path()); + let out = String::from_utf8_lossy(&o.stdout); + assert_eq!(o.status.code(), Some(3), "{out}"); + assert!(!out.contains("No issues found."), "{out}"); + assert!(out.contains("INCOMPLETE"), "{out}"); + + // Nothing allowed to run (exit 4). + let tree = tree_with_timeout(None); + let d = tree.path().join(".machine_readable/bot_directives"); + fs::create_dir_all(&d).unwrap(); + fs::write(d.join("panicbot.a2ml"), "allow = [\"diagnostics\"]\n").unwrap(); + let bin = TempDir::new().unwrap(); + stub(bin.path(), "exit 0"); + let o = scan_text(bin.path(), tree.path()); + let out = String::from_utf8_lossy(&o.stdout); + assert_eq!(o.status.code(), Some(4), "{out}"); + assert!(!out.contains("No issues found."), "{out}"); + assert!(out.contains("NOT RUN"), "{out}"); +} + +/// A clean, complete run still says so. +#[test] +fn text_mode_says_no_issues_for_a_clean_complete_run() { + let bin = TempDir::new().unwrap(); + let clean = r#"{"program_path":"/t","language":"rust","statistics":{"total_lines":10},"weak_points":[]}"#; + stub(bin.path(), &full_stub_body(ASSAY_NONE).replace(REAL, clean)); + let o = scan_text(bin.path(), tree_with_timeout(None).path()); + let out = String::from_utf8_lossy(&o.stdout); + assert!( + o.status.success(), + "{out} {}", + String::from_utf8_lossy(&o.stderr) + ); + assert!(out.contains("No issues found."), "{out}"); +} + +/// Run a dynamic scan against a stub whose `adjudicate` writes `report` and +/// exits `code`; returns the scan output. +fn scan_with_adjudicate(code: i32, report: &str) -> Output { + let bin = TempDir::new().unwrap(); + let old = r#"echo '{"verdict":"pass","processed_reports":2,"failed_reports":0}' > "$out" ;;"#; + let body = recording_stub_body(ASSAY_NONE); + assert!(body.contains(old), "recording stub changed"); + stub( + bin.path(), + &body.replace(old, &format!("echo '{report}' > \"$out\"; exit {code} ;;")), + ); + let tree = tree_with_timeout(None); + let prog = tree.path().join("prog"); + fs::write(&prog, "#!/bin/sh\nexit 0\n").unwrap(); + fs::set_permissions(&prog, fs::Permissions::from_mode(0o755)).unwrap(); + let home = TempDir::new().unwrap(); + Command::new(env!("CARGO_BIN_EXE_panicbot")) + .env_clear() + .env("PATH", format!("{}:/usr/bin:/bin", bin.path().display())) + .env("HOME", home.path()) + .env("RUST_LOG", "off") + .args(["--format", "json", "scan"]) + .arg(tree.path()) + .args(["--target", "prog"]) + .output() + .unwrap() +} + +const VERDICT_FAIL: &str = r#"{"verdict":"fail","processed_reports":2,"failed_reports":0,"priorities":[{"level":"high","message":"crash"}]}"#; + +/// A valid adjudicated fail: a finding, and no error part. +fn assert_valid_fail(o: &Output) { + let err = String::from_utf8_lossy(&o.stderr); + assert!(o.status.success(), "stderr: {err}"); + let v: serde_json::Value = serde_json::from_slice(&o.stdout).expect("a findings array"); + let rules: Vec<&str> = v + .as_array() + .expect("an array, so no part errored") + .iter() + .map(|f| f["rule_id"].as_str().unwrap()) + .collect(); + assert!(rules.contains(&"PB-ADJUDICATE-VERDICT"), "{rules:?}"); +} + +/// An error part for adjudicate whose detail contains `why`. +fn assert_adjudicate_error(o: &Output, why: &str) { + assert_eq!( + o.status.code(), + Some(3), + "stderr: {}", + String::from_utf8_lossy(&o.stderr) + ); + let v: serde_json::Value = serde_json::from_slice(&o.stdout).expect("an object"); + let part = v["parts"] + .as_array() + .unwrap() + .iter() + .find(|p| p["command"] == "adjudicate") + .expect("an adjudicate part"); + assert_eq!(part["status"], "error", "{part}"); + assert!(part["detail"].as_str().unwrap().contains(why), "{part}"); +} + +#[test] +fn adjudicate_exit_1_with_verdict_fail_is_a_valid_fail() { + assert_valid_fail(&scan_with_adjudicate(1, VERDICT_FAIL)); +} + +#[test] +fn adjudicate_exit_2_is_an_error_part() { + // Incomplete run: error even though the report is otherwise well formed. + assert_adjudicate_error(&scan_with_adjudicate(2, VERDICT_FAIL), "exited with"); +} + +#[test] +fn adjudicate_verdict_error_with_exit_0_is_an_error_part() { + assert_adjudicate_error( + &scan_with_adjudicate( + 0, + r#"{"verdict":"error","processed_reports":2,"failed_reports":0}"#, + ), + "verdict 'error'", + ); +} + +#[test] +fn adjudicate_old_contract_exit_0_with_verdict_fail_is_still_a_valid_fail() { + // panic-attack 410a8f82 exits 0 for every verdict. + assert_valid_fail(&scan_with_adjudicate(0, VERDICT_FAIL)); +} + +#[test] +fn adjudicate_exit_1_with_a_non_fail_verdict_is_an_error_part() { + assert_adjudicate_error( + &scan_with_adjudicate( + 1, + r#"{"verdict":"pass","processed_reports":2,"failed_reports":0}"#, + ), + "not 'fail'", + ); +} + fn tree_with_deed(clause: &str) -> TempDir { let t = TempDir::new().unwrap(); fs::write(t.path().join("a.rs"), "fn main() {}\n").unwrap(); @@ -504,3 +725,28 @@ fn the_bare_bot_spelling_stops_the_run_and_names_the_canonical_one() { let err = String::from_utf8_lossy(&o.stderr); assert!(err.contains("(bot :name panicbot ...)"), "{err}"); } + +/// Two descendants hold the pipes for staggered times: stdout until just +/// before the deadline, stderr far past it. Both reads share one deadline, so +/// the second read gets only what the first left, not a fresh allowance. +#[test] +fn staggered_pipe_holders_share_one_deadline() { + let bin = TempDir::new().unwrap(); + // Only assail holds the pipes; every other command answers normally. + stub( + bin.path(), + &full_stub_body(ASSAY_NONE).replacen( + "case \"$1\" in\n", + "case \"$1\" in\n assail) sleep 3.5 2>/dev/null &\n sleep 25 >/dev/null &\n exit 0 ;;\n", + 1, + ), + ); + let t = std::time::Instant::now(); + let o = scan(bin.path(), tree_with_timeout(Some(4)).path()); + let took = t.elapsed(); + assert!( + took < std::time::Duration::from_millis(6500), + "two staggered reads must finish within one deadline, took {took:?}" + ); + assert!(!o.status.success()); +} diff --git a/bots/ponsbot/Cargo.lock b/bots/ponsbot/Cargo.lock index 2323ec69..88a2af91 100644 --- a/bots/ponsbot/Cargo.lock +++ b/bots/ponsbot/Cargo.lock @@ -212,6 +212,7 @@ name = "ponsbot" version = "0.1.0" dependencies = [ "clap", + "rustix", "serde", "serde_json", "tempfile", diff --git a/bots/ponsbot/Cargo.toml b/bots/ponsbot/Cargo.toml index 2e8fbd46..f7e12741 100644 --- a/bots/ponsbot/Cargo.toml +++ b/bots/ponsbot/Cargo.toml @@ -22,6 +22,7 @@ path = "src/main.rs" clap = { version = "4.6.1", features = ["derive"] } serde = { version = "1.0.228", features = ["derive"] } serde_json = "1.0.150" +rustix = { version = "1.1.6", default-features = false, features = ["process", "std"] } toml = "1.1.2" [dev-dependencies] diff --git a/bots/ponsbot/src/scanner.rs b/bots/ponsbot/src/scanner.rs index 32251384..b614121c 100644 --- a/bots/ponsbot/src/scanner.rs +++ b/bots/ponsbot/src/scanner.rs @@ -24,8 +24,10 @@ use crate::translator::PonsFinding; use serde_json::Value; use std::io::Read; +use std::os::unix::process::CommandExt; use std::path::{Path, PathBuf}; -use std::process::{Command, Stdio}; +use std::process::{Child, Command, Stdio}; +use std::sync::mpsc; use std::thread; use std::time::{Duration, Instant}; @@ -102,12 +104,15 @@ pub fn run_pons(dir: &Path, timeout: Duration, expected_commit: &str) -> Outcome Ok(b) => b, Err(reason) => return Outcome::NotRun(reason), }; + // Own process group: a timeout must take pons' descendants down with it, + // not only pons (a survivor can hold the output pipes open indefinitely). let mut child = match Command::new(&bin) .args(["scan", "--format", "json", "."]) .current_dir(dir) .stdin(Stdio::null()) .stdout(Stdio::piped()) .stderr(Stdio::piped()) + .process_group(0) .spawn() { Ok(c) => c, @@ -120,50 +125,94 @@ pub fn run_pons(dir: &Path, timeout: Duration, expected_commit: &str) -> Outcome Err(e) => return Outcome::Error(format!("could not start {}: {e}", bin.display())), }; // Drain both pipes on threads so a large report cannot fill a pipe and - // wedge the child before the deadline logic sees it. + // wedge the child before the deadline logic sees it. Each reader hands its + // bytes back over a channel so the join can be bounded by the deadline. let (Some(mut out_pipe), Some(mut err_pipe)) = (child.stdout.take(), child.stderr.take()) else { - let _ = child.kill(); - let _ = child.wait(); - return Outcome::Error("pons pipes were not captured".to_string()); + let k = kill_note(kill_group(&mut child)); + return Outcome::Error(format!("pons pipes were not captured{k}")); }; - let out_t = thread::spawn(move || { + let (out_tx, out_rx) = mpsc::channel(); + let (err_tx, err_rx) = mpsc::channel(); + thread::spawn(move || { let mut b = Vec::new(); let _ = out_pipe.read_to_end(&mut b); - b + let _ = out_tx.send(b); }); - let err_t = thread::spawn(move || { + thread::spawn(move || { let mut b = Vec::new(); let _ = err_pipe.read_to_end(&mut b); - b + let _ = err_tx.send(b); }); let deadline = Instant::now() + timeout; let status = loop { match child.try_wait() { Ok(Some(s)) => break Ok(s), Ok(None) if Instant::now() >= deadline => { - let _ = child.kill(); - let _ = child.wait(); - break Err(()); + break Err(kill_note(kill_group(&mut child))); } Ok(None) => thread::sleep(Duration::from_millis(20)), Err(e) => { - let _ = child.kill(); - let _ = child.wait(); - let _ = out_t.join(); - let _ = err_t.join(); - return Outcome::Error(format!("could not wait for pons: {e}")); + let k = kill_note(kill_group(&mut child)); + return Outcome::Error(format!("could not wait for pons: {e}{k}")); } } }; - let stdout = String::from_utf8_lossy(&out_t.join().unwrap_or_default()).into_owned(); - let stderr = String::from_utf8_lossy(&err_t.join().unwrap_or_default()).into_owned(); - match status { - Err(()) => Outcome::Error(format!("pons did not finish within {}s", timeout.as_secs())), - Ok(s) => interpret(s.code(), &stdout, &stderr, expected_commit), + let status = match status { + Ok(s) => s, + Err(k) => { + return Outcome::Error(format!( + "pons did not finish within {}s{k}", + timeout.as_secs() + )) + } + }; + // pons has exited, but a descendant may still hold the pipes: bound the + // read by the same deadline, then take the whole group down. + let left = || deadline.saturating_duration_since(Instant::now()); + // Recompute for each read: the first may use up most of the allowance. + let (stdout, stderr) = match (out_rx.recv_timeout(left()), err_rx.recv_timeout(left())) { + (Ok(o), Ok(e)) => ( + String::from_utf8_lossy(&o).into_owned(), + String::from_utf8_lossy(&e).into_owned(), + ), + _ => { + let k = kill_note(kill_pgid(&child)); + return Outcome::Error(format!( + "pons left output pipes open past the {}s deadline (a descendant process is still running){k}", + timeout.as_secs() + )); + } + }; + interpret(status.code(), &stdout, &stderr, expected_commit) +} + +/// SIGKILL the whole process group led by `child`. The child was started with +/// `process_group(0)`, so its pid is the group id. ESRCH (the group is already +/// gone) is the desired end state, not an error. +fn kill_pgid(child: &Child) -> Result<(), String> { + let pid = rustix::process::Pid::from_child(child); + let pgid = pid.as_raw_nonzero(); + match rustix::process::kill_process_group(pid, rustix::process::Signal::KILL) { + Ok(()) | Err(rustix::io::Errno::SRCH) => Ok(()), + Err(e) => Err(format!("could not kill process group {pgid}: {e}")), } } +/// Kill the child's group, then the child itself, and reap it. Returns the +/// group-kill failure, if any, after the child has been killed and reaped. +fn kill_group(child: &mut Child) -> Result<(), String> { + let group = kill_pgid(child); + let _ = child.kill(); + let _ = child.wait(); + group +} + +/// Suffix for an error message when the group kill itself failed. +fn kill_note(r: Result<(), String>) -> String { + r.err().map(|e| format!(" ({e})")).unwrap_or_default() +} + /// First nonblank stderr line, at most 240 characters. fn first_line(stderr: &str) -> String { stderr diff --git a/bots/ponsbot/tests/adapter_test.rs b/bots/ponsbot/tests/adapter_test.rs index e418d2ca..546f8b42 100644 --- a/bots/ponsbot/tests/adapter_test.rs +++ b/bots/ponsbot/tests/adapter_test.rs @@ -355,3 +355,76 @@ fn a_relative_path_entry_is_resolved_before_the_cwd_changes() { ); assert_eq!(out_json(&o)[0]["rule_id"], "constant-condition"); } + +/// A pons that backgrounds a long-lived descendant and waits for it. Killing +/// only pons would leave the `sleep` holding the output pipes, so the scan +/// would block until it ended; the whole process group must be killed. +#[test] +fn timeout_kills_the_descendants_and_returns_promptly() { + let (bin, scan) = (TempDir::new().unwrap(), tree()); + let pidfile = bin.path().join("child.pid"); + let pons = stub( + bin.path(), + &format!("sleep 25 &\necho $! > {}\nwait", pidfile.display()), + ); + let t = std::time::Instant::now(); + let o = ponsbot(&pons, scan.path(), &["--timeout", "1"]); + assert!( + t.elapsed().as_secs() < 10, + "a descendant holding the pipes must not outlast the timeout" + ); + assert_eq!(o.status.code(), Some(2)); + assert!(out_json(&o)["reason"] + .as_str() + .unwrap() + .contains("did not finish within 1s")); + let pid = fs::read_to_string(&pidfile).unwrap().trim().to_string(); + let mut gone = false; + for _ in 0..50 { + if !Path::new(&format!("/proc/{pid}")).exists() + || fs::read_to_string(format!("/proc/{pid}/stat")) + .map(|s| s.contains(") Z ")) + .unwrap_or(true) + { + gone = true; + break; + } + std::thread::sleep(std::time::Duration::from_millis(100)); + } + assert!( + gone, + "the backgrounded descendant {pid} survived the timeout" + ); +} + +/// pons exits promptly but leaves a descendant holding its output pipes: the +/// read is bounded by the deadline and reported as an error, never a hang. +#[test] +fn a_descendant_holding_the_pipes_after_exit_is_an_error_not_a_hang() { + let (bin, scan) = (TempDir::new().unwrap(), tree()); + let pons = stub(bin.path(), "sleep 25 &\nexit 0"); + let t = std::time::Instant::now(); + let o = ponsbot(&pons, scan.path(), &["--timeout", "2"]); + assert!(t.elapsed().as_secs() < 10, "the pipe read must be bounded"); + assert_eq!(o.status.code(), Some(2)); +} + +/// Two descendants hold the pipes for staggered times: stdout until just +/// before the deadline, stderr far past it. Both reads share one deadline, so +/// the second read gets only what the first left, not a fresh allowance. +#[test] +fn staggered_pipe_holders_share_one_deadline() { + let (bin, scan) = (TempDir::new().unwrap(), tree()); + let pons = stub( + bin.path(), + "sleep 3.5 2>/dev/null &\nsleep 25 >/dev/null &\nexit 0", + ); + let t = std::time::Instant::now(); + let o = ponsbot(&pons, scan.path(), &["--timeout", "4"]); + let took = t.elapsed(); + assert!( + took < std::time::Duration::from_millis(6500), + "two staggered reads must finish within one deadline, took {took:?}" + ); + assert_eq!(o.status.code(), Some(2)); +} diff --git a/docs/REPORT-BACK.adoc b/docs/REPORT-BACK.adoc index 4a8f8746..22cecc0f 100644 --- a/docs/REPORT-BACK.adoc +++ b/docs/REPORT-BACK.adoc @@ -37,7 +37,9 @@ adopts it. | `scripts/fleet-report-back-build.sh` | Builds the enrolled adapter crates (`cargo build --release --locked`) into one - directory and installs panic-attack at the pinned commit for panicbot and, with `--pons`, pons at the commit in `bots/ponsbot/canon/pin.toml` for ponsbot. One + directory and installs panic-attack at the pinned commit for panicbot and, with `--pons`, pons for ponsbot. `--pons` must equal the commit in + `bots/ponsbot/canon/pin.toml`: any other commit (or an unreadable pin) installs + nothing, with a warning, and ponsbot reads `not_run`. One recipe for the reusable workflow and for inline callers; a crate that fails to build is a warning here and an `error` row later, never a dead run. diff --git a/scripts/fleet-report-back-build.sh b/scripts/fleet-report-back-build.sh index f5610dfc..691b0bf0 100755 --- a/scripts/fleet-report-back-build.sh +++ b/scripts/fleet-report-back-build.sh @@ -29,7 +29,7 @@ # default: read `fleet-report-back.sh --plan` output on stdin # --panic-attack also install panic-attack at this commit into --bin-dir # --pons also install pons (pons-cli) at this commit into --bin-dir, -# for ponsbot; the commit is bots/ponsbot/canon/pin.toml +# for ponsbot; it must equal bots/ponsbot/canon/pin.toml, else skipped # --build-timeout seconds per cargo invocation (default 900) # --build-budget seconds for every build together (default 2400). A crate # whose turn comes after the budget is spent is not built @@ -120,6 +120,10 @@ fi if [[ -n "$pons_sha" ]]; then if ! [[ "$pons_sha" =~ ^[0-9a-f]{40}$ ]]; then warn "pons not installed" "$(printf '%q' "$pons_sha") is not a 40-hex commit; ponsbot will read not_run" + elif pin_commit=$(sed -n 's/^commit[[:space:]]*=[[:space:]]*"\([0-9a-f]\{40\}\)"[[:space:]]*$/\1/p' "$fleet/bots/ponsbot/canon/pin.toml" 2>/dev/null | head -n 1 || true); [[ -z "$pin_commit" ]]; then + warn "pons not installed" "cannot read the pinned commit from bots/ponsbot/canon/pin.toml; ponsbot will read not_run" + elif [[ "$pons_sha" != "$pin_commit" ]]; then + warn "pons not installed" "$pons_sha differs from the commit ponsbot pins ($pin_commit); a binary at another commit would only be refused, so none is built; ponsbot will read not_run" else root="$HOME/.pons"; bin="$root/bin/pons" group "pons at $pons_sha" diff --git a/tests/fleet-report-back-build-test.sh b/tests/fleet-report-back-build-test.sh index c8c1d45d..656a3fc0 100755 --- a/tests/fleet-report-back-build-test.sh +++ b/tests/fleet-report-back-build-test.sh @@ -224,6 +224,8 @@ check "invalid crate tokens count as failures while the valid build completes" y # --- pons for ponsbot: pinned install, cached by commit, never fatal ----------- PSHA=bca1ea289a4f8a86bac6212731e6f8ec15c67ad4 +mkdir -p "$FLEET/bots/ponsbot/canon" +printf '[source]\nrepo = "hyperpolymath/pons-asinorum"\ncommit = "%s"\n' "$PSHA" > "$FLEET/bots/ponsbot/canon/pin.toml" PH="$TMP/pons-home"; mkdir -p "$PH" "$TMP/pons-tools" cat > "$TMP/pons-tools/cargo" <<'STUB' #!/usr/bin/env bash @@ -262,6 +264,14 @@ check "pons: ...and leaves no binary and no cache behind" "no no" \ run_pons_build pons-badsha --pons 'not-a-commit; rm -rf /' check "pons: a non-commit value never reaches cargo" 0 "$(grep -c . "$FLEET_PONS_CALLS" || true)" check "pons: ...and is warned about" yes "$(grep -q 'not a 40-hex commit' "$TMP/pons-badsha.log" && echo yes || echo no)" +run_pons_build pons-otherpin --pons 0123456789abcdef0123456789abcdef01234567 +check "pons: a commit that differs from bots/ponsbot/canon/pin.toml never reaches cargo" 0 "$(grep -c . "$FLEET_PONS_CALLS" || true)" +check "pons: ...is warned about, naming the pinned commit" yes "$(grep -q "differs from the commit ponsbot pins ($PSHA)" "$TMP/pons-otherpin.log" && echo yes || echo no)" +check "pons: ...and leaves no binary" "" "$(files "$TMP/pons-otherpin")" +mkdir -p "$TMP/nopin/bots" +run_pons_build pons-nopin --pons "$PSHA" --fleet "$TMP/nopin" +check "pons: an unreadable pin installs nothing and says so" "0 yes" \ + "$(grep -c . "$FLEET_PONS_CALLS" || true) $(grep -q 'cannot read the pinned commit' "$TMP/pons-nopin.log" && echo yes || echo no)" run_pons_build pons-budget --pons "$PSHA" --build-budget 0 check "pons: a spent build budget skips the install with a warning" "0 yes" \ "$(grep -c . "$FLEET_PONS_CALLS" || true) $(grep -q 'spent before its turn' "$TMP/pons-budget.log" && echo yes || echo no)"