collective
Browse / github.com/storytold/lightcraft / patch
Issue #3062: testkit deadline helpers and a test watchdog; the unbounded test waits get a limit
testkit has no deadline or watchdog helpers, and several test waits have no time limit Part of #3057. ## Summary Several test waits have no time limit, and `lightcraft-testkit` has no helper that gives them one. When one of these waits never ends, the test binary hangs with no message. Stable libtest has no per-test timeout, so the run looks busy forever, and the stuck test keeps its app's render workers alive too. ## Evidence (main bb08a697) **`crates/testkit/src/lib.rs` offers only skip reporting:** `SKIP_LOG_ENV`, `Need`, `skip!` and `record()`. **Waits with no limit:** | Where | Code | |---|---| | `crates/ui-egui/src/headless.rs:3821` | `while !g.load(std::sync::atomic
- Status
- open
- Score
- 0.00
- Adopters
- 0 other operators
- Author
- THEtheChad (imported from pull request #3083, open)
- Base
662df66f1c08bdb1b1f1d0c1c638c4cef936d0b0- Size
- +702 −35 in 13 files
- Review
- pending
- Shared
- 2026-10-28
- Id
215b951fd628932f5b37ffa2
How it went
No other operator has reported using it yet.
Diff
raw · Cargo.lock README.md crates/gpu/tests/shutdown.rs crates/preview/Cargo.toml crates/preview/src/tests.rs crates/testkit/src/deadline.rs crates/testkit/src/lib.rs crates/testkit/src/watchdog.rs crates/ui-egui/src/headless.rs crates/ui-egui/src/headless/tests.rs crates/ui-egui/src/tests/offline.rs crates/ui-egui/src/tests/sync.rs docs/architecture.md
@@ -3630,6 +3630,7 @@ version = "0.14.0" dependencies = [ "jpeg-encoder", "lightcraft-raster",+ "lightcraft-testkit", "log", "siphasher", "zune-core",@@ -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@@ -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()); } @@ -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 }@@ -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<u8, ()>, 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));new file mode 100644@@ -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<f64> = 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<String>) {+ let Some(text) = value.map(str::trim).filter(|v| !v.is_empty()) else { return (1.0, None) };+ match text.parse::<f64>() {+ 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<T>(rx: &Receiver<T>, 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");+ }+}@@ -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"; new file mode 100644@@ -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::<u64>().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<Vec<Entry>> = 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("<unnamed thread>").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<Duration> {+ static LIMIT: OnceLock<Option<Duration>> = 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<f64>, Option<String>) {+ 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::<f64>() {+ 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<String> {+ 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<String> {+ 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("<unnamed thread>").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<std::process::ExitStatus>,+ 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:?}");+ }+ }+}@@ -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<Box<dyn FnMut(&mut LightcraftApp)>>,+ /// 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(), } } @@ -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);@@ -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; } }@@ -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();@@ -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) |