Merge pull request #4473 from dotCooCoo/fix/more-load-sensitive-tests

Tests: the MCP concurrency, folder search and artboard export tests pass on a loaded machine

crates/engine/src/cmd/findfiles/tests.rs

@@ -66,9 +66,14 @@ fn rules(root: &Path) -> Rules {
     Rules { home: Some(root.join("Users/me")), user_content: vec![root.to_path_buf()], refused: vec![root.join("refused")] }
 }
 
-/// The search's progress once it ended (or after 10 seconds).
+/// How long a test waits for a search to end or to read a file. The wait only ends a test whose
+/// search never ends. A machine busy with other builds can hold a walker for seconds. It is shorter than a
+/// search's default 60 s deadline, which would end a search that does not end by itself.
+const WAIT: Duration = Duration::from_secs(30);
+
+/// The search's progress once it ended (or after [`WAIT`]).
 fn wait(s: &Search) -> Progress {
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     loop {
         let p = s.progress();
         if p.end.is_some() || Instant::now() > until {
@@ -205,14 +210,17 @@ fn the_search_ends_at_its_limits_and_when_stopped() {
 fn the_search_answers_at_its_deadline_while_a_walker_is_blocked() {
     let root = tree("blocked", &["f.ttf"]);
     let (tx, rx) = mpsc::channel();
+    let started = Instant::now();
     let s = begin(root.clone(), rules(&root), Limits { seconds: 0.2, ..Limits::default() }, 1, 1, Arc::new(Blocked(Mutex::new(rx))));
     std::thread::sleep(Duration::from_millis(300));
     let p = s.progress();
+    // The search ended when it answered, and it ran no longer than the test has waited.
+    let waited = started.elapsed().as_secs_f64();
     assert_eq!((p.state(), p.stopped()), ("stopped", Some("time")), "{p:?}");
-    assert!(p.seconds >= 0.2 && p.seconds < 5.0, "{p:?}");
+    assert!(p.seconds >= 0.2 && p.seconds <= waited, "{p:?}, {waited} s");
     let (tx2, rx2) = mpsc::channel();
     let s2 = begin(root.clone(), rules(&root), Limits::default(), 1, 1, Arc::new(Blocked(Mutex::new(rx2))));
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     while s2.progress().read == 0 && Instant::now() < until {
         std::thread::sleep(Duration::from_millis(2));
     }
@@ -246,7 +254,7 @@ fn files_found_are_kept_as_they_are_read() {
     let root = tree("kept", &["a.ttf", "b.ttf", "c.ttf"]);
     let (tx, rx) = mpsc::channel();
     let s = begin(root.clone(), rules(&root), Limits::default(), 1, 2, Arc::new(SecondBlocks(Mutex::new((0, rx)))));
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     while s.progress().read < 2 && Instant::now() < until {
         std::thread::sleep(Duration::from_millis(2));
     }
@@ -426,7 +434,7 @@ fn a_search_starts_with_the_threads_left_and_fails_when_none_is() {
     assert_eq!(c.err().as_deref(), Some("the search couldn't start: try again in a moment"));
     drop((tx_a, tx_b));
     assert_eq!((wait(&a).end, wait(&b).end), (Some(End::Done), Some(End::Done)));
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     while POOL.live() > 0 && Instant::now() < until {
         std::thread::sleep(Duration::from_millis(2));
     }

crates/engine/src/tests/fontfiles.rs

@@ -30,9 +30,14 @@ fn session_for(root: &Path) -> Session {
     s
 }
 
-/// `text.findFontFiles {}` once the search ended (10 seconds at most).
+/// How long a test waits for a search to end or to read a file. The wait only ends a test whose
+/// search never ends. A machine busy with other builds can hold a walker for seconds. It is shorter than a
+/// search's default `maxSeconds` of 60, which would end a search that does not end by itself.
+const WAIT: Duration = Duration::from_secs(30);
+
+/// `text.findFontFiles {}` once the search ended ([`WAIT`] at most).
 fn finished(s: &mut Session) -> Value {
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     loop {
         let r = s.execute("text.findFontFiles", &json!({})).unwrap();
         if r["state"] != "searching" || Instant::now() > until {
@@ -262,7 +267,7 @@ fn stop_ends_only_the_search_it_names() {
     let search = findfiles::start(root.clone(), s.search_rules.clone(), Limits::default(), 1, 1, Arc::new(Blocked(Mutex::new(rx)))).unwrap();
     let fonts = vec![Sought { family: "A".into(), style: "Regular".into(), status: FontMatch::Missing }];
     s.font_search = Some(FontSearch { id: 7, folder: root.to_string_lossy().into_owned(), fonts, search });
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     while s.execute("text.findFontFiles", &json!({})).unwrap()["searched"]["fontFiles"] != 1 && Instant::now() < until {
         std::thread::sleep(Duration::from_millis(2));
     }

crates/engine/src/tests/linkfiles.rs

@@ -42,9 +42,14 @@ fn placed(s: &mut Session, path: &Path) -> u64 {
     place(s, &path.to_string_lossy()).0
 }
 
-/// `links.findFiles {}` once the search ended (10 seconds at most).
+/// How long a test waits for a search to end or to read a file. The wait only ends a test whose
+/// search never ends. A machine busy with other builds can hold a walker for seconds. It is shorter than a
+/// search's default `maxSeconds` of 60, which would end a search that does not end by itself.
+const WAIT: Duration = Duration::from_secs(30);
+
+/// `links.findFiles {}` once the search ended ([`WAIT`] at most).
 fn finished(s: &mut Session) -> Value {
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     loop {
         let r = s.execute("links.findFiles", &json!({})).unwrap();
         if r["state"] != "searching" || Instant::now() > until {
@@ -206,7 +211,7 @@ fn stop_ends_only_the_search_it_names() {
     let search = findfiles::start(root.clone(), s.search_rules.clone(), Limits::default(), 1, 2, Arc::new(Blocked(Mutex::new(rx)))).unwrap();
     let links = vec![Sought { name: "a.png".into(), path: "/gone/a.png".into(), ids: vec![], size: None, hash: None }];
     s.link_search = Some(LinkSearch { id: 7, folder: root.to_string_lossy().into_owned(), links, sizes: Arc::default(), search });
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     while s.execute("links.findFiles", &json!({})).unwrap()["searched"]["read"] != 1 && Instant::now() < until {
         std::thread::sleep(Duration::from_millis(2));
     }

crates/engine/tests/font_folder.rs

@@ -10,9 +10,14 @@ use serde_json::{Value, json};
 use vectorcraft_engine::Session;
 use vectorcraft_engine::cmd::findfiles::{Rules, plain};
 
-/// `text.findFontFiles {}` once the search ended (10 seconds at most).
+/// How long the test waits for a search to end. The wait only ends the test if the search never
+/// ends. A machine busy with other builds can hold a walker for seconds. It is shorter than a search's
+/// default `maxSeconds` of 60, which would end a search that does not end by itself.
+const WAIT: Duration = Duration::from_secs(30);
+
+/// `text.findFontFiles {}` once the search ended ([`WAIT`] at most).
 fn finished(s: &mut Session) -> Value {
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     loop {
         let r = s.execute("text.findFontFiles", &json!({})).unwrap();
         if r["state"] != "searching" || Instant::now() > until {

crates/mcp/src/tests/concurrency.rs

@@ -144,18 +144,22 @@ impl Rig {
     }
 }
 
-const LONG: Duration = Duration::from_secs(20);
-const QUICK: Duration = Duration::from_secs(3);
+/// How long a test waits for the server to start a command, to answer or to log. The wait only ends
+/// a test whose server never does. A machine busy with other builds can hold a thread for seconds.
+const WAIT: Duration = Duration::from_secs(20);
+/// How long [`Slow`]'s long command runs unless it is cancelled: longer than [`WAIT`], so a request
+/// that waits behind it is not answered within the wait.
+const LONG: Duration = Duration::from_secs(60);
 
 #[test]
 fn ping_is_answered_while_a_command_runs() {
     let mut rig = Rig::new(LONG, Duration::from_millis(50));
     rig.run(1, "document.export");
-    assert_eq!(rig.started.recv_timeout(QUICK).unwrap(), "document.export");
+    assert_eq!(rig.started.recv_timeout(WAIT).unwrap(), "document.export");
     // Past `busy_after` the call counts as long-running.
     std::thread::sleep(Duration::from_millis(120));
     rig.request(2, "ping", json!({}));
-    let pong = rig.reply(2, QUICK).expect("ping must not wait for the running command");
+    let pong = rig.reply(2, WAIT).expect("ping must not wait for the running command");
     assert_eq!(pong["result"], json!({}));
     rig.notify("notifications/cancelled", json!({"requestId": 1}));
     rig.finish();
@@ -165,11 +169,11 @@ fn ping_is_answered_while_a_command_runs() {
 fn cancelling_stops_the_running_command_and_sends_no_reply() {
     let mut rig = Rig::new(LONG, Duration::from_secs(60));
     rig.run(1, "document.export");
-    rig.started.recv_timeout(QUICK).unwrap();
+    rig.started.recv_timeout(WAIT).unwrap();
     rig.notify("notifications/cancelled", json!({"requestId": 1, "reason": "user"}));
     // The engine is free again: the next command runs and answers.
     rig.run(2, "pdf.preset.list");
-    let end = Instant::now() + QUICK;
+    let end = Instant::now() + WAIT;
     loop {
         if rig.log.lock().unwrap().iter().any(|l| l == "cancelled document.export") {
             break;
@@ -187,10 +191,10 @@ fn cancelling_stops_the_running_command_and_sends_no_reply() {
 fn a_request_that_would_wait_behind_a_long_call_is_refused_as_busy() {
     let mut rig = Rig::new(LONG, Duration::from_millis(50));
     rig.run(1, "document.export");
-    rig.started.recv_timeout(QUICK).unwrap();
+    rig.started.recv_timeout(WAIT).unwrap();
     std::thread::sleep(Duration::from_millis(120));
     rig.run(2, "pdf.preset.list");
-    let busy = rig.reply(2, QUICK).expect("a busy answer, not a wait");
+    let busy = rig.reply(2, WAIT).expect("a busy answer, not a wait");
     assert_eq!(busy["error"]["code"], -32003, "{busy}");
     assert!(busy["error"]["message"].as_str().unwrap().contains("document.export"), "{busy}");
     assert_eq!(busy["error"]["data"]["busy"]["requestId"], "1", "{busy}");
@@ -208,7 +212,7 @@ fn quick_calls_pipelined_together_queue_and_answer_in_order() {
         rig.run(id, &format!("cmd{id}"));
     }
     for id in 1..=4 {
-        let r = rig.reply(id, QUICK).unwrap_or_else(|| panic!("no reply to {id}"));
+        let r = rig.reply(id, WAIT).unwrap_or_else(|| panic!("no reply to {id}"));
         assert!(r.get("error").is_none(), "{r}");
     }
     assert_eq!(*rig.log.lock().unwrap(), ["done cmd1", "done cmd2", "done cmd3", "done cmd4"]);
@@ -219,13 +223,13 @@ fn quick_calls_pipelined_together_queue_and_answer_in_order() {
 fn a_queued_request_that_is_cancelled_never_runs() {
     let mut rig = Rig::new(LONG, Duration::from_secs(60));
     rig.run(1, "document.export");
-    rig.started.recv_timeout(QUICK).unwrap();
+    rig.started.recv_timeout(WAIT).unwrap();
     rig.run(2, "never.runs");
     rig.run(3, "quick.last");
     // Request 2 may not have been read yet when the cancel is: it is the order of lines that counts.
     rig.notify("notifications/cancelled", json!({"requestId": 2}));
     rig.notify("notifications/cancelled", json!({"requestId": 1}));
-    let r = rig.reply(3, QUICK).expect("the engine goes on to the next request");
+    let r = rig.reply(3, WAIT).expect("the engine goes on to the next request");
     assert!(r.get("error").is_none(), "{r}");
     rig.notify("notifications/cancelled", json!({"requestId": 3}));
     let log = rig.log.lock().unwrap().clone();
@@ -239,13 +243,13 @@ fn a_queued_request_that_is_cancelled_never_runs() {
 fn cancelling_an_unknown_or_finished_request_changes_nothing() {
     let mut rig = Rig::new(Duration::from_millis(10), Duration::from_secs(60));
     rig.run(1, "quick");
-    assert!(rig.reply(1, QUICK).unwrap().get("result").is_some());
+    assert!(rig.reply(1, WAIT).unwrap().get("result").is_some());
     rig.notify("notifications/cancelled", json!({"requestId": 1}));
     rig.notify("notifications/cancelled", json!({"requestId": 99}));
     rig.notify("notifications/cancelled", json!({"requestId": [1], "reason": "junk"}));
     rig.notify("notifications/cancelled", json!("junk"));
     rig.run(2, "quick");
-    assert!(rig.reply(2, QUICK).unwrap().get("result").is_some());
+    assert!(rig.reply(2, WAIT).unwrap().get("result").is_some());
     rig.finish();
 }
 
@@ -254,7 +258,7 @@ fn initialize_cannot_be_cancelled() {
     let mut rig = Rig::new(LONG, Duration::from_secs(60));
     rig.request(1, "initialize", json!({}));
     rig.notify("notifications/cancelled", json!({"requestId": 1}));
-    assert!(rig.reply(1, QUICK).unwrap().get("result").is_some());
+    assert!(rig.reply(1, WAIT).unwrap().get("result").is_some());
     rig.finish();
 }
 
@@ -264,7 +268,7 @@ fn progress_reaches_a_client_that_gave_a_token_before_the_reply() {
     rig.request(1, "tools/call", json!({"name": "command_run", "arguments": {"id": "progress.demo"}, "_meta": {"progressToken": "tok"}}));
     let mut seen = vec![];
     let reply = loop {
-        let v = rig.next(QUICK).expect("a reply");
+        let v = rig.next(WAIT).expect("a reply");
         if v["method"] == "notifications/progress" {
             seen.push(v["params"].clone());
         } else {
@@ -279,7 +283,7 @@ fn progress_reaches_a_client_that_gave_a_token_before_the_reply() {
     assert_eq!(seen[1]["message"], "page 2");
     // Without a token nothing is sent.
     rig.run(2, "progress.demo");
-    let next = rig.next(QUICK).unwrap();
+    let next = rig.next(WAIT).unwrap();
     assert_eq!(next["id"], 2, "{next}");
     rig.finish();
 }
@@ -321,16 +325,18 @@ fn a_cancelled_export_through_the_real_engine_writes_nothing_and_leaves_the_sess
     let (started_tx, started) = mpsc::channel();
     let thread = std::thread::spawn(move || {
         let backend = Gated { inner: crate::Headless::with_document(), started: started_tx };
-        Server::new(Box::new(backend)).serve(BufReader::new(read), Lines(tx, vec![])).unwrap();
+        // Request 2 waits for the cancelled export to return, also when the export ran past the
+        // default busy limit (2 s) before it saw the cancel.
+        Server::new(Box::new(backend)).with_busy_after(Duration::from_secs(60)).serve(BufReader::new(read), Lines(tx, vec![])).unwrap();
     });
     let send = |w: &mut std::io::PipeWriter, v: Value| writeln!(w, "{v}").unwrap();
     let params = json!({"name": "command_run", "arguments": {"id": "document.export", "params": {"path": path.to_str().unwrap()}}});
     send(&mut to_server, json!({"jsonrpc": "2.0", "id": 1, "method": "tools/call", "params": params}));
-    started.recv_timeout(QUICK).unwrap();
+    started.recv_timeout(WAIT).unwrap();
     send(&mut to_server, json!({"jsonrpc": "2.0", "method": "notifications/cancelled", "params": {"requestId": 1}}));
     // The next request is answered: the cancelled export neither blocks nor breaks the engine.
     send(&mut to_server, json!({"jsonrpc": "2.0", "id": 2, "method": "tools/call", "params": {"name": "doc_inspect", "arguments": {}}}));
-    let reply: Value = serde_json::from_str(&replies.recv_timeout(QUICK).unwrap()).unwrap();
+    let reply: Value = serde_json::from_str(&replies.recv_timeout(WAIT).unwrap()).unwrap();
     assert_eq!(reply["id"], 2, "request 1 is not answered: {reply}");
     assert_eq!(reply["result"]["isError"], false, "{reply}");
     assert!(!path.exists(), "a cancelled export writes no file");
@@ -344,12 +350,13 @@ fn a_remote_call_stops_waiting_for_the_app_when_cancelled() {
     let listener = std::net::TcpListener::bind("127.0.0.1:0").unwrap();
     let addr = listener.local_addr().unwrap().to_string();
     // An app that takes the request and never answers.
+    let (done, held) = mpsc::channel::<()>();
     let app = std::thread::spawn(move || {
         let (conn, _) = listener.accept().unwrap();
         let mut line = String::new();
         BufReader::new(conn.try_clone().unwrap()).read_line(&mut line).unwrap();
-        // Hold the connection open until the test is done with it.
-        std::thread::sleep(Duration::from_secs(3));
+        // Hold the connection open until the test is done with it (or for `WAIT`).
+        let _ = held.recv_timeout(WAIT);
         drop(conn);
     });
     let mut remote = crate::Remote::connect(&addr).unwrap();
@@ -359,10 +366,11 @@ fn a_remote_call_stops_waiting_for_the_app_when_cancelled() {
         std::thread::sleep(Duration::from_millis(200));
         raise.cancel();
     });
-    let start = Instant::now();
     let r = cancel::scope(&token, None, || remote.call("engine.execute", json!({"command": "document.export"})));
     let why = r.unwrap_err();
     assert!(why.contains("cancelled"), "{why}");
-    assert!(start.elapsed() < Duration::from_secs(2), "returned when cancelled, not when the app answered");
+    // The app still holds the connection open.
+    assert!(!app.is_finished(), "returned when cancelled, not when the app answered");
+    done.send(()).ok();
     app.join().unwrap();
 }

crates/ui-egui/src/dialogs/find_links/tests.rs

@@ -67,9 +67,14 @@ fn opened_without(app: &mut VectorcraftApp, root: &Path, names: &[&str]) -> Vec<
     files
 }
 
-/// Draw the dialog until its search ends (10 seconds at most).
+/// How long a test waits for the dialog's search to end. The wait only ends a test whose search
+/// never ends. A machine busy with other builds can hold a walker for seconds. It is shorter than a
+/// search's default `maxSeconds` of 60, which would end a search that does not end by itself.
+const WAIT: Duration = Duration::from_secs(30);
+
+/// Draw the dialog until its search ends ([`WAIT`] at most).
 fn searched(app: &mut VectorcraftApp) {
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     while app.ui.dialog.as_ref().is_some_and(|d| d.str("state") == "searching") && Instant::now() < until {
         frame(app);
         std::thread::sleep(Duration::from_millis(5));

crates/ui-egui/src/dialogs/missing_fonts/tests.rs

@@ -55,6 +55,11 @@ fn open(app: &mut VectorcraftApp, path: &Path) {
     crate::io::open_path(app, &path.to_string_lossy()).unwrap();
 }
 
+/// How long a test waits for the dialog's search to end. The wait only ends a test whose search
+/// never ends. A machine busy with other builds can hold a walker for seconds. It is shorter than a
+/// search's default `maxSeconds` of 60, which would end a search that does not end by itself.
+const WAIT: Duration = Duration::from_secs(30);
+
 fn kind(app: &VectorcraftApp) -> Option<&str> {
     app.ui.dialog.as_ref().map(|d| d.kind.as_str())
 }
@@ -101,7 +106,7 @@ fn the_documents_fonts_folder_is_offered_and_searched_off_the_ui_thread() {
     let r = super::super::confirm(&mut app).unwrap();
     assert!(matches!(r["state"].as_str(), Some("searching" | "done")), "{r}");
     assert_eq!(kind(&app), Some(KIND), "the dialog stays open while it searches");
-    let until = Instant::now() + Duration::from_secs(10);
+    let until = Instant::now() + WAIT;
     while app.ui.dialog.as_ref().is_some_and(|d| d.str("state") == "searching") && Instant::now() < until {
         frame(&mut app);
         std::thread::sleep(Duration::from_millis(5));