diff --git a/Cargo.lock b/Cargo.lock --- a/Cargo.lock +++ b/Cargo.lock @@ -3630,6 +3630,7 @@ version = "0.14.0" dependencies = [ "jpeg-encoder", "lightcraft-raster", + "lightcraft-testkit", "log", "siphasher", "zune-core", diff --git a/README.md b/README.md --- a/README.md +++ b/README.md @@ -458,6 +458,13 @@ adapters per backend, corpus, fonts) and every skip by reason. It writes `target `target/ci/summary.md`, a block to paste into a PR (`--summary-md` prints it); `--hardware` also runs the GPU tests on every backend that has a hardware adapter. Nothing is uploaded. +libtest has no per-test timeout either, so test waits go through `lightcraft_testkit::wait_until` and +`recv_within`, which fail the test with what it waited for. `LIGHTCRAFT_TIME_SCALE=3` gives every such +limit three times as long on a slow or shared machine. A watchdog ends a test binary (exit status 124) +when a watched test (every ui-egui headless test, or one that calls `lightcraft_testkit::watch()`) has +run for `LIGHTCRAFT_TEST_WATCHDOG_MIN` minutes (default 30, times the time scale; `0` turns it off), +printing the watched tests still running. + **Chinese and Japanese text** need the shared font repo, an optional build input (official releases always include it): ```sh diff --git a/crates/gpu/tests/shutdown.rs b/crates/gpu/tests/shutdown.rs --- a/crates/gpu/tests/shutdown.rs +++ b/crates/gpu/tests/shutdown.rs @@ -40,9 +40,9 @@ fn nothing_renders_on_the_gpu_once_the_process_is_ending() { }) }; if has_gpu { - while rendered.load(Ordering::SeqCst) == 0 && !refused.load(Ordering::SeqCst) { - std::thread::yield_now(); - } + lightcraft_testkit::wait_until(Duration::from_secs(120), "the worker's first GPU render (or the GPU refusing it)", || { + rendered.load(Ordering::SeqCst) > 0 || refused.load(Ordering::SeqCst) + }); assert!(rendered.load(Ordering::SeqCst) > 0, "the GPU renders before the shutdown ({:?})", lightcraft_gpu::last_fallback()); } diff --git a/crates/preview/Cargo.toml b/crates/preview/Cargo.toml --- a/crates/preview/Cargo.toml +++ b/crates/preview/Cargo.toml @@ -15,3 +15,6 @@ jpeg-encoder = { workspace = true } zune-jpeg = { workspace = true } zune-core = { workspace = true } log = { workspace = true } + +[dev-dependencies] +lightcraft-testkit = { workspace = true } diff --git a/crates/preview/src/tests.rs b/crates/preview/src/tests.rs --- a/crates/preview/src/tests.rs +++ b/crates/preview/src/tests.rs @@ -182,17 +182,14 @@ fn pool_priorities_dedupe_and_drop() { 1000, Box::new(move || { let (m, cv) = &*g; - let mut open = m.lock().unwrap(); - while !*open { - open = cv.wait(open).unwrap(); - } + let limit = lightcraft_testkit::scaled(std::time::Duration::from_secs(60)); + let (_open, waited) = cv.wait_timeout_while(m.lock().unwrap(), limit, |open| !*open).unwrap(); + assert!(!waited.timed_out(), "the test never opened the gate"); 999 }), ); // wait until the worker took the gate job - while p.queued() > 0 { - std::thread::yield_now(); - } + lightcraft_testkit::wait_until(std::time::Duration::from_secs(30), "the worker takes the gate job", || p.queued() == 0); p.submit(1, 1, 5, Box::new(|| 1)); // off-screen thumb p.submit(2, 1, 10, Box::new(|| 2)); // visible thumb p.submit(3, 1, 100, Box::new(|| 3)); // loupe @@ -207,13 +204,10 @@ fn pool_priorities_dedupe_and_drop() { cv.notify_all(); } let mut order = Vec::new(); - while order.len() < 4 { - if let Some(d) = p.try_recv() { - order.push((d.slot, d.key, d.result)); - } else { - std::thread::yield_now(); - } - } + lightcraft_testkit::wait_until(std::time::Duration::from_secs(30), "four jobs done", || { + order.extend(std::iter::from_fn(|| p.try_recv()).map(|d| (d.slot, d.key, d.result))); + order.len() >= 4 + }); assert_eq!(order, vec![(999, 0, 999), (3, 1, 3), (2, 2, 22), (1, 1, 1)]); } @@ -243,7 +237,7 @@ fn pool_with_a_running_job() -> (JobPool, std::sync::mpsc::Sender<()>) { let _ = released.recv_timeout(std::time::Duration::from_secs(60)); }), ); - has_started.recv().unwrap(); + lightcraft_testkit::recv_within(&has_started, std::time::Duration::from_secs(30), "the job starts"); (p, release) } @@ -265,7 +259,7 @@ fn pool_drop_waits_for_running_job() { f.store(true, Ordering::SeqCst); }), ); - has_started.recv().unwrap(); + lightcraft_testkit::recv_within(&has_started, std::time::Duration::from_secs(30), "the job starts"); let q = queued_ran.clone(); p.submit(2, 0, 1, Box::new(move || q.store(true, Ordering::SeqCst))); drop(p); @@ -732,7 +726,7 @@ fn a_slot_runs_one_job_at_a_time() { }) }; p.submit(1, 1, 9, job(1, Some(released))); - assert_eq!(has_started.recv().unwrap(), 1); + assert_eq!(lightcraft_testkit::recv_within(&has_started, std::time::Duration::from_secs(30), "slot 1's first job starts"), 1); // two newer requests for the busy slot: the second replaces the first, neither starts p.submit(1, 2, 9, job(2, None)); p.submit(1, 3, 9, job(3, None)); diff --git a/crates/testkit/src/deadline.rs b/crates/testkit/src/deadline.rs new file mode 100644 --- /dev/null +++ b/crates/testkit/src/deadline.rs @@ -0,0 +1,196 @@ +//! Deadlines for test waits. Stable libtest has no per-test timeout, so a wait that never ends +//! hangs its test binary with no message (and keeps the app's workers alive). These helpers give +//! every wait a limit and fail the test with what it was waiting for. +//! +//! Every limit is stretched by [`time_scale`] (`LIGHTCRAFT_TIME_SCALE`), so a slow or shared +//! machine can give all of them more time at once. + +use std::sync::OnceLock; +use std::sync::mpsc::{Receiver, RecvTimeoutError}; +use std::time::{Duration, Instant}; + +/// The environment variable that stretches (or shrinks) every test time limit: a factor, `1` by +/// default. `LIGHTCRAFT_TIME_SCALE=3` gives each wait three times as long. +pub const TIME_SCALE_ENV: &str = "LIGHTCRAFT_TIME_SCALE"; + +/// The smallest factor [`time_scale`] returns: shrinking limits further only makes tests flaky. +pub const MIN_TIME_SCALE: f64 = 0.1; +/// The largest factor [`time_scale`] returns: past it a limit is as good as none. +pub const MAX_TIME_SCALE: f64 = 1000.0; + +/// The longest a poll of [`wait_until`] sleeps between two checks of its condition. +const MAX_POLL: Duration = Duration::from_millis(50); + +/// The factor every test time limit is multiplied by: `LIGHTCRAFT_TIME_SCALE`, read once per +/// process. Unset or empty means `1`. A number is clamped to [`MIN_TIME_SCALE`]..=[`MAX_TIME_SCALE`]; +/// anything else (not a number, NaN, infinite, zero or negative) is ignored with a note on stderr, +/// and the factor stays `1`. +pub fn time_scale() -> f64 { + static SCALE: OnceLock = OnceLock::new(); + *SCALE.get_or_init(|| { + let value = std::env::var(TIME_SCALE_ENV).ok(); + let (scale, note) = parse_time_scale(value.as_deref()); + if let Some(note) = note { + eprintln!("{TIME_SCALE_ENV}: {note}"); + } + scale + }) +} + +/// `d` stretched by [`time_scale`]. Saturates at [`Duration::MAX`] instead of overflowing. +pub fn scaled(d: Duration) -> Duration { + scale_by(d, time_scale()) +} + +/// `d × scale`, saturating; a factor that isn't a positive number leaves `d` as it is. +fn scale_by(d: Duration, scale: f64) -> Duration { + if !scale.is_finite() || scale <= 0.0 { + return d; + } + Duration::try_from_secs_f64(d.as_secs_f64() * scale).unwrap_or(Duration::MAX) +} + +/// The factor `LIGHTCRAFT_TIME_SCALE=value` means, and a note when the value was ignored or +/// clamped. +fn parse_time_scale(value: Option<&str>) -> (f64, Option) { + let Some(text) = value.map(str::trim).filter(|v| !v.is_empty()) else { return (1.0, None) }; + match text.parse::() { + Ok(s) if s.is_finite() && s > 0.0 => { + let clamped = s.clamp(MIN_TIME_SCALE, MAX_TIME_SCALE); + let note = (clamped != s).then(|| format!("{text} is outside {MIN_TIME_SCALE}..={MAX_TIME_SCALE}; using {clamped}")); + (clamped, note) + } + _ => (1.0, Some(format!("{text:?} is not a positive number; using 1"))), + } +} + +/// Wait until `cond` holds, checking it with a growing pause (1 ms up to 50 ms). Fails the test +/// (panics) with `"{what}" not reached after {elapsed}` once [`scaled`]`(timeout)` has passed. +/// `what` names the state waited for, as the failure should read: `"the scan's first row"`. +/// +/// Also bounds waits on other threads (a gated worker job, an injected probe): the panic ends +/// that thread's job instead of leaving it spinning after the test is gone. +#[allow(clippy::panic)] // failing the test with what it waited for is the point +#[track_caller] +pub fn wait_until(timeout: Duration, what: &str, mut cond: impl FnMut() -> bool) { + let limit = scaled(timeout); + let start = Instant::now(); + let mut pause = Duration::from_millis(1); + loop { + if cond() { + return; + } + let elapsed = start.elapsed(); + if elapsed >= limit { + panic!("\"{what}\" not reached after {elapsed:.2?} (limit {limit:?}: {timeout:?} × {TIME_SCALE_ENV} {})", time_scale()); + } + std::thread::sleep(pause.min(limit.saturating_sub(elapsed))); + pause = (pause * 2).min(MAX_POLL); + } +} + +/// Receive the next message from `rx`, waiting at most [`scaled`]`(timeout)`. Fails the test +/// (panics) with `"{what}" not received after {elapsed}` when it doesn't come, or when every +/// sender is gone first. +#[allow(clippy::panic)] // failing the test with what it waited for is the point +#[track_caller] +pub fn recv_within(rx: &Receiver, timeout: Duration, what: &str) -> T { + let limit = scaled(timeout); + let start = Instant::now(); + match rx.recv_timeout(limit) { + Ok(v) => v, + Err(RecvTimeoutError::Timeout) => { + panic!("\"{what}\" not received after {:.2?} (limit {limit:?}: {timeout:?} × {TIME_SCALE_ENV} {})", start.elapsed(), time_scale()) + } + Err(RecvTimeoutError::Disconnected) => panic!("\"{what}\" never sent: the sender hung up after {:.2?}", start.elapsed()), + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::sync::atomic::{AtomicUsize, Ordering}; + + #[test] + fn the_time_scale_reads_a_positive_factor_and_ignores_the_rest() { + assert_eq!(parse_time_scale(None), (1.0, None)); + assert_eq!(parse_time_scale(Some("")), (1.0, None)); + assert_eq!(parse_time_scale(Some(" ")), (1.0, None)); + assert_eq!(parse_time_scale(Some("2.5")), (2.5, None)); + assert_eq!(parse_time_scale(Some(" 3 ")), (3.0, None)); + for bad in ["0", "-2", "NaN", "nan", "inf", "-inf", "fast", "1e400", "0x10"] { + let (scale, note) = parse_time_scale(Some(bad)); + assert_eq!(scale, 1.0, "{bad}"); + assert!(note.is_some_and(|n| n.contains("not a positive number")), "{bad}"); + } + let (scale, note) = parse_time_scale(Some("1e9")); + assert_eq!(scale, MAX_TIME_SCALE); + assert!(note.is_some_and(|n| n.contains("outside"))); + let (scale, note) = parse_time_scale(Some("0.0001")); + assert_eq!(scale, MIN_TIME_SCALE); + assert!(note.is_some()); + } + + #[test] + fn scaling_saturates_instead_of_overflowing() { + assert_eq!(scale_by(Duration::from_secs(10), 2.0), Duration::from_secs(20)); + assert_eq!(scale_by(Duration::from_secs(10), 0.5), Duration::from_secs(5)); + assert_eq!(scale_by(Duration::MAX, MAX_TIME_SCALE), Duration::MAX); + assert_eq!(scale_by(Duration::from_secs(10), f64::NAN), Duration::from_secs(10)); + assert_eq!(scale_by(Duration::from_secs(10), -1.0), Duration::from_secs(10)); + assert_eq!(scale_by(Duration::ZERO, 3.0), Duration::ZERO); + } + + #[test] + fn wait_until_returns_once_the_condition_holds() { + let checks = AtomicUsize::new(0); + let start = Instant::now(); + wait_until(Duration::from_secs(30), "the third check", || checks.fetch_add(1, Ordering::SeqCst) >= 2); + assert_eq!(checks.load(Ordering::SeqCst), 3); + assert!(start.elapsed() < Duration::from_secs(10), "it doesn't wait out the limit"); + } + + #[test] + fn wait_until_sees_a_change_made_by_another_thread() { + let flag = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(false)); + let f = flag.clone(); + let t = std::thread::spawn(move || { + std::thread::sleep(Duration::from_millis(30)); + f.store(true, Ordering::SeqCst); + }); + wait_until(Duration::from_secs(30), "the flag", || flag.load(Ordering::SeqCst)); + t.join().unwrap(); + } + + #[test] + #[should_panic(expected = "\"the gate opens\" not reached after")] + fn wait_until_fails_the_test_with_what_it_waited_for() { + wait_until(Duration::from_millis(20), "the gate opens", || false); + } + + #[test] + fn recv_within_returns_the_message() { + let (tx, rx) = std::sync::mpsc::channel(); + let t = std::thread::spawn(move || { + std::thread::sleep(Duration::from_millis(20)); + tx.send(7).unwrap(); + }); + assert_eq!(recv_within(&rx, Duration::from_secs(30), "the job's result"), 7); + t.join().unwrap(); + } + + #[test] + #[should_panic(expected = "\"the job starts\" not received after")] + fn recv_within_fails_the_test_when_nothing_comes() { + let (_tx, rx) = std::sync::mpsc::channel::<()>(); + recv_within(&rx, Duration::from_millis(20), "the job starts"); + } + + #[test] + #[should_panic(expected = "\"the job starts\" never sent: the sender hung up")] + fn recv_within_fails_the_test_when_the_sender_is_gone() { + let (tx, rx) = std::sync::mpsc::channel::<()>(); + drop(tx); + recv_within(&rx, Duration::from_secs(30), "the job starts"); + } +} diff --git a/crates/testkit/src/lib.rs b/crates/testkit/src/lib.rs --- a/crates/testkit/src/lib.rs +++ b/crates/testkit/src/lib.rs @@ -20,6 +20,17 @@ //! `cargo xtask ci` lists the skips by need and reason in its summary and in //! `target/ci/report.json`. A test that runs part of its checks (e.g. only the CPU half) records //! the part it could not run the same way. +//! +//! **Deadlines.** Stable libtest has no per-test timeout, so a wait with no limit hangs its binary +//! with no message. Waits go through [`wait_until`] (a condition) and [`recv_within`] (a channel), +//! which fail the test with what they waited for; a hand-made limit (a condvar's +//! `wait_timeout_while`) uses [`scaled`]. Every limit is stretched by [`time_scale`] +//! (`LIGHTCRAFT_TIME_SCALE`, default 1) on a slow or shared machine. +//! +//! **Watchdog.** [`watch`] registers the running test; a test still registered after +//! `LIGHTCRAFT_TEST_WATCHDOG_MIN` minutes (default 30, × the time scale; `0` turns it off) makes +//! the watchdog print the watched tests still running and end the binary (exit status 124). ui-egui's +//! `Headless::new` calls it in that crate's unit tests. See [`watchdog`] for the defaults' reasons. #![forbid(unsafe_code)] #![deny(clippy::unwrap_used, clippy::expect_used, clippy::panic, clippy::unimplemented, clippy::todo, clippy::unreachable)] @@ -27,6 +38,12 @@ use std::fmt::Write as _; use std::io::Write as _; use std::path::Path; +mod deadline; +pub mod watchdog; + +pub use deadline::{MAX_TIME_SCALE, MIN_TIME_SCALE, TIME_SCALE_ENV, recv_within, scaled, time_scale, wait_until}; +pub use watchdog::{DEFAULT_WATCHDOG_MINUTES, WATCHDOG_ENV, WATCHDOG_EXIT_CODE, Watch, watch, watched}; + /// The environment variable naming the file skips are appended to (JSON lines). pub const SKIP_LOG_ENV: &str = "LIGHTCRAFT_SKIP_LOG"; diff --git a/crates/testkit/src/watchdog.rs b/crates/testkit/src/watchdog.rs new file mode 100644 --- /dev/null +++ b/crates/testkit/src/watchdog.rs @@ -0,0 +1,421 @@ +//! A watchdog for test binaries. Stable libtest has no per-test timeout: a test stuck in a wait +//! keeps its binary (and the app's render workers) alive for good, and the run only looks busy. +//! A test that calls [`watch`] (ui-egui's `Headless::new` does it for every headless test) is +//! registered under its thread's name, which libtest sets to the test's path. One thread per +//! process checks the registered tests; once one of them has run longer than the limit it prints +//! every registered test still running, with how long each has run, and ends the process with +//! [`WATCHDOG_EXIT_CODE`]. A +//! stuck run then ends with a list of names instead of hanging. +//! +//! **The limit** is `LIGHTCRAFT_TEST_WATCHDOG_MIN` minutes per test (fractions allowed), +//! [`DEFAULT_WATCHDOG_MINUTES`] when unset, stretched by [`crate::time_scale`]. `0` or `off` +//! turns the watchdog off (for a test paused in a debugger). Anything else that isn't a positive +//! number is ignored with a note on stderr, and the default applies. +//! +//! **Why 30 minutes by default, and on.** Off unless set would leave exactly the runs that need it +//! unguarded: an ad-hoc `cargo test` that hangs. The limit is per test, not per binary, so a long +//! binary (the ui-egui unit tests take minutes at 4 threads, far more on a cold debug build on a +//! loaded machine) never trips it; the slowest single test takes about a minute under load, so 30 +//! minutes is far past anything but a test that will never finish, and `LIGHTCRAFT_TIME_SCALE` +//! stretches it on a machine that is slower still. +//! +//! **How it ends the process.** A helper thread prints the report and calls `std::process::exit` +//! with [`WATCHDOG_EXIT_CODE`], so a stuck run normally leaves no crash report or core dump +//! behind. The process is stuck by definition, so that can get stuck too: a stuck test may hold +//! stderr's lock, an exit handler (a GPU driver's) may hang. The watchdog thread itself owns the +//! hard deadline and does no I/O: it aborts the process if it still runs [`ABORT_AFTER_EXIT`] +//! later, or at once if the helper thread can't be started. +//! +//! For testkit's own tests only, `LIGHTCRAFT_TEST_WATCHDOG_GRACE_MS` replaces that grace period +//! (whole milliseconds, held to 100 ms..=10 min; anything else keeps [`ABORT_AFTER_EXIT`]), so +//! the test of the abort doesn't wait ten seconds. +//! +//! The report goes straight to the process's stderr: libtest captures the output of a test's +//! threads (the watchdog's thread starts from the first watched test's), and a captured report +//! would be lost with the process. + +use std::fmt::Write as _; +use std::io::Write as _; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::{Arc, Mutex, Once, OnceLock, PoisonError, Weak}; +use std::time::{Duration, Instant}; + +/// The environment variable holding the per-test limit in minutes (`0` or `off`: no watchdog). +pub const WATCHDOG_ENV: &str = "LIGHTCRAFT_TEST_WATCHDOG_MIN"; + +/// The per-test limit in minutes when [`WATCHDOG_ENV`] is unset, before [`crate::time_scale`]. +pub const DEFAULT_WATCHDOG_MINUTES: f64 = 30.0; + +/// The exit status of a test binary the watchdog ended: 124, as `timeout(1)` uses. +pub const WATCHDOG_EXIT_CODE: i32 = 124; + +/// How long printing the report and exiting may take before the watchdog aborts the process. +pub const ABORT_AFTER_EXIT: Duration = Duration::from_secs(10); + +/// Replaces [`ABORT_AFTER_EXIT`], for testkit's own tests (milliseconds). +const GRACE_ENV: &str = "LIGHTCRAFT_TEST_WATCHDOG_GRACE_MS"; + +/// The grace period `LIGHTCRAFT_TEST_WATCHDOG_GRACE_MS=value` means: whole milliseconds held to +/// 100 ms..=10 min; unset, empty or not a whole number keeps [`ABORT_AFTER_EXIT`]. +fn parse_grace(value: Option<&str>) -> Duration { + match value.map(str::trim).and_then(|v| v.parse::().ok()) { + Some(ms) => Duration::from_millis(ms.clamp(100, 600_000)), + None => ABORT_AFTER_EXIT, + } +} + +/// One registered test. +struct Entry { + id: u64, + test: String, + since: Instant, + /// Alive while the registering thread runs: libtest runs each test on a thread of its own, so + /// a registration whose guard was leaked (or kept in a static) is dropped with its thread + /// instead of tripping the watchdog later in the run. + thread: Weak<()>, +} + +static WATCHED: Mutex> = Mutex::new(Vec::new()); +static NEXT_ID: AtomicU64 = AtomicU64::new(0); + +thread_local! { + static THREAD_ALIVE: Arc<()> = Arc::new(()); +} + +/// A test's registration with the watchdog; dropping it (at the end of the test, also when the +/// test panics) ends the registration. +#[must_use = "the test is watched only while the guard lives: `let _watch = watch();`"] +#[derive(Debug)] +pub struct Watch { + id: u64, +} + +impl Drop for Watch { + fn drop(&mut self) { + let mut watched = WATCHED.lock().unwrap_or_else(PoisonError::into_inner); + watched.retain(|e| e.id != self.id); + } +} + +/// Register the current test (by its thread's name) with the watchdog until the returned guard +/// is dropped, and start the watchdog thread on the first call. Hold the guard for the whole test: +/// `let _watch = lightcraft_testkit::watch();`. +pub fn watch() -> Watch { + let id = NEXT_ID.fetch_add(1, Ordering::Relaxed); + let thread = std::thread::current(); + let test = thread.name().unwrap_or("").to_owned(); + let alive = THREAD_ALIVE.try_with(Arc::downgrade).unwrap_or_default(); + WATCHED.lock().unwrap_or_else(PoisonError::into_inner).push(Entry { id, test, since: Instant::now(), thread: alive }); + if let Some(limit) = limit() { + start(limit); + } + Watch { id } +} + +/// The per-test limit ([`WATCHDOG_ENV`] × [`crate::time_scale`]), read once; `None` when off. +fn limit() -> Option { + static LIMIT: OnceLock> = OnceLock::new(); + *LIMIT.get_or_init(|| { + let value = std::env::var(WATCHDOG_ENV).ok(); + let (minutes, note) = parse_minutes(value.as_deref()); + if let Some(note) = note { + eprintln!("{WATCHDOG_ENV}: {note}"); + } + let minutes = minutes?; + // a limit too large for a Duration is no limit + Duration::try_from_secs_f64(minutes * 60.0).ok().map(crate::scaled) + }) +} + +/// The minutes `LIGHTCRAFT_TEST_WATCHDOG_MIN=value` means (`None`: off) and a note when the value +/// was ignored. +fn parse_minutes(value: Option<&str>) -> (Option, Option) { + let Some(text) = value.map(str::trim).filter(|v| !v.is_empty()) else { return (Some(DEFAULT_WATCHDOG_MINUTES), None) }; + if text.eq_ignore_ascii_case("off") { + return (None, None); + } + match text.parse::() { + Ok(0.0) => (None, None), + Ok(m) if m.is_finite() && m > 0.0 => (Some(m), None), + _ => (Some(DEFAULT_WATCHDOG_MINUTES), Some(format!("{text:?} is not a number of minutes (or 0 / off); using {DEFAULT_WATCHDOG_MINUTES}"))), + } +} + +/// Start the watchdog thread, once per process. +fn start(limit: Duration) { + static STARTED: Once = Once::new(); + STARTED.call_once(|| { + // read here, not when the watchdog fires: a stuck process may hold the environment's lock + let grace = parse_grace(std::env::var(GRACE_ENV).ok().as_deref()); + // check often enough that a short limit (tests of the watchdog) isn't overshot by much + let poll = (limit / 20).clamp(Duration::from_millis(10), Duration::from_secs(5)); + let spawned = std::thread::Builder::new().name("lightcraft-testkit-watchdog".into()).spawn(move || { + loop { + std::thread::sleep(poll); + let report = overdue(&WATCHED.lock().unwrap_or_else(PoisonError::into_inner), Instant::now(), limit); + if let Some(report) = report { + end_process(report, grace); + } + } + }); + if let Err(e) = spawned { + eprintln!("{WATCHDOG_ENV}: can't start the test watchdog ({e}); hung tests won't be stopped"); + } + }); +} + +/// End the process for a stuck test, on the watchdog thread. A helper thread prints `report` and +/// exits with [`WATCHDOG_EXIT_CODE`]; this thread does no I/O (stderr's lock may be held by the +/// stuck test) and aborts the process if it is still running `grace` ([`ABORT_AFTER_EXIT`]) later, +/// or at once when the helper can't be started. +fn end_process(report: String, grace: Duration) -> ! { + let reporter = std::thread::Builder::new().name("lightcraft-testkit-watchdog-exit".into()).spawn(move || { + // straight to stderr: `eprintln!` would go to the capture of the test that started the watchdog + let _ = writeln!(std::io::stderr(), "{report}"); + std::process::exit(WATCHDOG_EXIT_CODE) + }); + if reporter.is_ok() { + std::thread::sleep(grace); + } + std::process::abort() +} + +/// When a live registered test has run for `limit` or longer: the report printed before the +/// process ends, naming every live registered test, longest-running first. +fn overdue(entries: &[Entry], now: Instant, limit: Duration) -> Option { + let mut live: Vec<(&str, Duration)> = + entries.iter().filter(|e| e.thread.strong_count() > 0).map(|e| (e.test.as_str(), now.saturating_duration_since(e.since))).collect(); + live.sort_by_key(|&(_, ran)| std::cmp::Reverse(ran)); + let &(stuck, ran) = live.first().filter(|(_, ran)| *ran >= limit)?; + let mut report = format!( + "lightcraft-testkit watchdog: `{stuck}` has run for {}, past the limit of {} ({WATCHDOG_ENV} × {}); \ + ending the test binary. Watched tests still running:", + minutes(ran), + minutes(limit), + crate::TIME_SCALE_ENV, + ); + for (test, ran) in &live { + let _ = write!(report, "\n {test} ({})", minutes(*ran)); + } + Some(report) +} + +/// `95.5 s` → `1m 35.5s`. +fn minutes(d: Duration) -> String { + let secs = d.as_secs_f64(); + let whole = (secs / 60.0).floor(); + format!("{whole}m {:.1}s", secs - whole * 60.0) +} + +/// The names of the watched tests still running, as the watchdog would list them (a test can +/// check that it is watched). +pub fn watched() -> Vec { + let watched = WATCHED.lock().unwrap_or_else(PoisonError::into_inner); + watched.iter().filter(|e| e.thread.strong_count() > 0).map(|e| e.test.clone()).collect() +} + +#[cfg(test)] +mod tests { + use super::*; + + /// Set for the child process [`a_stuck_test_ends_its_binary_with_the_tests_still_running`] starts. + const CHILD_ENV: &str = "LIGHTCRAFT_TESTKIT_WATCHDOG_CHILD"; + + fn entry(test: &str, since: Instant, thread: &Arc<()>) -> Entry { + Entry { id: 0, test: test.into(), since, thread: Arc::downgrade(thread) } + } + + #[test] + fn the_limit_reads_minutes_and_off() { + assert_eq!(parse_minutes(None), (Some(DEFAULT_WATCHDOG_MINUTES), None)); + assert_eq!(parse_minutes(Some(" ")), (Some(DEFAULT_WATCHDOG_MINUTES), None)); + assert_eq!(parse_minutes(Some("45")), (Some(45.0), None)); + assert_eq!(parse_minutes(Some("0.5")), (Some(0.5), None)); + assert_eq!(parse_minutes(Some("0")), (None, None)); + assert_eq!(parse_minutes(Some("OFF")), (None, None)); + for bad in ["-1", "NaN", "inf", "ten", "1e400"] { + let (minutes, note) = parse_minutes(Some(bad)); + assert_eq!(minutes, Some(DEFAULT_WATCHDOG_MINUTES), "{bad}"); + assert!(note.is_some(), "{bad}"); + } + } + + #[test] + fn a_test_past_the_limit_is_reported_with_everything_still_running() { + let base = Instant::now(); + let (alive, gone) = (Arc::new(()), Arc::new(())); + let entries = vec![ + entry("ui::quick", base + Duration::from_secs(50), &alive), + entry("ui::stuck", base, &alive), + entry("ui::leaked_by_a_finished_thread", base, &gone), + ]; + drop(gone); + let limit = Duration::from_secs(60); + assert_eq!(overdue(&entries, base + Duration::from_secs(59), limit), None, "nothing is past the limit yet"); + let report = overdue(&entries, base + Duration::from_secs(60), limit).unwrap(); + assert!(report.contains("`ui::stuck` has run for 1m 0.0s, past the limit of 1m 0.0s"), "{report}"); + let stuck = report.find("\n ui::stuck (1m 0.0s)").unwrap(); + let quick = report.find("\n ui::quick (0m 10.0s)").unwrap(); + assert!(stuck < quick, "longest first: {report}"); + assert!(!report.contains("leaked"), "a finished thread's registration doesn't count: {report}"); + } + + #[test] + fn nothing_is_overdue_without_live_tests() { + let base = Instant::now(); + assert_eq!(overdue(&[], base + Duration::from_secs(3600), Duration::from_secs(1)), None); + let gone = Arc::new(()); + let entries = vec![entry("t", base, &gone)]; + drop(gone); + assert_eq!(overdue(&entries, base + Duration::from_secs(3600), Duration::from_secs(1)), None); + } + + #[test] + fn a_watch_registers_the_test_until_it_ends() { + let me = std::thread::current().name().unwrap_or("").to_owned(); + let count = || watched().iter().filter(|t| **t == me).count(); + let before = count(); + let w = watch(); + assert_eq!(count(), before + 1); + drop(w); + assert_eq!(count(), before); + } + + #[test] + fn a_test_that_panics_or_leaks_its_watch_is_unregistered() { + let named = |name: &str| watched().iter().filter(|t| *t == name).count(); + let panicked = std::thread::Builder::new() + .name("testkit::panicking_test".into()) + .spawn(|| { + let _watch = watch(); + panic!("the test fails"); + }) + .unwrap() + .join(); + assert!(panicked.is_err()); + assert_eq!(named("testkit::panicking_test"), 0, "unwinding drops the guard"); + std::thread::Builder::new().name("testkit::leaking_test".into()).spawn(|| std::mem::forget(watch())).unwrap().join().unwrap(); + assert_eq!(named("testkit::leaking_test"), 0, "the thread ended with the test"); + } + + /// Run as a child by [`a_stuck_test_ends_its_binary_with_the_tests_still_running`]: a test stuck + /// in a wait. Ends on its own after a minute, so a watchdog that never fires fails the parent + /// rather than hanging it. + #[test] + #[ignore = "a stuck test: run as a child process by a_stuck_test_ends_its_binary_with_the_tests_still_running"] + fn stuck_child() { + if std::env::var_os(CHILD_ENV).is_none() { + return; + } + let _watch = watch(); + std::thread::sleep(Duration::from_secs(60)); + } + + /// Run as a child by [`a_stuck_test_holding_stderr_still_ends_its_binary`]: a test stuck while + /// it holds stderr's lock, so the report can't be printed. + #[test] + #[ignore = "a stuck test: run as a child process by a_stuck_test_holding_stderr_still_ends_its_binary"] + fn stuck_child_holding_stderr() { + if std::env::var_os(CHILD_ENV).is_none() { + return; + } + let _watch = watch(); + let _stderr = std::io::stderr().lock(); + std::thread::sleep(Duration::from_secs(60)); + } + + /// How a child test run by [`run_stuck_child`] ended. + struct Child { + /// `None`: still running after the deadline, and killed. + status: Option, + stderr: String, + ran: Duration, + /// Run under `prlimit --core=1`, so an abort leaves no core dump. + no_core: bool, + } + + /// Run the ignored test `name` of this binary as a child under a watchdog of 0.3 s (and `env`), + /// killing it if it still runs after `deadline`. + fn run_stuck_child(name: &str, env: &[(&str, &str)], deadline: Duration) -> Child { + let start = Instant::now(); + let exe = std::env::current_exe().unwrap(); + let configure = |mut c: std::process::Command| { + // captured, as in a normal run: the report must get out anyway + c.args(["--ignored", "--exact", name, "--test-threads", "1"]) + .env(CHILD_ENV, "1") + .env(WATCHDOG_ENV, "0.005") + .env(crate::TIME_SCALE_ENV, "1") + .envs(env.iter().copied()) + .stdout(std::process::Stdio::null()) + .stderr(std::process::Stdio::piped()); + c + }; + // Linux: an aborted child leaves no core dump. A limit of 1 byte (not 0) also stops a + // core_pattern pipe (systemd-coredump, WSL's crash capture); without prlimit, run it as is. + let limited = if cfg!(target_os = "linux") { + let mut c = std::process::Command::new("prlimit"); + c.arg("--core=1:1").arg(&exe); + configure(c).spawn().ok() + } else { + None + }; + let no_core = limited.is_some(); + let mut child = match limited { + Some(c) => c, + None => configure(std::process::Command::new(&exe)).spawn().unwrap(), + }; + let ended = loop { + if child.try_wait().unwrap().is_some() { + break true; + } + if start.elapsed() > deadline { + let _ = child.kill(); + break false; + } + std::thread::sleep(Duration::from_millis(20)); + }; + let ran = start.elapsed(); + let out = child.wait_with_output().unwrap(); + Child { status: ended.then_some(out.status), stderr: String::from_utf8_lossy(&out.stderr).into_owned(), ran, no_core } + } + + #[test] + fn the_grace_period_reads_whole_milliseconds_within_bounds() { + assert_eq!(parse_grace(None), ABORT_AFTER_EXIT); + assert_eq!(parse_grace(Some("")), ABORT_AFTER_EXIT); + assert_eq!(parse_grace(Some(" 500 ")), Duration::from_millis(500)); + assert_eq!(parse_grace(Some("0")), Duration::from_millis(100)); + assert_eq!(parse_grace(Some("99999999999999999")), Duration::from_secs(600)); + for bad in ["-5", "1.5", "NaN", "soon", "18446744073709551616"] { + assert_eq!(parse_grace(Some(bad)), ABORT_AFTER_EXIT, "{bad}"); + } + } + + #[test] + fn a_stuck_test_ends_its_binary_with_the_tests_still_running() { + let c = run_stuck_child("watchdog::tests::stuck_child", &[], crate::scaled(Duration::from_secs(45))); + let (ran, stderr) = (c.ran, &c.stderr); + let status = c.status.unwrap_or_else(|| panic!("the watchdog didn't end the stuck test in {ran:?}: {stderr}")); + assert_eq!(status.code(), Some(WATCHDOG_EXIT_CODE), "the watchdog ends the run: {stderr}"); + assert!(stderr.contains("lightcraft-testkit watchdog: `watchdog::tests::stuck_child` has run for"), "{stderr}"); + assert!(stderr.contains("\n watchdog::tests::stuck_child ("), "{stderr}"); + } + + /// The report can't be printed while the stuck test holds stderr's lock: the watchdog thread + /// aborts the process once the grace period has passed instead of waiting for it. + #[test] + fn a_stuck_test_holding_stderr_still_ends_its_binary() { + let grace = Duration::from_millis(500); + let c = run_stuck_child("watchdog::tests::stuck_child_holding_stderr", &[(GRACE_ENV, "500")], crate::scaled(Duration::from_secs(45))); + let (ran, stderr) = (c.ran, &c.stderr); + let status = c.status.unwrap_or_else(|| panic!("the stuck test still ran after {ran:?}: {stderr}")); + assert!(!status.success(), "{status:?}"); + assert_ne!(status.code(), Some(WATCHDOG_EXIT_CODE), "it can't have printed and exited: {stderr}"); + assert!(ran >= grace, "aborted after the grace period, not before: {ran:?}"); + #[cfg(unix)] + if c.no_core { + use std::os::unix::process::ExitStatusExt as _; + assert!(!status.core_dumped(), "the abort left a core dump: {status:?}"); + } + } +} diff --git a/crates/ui-egui/src/headless.rs b/crates/ui-egui/src/headless.rs --- a/crates/ui-egui/src/headless.rs +++ b/crates/ui-egui/src/headless.rs @@ -269,6 +269,10 @@ pub struct Headless { /// create a prompt after the host input was already filtered for the previous frame. #[cfg(test)] after_raw_input_hook: Option>, + /// The test driving this session is watched while it lives: a test stuck past the watchdog's + /// limit ends the binary with the names of the tests still running (`lightcraft_testkit::watch`). + #[cfg(test)] + _watch: lightcraft_testkit::Watch, } /// A headless run (`lightcraft-cli snapshot`, tests) is a one-shot process: however it ends, it @@ -311,6 +315,8 @@ impl Headless { last_cursor: egui::CursorIcon::Default, #[cfg(test)] after_raw_input_hook: None, + #[cfg(test)] + _watch: lightcraft_testkit::watch(), } } diff --git a/crates/ui-egui/src/headless/tests.rs b/crates/ui-egui/src/headless/tests.rs --- a/crates/ui-egui/src/headless/tests.rs +++ b/crates/ui-egui/src/headless/tests.rs @@ -96,6 +96,20 @@ fn a_rejected_model_file_says_why_in_settings() { use super::*; use std::sync::Arc; +/// Every headless test is watched (issue #3062): one stuck past the watchdog's limit ends the +/// test binary with its name instead of hanging it. +#[test] +fn a_headless_session_watches_its_test() { + let me = std::thread::current().name().unwrap_or_default().to_owned(); + let mine = || lightcraft_testkit::watched().iter().filter(|t| **t == me).count(); + assert_eq!(mine(), 0); + let app = LightcraftApp::new(lightcraft_engine::Session::new(), crate::Services { png: None, ..Default::default() }); + let h = Headless::new(app, [400.0, 300.0], 1.0); + assert_eq!(mine(), 1); + drop(h); + assert_eq!(mine(), 0, "the watch ends with the session"); +} + /// The pretend host has a clipboard, as a desktop does: text the UI copies lands in it, and a /// cut, copy or paste request (from a context menu) comes back as that event on the next frame. #[test] @@ -3265,9 +3279,7 @@ fn browsing_the_same_folder_again_does_not_restart() { let (g, n) = (gate.clone(), started.clone()); h.app.session.media.file_probe = Some(std::sync::Arc::new(move |_: &str| { n.fetch_add(1, std::sync::atomic::Ordering::Relaxed); - while !g.load(std::sync::atomic::Ordering::Relaxed) { - std::thread::sleep(Duration::from_millis(5)); - } + lightcraft_testkit::wait_until(Duration::from_secs(60), "the test opens the probe's gate", || g.load(std::sync::atomic::Ordering::Relaxed)); Ok(lightcraft_engine::media::ProbeInfo { format: "PNG".into(), ..Default::default() }) })); let browse = |h: &mut Headless| h.request("engine.execute", json!({"command": "library.browse", "params": {"path": dir.to_string_lossy()}}), t); @@ -3384,9 +3396,7 @@ fn folder_scan_cancel_and_busy() { let gate = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(false)); let g = gate.clone(); h.app.session.media.file_probe = Some(std::sync::Arc::new(move |_: &str| { - while !g.load(std::sync::atomic::Ordering::Relaxed) { - std::thread::sleep(Duration::from_millis(5)); - } + lightcraft_testkit::wait_until(Duration::from_secs(60), "the test opens the probe's gate", || g.load(std::sync::atomic::Ordering::Relaxed)); Ok(lightcraft_engine::media::ProbeInfo { format: "PNG".into(), ..Default::default() }) })); let r = h.request("engine.execute", json!({"command": "file.addFolder", "params": {"path": dir.to_string_lossy()}}), t); diff --git a/crates/ui-egui/src/tests/offline.rs b/crates/ui-egui/src/tests/offline.rs --- a/crates/ui-egui/src/tests/offline.rs +++ b/crates/ui-egui/src/tests/offline.rs @@ -42,8 +42,8 @@ impl Calls { } /// The sleeping drive: every file-system call waits until [`Nas::wake`] (or takes one of the -/// calls [`Nas::let_through`] allows). A watchdog wakes it after [`WATCHDOG`] and records that it -/// had to (some frame was waiting for the drive). +/// calls [`Nas::let_through`] allows). A watchdog wakes it after [`WATCHDOG`] (× the test time +/// scale) and records that it had to (some frame was waiting for the drive). #[derive(Default)] struct Nas { /// (awake, calls let through while asleep) @@ -58,7 +58,7 @@ impl Nas { let dog = nas.clone(); std::thread::spawn(move || { let state = dog.state.lock().unwrap(); - let (mut state, _) = dog.changed.wait_timeout_while(state, WATCHDOG, |s| !s.0).unwrap(); + let (mut state, _) = dog.changed.wait_timeout_while(state, lightcraft_testkit::scaled(WATCHDOG), |s| !s.0).unwrap(); if !state.0 { dog.forced.store(true, Ordering::SeqCst); state.0 = true; @@ -69,8 +69,13 @@ impl Nas { } fn wait(&self) { let state = self.state.lock().unwrap(); - let mut state = self.changed.wait_while(state, |s| !s.0 && s.1 == 0).unwrap(); - if !state.0 { + // bounded without the watchdog thread too, should it be gone: it wakes the drive after + // WATCHDOG, so only a call nothing will ever wake gets to twice that + let limit = lightcraft_testkit::scaled(WATCHDOG * 2); + let (mut state, waited) = self.changed.wait_timeout_while(state, limit, |s| !s.0 && s.1 == 0).unwrap(); + if waited.timed_out() { + self.forced.store(true, Ordering::SeqCst); + } else if !state.0 { state.1 -= 1; } } diff --git a/crates/ui-egui/src/tests/sync.rs b/crates/ui-egui/src/tests/sync.rs --- a/crates/ui-egui/src/tests/sync.rs +++ b/crates/ui-egui/src/tests/sync.rs @@ -349,9 +349,7 @@ fn the_folders_scan_shows_a_row_and_its_cross_closes_the_dialog() { let gate = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(false)); let g = gate.clone(); h.app.session.media.file_probe = Some(std::sync::Arc::new(move |_: &str| { - while !g.load(std::sync::atomic::Ordering::Relaxed) { - std::thread::sleep(Duration::from_millis(5)); - } + lightcraft_testkit::wait_until(Duration::from_secs(60), "the test opens the probe's gate", || g.load(std::sync::atomic::Ordering::Relaxed)); Ok(lightcraft_engine::media::ProbeInfo { format: "PNG".into(), ..Default::default() }) })); crate::sync::open(&mut h.app, &dir.path("trip"), "trip", false).unwrap(); diff --git a/docs/architecture.md b/docs/architecture.md --- a/docs/architecture.md +++ b/docs/architecture.md @@ -1,6 +1,6 @@ # Architecture -> **Last reviewed:** 2026-10-10 · **Last updated:** 2026-10-23 · **Change:** minor (`cargo xtask ci`: one integration-test binary per crate, doctests apart, one WASM check) · **Target:** Adobe Lightroom Classic 15.5 / Lightroom 9.6 +> **Last reviewed:** 2026-10-10 · **Last updated:** 2026-10-26 · **Change:** minor (test deadlines and the test watchdog, `lightcraft-testkit`) · **Target:** Adobe Lightroom Classic 15.5 / Lightroom 9.6 How LightCraft is built today. The longer design document (`plan/architecture.md`) is local-only (`plan/` is gitignored); this page is the committed, current summary. Sizes are Rust lines counted @@ -83,10 +83,19 @@ time, skips) and `target/ci/summary.md` (Markdown for a PR; `--summary-md` print no host name, user name or absolute path, and nothing is uploaded. `--hardware` adds a step that runs the `lightcraft-gpu` tests once per backend with a hardware adapter (`LIGHTCRAFT_GPU_BACKEND`). +libtest has no per-test timeout, so a test wait never goes without a limit: `lightcraft_testkit::wait_until` +(a condition, polled with backoff) and `recv_within` (a channel) fail the test with what they waited for, +and a hand-made limit uses `scaled`. `LIGHTCRAFT_TIME_SCALE` (default 1, clamped to 0.1–1000) stretches +every limit at once on a slow machine. `lightcraft_testkit::watch()` registers the running test with a +per-process watchdog (ui-egui's `Headless::new` does it in that crate's unit tests): once a watched test +has run for `LIGHTCRAFT_TEST_WATCHDOG_MIN` minutes (default 30 × the time scale; `0` or `off` disables +it) it prints the watched tests still running and exits with status 124, so a hung run ends with names. + ## Revision history | Date | Change | Summary | |---|---|---| +| 2026-10-26 | minor | Quality gates: test deadlines (`wait_until`, `recv_within`, `LIGHTCRAFT_TIME_SCALE`) and the test watchdog | | 2026-10-23 | minor | Quality gates: one integration-test binary per crate, doctests apart, nextest on request, one WASM check | | 2026-10-11 | minor | Quality gates: the CI machine probe, visible skips (`testkit`) and `target/ci/report.json` | | 2026-10-10 | major | Created from the code (crate sizes, layers, data model, rendering, control, gates) |