collective
Browse / github.com/storytold/lightcraft / patch
Issue #3064: tests stop asserting on wall-clock time; their deadlines stretch with LIGHTCRAFT_TIME_SCALE
Tests that assert on wall-clock time fail on a loaded machine Part of #3057. Builds on #3062 (`time_scale`). ## Summary Some tests assert that something finished within a fixed wall-clock time. On a loaded machine (parallel builds, other agents, a CI runner sharing its cores) they fail even though nothing is wrong. ## Evidence (main bb08a697) **Assertions on speed:** | Where | Code | |---|---| | `crates/engine/src/availability.rs:319` | `assert!(t0.elapsed() < Duration::from_millis(150), "the caller never waits for the probe");` | | `crates/fetch/src/http.rs:635` | `assert!(t.elapsed() >= Duration::from_millis(100) && t.elapsed() < Duration::from_se
- Status
- open
- Score
- 0.00
- Adopters
- 0 other operators
- Author
- THEtheChad (imported from pull request #3096, open)
- Base
662df66f1c08bdb1b1f1d0c1c638c4cef936d0b0- Size
- +959 −145 in 27 files
- Review
- pending
- Shared
- 2026-10-28
- Id
9aff4509ad10b4b0a5355fd7
How it went
No other operator has reported using it yet.
Diff
raw · Cargo.lock README.md crates/catalog/Cargo.toml crates/catalog/src/tests.rs crates/engine/src/availability.rs crates/engine/src/denoise/gpu_tests.rs crates/engine/src/devices.rs crates/engine/src/tests/segment.rs crates/fetch/Cargo.toml crates/fetch/src/http.rs crates/fetch/src/tests.rs crates/gpu/tests/shutdown.rs crates/preview/Cargo.toml crates/preview/src/pool.rs crates/preview/src/tests.rs crates/raw/tests/it/robust.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/panels/activity.rs crates/ui-egui/src/tests/activity.rs crates/ui-egui/src/tests/offline.rs crates/ui-egui/src/tests/sync.rs crates/ui-egui/src/widgets/album_picker.rs docs/architecture.md
@@ -3326,6 +3326,7 @@ dependencies = [ "lightcraft-geom", "lightcraft-meta", "lightcraft-raw",+ "lightcraft-testkit", "log", "proptest", "serde",@@ -3498,6 +3499,7 @@ dependencies = [ name = "lightcraft-fetch" version = "0.14.0" dependencies = [+ "lightcraft-testkit", "log", "rustls", "rustls-rustcrypto",@@ -3630,6 +3632,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@@ -22,4 +22,6 @@ web-time = { workspace = true } [dev-dependencies] lightcraft-geom = { workspace = true }+# deadlines stretched by LIGHTCRAFT_TIME_SCALE+lightcraft-testkit = { workspace = true } proptest = { workspace = true }@@ -723,7 +723,10 @@ fn chains_of_smart_albums_stay_linear() { } let start = std::time::Instant::now(); assert_eq!(c.album_count(AlbumId(26)), 20);- assert!(start.elapsed() < std::time::Duration::from_secs(2), "took {:?}", start.elapsed());+ // a regression guard, not a speed measurement: linear is microseconds, 2^25 passes take minutes+ // (stretched by LIGHTCRAFT_TIME_SCALE for a loaded machine, never shrunk below 2 s)+ let limit = lightcraft_testkit::scaled(std::time::Duration::from_secs(2)).max(std::time::Duration::from_secs(2));+ assert!(start.elapsed() < limit, "took {:?}", start.elapsed()); } /// A smart album's own album filter (not only its rules) counts in loops: A filtered to "in A" is@@ -300,12 +300,19 @@ mod tests { let mut a = Availability::default(); let caller = std::thread::current().id(); let on_caller = Arc::new(AtomicUsize::new(0));- let c = on_caller.clone();+ // a sleeping NAS: every check waits until the test opens the gate (or gives up, so a+ // broken build fails instead of hanging)+ let gate = Arc::new((Mutex::new(false), std::sync::Condvar::new()));+ let finished = Arc::new(AtomicUsize::new(0));+ let (c, g, f) = (on_caller.clone(), gate.clone(), finished.clone()); a.set_probe(Arc::new(move |p| { if std::thread::current().id() == caller { c.fetch_add(1, Ordering::SeqCst); }- std::thread::sleep(Duration::from_millis(200)); // a sleeping NAS+ let (open, cv) = &*g;+ let limit = lightcraft_testkit::scaled(Duration::from_secs(5)).max(Duration::from_secs(5));+ drop(cv.wait_timeout_while(held(open), limit, |open| !*open).unwrap_or_else(PoisonError::into_inner));+ f.fetch_add(1, Ordering::SeqCst); p == "here" })); let woke = Arc::new(AtomicUsize::new(0));@@ -313,14 +320,13 @@ mod tests { a.run_in_background(Arc::new(move || { w.fetch_add(1, Ordering::SeqCst); }));- let t0 = std::time::Instant::now(); assert_eq!(a.exists("here"), None, "unknown at first"); assert_eq!(a.exists("gone"), None);- assert!(t0.elapsed() < Duration::from_millis(150), "the caller never waits for the probe");- let deadline = std::time::Instant::now() + Duration::from_secs(20);- while (a.exists("here").is_none() || a.exists("gone").is_none()) && std::time::Instant::now() < deadline {- std::thread::sleep(Duration::from_millis(10));- }+ // the gate is still shut, so a caller that waited for a check could not have got here yet+ assert_eq!(finished.load(Ordering::SeqCst), 0, "the caller never waits for the probe");+ *held(&gate.0) = true;+ gate.1.notify_all();+ wait_until("both answers", || a.exists("here").is_some() && a.exists("gone").is_some()); assert_eq!(a.exists("here"), Some(true)); assert_eq!(a.exists("gone"), Some(false)); assert!(a.is_offline("gone") && !a.is_offline("here") && !a.is_offline("unknown"));@@ -329,12 +335,10 @@ mod tests { assert!(a.gone_generation() >= 2); } + /// Wait for `done` (at most 20 s, stretched by `LIGHTCRAFT_TIME_SCALE`).+ #[track_caller] fn wait_until(what: &str, done: impl Fn() -> bool) {- let deadline = std::time::Instant::now() + Duration::from_secs(20);- while !done() {- assert!(std::time::Instant::now() < deadline, "timed out waiting: {what}");- std::thread::sleep(Duration::from_millis(2));- }+ lightcraft_testkit::wait_until(Duration::from_secs(20), what, done); } fn held<T>(m: &Mutex<T>) -> MutexGuard<'_, T> {@@ -483,12 +487,18 @@ mod tests { let mut a = Availability::default(); let log = Arc::new(Mutex::new(Vec::<String>::new())); let l = log.clone();- // the worker is held inside the fourth check until the sweep is told to give way+ // the worker is held inside the fourth check (and says it got there) until the sweep is told to+ // give way; the hold gives up after a while, so a failed test leaves no worker spinning let hold = Arc::new(std::sync::atomic::AtomicBool::new(true));- let h = hold.clone();+ let entered = Arc::new(std::sync::atomic::AtomicBool::new(false));+ let (h, e) = (hold.clone(), entered.clone()); a.set_probe(Arc::new(move |p| {- while p == "sweep 3" && h.load(Ordering::SeqCst) {- std::thread::sleep(Duration::from_millis(1));+ if p == "sweep 3" {+ e.store(true, Ordering::SeqCst);+ let t = std::time::Instant::now();+ while h.load(Ordering::SeqCst) && t.elapsed() < lightcraft_testkit::scaled(Duration::from_secs(30)).max(Duration::from_secs(30)) {+ std::thread::sleep(Duration::from_millis(1));+ } } held(&l).push(p.to_string()); true@@ -497,9 +507,12 @@ mod tests { let busy = busy_flag(&a); busy.store(false, Ordering::SeqCst); assert!(a.sweep((0..100).map(|i| format!("sweep {i}")).collect()));- wait_until("a few checks", || held(&log).len() >= 3);+ // the fourth check has started (so giving way now can't keep it from starting)+ wait_until("the worker inside the fourth check", || entered.load(Ordering::SeqCst));+ assert_eq!(held(&log).len(), 3); busy.store(true, Ordering::SeqCst); hold.store(false, Ordering::SeqCst);+ wait_until("the check in flight", || held(&log).len() >= 4); std::thread::sleep(YIELD_POLL * 2); let stopped = held(&log).len(); assert_eq!(stopped, 4, "stopped part way, after the check it was in");@@ -282,20 +282,30 @@ fn a_set_up_runs_beside_the_cpu_and_removes_its_marker() { fn a_set_up_that_takes_too_long_is_given_up_on() { let dir = folder("slowsetup"); let marker = dir.join(GPU_SETUP_MARKER);- let started = web_time::Instant::now();- let slow = || -> Result<(), String> {- std::thread::sleep(Duration::from_millis(600));+ // a card whose set-up is stuck until the test lets it go (it gives up after a while, so a caller+ // that waits for it fails the test instead of hanging it)+ let gate = Arc::new(AtomicBool::new(false));+ let finished = Arc::new(AtomicBool::new(false));+ let (g, f) = (gate.clone(), finished.clone());+ let slow = move || -> Result<(), String> {+ let t = web_time::Instant::now();+ while !g.load(Ordering::SeqCst) && t.elapsed() < lightcraft_testkit::scaled(Duration::from_secs(5)).max(Duration::from_secs(5)) {+ std::thread::sleep(Duration::from_millis(1));+ }+ f.store(true, Ordering::SeqCst); Ok(()) }; let r = set_up_card(&marker, Duration::from_millis(50), slow, || ()); assert!(r.as_ref().is_err_and(|e| e.contains("took longer") && worth_retrying(e)), "{r:?}");- assert!(started.elapsed() < Duration::from_millis(500), "the caller does not wait for the card");+ assert!(!finished.load(Ordering::SeqCst), "the caller does not wait for the card"); // while the first is still stuck, another set-up of the same model does not start a second one let again = set_up_card(&marker, Duration::from_secs(5), || Ok(()), || ()); assert!(again.is_err_and(|e| e.contains("still setting up") && worth_retrying(&e))); // once it ends its marker goes, and the card can be set up again+ gate.store(true, Ordering::SeqCst);+ let started = web_time::Instant::now(); while marker.exists() {- assert!(started.elapsed() < Duration::from_secs(10), "the stuck set-up ended");+ assert!(started.elapsed() < lightcraft_testkit::scaled(Duration::from_secs(10)), "the stuck set-up ended"); std::thread::sleep(Duration::from_millis(20)); } while SETTING_UP.lock().unwrap().iter().any(|m| m == &marker) {@@ -247,10 +247,10 @@ mod tests { Device { name: name.into(), path: format!("/v/{name}/DCIM"), root: format!("/v/{name}") } } - /// Wait (bounded) for `f`.+ /// Wait (bounded: 20 s, stretched by `LIGHTCRAFT_TIME_SCALE`) for `f`. fn until(f: impl Fn() -> bool) -> bool { let t = std::time::Instant::now();- while t.elapsed() < Duration::from_secs(20) {+ while t.elapsed() < lightcraft_testkit::scaled(Duration::from_secs(20)) { if f() { return true; }@@ -261,15 +261,21 @@ mod tests { #[test] fn slow_scans_never_block_and_hot_plug_still_arrives() {- // a scanner that takes 1.5 s (a sleeping network drive) and counts its runs- const SLOW: Duration = Duration::from_millis(1500);+ // a scanner held until the test opens its gate (a sleeping network drive) that counts its runs;+ // it gives up after a while so a get() that waits for it fails the test instead of hanging it let mounted = Arc::new(Mutex::new(Vec::<Device>::new())); let runs = Arc::new(AtomicUsize::new(0));- let (m, r) = (mounted.clone(), runs.clone());+ let finished = Arc::new(AtomicUsize::new(0));+ let gate = Arc::new(std::sync::atomic::AtomicBool::new(false));+ let (m, r, f, g) = (mounted.clone(), runs.clone(), finished.clone(), gate.clone()); let watch = DeviceWatch::new( move || { r.fetch_add(1, Ordering::SeqCst);- std::thread::sleep(SLOW);+ let t = std::time::Instant::now();+ while !g.load(Ordering::SeqCst) && t.elapsed() < lightcraft_testkit::scaled(Duration::from_secs(5)).max(Duration::from_secs(5)) {+ std::thread::sleep(Duration::from_millis(1));+ }+ f.fetch_add(1, Ordering::SeqCst); m.lock().unwrap().clone() }, Duration::from_millis(20),@@ -280,21 +286,23 @@ mod tests { c.fetch_add(1, Ordering::SeqCst); }); // cold: served at once (empty) while one scan runs in the background- let t = std::time::Instant::now(); for _ in 0..50 { assert!(watch.get().is_empty()); }- assert!(t.elapsed() < SLOW / 2, "get() waited for the scan: {:?}", t.elapsed());+ // the scan is still held: a get() that waited for it could not have returned yet+ assert_eq!(finished.load(Ordering::SeqCst), 0, "get() waited for the scan"); assert!(watch.refreshing());+ gate.store(true, Ordering::SeqCst); assert!(until(|| !watch.refreshing())); assert_eq!(runs.load(Ordering::SeqCst), 1, "requests while scanning are coalesced"); assert_eq!(changes.load(Ordering::SeqCst), 0, "nothing changed"); // a card is plugged in: the next stale request starts a rescan, still without waiting+ gate.store(false, Ordering::SeqCst); mounted.lock().unwrap().push(card("EOS_DIGITAL")); std::thread::sleep(Duration::from_millis(40));- let t = std::time::Instant::now(); assert!(watch.get().is_empty(), "the old list is served while rescanning");- assert!(t.elapsed() < SLOW / 2, "warm get() waited: {:?}", t.elapsed());+ assert_eq!(finished.load(Ordering::SeqCst), 1, "warm get() waited for the rescan");+ gate.store(true, Ordering::SeqCst); assert!(until(|| changes.load(Ordering::SeqCst) == 1), "a changed scan notifies"); assert_eq!(watch.get(), [card("EOS_DIGITAL")]); // explicit requests scan synchronously@@ -92,7 +92,7 @@ fn a_failing_download_ends_with_an_error_and_never_blocks() { line.clear(); } if let Some(released) = first.take() {- let _ = released.recv_timeout(Duration::from_secs(10));+ let _ = released.recv_timeout(lightcraft_testkit::scaled(Duration::from_secs(30)).max(Duration::from_secs(30))); } let _ = c.write_all(b"HTTP/1.1 404 Not Found\r\nContent-Length: 13\r\nConnection: close\r\n\r\n<h1>404</h1>\n"); }@@ -103,22 +103,23 @@ fn a_failing_download_ends_with_an_error_and_never_blocks() { let mut s = Session::with_demo(); s.segmenter.dir = Some(dir.clone()); s.segmenter.mirrors_file = Some(mirrors.clone());- let t = Instant::now(); let r = s.execute("segment.model.download", &json!({"acknowledged": true})).unwrap(); assert_eq!(r["started"], true);- assert!(t.elapsed() < Duration::from_secs(1), "starting a download returns at once");+ // the mirror holds its answer until `release`: still running means the call did not wait for it+ assert!(s.segmenter.download_status().running, "starting a download returns at once"); // a second request while it runs starts nothing let again = s.execute("segment.model.download", &json!({"acknowledged": true})).unwrap(); assert!(again["started"] == false || again["downloading"] == false);+ // AI mask requests meanwhile: an error while the mirror still holds the download, never a wait for it+ let e = s.execute("mask.add", &json!({"kind": "prompt", "text": "sky"})).unwrap_err().to_string();+ assert!(e.contains(NOT_INSTALLED), "{e}");+ assert!(s.segmenter.download_status().running, "the AI mask request did not wait for the download"); let _ = release.send(()); let t = Instant::now(); while s.segmenter.download_status().running {- assert!(t.elapsed() < Duration::from_secs(30), "the download never ended");- // AI mask requests meanwhile: an error at once, never a wait- let q = Instant::now();+ assert!(t.elapsed() < lightcraft_testkit::scaled(Duration::from_secs(30)), "the download never ended"); let e = s.execute("mask.add", &json!({"kind": "prompt", "text": "sky"})).unwrap_err().to_string(); assert!(e.contains(NOT_INSTALLED), "{e}");- assert!(q.elapsed() < Duration::from_millis(500)); std::thread::sleep(Duration::from_millis(20)); } let st = s.segmenter.download_status();@@ -15,3 +15,7 @@ rustls = { version = "0.23", default-features = false, features = ["std", "tls12 rustls-rustcrypto = "0.0.2-alpha" webpki-roots = "1" sha2 = { version = "0.10", default-features = false, features = ["std"] }++[dev-dependencies]+# deadlines stretched by LIGHTCRAFT_TIME_SCALE+lightcraft-testkit = { workspace = true }@@ -606,33 +606,51 @@ pub fn get(url: &Url, headers: &[(&str, String)], limits: &Limits) -> Result<Res mod tests_connect { use super::*; + /// `d` stretched by `LIGHTCRAFT_TIME_SCALE`, never shrunk: the bounds here sit on the client's+ /// fixed [`TICK`] (how often a wait looks at Cancel), which a scale below 1 doesn't shorten.+ fn stretched(d: Duration) -> Duration {+ lightcraft_testkit::scaled(d).max(d)+ }+ fn limits(cancel: &AtomicBool) -> Limits<'_> {- Limits { connect: Duration::from_millis(300), stall: Duration::from_secs(1), cancel }+ Limits { connect: stretched(Duration::from_millis(300)), stall: stretched(Duration::from_secs(1)), cancel } } /// A name lookup that hangs is given up on at the connect timeout, and Cancel stops it at once (issue #1532). #[test] fn a_hung_name_lookup_times_out_and_can_be_cancelled() { let cancel = AtomicBool::new(false);+ // (every time here is stretched by LIGHTCRAFT_TIME_SCALE, so the resolver stays far slower than the bounds) let slow = || {- std::thread::sleep(Duration::from_secs(10));+ std::thread::sleep(stretched(Duration::from_secs(10))); Ok(Vec::new()) }; let t = Instant::now();- let r = lookup("slow.example", slow, Instant::now() + Duration::from_millis(300), &limits(&cancel));+ let r = lookup("slow.example", slow, Instant::now() + stretched(Duration::from_millis(300)), &limits(&cancel)); assert!(matches!(&r, Err(HttpError::Connect(m)) if m.contains("timed out")), "{r:?}");- assert!(t.elapsed() < Duration::from_secs(2), "{:?}", t.elapsed());- // Cancel while the lookup is waiting on the resolver, not before it starts+ assert!(t.elapsed() < stretched(Duration::from_secs(2)), "{:?}", t.elapsed());+ // Cancel while the lookup is waiting on the resolver (100 ms after it started), not before it starts+ let (began, has_begun) = std::sync::mpsc::channel();+ let signalling = move || {+ let _ = began.send(());+ std::thread::sleep(stretched(Duration::from_secs(10)));+ Ok(Vec::new())+ }; let t = Instant::now(); let r = std::thread::scope(|scope| {- scope.spawn(|| {+ let cancel = &cancel;+ scope.spawn(move || {+ lightcraft_testkit::recv_within(&has_begun, Duration::from_secs(30), "the resolver starts"); std::thread::sleep(Duration::from_millis(100)); cancel.store(true, Ordering::Relaxed); });- lookup("slow.example", slow, Instant::now() + Duration::from_secs(30), &limits(&cancel))+ lookup("slow.example", signalling, Instant::now() + stretched(Duration::from_secs(30)), &limits(cancel)) }); assert!(matches!(r, Err(HttpError::Cancelled)), "{r:?}");- assert!(t.elapsed() >= Duration::from_millis(100) && t.elapsed() < Duration::from_secs(1), "{:?}", t.elapsed());+ // at least the 100 ms before Cancel; then noticed within a TICK (the margin is for a slow machine)+ let waited = t.elapsed();+ let limit = Duration::from_millis(100) + stretched(Duration::from_millis(900));+ assert!(waited >= Duration::from_millis(100) && waited < limit, "{waited:?} (limit {limit:?})"); // and a lookup asked for after Cancel doesn't start assert!(matches!(lookup("slow.example", slow, Instant::now() + Duration::from_secs(30), &limits(&cancel)), Err(HttpError::Cancelled))); // a lookup that answers is used@@ -647,10 +665,11 @@ mod tests_connect { let cancel = AtomicBool::new(false); // non-routable addresses: each either hangs until the deadline or fails at once, never longer let addrs: Vec<SocketAddr> = (1..=5).map(|i| format!("10.255.255.{i}:81").parse().unwrap()).collect();+ // five full timeouts would take 2 s; one shared one 400 ms let t = Instant::now();- let r = connect_any("blackhole", &addrs, Instant::now() + Duration::from_millis(400), &limits(&cancel));+ let r = connect_any("blackhole", &addrs, Instant::now() + stretched(Duration::from_millis(400)), &limits(&cancel)); assert!(r.is_err());- assert!(t.elapsed() < Duration::from_millis(1500), "{:?}", t.elapsed());+ assert!(t.elapsed() < stretched(Duration::from_millis(1500)), "{:?}", t.elapsed()); } } @@ -99,7 +99,8 @@ fn handle(mut s: TcpStream, hits: &AtomicUsize) { // half the file, then nothing let _ = s.write_all(format!("HTTP/1.1 200 OK\r\nContent-Length: {}\r\n\r\n", body.len()).as_bytes()); let _ = s.write_all(&body[..body.len() / 2]);- std::thread::sleep(Duration::from_secs(5));+ // (stretched with the client's timeouts, so it stays well past the stall timeout)+ std::thread::sleep(stretched(Duration::from_secs(5))); } "slow" => { let _ = s.write_all(format!("HTTP/1.1 200 OK\r\nContent-Length: {}\r\n\r\n", body.len()).as_bytes());@@ -136,8 +137,16 @@ fn tmp(name: &str) -> PathBuf { d } +/// `d` stretched by `LIGHTCRAFT_TIME_SCALE`, never shrunk: the timeouts and bounds here sit on the+/// test server's fixed pace (20 ms per kilobyte) and the client's fixed 250 ms poll.+fn stretched(d: Duration) -> Duration {+ lightcraft_testkit::scaled(d).max(d)+}++/// Short timeouts, stretched by `LIGHTCRAFT_TIME_SCALE` (a loaded machine can leave a working+/// connection quiet for longer). fn quick() -> Options {- Options { connect_timeout: Duration::from_secs(2), stall_timeout: Duration::from_millis(600), attempts: 2, token_env: None }+ Options { connect_timeout: stretched(Duration::from_secs(2)), stall_timeout: stretched(Duration::from_millis(600)), attempts: 2, token_env: None } } fn run(files: &[FileSpec<'_>], mirrors: &[String], dir: &Path, cancel: &AtomicBool) -> (Result<(), DownloadError>, Vec<Progress>) {@@ -283,7 +292,8 @@ fn a_stalled_server_times_out_and_the_next_mirror_finishes() { let t = Instant::now(); let (r, _) = run(&[pinned()], &[format!("{}/stall", srv.base), format!("{}/good", srv.base)], &dir, &AtomicBool::new(false)); r.unwrap();- assert!(t.elapsed() < Duration::from_secs(4), "{:?}", t.elapsed());+ // two stalled tries (600 ms each) and the good mirror, not two waits for the server to hang up (5 s each)+ assert!(t.elapsed() < stretched(Duration::from_secs(4)), "{:?}", t.elapsed()); assert_eq!(std::fs::read(dir.join("model.bin")).unwrap(), payload()); let _ = std::fs::remove_dir_all(&dir); }@@ -294,14 +304,18 @@ fn cancel_stops_quickly_and_keeps_the_part_for_later() { let dir = tmp("cancel"); let cancel = Arc::new(AtomicBool::new(false)); let c = cancel.clone();+ let part = part_path(&dir, "model.bin");+ // cancel once part of the file is written (the slow server takes 6 s for the whole of it) std::thread::spawn(move || {- std::thread::sleep(Duration::from_millis(400));+ lightcraft_testkit::wait_until(Duration::from_secs(30), "the first bytes of the part", || {+ std::fs::metadata(&part).is_ok_and(|m| m.len() > 0)+ }); c.store(true, Ordering::SeqCst); }); let t = Instant::now(); let (r, _) = run(&[pinned()], &[format!("{}/slow", srv.base)], &dir, &cancel); assert_eq!(r, Err(DownloadError::Cancelled));- assert!(t.elapsed() < Duration::from_secs(3), "{:?}", t.elapsed());+ assert!(t.elapsed() < stretched(Duration::from_secs(3)), "{:?}", t.elapsed()); assert!(!dir.join("model.bin").exists()); let kept = std::fs::metadata(part_path(&dir, "model.bin")).map(|m| m.len()).unwrap_or(0); assert!(kept > 0 && kept < 300_000, "{kept}");@@ -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 }@@ -42,6 +42,10 @@ struct Shared<S, R> { live: Mutex<Vec<std::thread::ThreadId>>, #[cfg(not(target_arch = "wasm32"))] ended: Condvar,+ /// Tests: how many times [`stop`] waited for a running job (a drop after a shutdown, or by+ /// the pool's own job, must not wait at all).+ #[cfg(all(test, not(target_arch = "wasm32")))]+ stop_waits: Arc<std::sync::atomic::AtomicUsize>, } /// How long dropping a pool waits for the jobs still running (see [`JobPool::shutdown`]).@@ -87,6 +91,8 @@ impl<S: Copy + Eq + Hash + Send + 'static, R: Send + 'static> JobPool<S, R> { live: Mutex::new(Vec::new()), #[cfg(not(target_arch = "wasm32"))] ended: Condvar::new(),+ #[cfg(all(test, not(target_arch = "wasm32")))]+ stop_waits: Arc::default(), }), tx, rx,@@ -166,6 +172,12 @@ impl<S: Copy + Eq + Hash + Send + 'static, R: Send + 'static> JobPool<S, R> { } } + /// Tests: the count of [`stop`]'s waits for a running job (it outlives the pool).+ #[cfg(all(test, not(target_arch = "wasm32")))]+ pub(crate) fn stop_waits(&self) -> Arc<std::sync::atomic::AtomicUsize> {+ self.shared.stop_waits.clone()+ }+ /// Worker threads that have not ended (0 before the first job, and on wasm). pub fn live_workers(&self) -> usize { #[cfg(not(target_arch = "wasm32"))]@@ -329,6 +341,8 @@ fn stop<S, R>(shared: &Shared<S, R>, workers: &mut Vec<std::thread::JoinHandle<( let mut live = shared.live.lock().unwrap_or_else(|e| e.into_inner()); while live.iter().any(|id| *id != me) { let Some(left) = timeout.checked_sub(t0.elapsed()).filter(|d| !d.is_zero()) else { break };+ #[cfg(test)]+ shared.stop_waits.fetch_add(1, Ordering::SeqCst); live = shared.ended.wait_timeout(live, left).unwrap_or_else(|e| e.into_inner()).0; } let running: Vec<std::thread::ThreadId> = live.iter().copied().filter(|id| *id != me).collect();@@ -4,6 +4,12 @@ use lightcraft_raster::Rgba8; use super::*; +/// `d` stretched by `LIGHTCRAFT_TIME_SCALE`, never shrunk: for a job held past the pool's fixed+/// 2 s drop wait, and for bounds above a fixed lower one.+fn stretched(d: std::time::Duration) -> std::time::Duration {+ lightcraft_testkit::scaled(d).max(d)+}+ #[test] fn cleared_generation_cannot_read_or_repopulate_memory_or_disk() { let dir = std::env::temp_dir().join(format!("lc-thumbnail-generation-{}-{}", std::process::id(), next_tick()));@@ -182,17 +188,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 +210,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)]); } @@ -240,10 +240,10 @@ fn pool_with_a_running_job() -> (JobPool<u8, ()>, std::sync::mpsc::Sender<()>) { 1, Box::new(move || { let _ = started.send(());- let _ = released.recv_timeout(std::time::Duration::from_secs(60));+ let _ = released.recv_timeout(stretched(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 +265,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);@@ -280,20 +280,22 @@ fn pool_shutdown_reports_workers_and_drop_does_not_wait_again() { let t0 = std::time::Instant::now(); assert!(!p.shutdown(std::time::Duration::from_millis(100)), "the job is still running"); let waited = t0.elapsed();- assert!(waited >= std::time::Duration::from_millis(100) && waited < std::time::Duration::from_secs(30), "{waited:?}");+ assert!(waited >= std::time::Duration::from_millis(100) && waited < stretched(std::time::Duration::from_secs(30)), "{waited:?}"); assert_eq!(p.live_workers(), 1); // stopped: nothing new is queued, and the job that ends is noticed p.submit(2, 0, 1, Box::new(|| ())); assert_eq!(p.queued(), 0); drop(release);- assert!(p.shutdown(std::time::Duration::from_secs(30)));+ assert!(p.shutdown(lightcraft_testkit::scaled(std::time::Duration::from_secs(30)))); assert_eq!(p.live_workers(), 0); let (mut p, _release) = pool_with_a_running_job(); assert!(!p.shutdown(std::time::Duration::ZERO));- let t0 = std::time::Instant::now();+ let waits = p.stop_waits();+ let before = waits.load(std::sync::atomic::Ordering::SeqCst); drop(p);- assert!(t0.elapsed() < std::time::Duration::from_secs(1), "dropped after a shutdown: no second wait");+ // (the job runs until `_release` goes: a second wait would have had something to wait for)+ assert_eq!(waits.load(std::sync::atomic::Ordering::SeqCst), before, "dropped after a shutdown: no second wait"); } #[test]@@ -303,7 +305,7 @@ fn pool_drop_is_bounded_when_a_job_never_ends() { let t0 = std::time::Instant::now(); drop(p); let waited = t0.elapsed();- assert!(waited >= std::time::Duration::from_secs(1) && waited < std::time::Duration::from_secs(30), "{waited:?}");+ assert!(waited >= std::time::Duration::from_secs(1) && waited < stretched(std::time::Duration::from_secs(30)), "{waited:?}"); } #[test]@@ -311,15 +313,14 @@ fn pool_stops_after_a_job_panicked_and_when_dropped_by_its_own_job() { // a worker that unwound is not waited for let mut p: JobPool<u8, ()> = JobPool::new(1); p.submit(1, 0, 1, Box::new(|| panic!("a job panics (expected in this test)")));- while p.live_workers() > 0 {- std::thread::yield_now();- }- assert!(p.shutdown(std::time::Duration::from_secs(30)));+ lightcraft_testkit::wait_until(std::time::Duration::from_secs(30), "the panicked worker ends", || p.live_workers() == 0);+ assert!(p.shutdown(lightcraft_testkit::scaled(std::time::Duration::from_secs(30)))); // the last owner of a pool is one of its jobs: the worker must not wait for (or join) itself let slot: Arc<std::sync::Mutex<Option<JobPool<u8, ()>>>> = Arc::new(std::sync::Mutex::new(None)); let (dropped, has_dropped) = std::sync::mpsc::channel(); let mut p: JobPool<u8, ()> = JobPool::new(1);+ let waits = p.stop_waits(); let s = slot.clone(); p.submit( 1,@@ -332,14 +333,14 @@ fn pool_stops_after_a_job_panicked_and_when_dropped_by_its_own_job() { } std::thread::yield_now(); };- let t0 = std::time::Instant::now(); drop(own);- let _ = dropped.send(t0.elapsed());+ let _ = dropped.send(()); }), ); *slot.lock().unwrap() = Some(p);- let waited = has_dropped.recv_timeout(std::time::Duration::from_secs(30)).unwrap();- assert!(waited < std::time::Duration::from_secs(1), "{waited:?}");+ lightcraft_testkit::recv_within(&has_dropped, std::time::Duration::from_secs(30), "the job drops its own pool");+ // the dropping job is the only one running: any wait would be for itself+ assert_eq!(waits.load(std::sync::atomic::Ordering::SeqCst), 0, "the job's drop waited for itself"); } #[test]@@ -688,16 +689,16 @@ fn pool_wait_keeps_the_finished_job_for_try_recv() { let mut p: JobPool<u8, u8> = JobPool::new(1); assert!(!p.wait(std::time::Duration::from_millis(10)), "nothing runs"); p.submit(1, 0, 1, Box::new(|| 7));- assert!(p.wait(std::time::Duration::from_secs(10)));+ assert!(p.wait(lightcraft_testkit::scaled(std::time::Duration::from_secs(10)))); assert!(p.wait(std::time::Duration::ZERO), "kept until taken"); assert_eq!(p.try_recv().map(|d| d.result), Some(7)); assert!(p.try_recv().is_none()); } -/// Wait up to `secs` for `f` to hold.+/// Wait up to `secs` (stretched by `LIGHTCRAFT_TIME_SCALE`) for `f` to hold. fn eventually(secs: u64, mut f: impl FnMut() -> bool) -> bool { let t0 = std::time::Instant::now();- while t0.elapsed() < std::time::Duration::from_secs(secs) {+ while t0.elapsed() < lightcraft_testkit::scaled(std::time::Duration::from_secs(secs)) { if f() { return true; }@@ -725,14 +726,14 @@ fn a_slot_runs_one_job_at_a_time() { most.fetch_max(now, Ordering::SeqCst); let _ = started.send(n); if let Some(w) = wait {- let _ = w.recv_timeout(std::time::Duration::from_secs(30));+ let _ = w.recv_timeout(stretched(std::time::Duration::from_secs(30))); } running.fetch_sub(1, Ordering::SeqCst); n }) }; 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));@@ -783,7 +784,7 @@ fn deferred_writes_are_bounded_and_drain_to_disk() { assert!(cache.queued_bytes() <= MAX_QUEUED_BYTES, "{} bytes queued", cache.queued_bytes()); } let t = std::time::Instant::now();- while cache.queued_bytes() > 0 && t.elapsed() < std::time::Duration::from_secs(120) {+ while cache.queued_bytes() > 0 && t.elapsed() < lightcraft_testkit::scaled(std::time::Duration::from_secs(120)) { std::thread::sleep(std::time::Duration::from_millis(20)); } assert_eq!(cache.queued_bytes(), 0, "the queue drains");@@ -104,7 +104,10 @@ fn hostile_dimensions_are_rejected_quickly() { let bytes = TiffWriter::default().write(&[ifd]).unwrap(); let t0 = std::time::Instant::now(); assert!(lightcraft_raw::decode(&bytes).is_err());- assert!(t0.elapsed().as_secs_f64() < 2.0);+ // a regression guard, not a speed measurement: rejecting it takes milliseconds, reading the 7 GB+ // frame it claims would take far longer (stretched by LIGHTCRAFT_TIME_SCALE for a loaded machine)+ let limit = lightcraft_testkit::scaled(std::time::Duration::from_secs(5)).max(std::time::Duration::from_secs(5));+ assert!(t0.elapsed() < limit, "took {:?} (limit {limit:?})", t0.elapsed()); } /// A Bayer DNG whose `BlackLevel` is a FLOAT holding NaN (or infinity), and a float CFA DNG withnew 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);@@ -23,6 +23,11 @@ pub const WIDTH: f32 = 280.0; const MARGIN: i8 = 8; const CROSS: f32 = 16.0; +/// Whether `task` has a row yet: from [`SHOW_AFTER_MS`] on.+pub(crate) fn due(task: &TaskInfo) -> bool {+ task.age_ms >= SHOW_AFTER_MS+}+ /// "3 of 25", "12 of 340 MB", "40 %"; empty while the amount of work isn't known. pub fn count_text(t: &TaskInfo) -> String { if t.total == 0 {@@ -62,7 +67,7 @@ pub fn show(app: &mut LightcraftApp, ctx: &egui::Context) { } // look again soon: a young task becomes due, bars move ctx.request_repaint_after(std::time::Duration::from_millis(100));- let tasks: Vec<&TaskInfo> = all.iter().filter(|t| t.age_ms >= SHOW_AFTER_MS).collect();+ let tasks: Vec<&TaskInfo> = all.iter().filter(|t| due(t)).collect(); if tasks.is_empty() { return; }@@ -6,18 +6,31 @@ use lightcraft_engine::activity::{Cancel, TaskInfo, Unit}; use serde_json::json; use crate::headless::Headless;-use crate::panels::activity::{WIDTH, count_text};+use crate::panels::activity::{SHOW_AFTER_MS, WIDTH, count_text, due}; use crate::{LightcraftApp, Services}; -// generous: merges and renders run on worker threads that a busy machine (a full workspace test run) slows a lot-const T: Duration = Duration::from_secs(60);+/// Generous: merges and renders run on worker threads that a busy machine (a full workspace test run)+/// slows a lot. Stretched by `LIGHTCRAFT_TIME_SCALE`.+fn t() -> Duration {+ stretched(Duration::from_secs(60))+}++/// `d` stretched by `LIGHTCRAFT_TIME_SCALE`, never shrunk: the waits here sit on fixed times (the+/// stand-in drive's 100 ms per file, the Auto Import listing every few seconds).+fn stretched(d: Duration) -> Duration {+ lightcraft_testkit::scaled(d).max(d)+} fn demo() -> Headless { let app = LightcraftApp::new(lightcraft_engine::Session::with_demo(), Services { png: None, ..Default::default() }); let mut h = Headless::new(app, [1200.0, 800.0], 1.0); // let the first renders finish: a render still running when the test binary exits can crash in the // GPU driver's teardown (the preview pool doesn't join its workers)- h.settle(T);+ h.settle(t());+ // and whatever the demo itself runs in the stack: on a loaded machine it outlives half a second+ // and its row would be counted with the test's own+ let ended = h.step_until(t(), |h| h.app.session.activity.list().is_empty());+ assert!(ended, "the demo's own tasks never ended: {:?}", h.app.session.activity.list()); h } @@ -44,7 +57,7 @@ fn wait_visible(h: &mut Headless) { fn click(h: &mut Headless, id: &str) { h.step(); h.step();- assert_eq!(h.request("ui.clickWidget", json!({"id": id}), T)["ok"], true, "{id}");+ assert_eq!(h.request("ui.clickWidget", json!({"id": id}), t())["ok"], true, "{id}"); for _ in 0..4 { h.step(); }@@ -57,14 +70,16 @@ fn rows_appear_after_half_a_second_and_cancel_by_click() { g.progress(2, 5); h.step(); // a frame on a loaded machine can outlast the half second: only judge a task still young after it- if h.app.session.activity.list()[0].age_ms < crate::panels::activity::SHOW_AFTER_MS {+ // (`a_task_has_a_row_from_half_a_second_on` checks the threshold itself without the clock)+ let young = h.app.session.activity.list().iter().any(|t| t.id == g.id() && !due(t));+ if young { assert!(!has(&h, &format!("activity:row:{}", g.id())), "not before 0.5 s"); } wait_visible(&mut h); assert!(has(&h, &format!("activity:row:{}", g.id()))); click(&mut h, &format!("activity:cancel:{}", g.id())); assert!(g.is_cancelled());- let inspect = h.request("ui.inspect", json!({}), T);+ let inspect = h.request("ui.inspect", json!({}), t()); assert_eq!(inspect["result"]["activity"][0]["cancelling"], true, "{}", inspect["result"]["activity"]); } @@ -97,6 +112,29 @@ fn not_cancellable_rows_have_no_cross() { assert!(!has(&h, &format!("activity:cancel:{}", g.id()))); } +/// The threshold the stack draws by, without the wall clock (a test that waits for real time can't tell+/// a row shown too early from a frame that took half a second on a loaded machine).+#[test]+fn a_task_has_a_row_from_half_a_second_on() {+ let task = |age_ms| TaskInfo {+ id: 1,+ kind: "export",+ label: "Exporting".into(),+ done: 0,+ total: 0,+ unit: Unit::Count,+ detail: String::new(),+ cancellable: true,+ cancelling: false,+ age_ms,+ };+ assert_eq!(SHOW_AFTER_MS, 500);+ assert!(!due(&task(0)), "a task just started has no row");+ assert!(!due(&task(SHOW_AFTER_MS - 1)), "nor one a moment short of half a second");+ assert!(due(&task(SHOW_AFTER_MS)), "half a second old: a row");+ assert!(due(&task(u64::MAX)));+}+ #[test] fn count_text_by_unit() { let mut t = TaskInfo {@@ -127,7 +165,7 @@ fn stale_cancel_is_harmless() { wait_visible(&mut h); let id = g.id(); drop(g);- let r = h.request("engine.execute", json!({"command": "activity.cancel", "params": {"id": id}}), T);+ let r = h.request("engine.execute", json!({"command": "activity.cancel", "params": {"id": id}}), t()); assert_eq!(r["ok"], false, "an error result, not a panic: {r}"); h.step(); assert!(h.app.ui.toast.is_none(), "{:?}", h.app.ui.toast);@@ -202,15 +240,15 @@ fn slow_writer(ms: u64) -> crate::SharedWrite { fn start_export(h: &mut Headless, n: usize) { let ids: Vec<u64> = h.app.session.visible_cloned().iter().take(n).map(|p| p.0).collect(); assert_eq!(ids.len(), n, "the demo library has {n} photos");- h.request("engine.execute", json!({"command": "library.select", "params": {"ids": ids}}), T);- h.request("engine.execute", json!({"command": "dialog.export", "params": {}}), T);+ h.request("engine.execute", json!({"command": "library.select", "params": {"ids": ids}}), t());+ h.request("engine.execute", json!({"command": "dialog.export", "params": {}}), t()); h.step(); if let Some(crate::state::Dialog::Export { full_size, resize, dir, .. }) = &mut h.app.ui.dialog { *full_size = false; *resize = lightcraft_engine::export::Resize::long_edge(64); *dir = "/lc-test-out".into(); }- let r = h.request("ui.dialog.confirm", json!({}), T);+ let r = h.request("ui.dialog.confirm", json!({}), t()); assert_eq!(r["ok"], true, "{r}"); } @@ -220,12 +258,12 @@ fn export_shows_a_row_and_stops_on_activity_cancel() { h.app.services.write_shared = Some(slow_writer(200)); start_export(&mut h, 5); assert!(h.app.export.is_some(), "running in the background");- let tasks = h.request("ui.inspect", json!({}), T)["result"]["activity"].clone();+ let tasks = h.request("ui.inspect", json!({}), t())["result"]["activity"].clone(); assert_eq!(tasks[0]["kind"], "export", "{tasks}"); assert_eq!(tasks[0]["total"], 5, "{tasks}"); let id = tasks[0]["id"].as_u64().unwrap();- assert_eq!(h.request("engine.execute", json!({"command": "activity.cancel", "params": {"id": id}}), T)["ok"], true);- assert!(h.step_until(Duration::from_secs(60), |h| h.app.export.is_none()));+ assert_eq!(h.request("engine.execute", json!({"command": "activity.cancel", "params": {"id": id}}), t())["ok"], true);+ assert!(h.step_until(t(), |h| h.app.export.is_none())); assert!(h.app.session.activity.list().is_empty()); assert!(h.app.last_export_result.as_ref().is_some_and(|r| r["cancelled"] == true), "{:?}", h.app.last_export_result); assert!(!has(&h, "button:exportCancel"), "the old window is gone");@@ -236,7 +274,7 @@ fn dead_export_worker_leaves_no_row() { let mut h = demo(); h.app.services.write_shared = Some(std::sync::Arc::new(|_: &str, _: &[u8]| -> Result<(), String> { panic!("synthetic writer panic") })); start_export(&mut h, 2);- assert!(h.step_until(Duration::from_secs(60), |h| h.app.export.is_none()));+ assert!(h.step_until(t(), |h| h.app.export.is_none())); assert!(h.app.session.activity.list().is_empty()); } @@ -264,7 +302,7 @@ fn gated_import(tag: &str, n: usize, gate: Option<std::sync::Arc<std::sync::atom && index >= lightcraft_engine::import::batch_size() { let t0 = std::time::Instant::now();- while !gate.load(std::sync::atomic::Ordering::Acquire) && t0.elapsed() < Duration::from_secs(60) {+ while !gate.load(std::sync::atomic::Ordering::Acquire) && t0.elapsed() < t() { std::thread::sleep(Duration::from_millis(1)); } }@@ -277,7 +315,7 @@ fn gated_import(tag: &str, n: usize, gate: Option<std::sync::Arc<std::sync::atom }) })); let mut h = Headless::new(LightcraftApp::new(s, Services { png: None, ..Default::default() }), [1200.0, 800.0], 1.0);- h.settle(T);+ h.settle(t()); (h, dir) } @@ -287,11 +325,11 @@ fn import_cancelled_by_command_reports_cancelled() { let (mut h, dir) = slow_import("cancel", n); let undo0 = h.app.session.undo.len(); crate::import::start_paths(&mut h.app, vec![dir.to_string_lossy().to_string()]).unwrap();- assert!(h.step_until(Duration::from_secs(60), |h| h.app.import.as_ref().is_some_and(|t| t.imported >= 2)));+ assert!(h.step_until(t(), |h| h.app.import.as_ref().is_some_and(|t| t.imported >= 2))); let tasks = h.app.session.activity.list(); assert_eq!(tasks.first().map(|t| t.kind), Some("import"), "{tasks:?}"); h.app.session.activity.cancel(tasks[0].id).unwrap();- assert!(h.step_until(Duration::from_secs(60), |h| h.app.import.is_none()));+ assert!(h.step_until(t(), |h| h.app.import.is_none())); assert!(h.app.session.activity.list().is_empty()); assert!(h.app.ui.toast.as_ref().is_some_and(|t| t.0.starts_with("Import cancelled")), "{:?}", h.app.ui.toast); assert!(h.app.session.catalog.len() < n, "stopped part-way");@@ -306,15 +344,15 @@ fn a_photo_chosen_during_an_import_stays_selected() { let gate = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(false)); let (mut h, dir) = gated_import("chosen", 20, Some(gate.clone())); crate::import::start_paths(&mut h.app, vec![dir.to_string_lossy().to_string()]).unwrap();- assert!(h.step_until(Duration::from_secs(60), |h| h.app.import.as_ref().is_some_and(|t| t.imported >= 2)));+ assert!(h.step_until(t(), |h| h.app.import.as_ref().is_some_and(|t| t.imported >= 2))); // the newest photo so far, never the import's first let chosen = h.app.session.catalog.photos().map(|p| p.id).max().expect("photos arrived");- let r = h.request("engine.execute", json!({"command": "library.select", "params": {"ids": [chosen.0]}}), T);+ let r = h.request("engine.execute", json!({"command": "library.select", "params": {"ids": [chosen.0]}}), t()); assert_eq!(r["ok"], true, "{r}"); // held at the gate until now, so the import cannot have ended however slowly the frames ran assert!(h.app.import.is_some(), "still importing"); gate.store(true, std::sync::atomic::Ordering::Release);- assert!(h.step_until(Duration::from_secs(60), |h| h.app.import.is_none()));+ assert!(h.step_until(t(), |h| h.app.import.is_none())); assert_eq!(h.app.session.catalog.len(), 20, "all imported"); assert_eq!(h.app.session.selection.active, Some(chosen)); let _ = std::fs::remove_dir_all(&dir);@@ -330,7 +368,7 @@ fn scan_shows_a_row_and_cancel_closes_it() { assert!(tasks[0].cancellable); h.app.session.activity.cancel(tasks[0].id).unwrap(); // like the old Cancel: the scan is dropped at once, without waiting for the file being read- assert!(h.step_until(Duration::from_secs(10), |h| h.app.scan.is_none()));+ assert!(h.step_until(stretched(Duration::from_secs(10)), |h| h.app.scan.is_none())); assert!(h.app.session.activity.list().is_empty()); for _ in 0..3 { h.step();@@ -356,7 +394,7 @@ fn bracket(tag: &str) -> (Headless, std::path::PathBuf) { session.execute("library.select", &json!({"ids": ids})).unwrap(); let app = LightcraftApp::new(session, Services { png: None, ..Default::default() }); let mut h = Headless::new(app, [1200.0, 800.0], 1.0);- h.settle(T);+ h.settle(t()); (h, dir) } @@ -372,7 +410,7 @@ fn final_merge_shows_a_row_and_cancels() { assert!(rows[0].cancellable); assert_eq!(rows[0].total, 1000); h.app.session.activity.cancel(rows[0].id).unwrap();- assert!(h.step_until(T, |h| h.app.merge.final_task.is_none()));+ assert!(h.step_until(t(), |h| h.app.merge.final_task.is_none())); assert!(h.app.merge.last_result.is_none(), "nothing merged"); assert_eq!(h.app.session.catalog.len(), before, "no photo added"); assert!(h.app.session.activity.list().is_empty());@@ -397,7 +435,7 @@ fn merge_dialog_remembers_the_last_settings_per_kind() { crate::merge::start_final(&mut h.app, &opts).unwrap(); let row = h.app.session.activity.list()[0].id; h.app.session.activity.cancel(row).unwrap();- assert!(h.step_until(T, |h| h.app.merge.final_task.is_none()));+ assert!(h.step_until(t(), |h| h.app.merge.final_task.is_none())); crate::merge::open(&mut h.app, "merge.hdr").unwrap(); let Some(crate::state::Dialog::Merge { opts: shown }) = &h.app.ui.dialog else { panic!("no merge dialog") }; assert_eq!(shown, &opts);@@ -443,21 +481,21 @@ fn batch_merge_runs_each_set_in_turn() { let app = LightcraftApp::new(session, Services { png: None, ..Default::default() }); let mut h = Headless::new(app, [1200.0, 800.0], 1.0); // the merge ordering does not need the grid's nine thumbnails; one Detail render is enough- let r = h.request("ui.set", json!({"view": "detail", "filmstrip": false}), T);+ let r = h.request("ui.set", json!({"view": "detail", "filmstrip": false}), t()); assert_eq!(r["ok"], true, "{r}");- assert!(h.settle(T), "the imported photos and the active preview settle");+ assert!(h.settle(t()), "the imported photos and the active preview settle"); let r = crate::menus::run_ui_command(&mut h.app, "merge.hdrBatch", &json!({})).unwrap().unwrap(); assert_eq!(r["sets"], 3); assert_eq!(h.app.merge.batch.len(), 2, "one running, two queued"); let rows = h.app.session.activity.list(); assert_eq!((rows.len(), rows.first().map(|r| r.kind)), (1, Some("merge"))); // the first merge finishes and the second starts by itself- assert!(h.step_until(T, |h| h.app.merge.batch.len() == 1 && h.app.merge.final_task.is_some()));+ assert!(h.step_until(t(), |h| h.app.merge.batch.len() == 1 && h.app.merge.final_task.is_some())); assert_eq!(h.app.session.catalog.len(), 10); // cancelling the second drops the third let rows = h.app.session.activity.list(); h.app.session.activity.cancel(rows[0].id).unwrap();- assert!(h.step_until(T, |h| h.app.merge.final_task.is_none()));+ assert!(h.step_until(t(), |h| h.app.merge.final_task.is_none())); assert!(h.app.merge.batch.is_empty()); assert_eq!(h.app.session.catalog.len(), 10, "nothing more merged"); assert!(h.app.session.activity.list().is_empty());@@ -477,7 +515,7 @@ fn find_missing_shows_an_indeterminate_row() { assert_eq!(rows.len(), 1, "{rows:?}"); assert_eq!((rows[0].kind, rows[0].label.as_str()), ("findMissing", "Find Missing Photos")); assert_eq!((rows[0].total, rows[0].cancellable), (0, false), "indeterminate, no ✕");- assert!(h.step_until(T, |h| h.app.tasks.is_empty()));+ assert!(h.step_until(t(), |h| h.app.tasks.is_empty())); assert!(h.app.session.activity.list().is_empty(), "the row goes with the task"); let _ = std::fs::remove_dir_all(dir); }@@ -489,7 +527,7 @@ fn auto_import_listing_has_no_row() { std::fs::create_dir_all(&dir).unwrap(); h.app.session.import_defaults.auto_folder = Some(dir.to_string_lossy().to_string()); // the watched folder is listed every few seconds, quietly- assert!(h.step_until(Duration::from_secs(10), |h| h.app.tasks.is_running("Auto Import")));+ assert!(h.step_until(stretched(Duration::from_secs(10)), |h| h.app.tasks.is_running("Auto Import"))); assert!(h.app.session.activity.list().is_empty(), "{:?}", h.app.session.activity.list()); h.app.session.import_defaults.auto_folder = None; let _ = std::fs::remove_dir_all(dir);@@ -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();@@ -450,7 +450,11 @@ mod tests { let open: Vec<u64> = (0..200u64).map(|f| f * 101 + 1).collect(); assert_eq!(visible_tree(&v, &open).len(), v.len()); assert_eq!(search(&v, "folder 7 wedding").len(), want);- assert!(start.elapsed() < std::time::Duration::from_secs(1), "took {:?}", start.elapsed());+ // a regression guard, not a speed measurement: this takes some 20 ms in a debug build; a path+ // worked out per row by scanning every album takes seconds (stretched by LIGHTCRAFT_TIME_SCALE,+ // never shrunk below 1 s)+ let limit = lightcraft_testkit::scaled(std::time::Duration::from_secs(1)).max(std::time::Duration::from_secs(1));+ assert!(start.elapsed() < limit, "took {:?}", start.elapsed()); } /// Every word typed is in the album's path (folders included), in any case; names that start@@ -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) |