From c15e50d7520d17e40846e44bd6dc53412d6802cd Mon Sep 17 00:00:00 2001 From: Surma Date: Sun, 25 Oct 2026 20:14:32 +0000 Subject: [PATCH 1/2] Bound native cargo builds and individual WASI tests with cancellable deadlines --- DECISIONS.md | 10 ++ PROTOCOL.md | 14 ++ cli/Cargo.toml | 1 + cli/src/cargo.rs | 236 ++++++++++++++++++++++++++++----- cli/src/test_runner.rs | 21 ++- cli/tests/host/cargo.rs | 287 +++++++++++++++++++++++++++++++++++++++- 6 files changed, 533 insertions(+), 36 deletions(-) diff --git a/DECISIONS.md b/DECISIONS.md index 09194b8..12bc175 100644 --- a/DECISIONS.md +++ b/DECISIONS.md @@ -70,6 +70,16 @@ a plugin, or a change that the agent makes to itself. that occur only in WASI, for example a missing WASI function or a panic at start. The test runner uses the same Wasmtime and the same mounts as the core. +- **Tests never run without a timeout.** `cargo.build` serializes its work + folder, so one hung test or build script must not block all later builds. + `timeout_secs` defaults to 900 seconds after mutex acquisition, excluding + queue time; `test_timeout_secs` defaults to 120 seconds per WASI instance. + Both are optional positive integers, never null/unlimited. Test timeouts name + the failing test and let other instances finish. Build deadlines and + cancellation kill cargo's process group before dropping the mutex; timeout + errors retain the phase, elapsed time, and recent output. Source preparation + and publication retain serialization while their blocking filesystem work + finishes, even if cancelled, to avoid overlapping writes to the work folder. - **The SDK is not published.** `cargo` points `sausage-plugin = "0.1"` at its own copy, which it also shows in `/plugins/cargo/sdk/`. - **Compiled code is a cache, not state.** It lives outside the world, in diff --git a/PROTOCOL.md b/PROTOCOL.md index fad66bd..65be64d 100644 --- a/PROTOCOL.md +++ b/PROTOCOL.md @@ -421,6 +421,20 @@ builds `/plugins/notes/source/`: {"passed", "failed", "output"}, "warnings"}`. If a step fails, it returns an error with the compiler or test output. +- Optional `timeout_secs` is an integer of at least 1, default **900** (not + null or unlimited). The wall-clock budget starts when the build acquires its + mutex, excluding queue time, and covers tests and release compilation together. + On expiry, cargo and its descendant process group are killed and the mutex is + released. Error -32004 has reason/message `timeout`, with `data.reason`, + `data.elapsed_secs`, `data.step` (`tests` or `release build`), `data.tests`, + and `data.output` containing the last 50 output lines. +- Optional `test_timeout_secs` is an integer of at least 1, default **120**. + Each WASI test instance has this wall-clock budget. On expiry, the instance + is killed, its named test fails with `timed out after N s`, and remaining + tests continue. The overall build budget still applies. +- Cancellation kills cargo's process group, including build scripts and test + runners, before releasing the build mutex. An attached build also stops when + its caller ends (under the normal process stopping deadline). - A call to `cargo.build` gets a process ID, a folder in `/proc`, and journal entries, like other calls. - `/plugins/cargo/sdk/` shows the source of the SDK. The dependency diff --git a/cli/Cargo.toml b/cli/Cargo.toml index 58adf5a..dbebbf6 100644 --- a/cli/Cargo.toml +++ b/cli/Cargo.toml @@ -36,6 +36,7 @@ chrono = { version = "0.4.42", default-features = false, features = ["clock"] } tempfile = "3.27.0" [dev-dependencies] +tokio = { version = "1", features = ["test-util"] } hyper = { version = "1.12.0", features = ["server", "http1"] } hyper-util = { version = "0.1.21", features = ["tokio"] } sausage-interface = { path = "../interface" } diff --git a/cli/src/cargo.rs b/cli/src/cargo.rs index c13d6b2..af3bf5d 100644 --- a/cli/src/cargo.rs +++ b/cli/src/cargo.rs @@ -4,11 +4,44 @@ use anyhow::{Context, Result, bail}; use include_dir::{Dir, include_dir}; use serde_json::{Value, json}; use sha2::{Digest, Sha256}; +use std::time::Duration; use std::{ path::{Path, PathBuf}, sync::Arc, }; -use tokio::process::Command; +use tokio::{io::AsyncReadExt, process::Command, time::Instant}; + +/// Default wall-clock budget after acquiring the build mutex (not queue time). +pub const DEFAULT_TIMEOUT_SECS: u64 = 900; +/// Default wall-clock budget for each WASI test instance. +pub const DEFAULT_TEST_TIMEOUT_SECS: u64 = 120; + +/// Wall-clock budgets for a build and its individual WASI tests. +#[derive(Clone, Copy, Debug)] +pub struct BuildOptions { + pub timeout_secs: u64, + pub test_timeout_secs: u64, +} +impl Default for BuildOptions { + fn default() -> Self { + Self { + timeout_secs: DEFAULT_TIMEOUT_SECS, + test_timeout_secs: DEFAULT_TEST_TIMEOUT_SECS, + } + } +} +/// Optional RPC seconds are positive integers; null does not disable a deadline. +fn seconds(params: &Value, name: &str, default: u64) -> Result { + match params.get(name) { + None => Ok(default), + Some(value) => value + .as_u64() + .filter(|seconds| *seconds >= 1) + .ok_or_else(|| { + crate::error(-32602, &format!("{name} must be an integer of at least 1")) + }), + } +} /// The native build plugin. pub const ID: &str = "cargo"; @@ -38,6 +71,8 @@ pub struct BuildFailure { pub reason: String, pub tests: TestResults, pub output: String, + pub elapsed_secs: Option, + pub step: Option<&'static str>, } impl std::fmt::Display for BuildFailure { fn fmt(&self, formatter: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { @@ -51,6 +86,8 @@ impl From for BuildFailure { reason: "build preparation failed".into(), output: format!("{error:#}"), tests: TestResults::default(), + elapsed_secs: None, + step: None, } } } @@ -142,19 +179,39 @@ impl Cargo { host.register_native(ID,Arc::new(move |_context,method,params| { let builder=builder.clone(); Box::pin(async move { - if method=="rpc.discover" { return Ok(json!({"openrpc":"1.2.6","info":{"title":"cargo","version":"native"},"methods":[{"name":"build","paramStructure":"by-name","params":[{"name":"plugin","required":true,"schema":{"type":"string"}}],"result":{"name":"build","schema":{"type":"object","required":["wasm","tests","warnings"],"properties":{"wasm":{"type":"string"},"warnings":{"type":"string"},"tests":{"type":"object","required":["passed","failed","output"],"properties":{"passed":{"type":"integer","minimum":0},"failed":{"type":"integer","minimum":0},"output":{"type":"string"}}}}}},"errors":[{"code":-32004,"message":"Build failed"}]}]})); } + if method=="rpc.discover" { return Ok(json!({"openrpc":"1.2.6","info":{"title":"cargo","version":"native"},"methods":[{"name":"build","paramStructure":"by-name","description":"Copies source, runs bounded WASI tests, then builds a release component. Deadlines kill cargo and its descendants; cancellation releases the build mutex.","params":[{"name":"plugin","required":true,"schema":{"type":"string"}},{"name":"timeout_secs","required":false,"description":"Total wall-clock limit in seconds for tests and release build after acquiring the build mutex (queue time excluded). Default 900; minimum 1. Cannot be disabled.","schema":{"type":"integer","minimum":1,"default":DEFAULT_TIMEOUT_SECS}},{"name":"test_timeout_secs","required":false,"description":"Wall-clock limit in seconds for each WASI test instance. Default 120; minimum 1. A timed-out test is named and fails; remaining tests continue.","schema":{"type":"integer","minimum":1,"default":DEFAULT_TEST_TIMEOUT_SECS}}],"result":{"name":"build","schema":{"type":"object","required":["wasm","tests","warnings"],"properties":{"wasm":{"type":"string"},"warnings":{"type":"string"},"tests":{"type":"object","required":["passed","failed","output"],"properties":{"passed":{"type":"integer","minimum":0},"failed":{"type":"integer","minimum":0},"output":{"type":"string"}}}}}},"errors":[{"code":-32004,"message":"Build failed"}]}]})); } if method!="build" { return Err(crate::error(-32601,"cargo method not found")); } let plugin=params["plugin"].as_str().ok_or_else(||crate::error(-32602,"plugin must be a string"))?; - match builder.build(&builder.world.plugin_dir(plugin).join("source")).await { + let options = BuildOptions { + timeout_secs: seconds(¶ms, "timeout_secs", DEFAULT_TIMEOUT_SECS)?, + test_timeout_secs: seconds(¶ms, "test_timeout_secs", DEFAULT_TEST_TIMEOUT_SECS)?, + }; + match builder.build_with_options(&builder.world.plugin_dir(plugin).join("source"), options).await { Ok(output)=>Ok(json!({"wasm":format!("/{}",output.wasm.strip_prefix(&builder.world.root).unwrap().display()),"tests":output.tests,"warnings":output.warnings})), - Err(failure)=>Err(json!({"code":-32004,"message":failure.reason,"data":{"tests":failure.tests,"output":failure.output}})), + Err(failure)=>Err(json!({"code":-32004,"message":failure.reason,"data":{"reason":failure.reason,"tests":failure.tests,"output":failure.output,"elapsed_secs":failure.elapsed_secs,"step":failure.step}})), } }) })); } /// Copies source once, runs WASI tests, then publishes a release component under state/cargo/builds. pub async fn build(&self, source: &Path) -> std::result::Result { + self.build_with_options(source, BuildOptions::default()) + .await + } + /// Like build, with explicit positive wall-clock budgets. Waiting for the mutex is unbounded. + pub async fn build_with_options( + &self, + source: &Path, + options: BuildOptions, + ) -> std::result::Result { + if options.timeout_secs == 0 || options.test_timeout_secs == 0 { + return Err(anyhow::anyhow!("timeouts must be at least 1 second").into()); + } let build_guard = self.builds.clone().lock_owned().await; + let started = Instant::now(); + let deadline = started + .checked_add(Duration::from_secs(options.timeout_secs)) + .ok_or_else(|| anyhow::anyhow!("timeout_secs is too large"))?; let work = self.world.state_dir(ID).join("work"); let target = self.target.clone(); let temporary = self.world.state_dir(ID).join("tmp"); @@ -208,16 +265,27 @@ impl Cargo { .await .map_err(anyhow::Error::from)??; let mut test = Command::new("cargo"); - test.args(["test", "--release", "--target", TARGET, "--target-dir"]) - .arg(&target) - .current_dir(&work) - .env("TMPDIR", &temporary) - .arg("--config") - .arg(format!( - "target.wasm32-wasip2.runner={}", - json!([self.runner, "test-runner"]) - )); - let output = run_command(test).await?; + test.args([ + "test", + "--no-fail-fast", + "--release", + "--target", + TARGET, + "--target-dir", + ]) + .arg(&target) + .current_dir(&work) + .env("TMPDIR", &temporary) + .env( + "SAUSAGE_TEST_TIMEOUT_SECS", + options.test_timeout_secs.to_string(), + ) + .arg("--config") + .arg(format!( + "target.wasm32-wasip2.runner={}", + json!([self.runner, "test-runner"]) + )); + let output = run_command(test, started, deadline, "tests", TestResults::default()).await?; let stdout = String::from_utf8_lossy(&output.stdout); let stderr = String::from_utf8_lossy(&output.stderr); let tests = TestResults { @@ -234,22 +302,24 @@ impl Cargo { reason: "WASI tests failed".into(), output: tests.output.clone(), tests, + elapsed_secs: None, + step: None, }); } + let mut build = Command::new("cargo"); + build + .args([ + "build", + "--release", + "--target", + TARGET, + "--message-format=json-render-diagnostics", + "--target-dir", + ]) + .arg(&target) + .current_dir(&work); + let output = run_command(build, started, deadline, "release build", tests.clone()).await?; let result = async { - let mut build = Command::new("cargo"); - build - .args([ - "build", - "--release", - "--target", - TARGET, - "--message-format=json-render-diagnostics", - "--target-dir", - ]) - .arg(&target) - .current_dir(&work); - let output = run_command(build).await?; let stdout = String::from_utf8_lossy(&output.stdout); let stderr = String::from_utf8_lossy(&output.stderr); let diagnostics = stderr.to_string(); @@ -292,6 +362,8 @@ impl Cargo { reason: "release build failed".into(), output: format!("{error:#}"), tests, + elapsed_secs: None, + step: None, }) } } @@ -306,16 +378,81 @@ impl Drop for ProcessGroup { } } /// Starts one process group and retains its guard across all output collection. -async fn run_command(mut command: Command) -> Result { +async fn run_command( + mut command: Command, + started: Instant, + deadline: Instant, + step: &'static str, + mut tests: TestResults, +) -> std::result::Result { command .process_group(0) .kill_on_drop(true) .stdin(std::process::Stdio::null()) .stdout(std::process::Stdio::piped()) .stderr(std::process::Stdio::piped()); - let child = command.spawn().context("start cargo")?; - let _group = ProcessGroup(child.id().unwrap()); - Ok(child.wait_with_output().await?) + let mut child = command.spawn().context("start cargo")?; + let group = ProcessGroup(child.id().unwrap()); + let mut stdout = child.stdout.take().unwrap(); + let mut stderr = child.stderr.take().unwrap(); + let mut out = Vec::new(); + let mut err = Vec::new(); + let (status, timed_out) = { + let collect = async { + let (status, _, _) = tokio::try_join!( + child.wait(), + stdout.read_to_end(&mut out), + stderr.read_to_end(&mut err) + )?; + Ok::<_, std::io::Error>(status) + }; + tokio::pin!(collect); + tokio::select! { + biased; + _ = tokio::time::sleep_until(deadline) => { + // Kill the entire tree before waiting for EOF/reaping cargo. The guard also + // covers cancellation while collecting, and runs before the mutex drops. + let _ = nix::sys::signal::killpg(nix::unistd::Pid::from_raw(group.0 as i32), nix::sys::signal::Signal::SIGKILL); + (collect.await, true) + } + status = &mut collect => (status, false), + } + }; + let status = status.map_err(anyhow::Error::from)?; + if timed_out { + let output = format!( + "{}\n{}", + String::from_utf8_lossy(&out), + String::from_utf8_lossy(&err) + ); + let output = output + .trim_end() + .lines() + .rev() + .take(50) + .collect::>() + .into_iter() + .rev() + .collect::>() + .join("\n"); + if step == "tests" { + tests.passed = test_count(&String::from_utf8_lossy(&out), "passed"); + tests.failed = test_count(&String::from_utf8_lossy(&out), "failed"); + tests.output = output.clone(); + } + return Err(BuildFailure { + reason: "timeout".into(), + tests, + output, + elapsed_secs: Some(started.elapsed().as_secs_f64()), + step: Some(step), + }); + } + Ok(std::process::Output { + status, + stdout: out, + stderr: err, + }) } /// Copies only source, excluding build outputs and git internals at every level. fn copy_source(source: &Path, destination: &Path, root: bool) -> Result<()> { @@ -457,3 +594,40 @@ fn strip_progress(output: &str) -> String { .collect::>() .join("\n") } + +#[cfg(test)] +mod timeout_tests { + use super::*; + + /// Deadline errors retain the shared start time, phase, test totals, and output tail. + #[tokio::test] + async fn timeout_diagnostics() { + let mut command = Command::new("sh"); + command.args([ + "-c", + "i=0; while [ $i -lt 100 ]; do echo diagnostic-$i; i=$((i+1)); done; exec sleep 1000", + ]); + let now = Instant::now(); + let failure = run_command( + command, + now - Duration::from_secs(10), + now + Duration::from_secs(1), + "release build", + TestResults { + passed: 7, + failed: 0, + output: "successful tests".into(), + }, + ) + .await + .unwrap_err(); + assert_eq!(failure.reason, "timeout"); + assert_eq!(failure.step, Some("release build")); + assert!(failure.elapsed_secs.unwrap() >= 11.0); + assert_eq!(failure.tests.passed, 7); + assert_eq!(failure.tests.output, "successful tests"); + assert_eq!(failure.output.lines().count(), 50); + assert!(failure.output.contains("diagnostic-99")); + assert!(!failure.output.contains("diagnostic-0\n")); + } +} diff --git a/cli/src/test_runner.rs b/cli/src/test_runner.rs index f42cffd..2384f9a 100644 --- a/cli/src/test_runner.rs +++ b/cli/src/test_runner.rs @@ -64,12 +64,21 @@ async fn instance( ("SAUSAGE_PLUGIN".into(), "test".into()), ("SAUSAGE_PARENT".into(), "core".into()), ]); + let timeout_secs = std::env::var("SAUSAGE_TEST_TIMEOUT_SECS") + .ok() + .and_then(|value| value.parse::().ok()) + .filter(|value| *value >= 1) + .unwrap_or(sausage::cargo::DEFAULT_TEST_TIMEOUT_SECS); + let deadline = tokio::time::Instant::now() + .checked_add(std::time::Duration::from_secs(timeout_secs)) + .ok_or_else(|| anyhow::anyhow!("test_timeout_secs is too large"))?; + let (ended, mut ended_rx) = tokio::sync::watch::channel(true); let mut guest = runtime .start_with_args( &component, InstanceConfig { filesystem, - store_ended: tokio::sync::watch::channel(true).0, + store_ended: ended, network: true, env, }, @@ -88,6 +97,7 @@ async fn instance( let mut stdout_open = true; let mut stderr_open = true; let mut handlers = tokio::task::JoinSet::new(); + let result = tokio::time::timeout_at(deadline, async { while stdout_open || stderr_open || !pending.is_empty() { tokio::select! { line=async { if let Some(line) = pending.pop_front() { Some(line) } else { guest.stdout.recv().await } }, if stdout_open || !pending.is_empty()=>match line { @@ -129,11 +139,18 @@ async fn instance( }, } } + Ok::<_, anyhow::Error>(guest.wait().await) + }).await; handlers.abort_all(); - let exit = guest.wait().await; + // Dropping the instance aborts even a CPU-bound WASI loop. Wait for the + // store and outstanding filesystem work before removing its test world. + drop(guest); + let _ = ended_rx.wait_for(|ended| *ended).await; let _ = stderr_task.await; tracker.idle().await; host.stop().await; + let exit = + result.map_err(|_| anyhow::anyhow!("timed out after {timeout_secs} s\n{output}"))??; Ok(Run { exit, output }) } /// Extracts libtest names from its stable list format. diff --git a/cli/tests/host/cargo.rs b/cli/tests/host/cargo.rs index 78be9c1..a99c1b6 100644 --- a/cli/tests/host/cargo.rs +++ b/cli/tests/host/cargo.rs @@ -12,6 +12,23 @@ impl TestWorld { World::create(&path).unwrap(); Self(path) } + /// Short-deadline tests must not queue on another test's Cargo target lock. + async fn timeout_host(&self, name: &str) -> Host { + Host::start_with_cache(&self.0, &Path::new(CACHE).join("timeouts").join(name)) + .await + .unwrap() + } + /// Creates a dependency-free plugin fixture. + fn simple(&self, name: &str, text: &str) { + let root = self.0.join(format!("plugins/{name}/source")); + std::fs::create_dir_all(root.join("src")).unwrap(); + std::fs::write( + root.join("Cargo.toml"), + format!("[package]\nname='{name}'\nversion='0.1.0'\nedition='2024'\n"), + ) + .unwrap(); + std::fs::write(root.join("src/main.rs"), text).unwrap(); + } /// Copies a fixture into its plugin source folder. fn source(&self, name: &str, source: &Path) { copy(source, &self.0.join(format!("plugins/{name}/source"))); @@ -606,6 +623,257 @@ async fn standalone_builder() { 1 ); } +/// SAU-126: a named CPU-bound WASI test times out, while other instances still run. +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn named_test_timeout_and_mutex_release() { + let world = TestWorld::new(); + world.simple("test-timeout", "fn main() {} #[test] fn a_hung() { loop { std::hint::black_box(1); } } #[test] fn z_remaining() { eprintln!(\"REMAINING_TEST_RAN\"); }"); + world.simple("next", "fn main() {} #[test] fn passes() {}"); + let integration = world.0.join("plugins/test-timeout/source/tests"); + std::fs::create_dir_all(&integration).unwrap(); + std::fs::write( + integration.join("remaining.rs"), + "#[test] fn integration_remaining() { eprintln!(\"REMAINING_BINARY_RAN\"); }", + ) + .unwrap(); + let host = world.timeout_host("named").await; + let error = tokio::time::timeout( + std::time::Duration::from_secs(60), + host.call( + "cargo.build", + json!({"plugin":"test-timeout", "test_timeout_secs":1, "timeout_secs":45}), + ), + ) + .await + .unwrap() + .unwrap_err(); + assert_eq!(error["code"], -32004); + assert_eq!(error["message"], "WASI tests failed"); + assert_eq!(error["data"]["tests"]["failed"], 1); + assert_eq!(error["data"]["tests"]["passed"], 2); + let output = error["data"]["output"].as_str().unwrap(); + assert!(output.contains("test a_hung ... FAILED"), "{output}"); + assert!(output.contains("timed out after 1 s"), "{output}"); + assert!(output.contains("REMAINING_TEST_RAN"), "{output}"); + assert!(output.contains("REMAINING_BINARY_RAN"), "{output}"); + let next = tokio::time::timeout( + std::time::Duration::from_secs(30), + host.call("cargo.build", json!({"plugin":"next"})), + ) + .await + .unwrap() + .unwrap(); + assert_eq!(next["tests"]["passed"], 1); + host.stop().await; +} + +/// Wait for a build-script child without using timing sleeps. +async fn script_child(world: &TestWorld) -> u32 { + tokio::time::timeout(std::time::Duration::from_secs(60), async { + loop { + if let Ok(text) = std::fs::read_to_string(world.0.join("state/cargo/work/child.pid")) + && let Ok(pid) = text.trim().parse() + { + break pid; + } + tokio::task::yield_now().await; + } + }) + .await + .expect("build script never started") +} +/// A killed descendant may briefly remain as a zombie, but cannot keep executing. +async fn child_ended(child: u32) { + tokio::time::timeout(std::time::Duration::from_secs(10), async { + loop { + match std::fs::read_to_string(format!("/proc/{child}/stat")) { + Ok(status) if status.split_whitespace().nth(2) == Some("Z") => break, + Err(error) if error.kind() == std::io::ErrorKind::NotFound => break, + _ => tokio::task::yield_now().await, + } + } + }) + .await + .expect("cargo descendant survived cancellation/timeout"); +} + +/// SAU-126: an explicit small total budget kills build.rs and unblocks a queued build. +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn build_timeout_and_queued_build() { + let world = TestWorld::new(); + world.source("hang", &fixture("cargo-hang")); + world.simple("next", "fn main() {} #[test] fn passes() {}"); + let host = world.timeout_host("queued").await; + let building = host.clone(); + let task = tokio::spawn(async move { + building + .call("cargo.build", json!({"plugin":"hang", "timeout_secs":5})) + .await + }); + let child = script_child(&world).await; + let queued_host = host.clone(); + let queued = tokio::spawn(async move { + queued_host + .call("cargo.build", json!({"plugin":"next", "timeout_secs":3})) + .await + }); + let error = task.await.unwrap().unwrap_err(); + assert_eq!(error["code"], -32004); + assert_eq!(error["message"], "timeout"); + assert_eq!(error["data"]["reason"], "timeout"); + assert_eq!(error["data"]["step"], "tests"); + assert!(error["data"]["elapsed_secs"].as_f64().unwrap() >= 5.0); + assert!(!error["data"]["output"].as_str().unwrap().is_empty()); + child_ended(child).await; + let next = tokio::time::timeout(std::time::Duration::from_secs(20), queued) + .await + .unwrap() + .unwrap() + .unwrap(); + assert_eq!(next["tests"]["passed"], 1); + host.stop().await; +} + +/// SAU-126: the same total deadline covers release compilation and retains test results. +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn release_build_timeout_retains_tests() { + let world = TestWorld::new(); + world.simple( + "release-timeout", + r#"fn main() {} +#[test] fn prepare_release() { + std::fs::write(concat!(env!("CARGO_MANIFEST_DIR"), "/release-marker"), "ready").unwrap(); +}"#, + ); + std::fs::write( + world.0.join("plugins/release-timeout/source/build.rs"), + r#" +fn main() { + println!("cargo:rerun-if-changed=release-marker"); + if std::path::Path::new("release-marker").exists() { + std::process::Command::new("sh") + .args(["-c", "echo $$ > child.pid; exec sleep 1000"]) + .status().unwrap(); + } +}"#, + ) + .unwrap(); + let host = world.timeout_host("release").await; + let building = host.clone(); + let task = tokio::spawn(async move { + building + .call( + "cargo.build", + json!({"plugin":"release-timeout", "timeout_secs":5}), + ) + .await + }); + let child = script_child(&world).await; + let error = tokio::time::timeout(std::time::Duration::from_secs(10), task) + .await + .unwrap() + .unwrap() + .unwrap_err(); + assert_eq!(error["code"], -32004); + assert_eq!(error["data"]["reason"], "timeout"); + assert_eq!(error["data"]["step"], "release build"); + assert_eq!(error["data"]["tests"]["passed"], 1); + assert!(error["data"]["elapsed_secs"].as_f64().unwrap() >= 5.0); + child_ended(child).await; + host.stop().await; +} + +/// SAU-126: omission selects the real 900-second deadline, without a 15-minute test. +#[tokio::test] +async fn omitted_build_timeout_uses_default() { + let world = TestWorld::new(); + world.source("hang", &fixture("cargo-hang")); + let host = world.timeout_host("default").await; + let building = host.clone(); + let task = + tokio::spawn(async move { building.call("cargo.build", json!({"plugin":"hang"})).await }); + let child = script_child(&world).await; + tokio::time::pause(); + tokio::time::advance(std::time::Duration::from_secs( + sausage::cargo::DEFAULT_TIMEOUT_SECS, + )) + .await; + // Let the awakened deadline observe the advanced clock before resuming it. + tokio::task::yield_now().await; + let error = task.await.unwrap().unwrap_err(); + tokio::time::resume(); + assert_eq!(error["data"]["reason"], "timeout"); + assert!(error["data"]["elapsed_secs"].as_f64().unwrap() >= 900.0); + child_ended(child).await; + host.stop().await; +} + +/// SAU-126: a caller ending stops its attached native build and releases the mutex. +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn ended_caller_releases_build_mutex() { + let world = TestWorld::new(); + world.source("hang", &fixture("cargo-hang")); + world.simple("next", "fn main() {} #[test] fn passes() {}"); + let host = world.timeout_host("caller").await; + let (finish, finished) = tokio::sync::watch::channel(false); + host.register_native( + "caller", + std::sync::Arc::new(move |context, _, _| { + let mut finished = finished.clone(); + Box::pin(async move { + tokio::spawn( + async move { context.call("cargo.build", json!({"plugin":"hang"})).await }, + ); + let _ = finished.wait_for(|done| *done).await; + Ok(json!({})) + }) + }), + ); + let calling = host.clone(); + let caller = tokio::spawn(async move { calling.call("caller.run", json!({})).await }); + let child = script_child(&world).await; + let queued_host = host.clone(); + let queued = tokio::spawn(async move { + queued_host + .call("cargo.build", json!({"plugin":"next"})) + .await + }); + finish.send_replace(true); + caller.await.unwrap().unwrap(); + let next = tokio::time::timeout(std::time::Duration::from_secs(12), queued) + .await + .expect("ended caller retained mutex") + .unwrap() + .unwrap(); + assert_eq!(next["tests"]["passed"], 1); + child_ended(child).await; + host.stop().await; +} + +/// SAU-126: discovery exposes non-null defaults; invalid budgets cannot disable limits. +#[tokio::test] +async fn timeout_params_discovery_and_validation() { + let world = TestWorld::new(); + let host = Host::start_with_cache(&world.0, Path::new(CACHE)) + .await + .unwrap(); + let doc = host.call("cargo.rpc.discover", json!({})).await.unwrap(); + let params = doc["methods"][0]["params"].as_array().unwrap(); + for (name, default) in [("timeout_secs", 900), ("test_timeout_secs", 120)] { + let param = params.iter().find(|param| param["name"] == name).unwrap(); + assert_eq!(param["schema"]["default"], default); + assert_eq!(param["schema"]["minimum"], 1); + assert!(!param["description"].as_str().unwrap().is_empty()); + for value in [json!(0), json!(-1), json!(1.5), json!("1"), json!(null)] { + let mut args = json!({"plugin":"missing"}); + args[name] = value; + let error = host.call("cargo.build", args).await.unwrap_err(); + assert_eq!(error["code"], -32602, "{error}"); + } + } + host.stop().await; +} + /// PROTOCOL 11: killing a native build also kills its build-script descendants. #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn kill_process_group() { @@ -615,9 +883,7 @@ async fn kill_process_group() { ); let world = TestWorld::new(); world.source("hang", &fixture("cargo-hang")); - let host = Host::start_with_cache(&world.0, Path::new(CACHE)) - .await - .unwrap(); + let host = world.timeout_host("kill").await; let building = host.clone(); let task = tokio::spawn(async move { building.call("cargo.build", json!({"plugin":"hang"})).await }); @@ -685,8 +951,23 @@ async fn kill_process_group() { .unwrap() .is_empty() ); + // Queue a build on the SAME builder before cancelling the lock holder. + world.simple("next", "fn main() {} #[test] fn passes() {}"); + let queued_host = host.clone(); + let queued = tokio::spawn(async move { + queued_host + .call("cargo.build", json!({"plugin":"next"})) + .await + }); host.call("core.kill", json!({"pid":pid})).await.unwrap(); assert!(task.await.unwrap().is_err()); + child_ended(ancestor).await; + let next = tokio::time::timeout(std::time::Duration::from_secs(10), queued) + .await + .expect("cancelled build retained mutex") + .unwrap() + .unwrap(); + assert_eq!(next["tests"]["passed"], 1); tokio::time::timeout(std::time::Duration::from_secs(10), async { loop { let status = std::fs::read_to_string(format!("/proc/{child}/stat")); From e26260d36eb8e7bf9e0b7edfed90c0dcff77fc19 Mon Sep 17 00:00:00 2001 From: Surma Date: Mon, 26 Oct 2026 13:54:15 +0000 Subject: [PATCH 2/2] Spool native cargo build and test streams to persistent world logs --- PROTOCOL.md | 16 ++- cli/src/cargo.rs | 253 ++++++++++++++++++++++++++++++++++++---- cli/tests/host/cargo.rs | 37 ++++++ 3 files changed, 285 insertions(+), 21 deletions(-) diff --git a/PROTOCOL.md b/PROTOCOL.md index 1a39292..5e96d29 100644 --- a/PROTOCOL.md +++ b/PROTOCOL.md @@ -448,9 +448,23 @@ builds `/plugins/notes/source/`: 3. It builds the release `.wasm` for `wasm32-wasip2`. The tests and the build share the compiled dependencies. 4. It returns `{"wasm": "/state/cargo/builds//notes.wasm", "tests": - {"passed", "failed", "output"}, "warnings"}`. If a step fails, it returns + {"passed", "failed", "output"}, "warnings", "logs"}`. If a step fails, it returns an error with the compiler or test output. +- Before running commands, it creates `/logs/cargo//.stdout.log` + and `.stderr.log` (UTC date, unique build ID). Both test and release phases + append their raw bytes directly to these files, before any parsing, progress + filtering or UTF-8 conversion. This includes successful JSON build output. + `/logs` is a top-level world folder, created if missing, not under `/state`. +- Success results and error -32004 `data` include `logs`: + `{"stdout":{"path":"/logs/cargo/...stdout.log","bytes":123}, + "stderr":{"path":"/logs/cargo/...stderr.log","bytes":45},"total_bytes":168}`. + Counts are raw bytes, not characters. `logs` is null only if log creation + itself fails. Preparation failures otherwise include empty log files. + Inline diagnostics may be filtered or shortened; the files are the full truth. +- Logs remain after failure, total/test timeout, and cancellation. Cancellation + need not return a result; its files remain discoverable in `/logs/cargo/`. + Pruning numeric `/state/cargo/builds/` artifact folders does not prune logs. - Optional `timeout_secs` is an integer of at least 1, default **900** (not null or unlimited). The wall-clock budget starts when the build acquires its mutex, excluding queue time, and covers tests and release compilation together. diff --git a/cli/src/cargo.rs b/cli/src/cargo.rs index af3bf5d..717f6c6 100644 --- a/cli/src/cargo.rs +++ b/cli/src/cargo.rs @@ -9,7 +9,7 @@ use std::{ path::{Path, PathBuf}, sync::Arc, }; -use tokio::{io::AsyncReadExt, process::Command, time::Instant}; +use tokio::{process::Command, time::Instant}; /// Default wall-clock budget after acquiring the build mutex (not queue time). pub const DEFAULT_TIMEOUT_SECS: u64 = 900; @@ -58,9 +58,78 @@ pub struct TestResults { pub failed: u64, pub output: String, } +/// Raw, unfiltered output shared by the test and release phases of one build. +#[derive(Clone, Debug, serde::Serialize)] +pub struct BuildLogs { + pub stdout: StreamLog, + pub stderr: StreamLog, + pub total_bytes: u64, +} +#[derive(Clone, Debug, serde::Serialize)] +pub struct StreamLog { + pub path: String, + pub bytes: u64, +} +/// Persistent descriptors are inherited by cargo, so cancellation cannot lose +/// bytes already written by cargo or its descendants. No buffered writer is used. +struct LogFiles { + stdout: std::fs::File, + stderr: std::fs::File, + stdout_path: PathBuf, + stderr_path: PathBuf, +} +impl LogFiles { + fn create(world: &Path) -> Result { + let directory = world + .join("logs/cargo") + .join(chrono::Utc::now().format("%Y-%m-%d").to_string()); + std::fs::create_dir_all(&directory).context("create cargo log directory")?; + let id = uuid::Uuid::now_v7(); + let stdout_path = directory.join(format!("{id}.stdout.log")); + let stderr_path = directory.join(format!("{id}.stderr.log")); + let create = |path: &Path| { + std::fs::OpenOptions::new() + .create_new(true) + .append(true) + .open(path) + .with_context(|| format!("create {}", path.display())) + }; + Ok(Self { + stdout: create(&stdout_path)?, + stderr: create(&stderr_path)?, + stdout_path, + stderr_path, + }) + } + fn info(&self, world: &Path) -> Result { + let stream = |file: &std::fs::File, path: &Path| -> Result { + Ok(StreamLog { + path: format!("/{}", path.strip_prefix(world)?.display()), + bytes: file.metadata()?.len(), + }) + }; + let stdout = stream(&self.stdout, &self.stdout_path)?; + let stderr = stream(&self.stderr, &self.stderr_path)?; + Ok(BuildLogs { + total_bytes: stdout.bytes + stderr.bytes, + stdout, + stderr, + }) + } + fn read(&self, path: &Path, offset: u64) -> Result> { + use std::io::{Read, Seek, SeekFrom}; + let mut file = + std::fs::File::open(path).with_context(|| format!("read {}", path.display()))?; + file.seek(SeekFrom::Start(offset))?; + let mut bytes = Vec::new(); + file.read_to_end(&mut bytes)?; + Ok(bytes) + } +} /// A successful build, usable without a running host. #[derive(Debug)] pub struct BuildOutput { + pub logs: Option, pub wasm: PathBuf, pub warnings: String, pub tests: TestResults, @@ -68,6 +137,7 @@ pub struct BuildOutput { /// A failed compiler or test phase, with its complete diagnostics. #[derive(Debug)] pub struct BuildFailure { + pub logs: Option, pub reason: String, pub tests: TestResults, pub output: String, @@ -83,6 +153,7 @@ impl std::error::Error for BuildFailure {} impl From for BuildFailure { fn from(error: anyhow::Error) -> Self { Self { + logs: None, reason: "build preparation failed".into(), output: format!("{error:#}"), tests: TestResults::default(), @@ -179,7 +250,7 @@ impl Cargo { host.register_native(ID,Arc::new(move |_context,method,params| { let builder=builder.clone(); Box::pin(async move { - if method=="rpc.discover" { return Ok(json!({"openrpc":"1.2.6","info":{"title":"cargo","version":"native"},"methods":[{"name":"build","paramStructure":"by-name","description":"Copies source, runs bounded WASI tests, then builds a release component. Deadlines kill cargo and its descendants; cancellation releases the build mutex.","params":[{"name":"plugin","required":true,"schema":{"type":"string"}},{"name":"timeout_secs","required":false,"description":"Total wall-clock limit in seconds for tests and release build after acquiring the build mutex (queue time excluded). Default 900; minimum 1. Cannot be disabled.","schema":{"type":"integer","minimum":1,"default":DEFAULT_TIMEOUT_SECS}},{"name":"test_timeout_secs","required":false,"description":"Wall-clock limit in seconds for each WASI test instance. Default 120; minimum 1. A timed-out test is named and fails; remaining tests continue.","schema":{"type":"integer","minimum":1,"default":DEFAULT_TEST_TIMEOUT_SECS}}],"result":{"name":"build","schema":{"type":"object","required":["wasm","tests","warnings"],"properties":{"wasm":{"type":"string"},"warnings":{"type":"string"},"tests":{"type":"object","required":["passed","failed","output"],"properties":{"passed":{"type":"integer","minimum":0},"failed":{"type":"integer","minimum":0},"output":{"type":"string"}}}}}},"errors":[{"code":-32004,"message":"Build failed"}]}]})); } + if method=="rpc.discover" { return Ok(json!({"openrpc":"1.2.6","info":{"title":"cargo","version":"native"},"methods":[{"name":"build","paramStructure":"by-name","description":"Copies source, runs bounded WASI tests, then builds a release component. Deadlines kill cargo and its descendants; cancellation releases the build mutex.","params":[{"name":"plugin","required":true,"schema":{"type":"string"}},{"name":"timeout_secs","required":false,"description":"Total wall-clock limit in seconds for tests and release build after acquiring the build mutex (queue time excluded). Default 900; minimum 1. Cannot be disabled.","schema":{"type":"integer","minimum":1,"default":DEFAULT_TIMEOUT_SECS}},{"name":"test_timeout_secs","required":false,"description":"Wall-clock limit in seconds for each WASI test instance. Default 120; minimum 1. A timed-out test is named and fails; remaining tests continue.","schema":{"type":"integer","minimum":1,"default":DEFAULT_TEST_TIMEOUT_SECS}}],"result":{"name":"build","schema":{"type":"object","required":["wasm","tests","warnings","logs"],"properties":{"logs":{"type":"object","required":["stdout","stderr","total_bytes"],"properties":{"stdout":{"type":"object","required":["path","bytes"],"properties":{"path":{"type":"string"},"bytes":{"type":"integer","minimum":0}}},"stderr":{"type":"object","required":["path","bytes"],"properties":{"path":{"type":"string"},"bytes":{"type":"integer","minimum":0}}},"total_bytes":{"type":"integer","minimum":0}}},"wasm":{"type":"string"},"warnings":{"type":"string"},"tests":{"type":"object","required":["passed","failed","output"],"properties":{"passed":{"type":"integer","minimum":0},"failed":{"type":"integer","minimum":0},"output":{"type":"string"}}}}}},"errors":[{"code":-32004,"message":"Build failed"}]}]})); } if method!="build" { return Err(crate::error(-32601,"cargo method not found")); } let plugin=params["plugin"].as_str().ok_or_else(||crate::error(-32602,"plugin must be a string"))?; let options = BuildOptions { @@ -187,8 +258,8 @@ impl Cargo { test_timeout_secs: seconds(¶ms, "test_timeout_secs", DEFAULT_TEST_TIMEOUT_SECS)?, }; match builder.build_with_options(&builder.world.plugin_dir(plugin).join("source"), options).await { - Ok(output)=>Ok(json!({"wasm":format!("/{}",output.wasm.strip_prefix(&builder.world.root).unwrap().display()),"tests":output.tests,"warnings":output.warnings})), - Err(failure)=>Err(json!({"code":-32004,"message":failure.reason,"data":{"reason":failure.reason,"tests":failure.tests,"output":failure.output,"elapsed_secs":failure.elapsed_secs,"step":failure.step}})), + Ok(output)=>Ok(json!({"wasm":format!("/{}",output.wasm.strip_prefix(&builder.world.root).unwrap().display()),"tests":output.tests,"warnings":output.warnings,"logs":output.logs})), + Err(failure)=>Err(json!({"code":-32004,"message":failure.reason,"data":{"reason":failure.reason,"tests":failure.tests,"output":failure.output,"elapsed_secs":failure.elapsed_secs,"step":failure.step,"logs":failure.logs}})), } }) })); @@ -203,6 +274,26 @@ impl Cargo { &self, source: &Path, options: BuildOptions, + ) -> std::result::Result { + let logs = LogFiles::create(&self.world.root)?; + let result = self.build_logged(source, options, &logs).await; + let info = logs.info(&self.world.root)?; + match result { + Ok(mut output) => { + output.logs = Some(info); + Ok(output) + } + Err(mut failure) => { + failure.logs = Some(info); + Err(failure) + } + } + } + async fn build_logged( + &self, + source: &Path, + options: BuildOptions, + logs: &LogFiles, ) -> std::result::Result { if options.timeout_secs == 0 || options.test_timeout_secs == 0 { return Err(anyhow::anyhow!("timeouts must be at least 1 second").into()); @@ -285,7 +376,15 @@ impl Cargo { "target.wasm32-wasip2.runner={}", json!([self.runner, "test-runner"]) )); - let output = run_command(test, started, deadline, "tests", TestResults::default()).await?; + let output = run_command( + test, + started, + deadline, + "tests", + TestResults::default(), + logs, + ) + .await?; let stdout = String::from_utf8_lossy(&output.stdout); let stderr = String::from_utf8_lossy(&output.stderr); let tests = TestResults { @@ -299,6 +398,7 @@ impl Cargo { }; if !output.status.success() { return Err(BuildFailure { + logs: None, reason: "WASI tests failed".into(), output: tests.output.clone(), tests, @@ -318,7 +418,15 @@ impl Cargo { ]) .arg(&target) .current_dir(&work); - let output = run_command(build, started, deadline, "release build", tests.clone()).await?; + let output = run_command( + build, + started, + deadline, + "release build", + tests.clone(), + logs, + ) + .await?; let result = async { let stdout = String::from_utf8_lossy(&output.stdout); let stderr = String::from_utf8_lossy(&output.stderr); @@ -352,6 +460,7 @@ impl Cargo { }) .await??; Ok(BuildOutput { + logs: None, wasm: destination, warnings: strip_progress(&diagnostics), tests: tests.clone(), @@ -359,6 +468,7 @@ impl Cargo { } .await; result.map_err(|error: anyhow::Error| BuildFailure { + logs: None, reason: "release build failed".into(), output: format!("{error:#}"), tests, @@ -384,28 +494,23 @@ async fn run_command( deadline: Instant, step: &'static str, mut tests: TestResults, + logs: &LogFiles, ) -> std::result::Result { command .process_group(0) .kill_on_drop(true) .stdin(std::process::Stdio::null()) - .stdout(std::process::Stdio::piped()) - .stderr(std::process::Stdio::piped()); + // Child writes go straight to persistent files: no pipe buffers or reader + // tasks can be dropped on cancellation. Parsing happens only afterwards. + .stdout(logs.stdout.try_clone().context("clone stdout log")?) + .stderr(logs.stderr.try_clone().context("clone stderr log")?); + let out_start = logs.stdout.metadata().context("stat stdout log")?.len(); + let err_start = logs.stderr.metadata().context("stat stderr log")?.len(); let mut child = command.spawn().context("start cargo")?; let group = ProcessGroup(child.id().unwrap()); - let mut stdout = child.stdout.take().unwrap(); - let mut stderr = child.stderr.take().unwrap(); - let mut out = Vec::new(); - let mut err = Vec::new(); + let (status, timed_out) = { - let collect = async { - let (status, _, _) = tokio::try_join!( - child.wait(), - stdout.read_to_end(&mut out), - stderr.read_to_end(&mut err) - )?; - Ok::<_, std::io::Error>(status) - }; + let collect = child.wait(); tokio::pin!(collect); tokio::select! { biased; @@ -419,6 +524,10 @@ async fn run_command( } }; let status = status.map_err(anyhow::Error::from)?; + // Also stop any descendants that kept the streams open after cargo exited. + drop(group); + let out = logs.read(&logs.stdout_path, out_start)?; + let err = logs.read(&logs.stderr_path, err_start)?; if timed_out { let output = format!( "{}\n{}", @@ -441,6 +550,7 @@ async fn run_command( tests.output = output.clone(); } return Err(BuildFailure { + logs: None, reason: "timeout".into(), tests, output, @@ -599,6 +709,103 @@ fn strip_progress(output: &str) -> String { mod timeout_tests { use super::*; + /// Streams retain exact bytes, including non-UTF8, progress and JSON; phases append. + #[tokio::test] + async fn raw_streams_append_before_parsing() { + let directory = tempfile::tempdir().unwrap(); + let logs = LogFiles::create(directory.path()).unwrap(); + for _ in 0..2 { + let mut command = Command::new("sh"); + command.args(["-c", "printf '\\377raw\\r'; printf ' Compiling progress\\n{\"reason\":\"compiler-artifact\"}\\n' >&2; exit 3"]); + let now = Instant::now(); + let output = tokio::time::timeout( + Duration::from_secs(5), + run_command( + command, + now, + now + Duration::from_secs(3), + "tests", + TestResults::default(), + &logs, + ), + ) + .await + .unwrap() + .unwrap(); + assert!(!output.status.success()); + assert_eq!(output.stdout, b"\xffraw\r"); + assert!(String::from_utf8_lossy(&output.stderr).contains("Compiling progress")); + } + assert_eq!( + std::fs::read(&logs.stdout_path).unwrap(), + b"\xffraw\r\xffraw\r" + ); + let info = logs.info(directory.path()).unwrap(); + assert_eq!(info.stdout.bytes, 10); + assert_eq!(info.total_bytes, info.stdout.bytes + info.stderr.bytes); + assert!(info.stdout.path.starts_with("/logs/cargo/")); + assert!(!directory.path().join("state/cargo").exists()); + } + + /// Cancellation leaves kernel-written data intact, even without a newline. + #[tokio::test] + async fn cancelled_command_keeps_logs() { + use notify::Watcher; + let directory = tempfile::tempdir().unwrap(); + let logs = LogFiles::create(directory.path()).unwrap(); + let (tx, mut rx) = tokio::sync::mpsc::unbounded_channel(); + let mut watcher = + notify::recommended_watcher(move |event: notify::Result| { + if let Ok(event) = event { + if event + .paths + .iter() + .any(|path| path.file_name().is_some_and(|name| name == "ready")) + { + let _ = tx.send(()); + } + } + }) + .unwrap(); + watcher + .watch(directory.path(), notify::RecursiveMode::NonRecursive) + .unwrap(); + let mut command = Command::new("sh"); + command.args(["-c", "printf 'partial\\377'; printf 'stderr\\r' >&2; touch \"$1/ready\"; exec sleep 1000", "sh"]).arg(directory.path()); + let now = Instant::now(); + let task = tokio::spawn(async move { + run_command( + command, + now, + now + Duration::from_secs(60), + "tests", + TestResults::default(), + &logs, + ) + .await + }); + tokio::time::timeout(Duration::from_secs(5), rx.recv()) + .await + .unwrap() + .unwrap(); + task.abort(); + assert!(task.await.unwrap_err().is_cancelled()); + let paths: Vec<_> = std::fs::read_dir(directory.path().join("logs/cargo")) + .unwrap() + .flat_map(|day| std::fs::read_dir(day.unwrap().path()).unwrap()) + .map(|file| file.unwrap().path()) + .collect(); + assert_eq!(paths.len(), 2); + for path in paths { + let expected: &[u8] = if path.to_string_lossy().ends_with(".stdout.log") { + b"partial\xff" + } else { + b"stderr\r" + }; + assert_eq!(std::fs::read(path).unwrap(), expected); + } + } + /// Deadline errors retain the shared start time, phase, test totals, and output tail. #[tokio::test] async fn timeout_diagnostics() { @@ -607,6 +814,8 @@ mod timeout_tests { "-c", "i=0; while [ $i -lt 100 ]; do echo diagnostic-$i; i=$((i+1)); done; exec sleep 1000", ]); + let directory = tempfile::tempdir().unwrap(); + let logs = LogFiles::create(directory.path()).unwrap(); let now = Instant::now(); let failure = run_command( command, @@ -618,6 +827,7 @@ mod timeout_tests { failed: 0, output: "successful tests".into(), }, + &logs, ) .await .unwrap_err(); @@ -629,5 +839,8 @@ mod timeout_tests { assert_eq!(failure.output.lines().count(), 50); assert!(failure.output.contains("diagnostic-99")); assert!(!failure.output.contains("diagnostic-0\n")); + let raw = std::fs::read_to_string(&logs.stdout_path).unwrap(); + assert_eq!(raw.lines().count(), 100); + assert!(raw.starts_with("diagnostic-0\n")); } } diff --git a/cli/tests/host/cargo.rs b/cli/tests/host/cargo.rs index a99c1b6..e860322 100644 --- a/cli/tests/host/cargo.rs +++ b/cli/tests/host/cargo.rs @@ -73,8 +73,28 @@ async fn build(world: &TestWorld, name: &str) -> Result { .register(&host); let result = host.call("cargo.build", json!({"plugin":name})).await; host.stop().await; + let logs = match &result { + Ok(output) => &output["logs"], + Err(error) => &error["data"]["logs"], + }; + check_logs(world, logs); result } +/// RPC paths point at full raw streams, outside pruned build folders. +fn check_logs(world: &TestWorld, logs: &Value) { + let mut total = 0; + for stream in ["stdout", "stderr"] { + let path = logs[stream]["path"].as_str().expect("log path"); + assert!(path.starts_with("/logs/cargo/")); + assert!(path.ends_with(&format!(".{stream}.log"))); + let bytes = std::fs::metadata(world.0.join(path.trim_start_matches('/'))) + .unwrap() + .len(); + assert_eq!(logs[stream]["bytes"], bytes); + total += bytes; + } + assert_eq!(logs["total_bytes"], total); +} struct Valid { world: TestWorld, result: Value, @@ -206,6 +226,20 @@ async fn build_output_and_warnings() { .unwrap() .contains("fixture build warning") ); + let logs = &valid.result["logs"]; + let raw = |stream: &str| { + std::fs::read_to_string( + valid.world.0.join( + logs[stream]["path"] + .as_str() + .unwrap() + .trim_start_matches('/'), + ), + ) + .unwrap() + }; + assert!(raw("stdout").contains("\"reason\":\"compiler-artifact\"")); + assert!(raw("stderr").contains("Finished ")); let output = valid.result["tests"]["output"].as_str().unwrap(); assert!(output.contains("INTEGRATION_CASE")); assert!(!output.contains("Compiling ")); @@ -277,6 +311,7 @@ async fn native_discovery_and_error_paths() { .await .unwrap_err(); assert_eq!(error["code"], -32004); + check_logs(&world, &error["data"]["logs"]); assert!( error["data"]["output"] .as_str() @@ -721,6 +756,7 @@ async fn build_timeout_and_queued_build() { assert_eq!(error["code"], -32004); assert_eq!(error["message"], "timeout"); assert_eq!(error["data"]["reason"], "timeout"); + check_logs(&world, &error["data"]["logs"]); assert_eq!(error["data"]["step"], "tests"); assert!(error["data"]["elapsed_secs"].as_f64().unwrap() >= 5.0); assert!(!error["data"]["output"].as_str().unwrap().is_empty()); @@ -776,6 +812,7 @@ fn main() { .unwrap_err(); assert_eq!(error["code"], -32004); assert_eq!(error["data"]["reason"], "timeout"); + check_logs(&world, &error["data"]["logs"]); assert_eq!(error["data"]["step"], "release build"); assert_eq!(error["data"]["tests"]["passed"], 1); assert!(error["data"]["elapsed_secs"].as_f64().unwrap() >= 5.0);