diff --git a/tests/runner/src/collect-k3s.sh b/tests/runner/src/collect-k3s.sh index 3b8408a2a5..bdaf774e57 100755 --- a/tests/runner/src/collect-k3s.sh +++ b/tests/runner/src/collect-k3s.sh @@ -28,6 +28,27 @@ collect_log() { printf '\ncommand status: %s\n' "${PIPESTATUS[0]}" } +# Gateway logs cover the whole run, so a failing test's window is included. +# The runner records when the run started; without that, use a fixed window. +# The tail is larger than for other logs because a gateway logs many lines. +RUN_STARTED_FILE=/var/tmp/openshell-run-started +log_since=--since=30m +if run_started=$(cat "$RUN_STARTED_FILE" 2>/dev/null) && + [[ $run_started =~ ^[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}Z$ ]]; then + log_since=--since-time=$run_started +fi + +collect_gateway_log() { + printf '\n### %s (%s)\n' "$1" "$log_since" + shift + timeout 20s "$@" 2>&1 | { + head -c 65536 + printf '\n### Remaining log tail\n' + tail -c 524288 + } + printf '\ncommand status: %s\n' "${PIPESTATUS[0]}" +} + { date --utc --iso-8601=seconds collect 'K3s service state' systemctl show k3s.service \ @@ -74,8 +95,8 @@ collect_log() { mapfile -t gateway_pods < <(timeout 10s /usr/local/bin/k3s kubectl --request-timeout=5s -n openshell get pods \ --selector app.kubernetes.io/name=openshell,app.kubernetes.io/instance=openshell --output name 2>/dev/null) for pod in "${gateway_pods[@]}"; do - collect "Gateway current logs ($pod)" /usr/local/bin/k3s kubectl --request-timeout=5s -n openshell logs "$pod" -c openshell-gateway --tail=300 --timestamps - collect "Gateway previous logs ($pod)" /usr/local/bin/k3s kubectl --request-timeout=5s -n openshell logs "$pod" -c openshell-gateway --previous --tail=300 --timestamps + collect_gateway_log "Gateway current logs ($pod)" /usr/local/bin/k3s kubectl --request-timeout=5s -n openshell logs "$pod" -c openshell-gateway "$log_since" --timestamps + collect_gateway_log "Gateway previous logs ($pod)" /usr/local/bin/k3s kubectl --request-timeout=5s -n openshell logs "$pod" -c openshell-gateway --previous "$log_since" --timestamps done collect 'Memory' free -m collect 'Disk' df -h / /var/lib/rancher/k3s diff --git a/tests/runner/src/execute.rs b/tests/runner/src/execute.rs index 7a7aa62cc2..20da81d70d 100644 --- a/tests/runner/src/execute.rs +++ b/tests/runner/src/execute.rs @@ -42,6 +42,9 @@ const READY_SLACK: Duration = Duration::from_mins(1); const NEXTEST_TEST_FAILED: i32 = 100; /// nextest's exit code when `--no-tests fail` found no tests to run. const NEXTEST_NO_TESTS_RUN: i32 = 4; +/// The variable that tells a test its per-test limit; testkit reads it +/// (`openshell_testkit::TIMEOUT_ENV`). +const TEST_TIMEOUT_ENV: &str = "OPENSHELL_TEST_TIMEOUT_SECS"; /// How long a stopped test has between SIGTERM and SIGKILL. Matches nextest's /// default, so both kinds of bundle stop a hung test the same way. const TEST_GRACE_SECS: u64 = 10; @@ -313,7 +316,10 @@ async fn run_tests(session: &Session, run: &Run<'_>) -> Result { let config = format!("{guest}/nextest.toml"); let timeout = TEST_TIMEOUT_SECS.to_string(); let grace = TEST_GRACE_SECS.to_string(); - let mut tests = vec!["env"]; + // Each test is told its own limit, so a stuck step fails with its own + // error before the runner stops the test. + let budget = format!("{TEST_TIMEOUT_ENV}={TEST_TIMEOUT_SECS}"); + let mut tests = vec!["env", budget.as_str()]; tests.extend(env.iter().map(String::as_str)); match kind { Kind::Nextest => { @@ -371,7 +377,7 @@ async fn run_tests(session: &Session, run: &Run<'_>) -> Result { // can be credentials, never appear in the command (or its errors). let log = format!("{guest}/{NEXTEST_LOG}"); let script = format!( - r#"exec >"$0" 2>&1; {}; exec "$@""#, + r#"exec >"$0" 2>&1; date -u +%Y-%m-%dT%H:%M:%SZ >{RUN_STARTED_FILE} || true; {}; exec "$@""#, test_env::export_script(test_env::ENV_DIR) ); let mut command = vec!["sh", "-c", &script, &log]; @@ -441,6 +447,9 @@ const WAIT_K3S_CONTROLLER: &str = include_str!("wait-k3s-controller.sh"); /// The script retries for up to ten minutes; this catches one that stalls. const WAIT_K3S_CONTROLLER_TIMEOUT: Duration = Duration::from_mins(12); +/// Where the run records when it started, in RFC 3339 UTC. The k3s diagnostics +/// read it (see `collect-k3s.sh`) to collect the gateway's logs from then on. +const RUN_STARTED_FILE: &str = "/var/tmp/openshell-run-started"; /// Where the guest keeps the script's output until it is copied out. const COLLECT_K3S_OUTPUT: &str = "/var/tmp/openshell-k3s-diagnostics.txt"; /// How long the guest lets the script run before stopping it. The script @@ -550,6 +559,11 @@ mod tests { assert!(matches!(status(2), Status::Error(_))); } + #[test] + fn k3s_diagnostics_read_the_file_the_run_writes() { + assert!(COLLECT_K3S.contains(RUN_STARTED_FILE)); + } + #[test] fn k3s_diagnostics_keep_everything_the_old_playbook_collected() { for wanted in [ @@ -576,6 +590,7 @@ mod tests { "free -m", "df -h", "[REDACTED]", + "--since-time", ] { assert!(COLLECT_K3S.contains(wanted), "missing {wanted:?}"); } diff --git a/tests/testkit/README.md b/tests/testkit/README.md index 09fcd05052..03550c5418 100644 --- a/tests/testkit/README.md +++ b/tests/testkit/README.md @@ -122,6 +122,14 @@ plaintext and mTLS gateways. `OPENSHELL_WORKSPACE` selects the workspace (default `openshell` on PATH). The CLI always targets the same gateway and workspace as the SDK. Each test logs the gateway it used. +`OPENSHELL_TEST_TIMEOUT_SECS` is the time one test may take, as the runner +enforces it. The runner sets it. When set, `cx.cli`, `cx.exec` and the wait +helpers give up about five seconds before that limit, with their own error, +instead of leaving the test to be stopped. When unset, as under plain +`cargo test`, each step keeps its own timeout. A CLI command that runs longer +than ten seconds, exits non-zero, or is still running after 30 seconds is +reported on stderr; fast successful commands print nothing. + Wait for the gateway, then run a suite. Run tests that share a gateway one at a time: diff --git a/tests/testkit/testkit/Cargo.toml b/tests/testkit/testkit/Cargo.toml index abfa8cf97b..7d5cda4851 100644 --- a/tests/testkit/testkit/Cargo.toml +++ b/tests/testkit/testkit/Cargo.toml @@ -30,7 +30,7 @@ serde = { version = "1", features = ["derive"] } serde_json = "1" serde_yml = { package = "noyalib", version = "0.0.53", default-features = false, features = ["std", "compat-serde-yaml"] } tempfile = "3" -tokio = { version = "1.43", features = ["macros", "process", "rt", "time"] } +tokio = { version = "1.43", features = ["io-util", "macros", "process", "rt", "time"] } tonic = "0.14" [target.'cfg(unix)'.dependencies] diff --git a/tests/testkit/testkit/src/budget.rs b/tests/testkit/testkit/src/budget.rs new file mode 100644 index 0000000000..c8aad86b69 --- /dev/null +++ b/tests/testkit/testkit/src/budget.rs @@ -0,0 +1,98 @@ +// SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +// SPDX-License-Identifier: Apache-2.0 + +//! The time one test may take, so a stuck step fails with its own error +//! before whoever runs the tests stops the test with a generic timeout. +//! +//! The runner exports the limit it enforces in [`TIMEOUT_ENV`]. Without it, +//! as when a test runs under plain `cargo test`, nothing is capped and each +//! step keeps its own timeout. + +use std::sync::OnceLock; +use std::sync::atomic::{AtomicBool, Ordering}; +use std::time::{Duration, Instant}; + +/// The per-test limit the runner enforces, in seconds. +pub const TIMEOUT_ENV: &str = "OPENSHELL_TEST_TIMEOUT_SECS"; + +/// How long before the limit a step gives up, so its error is reported and +/// the test cleans up before the runner stops it. +const MARGIN: Duration = Duration::from_secs(5); + +/// The least a step is given, so it still reports a timeout of its own. +const FLOOR: Duration = Duration::from_secs(1); + +/// Set once the test body is over: cleanup needs its own timeouts, because it +/// is most needed when the budget ran out. +static RELEASED: AtomicBool = AtomicBool::new(false); + +static DEADLINE: OnceLock> = OnceLock::new(); + +/// Start the clock for the current test. Call once, when the test starts. +pub(crate) fn start() { + DEADLINE.get_or_init(|| deadline_from(std::env::var(TIMEOUT_ENV).ok().as_deref())); +} + +/// Stop capping, for cleanup. +pub(crate) fn release() { + RELEASED.store(true, Ordering::Relaxed); +} + +fn deadline_from(value: Option<&str>) -> Option { + let secs: u64 = value?.trim().parse().ok().filter(|secs| *secs > 0)?; + Instant::now().checked_add(Duration::from_secs(secs).saturating_sub(MARGIN)) +} + +/// `timeout`, or the time left in the test's budget if that is less. +pub(crate) fn cap(timeout: Duration) -> Duration { + if RELEASED.load(Ordering::Relaxed) { + return timeout; + } + cap_at(timeout, DEADLINE.get().copied().flatten()) +} + +fn cap_at(timeout: Duration, deadline: Option) -> Duration { + match deadline { + Some(deadline) => timeout.min( + deadline + .saturating_duration_since(Instant::now()) + .max(FLOOR), + ), + None => timeout, + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn no_limit_leaves_the_timeout_alone() { + assert_eq!(deadline_from(None), None); + assert_eq!(deadline_from(Some("soon")), None); + assert_eq!(deadline_from(Some("0")), None); + assert_eq!( + cap_at(Duration::from_secs(300), None), + Duration::from_secs(300) + ); + } + + #[test] + fn a_step_gets_no_more_than_the_time_left() { + let deadline = deadline_from(Some("120")).unwrap(); + let capped = cap_at(Duration::from_secs(300), Some(deadline)); + assert!(capped <= Duration::from_secs(115), "{capped:?}"); + assert!(capped > Duration::from_secs(100), "{capped:?}"); + // A short step keeps its own timeout. + assert_eq!( + cap_at(Duration::from_secs(10), Some(deadline)), + Duration::from_secs(10) + ); + } + + #[test] + fn an_exhausted_budget_still_leaves_a_floor() { + let passed = Instant::now(); + assert_eq!(cap_at(Duration::from_secs(300), Some(passed)), FLOOR); + } +} diff --git a/tests/testkit/testkit/src/cli.rs b/tests/testkit/testkit/src/cli.rs index 5ac54e4108..debec34c24 100644 --- a/tests/testkit/testkit/src/cli.rs +++ b/tests/testkit/testkit/src/cli.rs @@ -11,7 +11,10 @@ use std::ffi::OsStr; use std::path::{Path, PathBuf}; use std::process::Stdio; -use std::time::Duration; +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; + +use tokio::io::AsyncReadExt; use serde::de::DeserializeOwned; @@ -20,6 +23,14 @@ use crate::gateway::{ENDPOINT_ENV, GATEWAY_ENV, Gateway, WORKSPACE_ENV}; /// How long one CLI invocation may take. pub const CLI_TIMEOUT: Duration = Duration::from_mins(5); +/// A command that takes longer than this is reported when it finishes. +const SLOW_COMMAND: Duration = Duration::from_secs(10); +/// How often a command that is still running is reported. +const STILL_RUNNING_EVERY: Duration = Duration::from_secs(30); +/// How much of a timed-out command's output the error includes. +const TIMEOUT_OUTPUT_BYTES: usize = 2048; +/// How long to wait for a stopped command's output to close. +const CAPTURE_CLOSE: Duration = Duration::from_secs(2); /// The CLI binary to run. Defaults to `openshell` on PATH. pub(crate) const BIN_ENV: &str = "OPENSHELL_BIN"; @@ -94,6 +105,21 @@ impl Cli { env: &[(&str, &str)], args: I, ) -> Result + where + I: IntoIterator, + S: AsRef, + { + self.run_limited(crate::budget::cap(CLI_TIMEOUT), dir, env, args) + .await + } + + async fn run_limited( + &self, + limit: Duration, + dir: Option<&Path>, + env: &[(&str, &str)], + args: I, + ) -> Result where I: IntoIterator, S: AsRef, @@ -132,18 +158,76 @@ impl Cli { process.current_dir(dir); } - let output = tokio::time::timeout(CLI_TIMEOUT, process.output()) - .await - .map_err(|_| Error::msg(format!("timed out after {CLI_TIMEOUT:?}"))) - .context(format!("run {command}"))? + let started = Instant::now(); + let mut child = process + .stdout(Stdio::piped()) + .stderr(Stdio::piped()) + .spawn() + .map_err(|error| Error::from_error(&error)) + .context(format!("run {command}"))?; + let stdout = Capture::start(child.stdout.take()); + let stderr = Capture::start(child.stderr.take()); + + // Say so while a command is still running, so a hang shows in the + // test's output instead of only in nextest's generic timeout. + let mut next_note = STILL_RUNNING_EVERY; + let status = loop { + let elapsed = started.elapsed(); + if elapsed >= limit { + break None; + } + let wait = next_note.min(limit).saturating_sub(elapsed); + tokio::select! { + status = child.wait() => break Some(status), + () = tokio::time::sleep(wait) => {} + } + if started.elapsed() >= next_note && started.elapsed() < limit { + eprintln!( + "still running after {}s: {command}", + started.elapsed().as_secs() + ); + next_note += STILL_RUNNING_EVERY; + } + }; + + let Some(status) = status else { + // Stop it, and report what it printed so far. + let _ = child.kill().await; + let (stdout, stderr) = (stdout.finish().await, stderr.finish().await); + let budget = if limit < CLI_TIMEOUT { + " (the test's time budget)" + } else { + "" + }; + return Err(Error::msg(format!( + "timed out after {limit:?}{budget}; stdout: {}; stderr: {}", + tail(&stdout), + tail(&stderr) + )) + .context(format!("run {command}"))); + }; + let status = status .map_err(|error| Error::from_error(&error)) .context(format!("run {command}"))?; + let stdout = stdout.finish().await; + let stderr = stderr.finish().await; + + // A signal-terminated CLI has no code; report it as a failure. + let exit_code = status.code().unwrap_or(-1); + let took = started.elapsed(); + if exit_code != 0 { + eprintln!( + "`{command}` exited with {exit_code} after {}s", + took.as_secs() + ); + } else if took >= SLOW_COMMAND { + eprintln!("`{command}` took {}s", took.as_secs()); + } Ok(CliOutput { command, - // A signal-terminated CLI has no code; report it as a failure. - exit_code: output.status.code().unwrap_or(-1), - stdout: String::from_utf8_lossy(&output.stdout).into_owned(), - stderr: String::from_utf8_lossy(&output.stderr).into_owned(), + exit_code, + stdout: String::from_utf8_lossy(&stdout).into_owned(), + stderr: String::from_utf8_lossy(&stderr).into_owned(), }) } } @@ -180,3 +264,119 @@ impl CliOutput { .context(format!("parse JSON output of `{}`", self.command)) } } + +/// A child's output, collected as it arrives so that what a command printed +/// before it was stopped is not lost. +struct Capture { + buffer: Arc>>, + task: tokio::task::JoinHandle<()>, +} + +impl Capture { + fn start(stream: Option) -> Self + where + R: tokio::io::AsyncRead + Unpin + Send + 'static, + { + let buffer = Arc::new(Mutex::new(Vec::new())); + let sink = Arc::clone(&buffer); + let task = tokio::spawn(async move { + let Some(mut stream) = stream else { return }; + let mut chunk = [0u8; 8192]; + while let Ok(n) = stream.read(&mut chunk).await { + if n == 0 { + break; + } + sink.lock() + .unwrap_or_else(std::sync::PoisonError::into_inner) + .extend_from_slice(&chunk[..n]); + } + }); + Self { buffer, task } + } + + /// Wait for the stream to close, up to [`CAPTURE_CLOSE`], and return what + /// was read. A grandchild that keeps the pipe open does not hold this up. + async fn finish(self) -> Vec { + let Self { buffer, mut task } = self; + if tokio::time::timeout(CAPTURE_CLOSE, &mut task) + .await + .is_err() + { + task.abort(); + } + std::mem::take( + &mut *buffer + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner), + ) + } +} + +/// The end of `output`, trimmed, for an error message. +fn tail(output: &[u8]) -> String { + let start = output.len().saturating_sub(TIMEOUT_OUTPUT_BYTES); + let text = String::from_utf8_lossy(&output[start..]); + let text = text.trim(); + if text.is_empty() { + "(none)".to_string() + } else if start > 0 { + format!("...{text}") + } else { + text.to_string() + } +} + +#[cfg(test)] +mod tests { + use super::*; + + fn sh() -> Cli { + Cli { + binary: PathBuf::from("sh"), + gateway: Gateway::from_endpoint( + "http://127.0.0.1:1".to_string(), + "default".to_string(), + ), + } + } + + #[tokio::test] + async fn a_command_past_its_limit_fails_with_its_name_and_output() { + let error = sh() + .run_limited( + Duration::from_millis(500), + None, + &[], + ["-c", "echo partial; echo oops >&2; sleep 30"], + ) + .await + .unwrap_err() + .to_string(); + assert!(error.contains("run sh -c echo partial"), "{error}"); + assert!(error.contains("timed out after"), "{error}"); + assert!(error.contains("stdout: partial"), "{error}"); + assert!(error.contains("stderr: oops"), "{error}"); + } + + #[tokio::test] + async fn a_fast_command_returns_its_output() { + let output = sh() + .run_limited( + Duration::from_secs(30), + None, + &[], + ["-c", "echo hi; exit 3"], + ) + .await + .unwrap(); + assert_eq!(output.exit_code, 3); + assert_eq!(output.stdout.trim(), "hi"); + } + + #[test] + fn tail_keeps_the_end_of_long_output() { + let long = "x".repeat(TIMEOUT_OUTPUT_BYTES + 10); + assert!(tail(long.as_bytes()).starts_with("...")); + assert_eq!(tail(b" "), "(none)"); + } +} diff --git a/tests/testkit/testkit/src/context.rs b/tests/testkit/testkit/src/context.rs index 7f09ad7397..d30fcdce33 100644 --- a/tests/testkit/testkit/src/context.rs +++ b/tests/testkit/testkit/src/context.rs @@ -258,6 +258,7 @@ impl Context { /// created and has not deleted. Returns the cleanup failures; they are /// reported separately from the test result. pub(crate) async fn cleanup(&self) -> Vec { + crate::budget::release(); self.cleanup.run(CLEANUP_TIMEOUT).await } } @@ -479,7 +480,7 @@ impl Sandbox { pub async fn wait_ready(&self) -> Result { let snapshot = self .client - .wait_ready(&self.name, READY_TIMEOUT) + .wait_ready(&self.name, crate::budget::cap(READY_TIMEOUT)) .await .context(format!("wait for sandbox {} to be ready", self.name))?; crate::ensure!( @@ -616,7 +617,7 @@ impl Sandbox { { let command: Vec = command.into_iter().map(Into::into).collect(); let options = ExecOptions { - timeout: Some(EXEC_TIMEOUT), + timeout: Some(crate::budget::cap(EXEC_TIMEOUT)), ..ExecOptions::default() }; let result = self diff --git a/tests/testkit/testkit/src/lib.rs b/tests/testkit/testkit/src/lib.rs index 8520fb80b3..1a5310a4a1 100644 --- a/tests/testkit/testkit/src/lib.rs +++ b/tests/testkit/testkit/src/lib.rs @@ -26,6 +26,7 @@ //! [`main`] is a test program that lists, runs, and reports its tests without //! Cargo (see [`program`]). +mod budget; mod cleanup; mod cli; mod context; @@ -41,6 +42,7 @@ mod registry; mod run; mod yaml_file; +pub use budget::TIMEOUT_ENV; pub use cleanup::CLEANUP_TIMEOUT; pub use cli::{CLI_TIMEOUT, Cli, CliOutput}; pub use context::{ diff --git a/tests/testkit/testkit/src/poll.rs b/tests/testkit/testkit/src/poll.rs index 838d89526d..9209162cf3 100644 --- a/tests/testkit/testkit/src/poll.rs +++ b/tests/testkit/testkit/src/poll.rs @@ -25,6 +25,7 @@ pub async fn poll_until( interval: Duration, mut observe: impl AsyncFnMut() -> Result>, ) -> Result { + let timeout = crate::budget::cap(timeout); let started = Instant::now(); loop { match observe().await? { diff --git a/tests/testkit/testkit/src/run.rs b/tests/testkit/testkit/src/run.rs index 701fc6e6ec..96a6a1a366 100644 --- a/tests/testkit/testkit/src/run.rs +++ b/tests/testkit/testkit/src/run.rs @@ -33,6 +33,7 @@ where F: AsyncFnOnce(&mut Context) -> Result, { let name = info.name; + crate::budget::start(); eprintln!("[{name}] {}", info.description); let gateway = Gateway::from_env().unwrap_or_else(|error| panic!("[{name}] {error}"));