From 4c26122357f39b092bf109953e90a81e3b70e871 Mon Sep 17 00:00:00 2001 From: Valentin Haudiquet Date: Thu, 17 Sep 2026 15:18:23 +0200 Subject: [PATCH] test: keep cargo test output quiet with per-test logs and a failure matrix cargo test used to be unreadable: subprocesses inherited the terminal, so dpkg-buildpackage, apt and configure output interleaved with the harness summary, and env_logger lines from parallel tests crossed each other. New test_support module, compiled into test binaries only (inert stubs otherwise) and initialized before main via .init_array: - all log output goes to target/pkh-test-logs/.log, one file per test thread, so concurrent tests never interleave - context-launched commands are captured line by line into the same file (driver-level wrapper); test-code spawns use run_logged() - a panic hook records failures and an atexit callback prints a matrix (test name, panic location, message, log path) after the libtest summary; tests panicking on purpose can opt out with a guard Also fixes two test bugs found on the way: - diff_checkbuilddeps_matrix compared dpkg-checkbuilddeps diagnostics against English messages without pinning the locale - run_source_build in differential tests now captures output like the live-UI path does --- src/build/mod.rs | 56 ++--- src/context/api.rs | 4 +- src/context/mod.rs | 4 + src/deb/ephemeral.rs | 3 + src/lib.rs | 4 + src/test_support.rs | 486 +++++++++++++++++++++++++++++++++++++++++++ 6 files changed, 532 insertions(+), 25 deletions(-) create mode 100644 src/test_support.rs diff --git a/src/build/mod.rs b/src/build/mod.rs index 7a7918e..8ac08b5 100644 --- a/src/build/mod.rs +++ b/src/build/mod.rs @@ -210,7 +210,10 @@ pub fn run_source_build( opts: &SourceBuildOptions, ui: Option>, ) -> Result> { - let sink: Option> = ui.as_ref().map(|u| u.sink()); + // Without a live UI, test runs still capture command output into the + // per-test log file instead of letting it inherit the terminal + let sink: Option> = + ui.as_ref().map(|u| u.sink()).or_else(crate::test_support::subprocess_sink); // ------------------------------------------------------------------ // 1. Sanity checks // ------------------------------------------------------------------ @@ -1304,7 +1307,7 @@ mod differential_tests { } } cmd.arg("-f").arg(&tarball).arg(&dir_name); - let status = cmd.status().expect("run tar"); + let status = crate::test_support::run_logged(&mut cmd).expect("run tar"); assert!(status.success(), "tar failed for {}", tarball.display()); } @@ -1312,12 +1315,10 @@ mod differential_tests { } fn copy_path(src: &Path, dst_root: &Path) { - let status = Command::new("cp") - .arg("-a") - .arg(src) - .arg(dst_root) - .status() - .expect("run cp -a"); + let status = crate::test_support::run_logged( + Command::new("cp").arg("-a").arg(src).arg(dst_root), + ) + .expect("run cp -a"); assert!( status.success(), "cp -a {} {} failed", @@ -1327,11 +1328,12 @@ mod differential_tests { } fn run_dpkg(tree: &Path) { - let status = Command::new("dpkg-buildpackage") - .current_dir(tree) - .args(["-S", "-I", "-i", "-nc", "-d", "--no-sign"]) - .status() - .expect("failed to run dpkg-buildpackage (is dpkg-dev installed?)"); + let status = crate::test_support::run_logged( + Command::new("dpkg-buildpackage") + .current_dir(tree) + .args(["-S", "-I", "-i", "-nc", "-d", "--no-sign"]), + ) + .expect("failed to run dpkg-buildpackage (is dpkg-dev installed?)"); assert!(status.success(), "dpkg-buildpackage failed"); } @@ -1551,8 +1553,12 @@ mod differential_tests { // builtin dependencies (build-essential:native), matching the // native checker which knows no builtins. All options must precede // the control-file operand (POSIX-style option parsing). + // The diagnostics are compared against the native checker's English + // messages, so the tool must run under the C locale regardless of + // the host configuration. let output = Command::new("dpkg-checkbuilddeps") .current_dir(dir.path()) + .env("LC_ALL", "C") .arg("--admindir") .arg(&admindir) .args(args) @@ -1782,11 +1788,12 @@ Provides: virtual-thing (= 2.0), plain-virtual let ours_tree = write_tree(&ours_root); // Golden side: real dpkg-buildpackage binary build. - let status = Command::new("dpkg-buildpackage") - .current_dir(&golden_tree) - .args(["-b", "-d", "--no-sign"]) - .status() - .expect("run dpkg-buildpackage (is dpkg-dev installed?)"); + let status = crate::test_support::run_logged( + Command::new("dpkg-buildpackage") + .current_dir(&golden_tree) + .args(["-b", "-d", "--no-sign"]), + ) + .expect("run dpkg-buildpackage (is dpkg-dev installed?)"); assert!(status.success(), "golden dpkg-buildpackage -b failed"); // Ours: emulate the pkh deb flow (rules build + rules binary with a @@ -1811,12 +1818,13 @@ Provides: virtual-thing (= 2.0), plain-virtual .collect(); for target in ["build", "binary"] { - let status = Command::new("debian/rules") - .current_dir(&ours_tree) - .envs(build_env_vars.clone()) - .arg(target) - .status() - .expect("run rules target"); + let status = crate::test_support::run_logged( + Command::new("debian/rules") + .current_dir(&ours_tree) + .envs(build_env_vars.clone()) + .arg(target), + ) + .expect("run rules target"); assert!(status.success(), "debian/rules {target} failed"); } diff --git a/src/context/api.rs b/src/context/api.rs index 8a90ec9..f2e5970 100644 --- a/src/context/api.rs +++ b/src/context/api.rs @@ -311,7 +311,9 @@ impl Context { overlay_mounts: std::sync::Mutex::new(Vec::new()), }), }; - *driver_lock = Some(driver); + // In test runs, commands whose output would inherit the terminal + // are captured into the per-test log file instead + *driver_lock = Some(crate::test_support::wrap_driver(driver)); } driver_lock } diff --git a/src/context/mod.rs b/src/context/mod.rs index 4ad8982..893090d 100644 --- a/src/context/mod.rs +++ b/src/context/mod.rs @@ -8,6 +8,10 @@ mod ssh; mod unshare; pub use api::{Context, ContextCommand, ContextConfig, LineSink, Stream}; +// The driver trait is implementation detail of the context API; it is only +// needed crate-internally (test-run capture wrapper), so keep it out of the +// public surface (and its documentation requirement). +pub(crate) use api::ContextDriver; pub use manager::ContextManager; use std::sync::Arc; diff --git a/src/deb/ephemeral.rs b/src/deb/ephemeral.rs index e701426..4f265ad 100644 --- a/src/deb/ephemeral.rs +++ b/src/deb/ephemeral.rs @@ -887,6 +887,9 @@ mod cleanup_registry_tests { #[test] fn panicking_hook_does_not_skip_the_others() { let _serial = test_lock(); + // The hook below panics on purpose: do not record it as a test + // failure in the end-of-run matrix + let _quiet = crate::test_support::suppress_failure_recording(); let (before, ran_before) = counting_hook(); let boom = register_cleanup_hook(Box::new(|| panic!("cleanup exploded"))); diff --git a/src/lib.rs b/src/lib.rs index a8326cb..c2f42f1 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -37,6 +37,10 @@ pub mod ui; /// Handle context for .deb building: locally, over ssh, in a chroot... pub mod context; +/// Quiet test runs: per-test log files, subprocess capture and failure +/// matrix (inert passthrough outside test binaries) +pub(crate) mod test_support; + /// Utility functions pub(crate) mod utils; diff --git a/src/test_support.rs b/src/test_support.rs new file mode 100644 index 0000000..9ee0142 --- /dev/null +++ b/src/test_support.rs @@ -0,0 +1,486 @@ +//! Test-run support: quiet console, per-test log files and an end-of-run +//! failure matrix. +//! +//! In test binaries (registered from `lib.rs`) and initialized before `main` +//! through an `.init_array` entry so every test gets the same treatment, with +//! or without `#[test_log::test]`: +//! +//! - all `log` output is written to a per-test file under +//! `target/pkh-test-logs/` instead of the terminal, so concurrent tests +//! never interleave their logs; +//! - subprocesses launched through a [`crate::context::Context`] (the whole +//! build pipeline: apt, dpkg, make, compilers, ...) are captured line by +//! line into the same per-test file instead of inheriting the terminal, +//! which used to garble the `cargo test` output beyond readability; +//! - [`run_logged`] does the same for direct `std::process::Command` spawns +//! from test code (e.g. the differential `dpkg-buildpackage` runs); +//! - a panic hook records test failures, and an `atexit` callback prints a +//! failure matrix (test name, panic message, log file path) right after +//! the libtest summary. +//! +//! Outside of test builds everything is an inert passthrough stub: the +//! production CLI behaves exactly as before. +//! +//! Attribution relies on libtest naming each test's thread after the test — +//! true for the default parallel runner. With `--test-threads=1` tests run +//! on the anonymous main thread and share `_uncategorized.log` instead; the +//! failure matrix then points at that file, and the panic location still +//! identifies the failing test. +//! +//! The panic hook records every panic of the process: the suite currently +//! has no `#[should_panic]` tests, so no filtering is needed; if one is +//! added, exclude it in `record_failure`. + +/// Production builds get passthrough stubs: no logger hijacking, no log +/// directory, commands inherit the terminal as always. +#[cfg(not(test))] +#[allow(dead_code)] +mod imp { + pub(crate) fn active() -> bool { + false + } + + pub(crate) fn subprocess_sink() -> Option> { + None + } + + pub(crate) fn wrap_driver( + driver: Box, + ) -> Box { + driver + } + + pub(crate) fn run_logged( + cmd: &mut std::process::Command, + ) -> std::io::Result { + cmd.status() + } + + pub(crate) fn suppress_failure_recording() -> SuppressFailuresStub { + SuppressFailuresStub + } + + /// Type returned by the production stub of + /// [`suppress_failure_recording`] + pub(crate) struct SuppressFailuresStub; +} + +#[cfg(test)] +mod imp { + use std::collections::HashMap; + use std::fmt::Write as _; + use std::fs::{self, File}; + use std::io::{self, Write as _}; + use std::panic::PanicHookInfo; + use std::path::{Path, PathBuf}; + use std::process::{Command, ExitStatus}; + use std::sync::{Arc, Mutex, OnceLock}; + + use crate::context::{ContextDriver, LineSink, Stream}; + + /// Directory receiving one log file per test + fn log_dir() -> PathBuf { + Path::new(env!("CARGO_MANIFEST_DIR")).join("target/pkh-test-logs") + } + + /// Log file of the current test thread, if attributable to a test + /// + /// Returns `None` for the anonymous `main` thread (`--test-threads=1`) + /// and for helper threads spawned by libraries: their output would be + /// misattributed, so it goes to the shared `_uncategorized.log`. + fn current_test_log_path() -> Option { + let thread = std::thread::current(); + let name = thread.name()?; + if name == "main" { + return None; + } + Some(log_dir().join(format!("{}.log", sanitize_test_name(name)))) + } + + /// File name-safe version of a test path (`a::b` → `a__b`) + fn sanitize_test_name(name: &str) -> String { + name.chars() + .map(|c| { + if c.is_ascii_alphanumeric() || c == '-' || c == '_' { + c + } else { + '_' + } + }) + .collect() + } + + /// Log file used when output cannot be attributed to one test + fn uncategorized_log_path() -> PathBuf { + log_dir().join("_uncategorized.log") + } + + /// Opened per-test log files, shared so that subprocess-capture threads + /// can append to the file of the test that started the command + fn files() -> &'static Mutex>>> { + static FILES: OnceLock>>>> = OnceLock::new(); + FILES.get_or_init(|| Mutex::new(HashMap::new())) + } + + /// Append one already-formatted line to the per-test log file at `path`, + /// creating it (with a header) on first use + fn append_line(path: &Path, line: &str) { + let file = { + let mut files = files().lock().unwrap_or_else(|e| e.into_inner()); + files + .entry(path.to_path_buf()) + .or_insert_with(|| { + Arc::new(Mutex::new(File::create(path).unwrap_or_else(|e| { + panic!("cannot open test log file {}: {e}", path.display()) + }))) + }) + .clone() + }; + let mut file = file.lock().unwrap_or_else(|e| e.into_inner()); + let _ = writeln!(file, "{line}"); + let _ = file.flush(); + } + + /// Whether a test is running and per-test logging is set up + pub(crate) fn active() -> bool { + ACTIVE.load(std::sync::atomic::Ordering::Relaxed) + } + + static ACTIVE: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false); + + // Runs before `main` of the test binary: installs the logger, the panic + // hook and the end-of-run matrix printer before any test starts. + #[used] + #[unsafe(link_section = ".init_array")] + static INIT: extern "C" fn() = init; + + extern "C" fn init() { + ACTIVE.store(true, std::sync::atomic::Ordering::Relaxed); + + // Do not prune the log directory here: `cargo test` may run several + // test binaries in sequence and later ones must not destroy the + // logs of earlier ones. Per-test files are truncated on first write, + // so the current run's logs are always current. + let _ = fs::create_dir_all(log_dir()); + + if log::set_boxed_logger(Box::new(TestLogger)).is_ok() { + log::set_max_level(log_filter_from_env()); + } + + let previous = std::panic::take_hook(); + std::panic::set_hook(Box::new(move |info| { + record_failure(info); + previous(info); + })); + + // SAFETY: `print_failure_matrix` is a plain function pointer with no + // argument; registering it as an exit handler is infallible. + unsafe { + libc::atexit(print_failure_matrix); + } + } + + /// Log level from `RUST_LOG`, defaulting to `info` like the CLI + fn log_filter_from_env() -> log::LevelFilter { + match std::env::var("RUST_LOG").as_deref() { + Ok("trace") => log::LevelFilter::Trace, + Ok("debug") => log::LevelFilter::Debug, + Ok("warn") => log::LevelFilter::Warn, + Ok("error") => log::LevelFilter::Error, + Ok("off") => log::LevelFilter::Off, + _ => log::LevelFilter::Info, + } + } + + /// Logger writing every record into the current test's log file + struct TestLogger; + + impl log::Log for TestLogger { + fn enabled(&self, metadata: &log::Metadata) -> bool { + metadata.level() <= log::max_level() + } + + fn log(&self, record: &log::Record) { + if !self.enabled(record.metadata()) { + return; + } + let timestamp = chrono::Utc::now().format("%H:%M:%S%.3f"); + let line = format!( + "{timestamp} {:<5} {}: {}", + record.level(), + record.target(), + record.args() + ); + append_line( + ¤t_test_log_path().unwrap_or_else(uncategorized_log_path), + &line, + ); + } + + fn flush(&self) {} + } + + /// One recorded test panic + struct Failure { + /// Name of the panicking thread: the test path for parallel runs + test: String, + /// Source location of the panic + location: String, + /// Panic message + message: String, + /// Per-test log file + log: PathBuf, + } + + static FAILURES: Mutex> = Mutex::new(Vec::new()); + + /// While alive on the current thread, panics are not recorded as test + /// failures + /// + /// For tests that panic on purpose (e.g. a cleanup hook whose panic is + /// caught and part of the behavior under test): without this they would + /// show up as phantom entries in the end-of-run failure matrix. + pub(crate) fn suppress_failure_recording() -> SuppressFailures { + SUPPRESSED.with(|count| count.set(count.get() + 1)); + SuppressFailures + } + + thread_local! { + static SUPPRESSED: std::cell::Cell = const { std::cell::Cell::new(0) }; + } + + pub(crate) struct SuppressFailures; + + impl Drop for SuppressFailures { + fn drop(&mut self) { + SUPPRESSED.with(|count| count.set(count.get().saturating_sub(1))); + } + } + + fn record_failure(info: &PanicHookInfo<'_>) { + if SUPPRESSED.with(|count| count.get() > 0) { + return; + } + let thread = std::thread::current(); + let test = thread.name().unwrap_or("").to_string(); + let location = info + .location() + .map(|l| format!("{}:{}:{}", l.file(), l.line(), l.column())) + .unwrap_or_default(); + let message = payload_message(info.payload()); + let log = current_test_log_path().unwrap_or_else(uncategorized_log_path); + append_line(&log, &format!("PANIC: {message}")); + FAILURES + .lock() + .unwrap_or_else(|e| e.into_inner()) + .push(Failure { + test, + location, + message, + log, + }); + } + + fn payload_message(payload: &(dyn std::any::Any + Send)) -> String { + if let Some(s) = payload.downcast_ref::<&str>() { + (*s).to_string() + } else if let Some(s) = payload.downcast_ref::() { + s.clone() + } else { + "panic with non-string payload".to_string() + } + } + + /// Print the failure matrix after the libtest summary (registered via + /// `atexit`, so it always runs last) + extern "C" fn print_failure_matrix() { + let failures = FAILURES.lock().unwrap_or_else(|e| e.into_inner()); + if failures.is_empty() { + return; + } + + let mut out = String::new(); + let _ = writeln!( + out, + "\n═══ pkh test failures: {} ═══ per-test logs in {} ═══", + failures.len(), + log_dir().display() + ); + for failure in failures.iter() { + let _ = writeln!(out, " • {}", failure.test); + if !failure.location.is_empty() { + let _ = writeln!(out, " at {}", failure.location); + } + let _ = writeln!(out, " panic {}", failure.message); + let _ = writeln!(out, " log {}", failure.log.display()); + } + let mut stderr = io::stderr().lock(); + let _ = stderr.write_all(out.as_bytes()); + let _ = stderr.flush(); + } + + /// Line sink forwarding subprocess output into a test's log file + struct TestFileSink { + path: PathBuf, + } + + impl LineSink for TestFileSink { + fn line(&self, stream: Stream, line: &str) { + let label = match stream { + Stream::Stdout => "out", + Stream::Stderr => "err", + }; + append_line(&self.path, &format!("[{label}] {line}")); + } + } + + /// Capture sink for subprocesses launched from the current test + /// + /// Returns `None` outside of test runs, letting callers keep their + /// normal inherit-or-UI-sink behavior. + pub(crate) fn subprocess_sink() -> Option> { + if !active() { + return None; + } + Some(Arc::new(TestFileSink { + path: current_test_log_path().unwrap_or_else(uncategorized_log_path), + })) + } + + /// Wrap a context driver so that plain (uncaptured) `run`/`run_output` + /// commands still have their output logged in test runs instead of + /// inheriting the terminal + pub(crate) fn wrap_driver( + driver: Box, + ) -> Box { + if !active() { + return driver; + } + Box::new(CapturingDriver { inner: driver }) + } + + struct CapturingDriver { + inner: Box, + } + + impl ContextDriver for CapturingDriver { + fn run( + &self, + program: &str, + args: &[String], + env: &[(String, String)], + cwd: Option<&str>, + ) -> io::Result { + match subprocess_sink() { + Some(sink) => self.inner.run_captured(program, args, env, cwd, sink), + None => self.inner.run(program, args, env, cwd), + } + } + + fn run_captured( + &self, + program: &str, + args: &[String], + env: &[(String, String)], + cwd: Option<&str>, + sink: Arc, + ) -> io::Result { + self.inner.run_captured(program, args, env, cwd, sink) + } + + fn run_output( + &self, + program: &str, + args: &[String], + env: &[(String, String)], + cwd: Option<&str>, + ) -> io::Result { + let sink = subprocess_sink(); + // Commands whose stdout is parsed still need the real output, so + // delegate to run_output and additionally forward the lines to + // the per-test log + let output = self.inner.run_output(program, args, env, cwd)?; + if let Some(sink) = sink { + for line in String::from_utf8_lossy(&output.stdout).lines() { + sink.line(Stream::Stdout, line); + } + for line in String::from_utf8_lossy(&output.stderr).lines() { + sink.line(Stream::Stderr, line); + } + } + Ok(output) + } + + fn ensure_available(&self, src: &Path, dest_root: &str) -> io::Result { + self.inner.ensure_available(src, dest_root) + } + + fn retrieve_path(&self, src: &Path, dest: &Path) -> io::Result<()> { + self.inner.retrieve_path(src, dest) + } + + fn list_files(&self, path: &Path) -> io::Result> { + self.inner.list_files(path) + } + + fn create_temp_dir(&self) -> io::Result { + self.inner.create_temp_dir() + } + + fn copy_path(&self, src: &Path, dest: &Path) -> io::Result<()> { + self.inner.copy_path(src, dest) + } + + fn read_file(&self, path: &Path) -> io::Result { + self.inner.read_file(path) + } + + fn write_file(&self, path: &Path, content: &str) -> io::Result<()> { + self.inner.write_file(path, content) + } + + fn exists(&self, path: &Path) -> io::Result { + self.inner.exists(path) + } + + fn cleanup(&self) -> io::Result<()> { + self.inner.cleanup() + } + } + + /// Run a command from test code with its output captured into the + /// per-test log file (the console stays quiet; the output is available + /// on failure) + pub(crate) fn run_logged(cmd: &mut Command) -> io::Result { + if !active() { + return cmd.status(); + } + let path = current_test_log_path().unwrap_or_else(uncategorized_log_path); + append_line(&path, &format!("[run] {}", display_command(cmd))); + append_line(&path, &format!("[run] cwd: {}", display_cwd(cmd))); + + let output = cmd.stdin(std::process::Stdio::null()).output()?; + for line in String::from_utf8_lossy(&output.stdout).lines() { + append_line(&path, &format!("[out] {line}")); + } + for line in String::from_utf8_lossy(&output.stderr).lines() { + append_line(&path, &format!("[err] {line}")); + } + append_line(&path, &format!("[run] status: {}", output.status)); + Ok(output.status) + } + + fn display_command(cmd: &Command) -> String { + let mut parts = vec![cmd.get_program().to_string_lossy().to_string()]; + parts.extend(cmd.get_args().map(|a| a.to_string_lossy().to_string())); + parts.join(" ") + } + + fn display_cwd(cmd: &Command) -> String { + cmd.get_current_dir() + .map(|d| d.display().to_string()) + .unwrap_or_else(|| "".to_string()) + } +} + +pub(crate) use imp::*;