brokerd: escape container errors in the log; prefix and quote two messages

Implemented-By: OpenCode session (model recorded in docs/implementer-log.md)

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: <name>@sha256:<64 hex digits>",
+                "[runner] image is {:?}; it must be named by digest: <name>@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
                     ),
                 ));

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()));
             }

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,

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<build::Build>, 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<build::Build> {
+    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);
+}

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);
+}