Merge 'e26260d36eb8e7bf9e0b7edfed90c0dcff77fc19'
ci / check (push) Failing after 11m35s

This commit is contained in:
2026-10-26 13:59:16 +00:00
6 changed files with 801 additions and 40 deletions
+10
View File
@@ -84,6 +84,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
+29 -1
View File
@@ -463,9 +463,37 @@ 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/<n>/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/<YYYY-MM-DD>/<build-id>.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.
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
+1
View File
@@ -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" }
+421 -34
View File
@@ -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::{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<u64, Value> {
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";
@@ -25,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<Self> {
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<BuildLogs> {
let stream = |file: &std::fs::File, path: &Path| -> Result<StreamLog> {
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<Vec<u8>> {
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<BuildLogs>,
pub wasm: PathBuf,
pub warnings: String,
pub tests: TestResults,
@@ -35,9 +137,12 @@ pub struct BuildOutput {
/// A failed compiler or test phase, with its complete diagnostics.
#[derive(Debug)]
pub struct BuildFailure {
pub logs: Option<BuildLogs>,
pub reason: String,
pub tests: TestResults,
pub output: String,
pub elapsed_secs: Option<f64>,
pub step: Option<&'static str>,
}
impl std::fmt::Display for BuildFailure {
fn fmt(&self, formatter: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
@@ -48,9 +153,12 @@ impl std::error::Error for BuildFailure {}
impl From<anyhow::Error> for BuildFailure {
fn from(error: anyhow::Error) -> Self {
Self {
logs: None,
reason: "build preparation failed".into(),
output: format!("{error:#}"),
tests: TestResults::default(),
elapsed_secs: None,
step: None,
}
}
}
@@ -142,19 +250,59 @@ 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","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"))?;
match builder.build(&builder.world.plugin_dir(plugin).join("source")).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}})),
let options = BuildOptions {
timeout_secs: seconds(&params, "timeout_secs", DEFAULT_TIMEOUT_SECS)?,
test_timeout_secs: seconds(&params, "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,"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}})),
}
})
}));
}
/// 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<BuildOutput, BuildFailure> {
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<BuildOutput, BuildFailure> {
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<BuildOutput, BuildFailure> {
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 +356,35 @@ 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(),
logs,
)
.await?;
let stdout = String::from_utf8_lossy(&output.stdout);
let stderr = String::from_utf8_lossy(&output.stderr);
let tests = TestResults {
@@ -231,25 +398,36 @@ impl Cargo {
};
if !output.status.success() {
return Err(BuildFailure {
logs: None,
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(),
logs,
)
.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();
@@ -282,6 +460,7 @@ impl Cargo {
})
.await??;
Ok(BuildOutput {
logs: None,
wasm: destination,
warnings: strip_progress(&diagnostics),
tests: tests.clone(),
@@ -289,9 +468,12 @@ impl Cargo {
}
.await;
result.map_err(|error: anyhow::Error| BuildFailure {
logs: None,
reason: "release build failed".into(),
output: format!("{error:#}"),
tests,
elapsed_secs: None,
step: None,
})
}
}
@@ -306,16 +488,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<std::process::Output> {
async fn run_command(
mut command: Command,
started: Instant,
deadline: Instant,
step: &'static str,
mut tests: TestResults,
logs: &LogFiles,
) -> std::result::Result<std::process::Output, BuildFailure> {
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?)
// 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 (status, timed_out) = {
let collect = child.wait();
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)?;
// 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{}",
String::from_utf8_lossy(&out),
String::from_utf8_lossy(&err)
);
let output = output
.trim_end()
.lines()
.rev()
.take(50)
.collect::<Vec<_>>()
.into_iter()
.rev()
.collect::<Vec<_>>()
.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 {
logs: None,
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 +704,143 @@ fn strip_progress(output: &str) -> String {
.collect::<Vec<_>>()
.join("\n")
}
#[cfg(test)]
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<notify::Event>| {
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() {
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 directory = tempfile::tempdir().unwrap();
let logs = LogFiles::create(directory.path()).unwrap();
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(),
},
&logs,
)
.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"));
let raw = std::fs::read_to_string(&logs.stdout_path).unwrap();
assert_eq!(raw.lines().count(), 100);
assert!(raw.starts_with("diagnostic-0\n"));
}
}
+19 -2
View File
@@ -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::<u64>().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.
+321 -3
View File
@@ -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")));
@@ -56,8 +73,28 @@ async fn build(world: &TestWorld, name: &str) -> Result<Value, Value> {
.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,
@@ -189,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 "));
@@ -260,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()
@@ -606,6 +658,259 @@ 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");
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());
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");
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);
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 +920,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 +988,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"));