487 lines
17 KiB
Rust
487 lines
17 KiB
Rust
//! 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;
|
|
}
|
|
|
|
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<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(
|
|
¤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<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())
|
|
}
|
|
}
|