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/<test>.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
This commit is contained in:
2026-09-17 15:18:23 +02:00
parent 3ed95725e4
commit 4c26122357
6 changed files with 532 additions and 25 deletions
+32 -24
View File
@@ -210,7 +210,10 @@ pub fn run_source_build(
opts: &SourceBuildOptions,
ui: Option<Arc<DebUi>>,
) -> Result<SourceBuildOutput, Box<dyn Error>> {
let sink: Option<Arc<dyn LineSink>> = 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<Arc<dyn LineSink>> =
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");
}
+3 -1
View File
@@ -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
}
+4
View File
@@ -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;
+3
View File
@@ -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")));
+4
View File
@@ -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;
+486
View File
@@ -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<std::sync::Arc<dyn crate::context::LineSink>> {
None
}
pub(crate) fn wrap_driver(
driver: Box<dyn crate::context::ContextDriver + Send + Sync>,
) -> Box<dyn crate::context::ContextDriver + Send + Sync> {
driver
}
pub(crate) fn run_logged(
cmd: &mut std::process::Command,
) -> std::io::Result<std::process::ExitStatus> {
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<PathBuf> {
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<HashMap<PathBuf, Arc<Mutex<File>>>> {
static FILES: OnceLock<Mutex<HashMap<PathBuf, Arc<Mutex<File>>>>> = 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(
&current_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<Vec<Failure>> = 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<usize> = 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("<unnamed>").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::<String>() {
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<Arc<dyn LineSink>> {
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<dyn ContextDriver + Send + Sync>,
) -> Box<dyn ContextDriver + Send + Sync> {
if !active() {
return driver;
}
Box::new(CapturingDriver { inner: driver })
}
struct CapturingDriver {
inner: Box<dyn ContextDriver + Send + Sync>,
}
impl ContextDriver for CapturingDriver {
fn run(
&self,
program: &str,
args: &[String],
env: &[(String, String)],
cwd: Option<&str>,
) -> io::Result<ExitStatus> {
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<dyn LineSink>,
) -> io::Result<ExitStatus> {
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<std::process::Output> {
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<PathBuf> {
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<Vec<PathBuf>> {
self.inner.list_files(path)
}
fn create_temp_dir(&self) -> io::Result<String> {
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<String> {
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<bool> {
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<ExitStatus> {
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(|| "<current>".to_string())
}
}
pub(crate) use imp::*;