diff --git a/crates/brokerd/src/config.rs b/crates/brokerd/src/config.rs index f622d96..5e4c7ca 100644 --- a/crates/brokerd/src/config.rs +++ b/crates/brokerd/src/config.rs @@ -176,7 +176,7 @@ impl Config { } if let Some(runner) = &config.runner { let where_image = format!( - "[runner] image is {}; it must be named by digest: @sha256:<64 hex digits>", + "[runner] image is {:?}; it must be named by digest: @sha256:<64 hex digits>", runner.image ); let (name, hex) = match runner.image.rsplit_once("@sha256:") { @@ -198,7 +198,7 @@ impl Config { return Err(ConfigError::Invalid( path.to_path_buf(), format!( - "[runner] memory is {}; it must be a number and one of b, k, m, g", + "[runner] memory is {:?}; it must be a number and one of b, k, m, g", runner.memory ), )); diff --git a/crates/brokerd/src/container.rs b/crates/brokerd/src/container.rs index 424c45b..d4f8f3b 100644 --- a/crates/brokerd/src/container.rs +++ b/crates/brokerd/src/container.rs @@ -214,16 +214,20 @@ impl Podman { truncated, }), Some(2) => { - (self.log)(err); + (self.log)(&format!("brokerd: {name}: the tool could not run: {err:?}")); Err(RunError::Failed(COULD_NOT_RUN.to_string())) } Some(125..=127) => { - (self.log)(&format!("{err}\n{RUNBOOK}")); + (self.log)(&format!( + "brokerd: podman could not start {name}: {err:?}\n{RUNBOOK}" + )); Err(RunError::Unavailable(CANNOT_START.to_string())) } Some(137) => Err(RunError::Failed(KILLED.to_string())), _ => { - (self.log)(&format!("brokerd: container {name} exited {status}\n{err}")); + (self.log)(&format!( + "brokerd: container {name} exited {status}: {err:?}" + )); Err(RunError::Failed(UNEXPECTED.to_string())) } }, @@ -302,7 +306,7 @@ impl Podman { Ok(output) => { let stderr = String::from_utf8_lossy(&output.stderr).into_owned(); (self.log)(&format!( - "brokerd: podman could not start {name}-egress: {stderr}\n{RUNBOOK}" + "brokerd: podman could not start {name}-egress: {stderr:?}\n{RUNBOOK}" )); return Err(RunError::Unavailable(CANNOT_START.to_string())); } diff --git a/crates/brokerd/src/main.rs b/crates/brokerd/src/main.rs index 2938f31..98df926 100644 --- a/crates/brokerd/src/main.rs +++ b/crates/brokerd/src/main.rs @@ -97,7 +97,7 @@ fn main() -> ExitCode { broker_path.display(), admin_path.display() ); - eprintln!("{runtime_notice}"); + eprintln!("brokerd: {runtime_notice}"); match started.run() { Ok(()) => ExitCode::SUCCESS, diff --git a/crates/brokerd/tests/container_log.rs b/crates/brokerd/tests/container_log.rs new file mode 100644 index 0000000..dd5990b --- /dev/null +++ b/crates/brokerd/tests/container_log.rs @@ -0,0 +1,128 @@ +//! What a tool or Podman writes on standard error reaches `brokerd`'s log escaped, one entry per +//! event: it cannot start a line of its own or forge a runbook pointer (M3b review finding 5). +//! Do not edit. + +#[path = "support/build.rs"] +mod build; +#[path = "support/fake_podman.rs"] +mod fake_podman; + +use brokerd::container::{CANNOT_START, COULD_NOT_RUN, Podman, UNEXPECTED}; +use brokerd::policy::{Outcome, SessionState, decide}; +use brokerd::runner::run; +use build::{fetch, grant, now, read, set}; +use fake_podman::{Fake, Lines, serial}; +use proto::{Mode, ToolRequest, ToolResponse}; + +const FORGED: &str = "real line\nbrokerd: forged\nsee docs/runbook.md#grants-invalid"; + +fn call(fake: &Fake, req: ToolRequest, grants: Vec, log: &Lines) -> ToolResponse { + let podman = Podman::new(fake.runner(""), fake.dir.join("egress"), log.sink()); + let decision = match decide(req, &set(grants), SessionState::default(), now()) { + Outcome::Allowed(d) => d, + other => panic!("not allowed: {other:?}"), + }; + run(decision, &podman) +} + +/// No entry holds the forged text as lines of its own; the one that carries it has it escaped. +fn escaped(log: &Lines) { + let entries = log.0.lock().unwrap().clone(); + for entry in &entries { + assert!(!entry.contains("\nbrokerd: forged"), "raw: {entry:?}"); + assert!( + !entry.contains("\nsee docs/runbook.md#grants-invalid"), + "raw: {entry:?}" + ); + } + assert!( + entries + .iter() + .any(|e| e.contains(r"real line\nbrokerd: forged")), + "the error is still logged, escaped: {entries:?}" + ); +} + +fn notes() -> Vec { + vec![grant("notes", "read_file", Mode::Auto).paths(&["/n"])] +} + +#[test] +fn a_tool_that_could_not_run() { + let _s = serial(); + let fake = Fake::new( + "log-2", + &format!("cat > /dev/null; printf '{FORGED}' >&2; exit 2"), + ); + let log = Lines::default(); + assert_eq!( + call(&fake, read("/n/a"), notes(), &log), + ToolResponse::Failed { + message: COULD_NOT_RUN.to_string() + } + ); + escaped(&log); +} + +#[test] +fn a_container_podman_could_not_start_keeps_its_one_real_pointer() { + let _s = serial(); + let fake = Fake::new( + "log-125", + &format!("cat > /dev/null; printf '{FORGED}' >&2; exit 125"), + ); + let log = Lines::default(); + assert_eq!( + call(&fake, read("/n/a"), notes(), &log), + ToolResponse::Failed { + message: CANNOT_START.to_string() + } + ); + escaped(&log); + let entries = log.0.lock().unwrap().clone(); + assert!( + entries + .iter() + .any(|e| e.ends_with("\nsee docs/runbook.md#runner-unavailable")), + "{entries:?}" + ); +} + +#[test] +fn an_unexpected_ending() { + let _s = serial(); + let fake = Fake::new( + "log-3", + &format!("cat > /dev/null; printf '{FORGED}' >&2; exit 3"), + ); + let log = Lines::default(); + assert_eq!( + call(&fake, read("/n/a"), notes(), &log), + ToolResponse::Failed { + message: UNEXPECTED.to_string() + } + ); + escaped(&log); +} + +#[test] +fn a_proxy_podman_could_not_start() { + let _s = serial(); + let body = + format!("if [ \"$2\" = -d ]; then printf '{FORGED}' >&2; exit 125; fi; cat > /dev/null"); + let fake = Fake::new("log-egress", &body); + let log = Lines::default(); + let got = call( + &fake, + fetch("https://example.com/"), + vec![grant("web", "http_fetch", Mode::Auto).hosts(&["example.com"])], + &log, + ); + assert_eq!( + got, + ToolResponse::Failed { + message: CANNOT_START.to_string() + } + ); + escaped(&log); +} diff --git a/crates/brokerd/tests/notices.rs b/crates/brokerd/tests/notices.rs new file mode 100644 index 0000000..65aae3e --- /dev/null +++ b/crates/brokerd/tests/notices.rs @@ -0,0 +1,80 @@ +//! Two small texts from the M3b review: every line `brokerd serve` prints about its runtime starts +//! with `brokerd:`, and a bad `[runner]` value is quoted in its error. Do not edit. + +#[path = "support/fake_podman.rs"] +mod fake_podman; + +use std::io::Read; +use std::os::unix::net::UnixStream; +use std::process::{Command, Stdio}; +use std::time::{Duration, Instant}; + +use brokerd::config::{Config, ConfigError}; +use fake_podman::{Fake, IMAGE, serial}; + +#[test] +fn the_runtime_notice_starts_with_brokerd() { + let _s = serial(); + let fake = Fake::new("notice", "exit 0"); + let home = fake.dir.join("home"); + std::fs::create_dir_all(home.join("grants")).unwrap(); + let config = fake.dir.join("brokerd.toml"); + std::fs::write( + &config, + format!( + "[paths]\nhome = \"{0}\"\ngrants = \"{0}/grants\"\n[runner]\npodman = \"{1}\"\nimage = \"{IMAGE}\"\n", + home.display(), + fake.script.display() + ), + ) + .unwrap(); + let mut child = Command::new(env!("CARGO_BIN_EXE_brokerd")) + .args(["serve", "--config"]) + .arg(&config) + .stderr(Stdio::piped()) + .spawn() + .unwrap(); + let until = Instant::now() + Duration::from_secs(10); + while UnixStream::connect(home.join("run/loop-broker/broker.sock")).is_err() { + assert!(Instant::now() < until, "brokerd never listened"); + std::thread::sleep(Duration::from_millis(20)); + } + std::thread::sleep(Duration::from_millis(100)); + child.kill().unwrap(); + child.wait().unwrap(); + let mut printed = String::new(); + child + .stderr + .take() + .unwrap() + .read_to_string(&mut printed) + .unwrap(); + assert!( + printed + .lines() + .any(|l| l == format!("brokerd: tools run in containers from {IMAGE}")), + "{printed}" + ); +} + +#[test] +fn a_bad_runner_value_is_quoted() { + let dir = std::env::temp_dir().join(format!("bx-notice-cfg-{}", std::process::id())); + std::fs::create_dir_all(&dir).unwrap(); + let cases = [ + ("image = \"not by digest\"", "\"not by digest\""), + ( + &*format!("image = \"{IMAGE}\"\nmemory = \"lots\""), + "\"lots\"", + ), + ]; + for (n, (body, quoted)) in cases.iter().enumerate() { + let path = dir.join(format!("q{n}.toml")); + std::fs::write(&path, format!("[runner]\n{body}\n")).unwrap(); + match Config::load(&path) { + Err(ConfigError::Invalid(_, why)) => assert!(why.contains(quoted), "{why}"), + other => panic!("{body}: {other:?}"), + } + } + let _ = std::fs::remove_dir_all(&dir); +} diff --git a/docs/implementer-log.md b/docs/implementer-log.md index fa7fbd3..e0a6dd4 100644 --- a/docs/implementer-log.md +++ b/docs/implementer-log.md @@ -6,6 +6,7 @@ reviewer adds findings under "Reviews" once per milestone. | Task | Date | Status | Gate runs | First gate | Deviations | Notes | Model | |---|---|---|---|---|---|---|---| +| M3b/16-brokerd-log-escaping | 2026-09-23 | done | 1 | pass | none | Escaped the container's standard error before logging it (M3b review finding 5) and prefixed/quoted three small texts (finding 7). `container.rs` `answer`: exit 2 logs `brokerd: {name}: the tool could not run: {err:?}` instead of the raw stderr; exit 125..=127 logs `brokerd: podman could not start {name}: {err:?}\n{RUNBOOK}` (was `{err}\n{RUNBOOK}`); the `_` arm logs `brokerd: container {name} exited {status}: {err:?}` (the trailing `\n{err}` moved inside the debug format). `start_egress`: the proxy's `podman run -d` failure now logs `{stderr:?}`. `main.rs`: the runtime notice prints `brokerd: {runtime_notice}`. `config.rs`: the image and memory `[runner]` errors use `{:?}` so the bad value is quoted. Copied `tests/container_log.rs` and `tests/notices.rs`; 4, 2, 2 and 7 passed; `make gate` prints `gate: ok` first run. | ? | | M3b/15-brokerd-pipes-grace | 2026-09-23 | done | 1 | pass | none | Fixed the two M3b review findings in `pipes.rs`. Added `pub const GRACE: Duration = Duration::from_secs(2)`; replaced the `JoinHandle`-holding `Io` with one holding `Option, bool)>>` for stdout/stderr and added the `Finished { out, truncated, err, open }` struct. `Io::start` now returns `std::io::Result`: the stdin writer is started with `Builder::new().spawn(...)` and its handle dropped (never joined, a spawn error returned with `?`); a new private `reader(pipe, cap) -> io::Result>` starts one detached reader per pipe and returns a spawn error, used for both stdout (`cap`) and stderr (`err_cap`). `Io::finish(grace)` sets one `until = Instant::now() + grace` and calls a private `collect(rx, until)` per receiver: `recv_timeout(until.saturating_duration_since(now))` → `Ok` keeps bytes, `Timeout` sets `open`, `Disconnected` (panicked reader) counts closed; `open` is `stdout_open || stderr_open`. `read_capped` unchanged in behavior, now `cap.saturating_sub(kept.len())` and `chunk.get(..take).unwrap_or_default()` (no indexing, no wrapping subtraction). `container.rs`: added `pub const OUTPUT_OPEN` after `TIMED_OUT`, `use crate::pipes::{GRACE, Io}`, and replaced the `run_container` tail with the task's `Io::start` match (on spawn error, `podman kill`/`rm -f`, `child.kill()`/`wait()`, log + `Unavailable(CANNOT_START)`), then `io.finish(GRACE)` and the `done.open && status.is_some()` check returning `Failed(OUTPUT_OPEN)` (a timed-out call, `status` None, still answers `TIMED_OUT`). All `std::thread::spawn` gone from `crates/brokerd/src/`. Copied `tests/container_grace.rs`; 4 passed in ~4.4s, container 11, container_egress 6, all five runs; `make gate` prints `gate: ok` first run. | ? | | M3b/14-brokerd-pipes-module | 2026-09-23 | done | 1 | pass | none | Pure move: cut `struct Io`, `impl Io { start, finish }`, and `fn read_capped` from `container.rs` and pasted them into `crates/brokerd/src/pipes.rs` with bodies unchanged and `pub(crate)` visibility; `Io::start` now calls `crate::container::STDERR_KEPT` (the constant stays in `container.rs` since the tests import it). Added the module doc comment and the `use std::io::{Read, Write}`, `use std::process::Child`, `use std::thread::JoinHandle` lines. `lib.rs` gained `pub mod pipes;` between `ledger` and `podman`. `container.rs` gained `use crate::pipes::Io;` and lost the `Read, Write` and `JoinHandle` imports the compiler reported unused; nothing else changed. `cargo fmt --all` reflowed the `STDERR_KEPT` call line in `start` to wrap. `cargo check`/clippy clean; container 11, container_egress 6, serve_runner 2 pass; `grep "struct Io\|fn read_capped" container.rs` prints nothing and `container.rs` is 350 lines. `make gate` prints `gate: ok` on the first run. | ? | | M3b/13-brokerd-serve-runner | 2026-09-23 | done | 1 | pass | none | The `Podman` runtime was already written in task 12 (`crates/brokerd/src/container.rs`), so this task only wired it into `serve`. In `main.rs`: after the config loads, added `let log: Arc = Arc::new(|line| eprintln!("{line}"))`; chose the runtime and its notice with a match on `&cfg.runner` — `Some(runner)` captures `runner.image` first then `Box::new(Podman::new(runner.clone(), cfg.egress_dir(), Arc::clone(&log)))` with notice `tools run in containers from {image}`; `None` → `Box::new(Refusing)` with notice `no [runner] section: every tool call is refused`. Passed `runtime` and `log` to `serve::start` (its signature needed no change — it already took `Box` and `Arc`), and printed the notice with `eprintln!` after the `serving tools on … and approvals on …` line. Added `use brokerd::container::Podman` and `Runtime` to the imports. Copied `tests/serve_runner.rs`; the 2 new tests plus the 9 serve tests pass; `make gate` prints `gate: ok` on the first run. | ? |