//! 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; } pub(crate) use imp::*; #[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()) } }