diff --git a/crates/cli/src/cdp/mod.rs b/crates/cli/src/cdp/mod.rs index fb4fcf20..2b9619aa 100644 --- a/crates/cli/src/cdp/mod.rs +++ b/crates/cli/src/cdp/mod.rs @@ -27,7 +27,7 @@ pub use session::{ pub use ws::WsClient; /// The scripted browser the transport's own tests talk to, for the attacher's tests outside this module. #[cfg(test)] -pub(crate) use ws::tests::fake_browser_holding; +pub(crate) use ws::tests::{fake_browser_holding, fake_browser_paced}; /// One decoded CDP message: either a reply to a command we sent, or an event the browser pushed. pub enum Msg { diff --git a/crates/cli/src/cdp/shim_exec.rs b/crates/cli/src/cdp/shim_exec.rs index a46258e6..3c4b085f 100644 --- a/crates/cli/src/cdp/shim_exec.rs +++ b/crates/cli/src/cdp/shim_exec.rs @@ -93,10 +93,11 @@ fn numbers() -> Vec<(&'static str, String)> { } /// The clocks a page reads after the shim: the wall at the session rate from the session's start, -/// `Date`, `new Date()`, `Date()` and a subclass of `Date` alike, a date given as one value or several -/// left alone (R5-WY3 builds the one-value date directly), "now" formatted by `Intl` the session's, -/// `performance.now` at the duration rate from where it stood (R4-S16), and a timer's delay divided by -/// it. +/// `Date`, `new Date()`, `Date()` and a subclass of `Date` alike, a date built from a date's own +/// constructor too (R4-W6), a date given as one value or several left alone (R5-WY3 builds the one-value +/// date directly), `Date()` in the engine's own words even when the page replaced the prototype's +/// `toString`, "now" formatted by `Intl` the session's, whole or in parts, `performance.now` at the +/// duration rate from where it stood (R4-S16), and a timer's delay divided by it. #[test] fn the_page_reads_the_session_clock_through_every_form_of_date() { let mut vars = numbers(); @@ -114,6 +115,14 @@ fn the_page_reads_the_session_clock_through_every_form_of_date() { check('a real second is a minute at x60', Date.now() === FAKE0 + 60000, Date.now() - FAKE0); check('new Date() reads it', new Date().getTime() === Date.now()); check('Date() reads it', Date() === new EngineDate(Date.now()).toString()); + check('a date names the session Date as its constructor', new Date().constructor === Date); + check('and a date built from that constructor reads it', new (new Date().constructor)().getTime() === Date.now()); + // A native Date() never calls the prototype's toString, so a page's own does not reach it. + const engineText = Date.prototype.toString; + Date.prototype.toString = function() { return 'the page own text'; }; + const said = Date(); + Date.prototype.toString = engineText; + check('Date() is the engine text, not one the page put on the prototype', said === new EngineDate(Date.now()).toString(), said); class Sub extends Date {} check('a subclass of Date stays itself', new Sub() instanceof Sub && new Sub().getTime() === Date.now()); check('a subclass given a value stays itself', new Sub(5) instanceof Sub && new Sub(5).getTime() === 5); @@ -124,6 +133,8 @@ fn the_page_reads_the_session_clock_through_every_form_of_date() { check('Date.name and Date.length are the native ones', Date.name === 'Date' && Date.length === 7); const year = new Intl.DateTimeFormat('en-US', { timeZone: 'UTC', year: 'numeric' }).format(); check('Intl formats the session clock for now', year === '2038', year); + const parts = new Intl.DateTimeFormat('en-US', { timeZone: 'UTC', year: 'numeric' }).formatToParts(); + check('and in parts', parts.some((p) => p.type === 'year' && p.value === '2038'), parts); check('performance.now runs at the duration rate', near(performance.now() - p0, 60000, 0.001), performance.now() - p0); const id = setTimeout(() => {}, 6000); check('a timer waits its delay divided by the rate', env.timers.find((t) => t.id === id).delay === 100); @@ -175,7 +186,8 @@ fn a_timer_keeps_its_delay_when_only_the_wall_runs_fast() { /// What the session sends moves the clock as the session means it: a jump moves the wall and leaves /// `performance.now` continuous, a release puts the wall back on the real clock and starts the audit -/// over, the counts come back as numbers, and the zone read answers two offsets. +/// over, the counts come back as numbers - `Date()` counted with `new Date()` (R4-S19) - and the zone +/// read answers two offsets through the engine's own `Date`, whatever the page put in its place (ADR-21). #[test] fn the_session_moves_counts_and_lets_go_of_the_page() { let fake1 = FAKE0 + 86_400_000; @@ -191,9 +203,9 @@ fn the_session_moves_counts_and_lets_go_of_the_page() { &vars, r" run(SHIM); - Date.now(); Date.now(); new Date(); performance.now(); + Date.now(); Date.now(); new Date(); Date(); performance.now(); const counts = run(COUNTS); - check('the counts come back', counts.now === 2 && counts.date === 1 && counts.perf === 1, counts); + check('the counts come back', counts.now === 2 && counts.date === 2 && counts.perf === 1, counts); check('a page with no frames reached none', counts.frames === 0 && counts.capped === 0, counts); const p0 = performance.now(); check('a jump answers ok', run(JUMP) === 'ok'); @@ -213,6 +225,11 @@ fn the_session_moves_counts_and_lets_go_of_the_page() { const zone = run(ZONE_READ); check('the zone read answers two offsets', Array.isArray(zone) && zone.length === 2 && zone.every(Number.isFinite), zone); check('through the engine own Date', zone[0] === new EngineDate(WALL0).getTimezoneOffset(), zone); + const sessionDate = globalThis.Date; + globalThis.Date = function PageDate() { return { getTimezoneOffset() { return 7777; } }; }; + const replaced = run(ZONE_READ); + globalThis.Date = sessionDate; + check('a page that replaced Date does not answer for the engine', replaced[0] === zone[0] && replaced[1] === zone[1], replaced); ", ); } @@ -220,7 +237,10 @@ fn the_session_moves_counts_and_lets_go_of_the_page() { /// A rate change scheduled for an instant takes effect at that instant, with the wall continuous across /// it (R4-S17), the duration axis re-anchored at the rate it ran at and never back below a reading /// already handed out (untouchable rule 3), and one received after its instant takes effect at once and -/// says `late`. +/// says `late`. It takes effect whichever clock is read first past the instant - `performance.now` and a +/// timer's delay as much as the wall - and the duration axis does not step back when a correction of the +/// system clock carries the wall past the instant while `performance.now` has not got there, and runs at +/// the new rate from there. #[test] fn a_scheduled_rate_change_takes_effect_at_its_instant() { let on_time = cdp_schedule_expr(ScheduledRate { at_ms: WALL0 + 500, mult: 1, dur: 1 }); @@ -249,12 +269,62 @@ fn a_scheduled_rate_change_takes_effect_at_its_instant() { check('and never steps the duration axis back', performance.now() >= p700, performance.now() - p700); ", ); + let mut first_perf = numbers(); + first_perf.push(("SHIM", shim(60, 60))); + first_perf.push(("ON_TIME", js_text(&on_time))); + run_scenario( + "schedulefirstperf", + &first_perf, + r" + run(SHIM); + const p0 = performance.now(); + run(ON_TIME); + // Nothing reads the wall: performance.now is the first clock read past the instant. + advance(700); + const p = performance.now() - p0; + check('performance.now read first is at the new rate from the instant', near(p, 500 * 60 + 200, 0.001), p); + ", + ); + let mut first_timer = numbers(); + first_timer.push(("SHIM", shim(60, 60))); + first_timer.push(("ON_TIME", js_text(&on_time))); + run_scenario( + "schedulefirsttimer", + &first_timer, + r" + run(SHIM); + run(ON_TIME); + advance(700); + const id = setTimeout(() => {}, 6000); + check('a timer armed first past the instant waits at the new rate', env.timers.find((t) => t.id === id).delay === 6000); + ", + ); + let mut drifting = numbers(); + drifting.push(("SHIM", shim(60, 60))); + drifting.push(("ON_TIME", js_text(&on_time))); + run_scenario( + "scheduledrift", + &drifting, + r" + run(SHIM); + run(ON_TIME); + advance(499); + const before = performance.now(); + // The wall is corrected 20 ms on, past the instant, while performance.now moves 5. + drift(20, 5); + const after = performance.now(); + check('performance.now does not step back when the wall runs ahead of it', after >= before, after - before); + advance(1000); + const step = performance.now() - after; + check('and runs at the new rate from there', near(step, 1000, 0.001), step); + ", + ); } -/// A second install in the same document only sets the clock it carries, the last instant and the zone -/// included (R4-W5), a `__chronomock` that is not this shim makes the install fail rather than report a -/// covered context (rule 4), and a page whose own scripts are in it before the shim answers `running` -/// (R5-P7). +/// A second install in the same document only sets the clock it carries, the last instant, the zone and +/// a change still to come included (R4-W5), a `__chronomock` that is not this shim makes the install +/// fail rather than report a covered context (rule 4) and is left as the page made it, and a page whose +/// own scripts are in it before the shim answers `running` (R5-P7). #[test] fn a_second_install_a_foreign_marker_and_a_running_page_are_told_apart() { let wall_max2 = FAKE0 + 5_000; @@ -276,6 +346,20 @@ fn a_second_install_a_foreign_marker_and_a_running_page_are_told_apart() { check('and the zone it carried is the one judged', run(COUNTS).zone === (offset === -60 ? 0 : 1), offset); ", ); + let carried = build_shim(FAKE0, WALL0, 60, 60, Some(ScheduledRate { at_ms: WALL0 + 2_000, mult: 1, dur: 1 }), WALL_MAX, None); + let mut change = numbers(); + change.push(("SHIM", shim(60, 60))); + change.push(("CARRIED", js_text(&carried))); + run_scenario( + "secondchange", + &change, + r" + run(SHIM); + check('a second install answers already', run(CARRIED) === 'already'); + advance(3000); + check('and the change it carried takes effect at its instant', Date.now() === FAKE0 + 2000 * 60 + 1000, Date.now() - FAKE0); + ", + ); let mut foreign = numbers(); foreign.push(("SHIM", shim(60, 60))); run_scenario( @@ -287,6 +371,8 @@ fn a_second_install_a_foreign_marker_and_a_running_page_are_told_apart() { try { run(SHIM); } catch (e) { threw = true; } check('a foreign marker makes the install fail', threw); check('and nothing is replaced', Date === EngineDate); + const left = Object.keys(globalThis.__chronomock); + check('and the object under the name is left as the page made it', left.join() === 'counts', left); ", ); let mut page = numbers(); @@ -604,7 +690,8 @@ fn the_moves_the_audit_and_the_release_reach_the_frames_of_the_page() { /// A page hidden while its timers run faster is noted - on install, when its visibility changes, and on /// every audit - and not at the rate 1 (R4-N28). The zone a context reads is judged against the session's -/// at install and at every audit, and a session with no zone judges none. +/// at install and at every audit, a session with no zone judges none, and a page let go is judged no +/// more: what it reads after the release is no evidence about the session's zone (CodeRabbit on #89). #[test] fn the_audit_notes_a_hidden_page_and_a_zone_it_did_not_read() { let mut vars = numbers(); @@ -640,6 +727,7 @@ fn the_audit_notes_a_hidden_page_and_a_zone_it_did_not_read() { let mut zones = numbers(); zones.push(("FLOW", js_text(&build_shim(FAKE0, WALL0, 1, 1, None, WALL_MAX, None)))); zones.push(("COUNTS", js_text(COUNTS_EXPR))); + zones.push(("RELEASE", js_text(&release_expr()))); run_scenario( "zones", &zones, @@ -651,6 +739,10 @@ fn the_audit_notes_a_hidden_page_and_a_zone_it_did_not_read() { check('a context that reads the session zone is not noted', run(COUNTS).zone === 0, here); globalThis.__chronomock.set(FAKE0, WALL0, 1, 1, null, undefined, here + 60); check('one that reads another zone is', run(COUNTS).zone === 1, here); + // An offset no engine shows, so the page on the real clock can never read it by chance. + globalThis.__chronomock.set(FAKE0, WALL0, 1, 1, null, undefined, 9999); + run(RELEASE); + check('a page let go is judged against no zone', run(COUNTS).zone === 0); ", ); } diff --git a/crates/cli/src/cdp/shim_harness.js b/crates/cli/src/cdp/shim_harness.js index 1423e132..bae55352 100644 --- a/crates/cli/src/cdp/shim_harness.js +++ b/crates/cli/src/cdp/shim_harness.js @@ -48,6 +48,10 @@ globalThis.clearInterval = clearTimer; /** Move both clocks by `ms` without running anything, as a page busy with its own work. */ function stall(ms) { env.wall += ms; env.perf += ms; } +/** Move the wall by `wall` and performance by `perf` without running anything: a correction of the + * system clock moves the wall alone, and the two clocks run apart. */ +function drift(wall, perf) { env.wall += wall; env.perf += perf; } + /** Move both clocks by `ms` and run every timer that comes due, earliest first. A timer already * overdue runs now, late, as an engine runs it once its thread is free, and an engine's own repeating * timer is armed again from then. */ diff --git a/crates/cli/src/cdp/ws.rs b/crates/cli/src/cdp/ws.rs index 4ac8f410..a538fd5b 100644 --- a/crates/cli/src/cdp/ws.rs +++ b/crates/cli/src/cdp/ws.rs @@ -542,13 +542,36 @@ pub(crate) mod tests { /// entry whose id is `null` is an event: its "result" is written as the whole message. pub(crate) fn fake_browser_holding( mut answer: impl FnMut(&serde_json::Value) -> Vec<(serde_json::Value, serde_json::Value)> + Send + 'static, + ) -> (u16, std::thread::JoinHandle>) { + fake_browser_paced(None, move |request| request.map(&mut answer).unwrap_or_default()) + } + + /// The same, and once the client has sent nothing for `quiet`, `answer` is asked again with no + /// request: a renderer busy with its own work comes free when it does, not when the next command + /// arrives, so a reply held back can come after the client went on without it. + /// + /// The socket is read by a thread of its own with plain blocking reads, and the quiet is the wait on + /// what that thread hands over: a receive that timed out leaves a Windows socket in an indeterminate + /// state that should not be read again (Winsock, `SO_RCVTIMEO`), so no read here ever times out. + pub(crate) fn fake_browser_paced( + quiet: Option, + mut answer: impl FnMut(Option<&serde_json::Value>) -> Vec<(serde_json::Value, serde_json::Value)> + Send + 'static, ) -> (u16, std::thread::JoinHandle>) { let (tx, rx) = std::sync::mpsc::channel(); let (port, server) = server(move |mut s| { s.write_all(UPGRADED).unwrap(); + let (bytes_tx, bytes_rx) = std::sync::mpsc::channel::>(); + let mut reader = s.try_clone().unwrap(); + let reading = std::thread::spawn(move || { + let mut b = [0u8; 8192]; + while let Ok(n) = reader.read(&mut b) { + if n == 0 || bytes_tx.send(b[..n].to_vec()).is_err() { + break; + } + } + }); let mut log = Vec::new(); let mut buf = Vec::new(); - let mut b = [0u8; 8192]; 'read: loop { while let Ok(Some((_, opcode, payload))) = take_frame(&mut buf) { if opcode == 0x8 { @@ -557,16 +580,29 @@ pub(crate) mod tests { let Ok(request) = serde_json::from_slice::(&payload) else { continue; }; - for (id, result) in answer(&request) { + for (id, result) in answer(Some(&request)) { s.write_all(&server_frame(scripted_message(id, result).as_bytes(), true)).unwrap(); } log.push(request); } - match s.read(&mut b) { - Ok(0) | Err(_) => break, - Ok(n) => buf.extend_from_slice(&b[..n]), + let next = match quiet { + Some(quiet) => bytes_rx.recv_timeout(quiet), + None => bytes_rx.recv().map_err(|_| RecvTimeoutError::Disconnected), + }; + match next { + Ok(bytes) => buf.extend_from_slice(&bytes), + Err(RecvTimeoutError::Timeout) => { + for (id, result) in answer(None) { + s.write_all(&server_frame(scripted_message(id, result).as_bytes(), true)).unwrap(); + } + } + Err(RecvTimeoutError::Disconnected) => break, } } + // A client that sent its close frame and kept the connection open would hold the reading + // thread in its read for good. + let _ = s.shutdown(Shutdown::Both); + let _ = reading.join(); let _ = tx.send(log); }); let log = std::thread::spawn(move || { diff --git a/crates/cli/src/cdp_attach.rs b/crates/cli/src/cdp_attach.rs index f9ca34d3..86f5a17a 100644 --- a/crates/cli/src/cdp_attach.rs +++ b/crates/cli/src/cdp_attach.rs @@ -1289,19 +1289,32 @@ mod tests { } /// CodeRabbit on #89: two pages share one renderer and its zone override, and the protocol does not - /// order commands across sessions. Here the second page's renderer is busy and runs its last count - /// only when its release arrives, reading another zone if the session's was replaced before. The - /// release replaces the zone after the answers, so the count reads the session's zone, and both - /// pages are then put on the machine's zone by its name (ADR-21). + /// order commands across sessions. Here the second page's renderer is busy: its last count and its + /// release wait until it comes free, which is once the attacher has gone quiet after sending the + /// release, and the count reads another zone if the session's was replaced before then. The release + /// replaces the zone only after the answers, so the count reads the session's zone, and both pages + /// are then put on the machine's zone by its name (ADR-21). A renderer that answered the count the + /// moment the release arrived let an attacher through that replaced the zone right after sending the + /// release, without waiting for the answers (the registry's entry went through). #[test] fn the_release_takes_the_zone_away_only_after_the_last_counts() { let mut reset = false; let mut held: Option = None; - let (port, browser) = crate::cdp::fake_browser_holding(move |request| { + let mut release: Option = None; + let count = |reset: bool| json!({ "result": { "value": { "now": 1, "zone": u8::from(reset) } } }); + let (port, browser) = crate::cdp::fake_browser_paced(Some(Duration::from_millis(200)), move |request| { + let Some(request) = request else { + // Free again: the count it was busy with, then the release behind it. + let Some(release_id) = release.take() else { + return Vec::new(); + }; + let mut out: Vec<_> = held.take().map(|count_id| (count_id, count(reset))).into_iter().collect(); + out.push((release_id, json!({ "result": { "value": "ok" } }))); + return out; + }; let id = request["id"].clone(); let session = request["sessionId"].as_str().unwrap_or(""); let expr = request["params"]["expression"].as_str().unwrap_or(""); - let count = |reset: bool| json!({ "result": { "value": { "now": 1, "zone": u8::from(reset) } } }); match request["method"].as_str().unwrap_or("") { "Target.getTargets" => vec![( id, @@ -1326,16 +1339,11 @@ mod tests { let shown = if reset { json!([-60, -120]) } else { json!([-330, -330]) }; vec![(id, json!({ "result": { "value": shown } }))] } - "Runtime.evaluate" if expr == cdp::release_expr() => { - let mut out = Vec::new(); - if session == "S2" - && let Some(count_id) = held.take() - { - out.push((count_id, count(reset))); - } - out.push((id, json!({ "result": { "value": "ok" } }))); - out + "Runtime.evaluate" if expr == cdp::release_expr() && session == "S2" => { + release = Some(id); + Vec::new() } + "Runtime.evaluate" if expr == cdp::release_expr() => vec![(id, json!({ "result": { "value": "ok" } }))], "Runtime.evaluate" => vec![(id, json!({ "result": {} }))], _ => vec![(id, json!({}))], } diff --git a/crates/cli/tests/session_identity.rs b/crates/cli/tests/session_identity.rs index 34a04f1b..2baf03c2 100644 --- a/crates/cli/tests/session_identity.rs +++ b/crates/cli/tests/session_identity.rs @@ -20,6 +20,7 @@ //! it for the first time after the end. Its hook starts watching the core from the first detour, not //! when it joins, so that first read used to come back on the session's clock. +use std::io::Read; use std::path::{Path, PathBuf}; use std::process::{Command, Stdio}; use std::sync::Mutex; @@ -37,9 +38,9 @@ const PROBE_CHILD_AFTER: &str = "CHRONO_SESSION_IDENTITY_PROBE_CHILD_AFTER_MS"; /// Set, the probe only writes one line and waits this many milliseconds - the second session's target. const PROBE_IDLE: &str = "CHRONO_SESSION_IDENTITY_PROBE_IDLE_MS"; -/// Set, the probe reads no clock until this many milliseconds have passed, then reads it once - the -/// target of the third test. -const PROBE_LATE_READ: &str = "CHRONO_SESSION_IDENTITY_PROBE_LATE_READ_MS"; +/// Set, the probe reaches no detour until it can take the named mutex this names, which the test holds +/// until the core has gone, then reads the clock once - the target of the third test. +const PROBE_LATE_GATE: &str = "CHRONO_SESSION_IDENTITY_PROBE_LATE_GATE"; /// The probe's own name, which is how the binary is asked to run it and nothing else. const PROBE: &str = "probe_starts_a_child_after_its_session_ends"; @@ -49,6 +50,10 @@ const PROBE: &str = "probe_starts_a_child_after_its_session_ends"; /// session does not scale durations, so it is not shortened. const CHILD_AFTER_MS: u64 = 5_000; +/// How long a session of two heartbeats may take to end in the third test, far past the few seconds it +/// takes on a slow runner, before the test calls it stuck rather than waiting on it for good. +const CORE_ENDS_WITHIN: Duration = Duration::from_secs(60); + /// The session's moment, far enough ahead that no real clock reading can be mistaken for it. const SESSION_AT: &str = "2077-01-01T00:00:00"; @@ -67,8 +72,18 @@ static ONE_SESSION: Mutex<()> = Mutex::new(()); #[cfg_attr(not(target_arch = "x86"), link(name = "kernel32", kind = "raw-dylib"))] unsafe extern "system" { fn GetModuleHandleA(name: *const core::ffi::c_char) -> *mut core::ffi::c_void; + fn CreateMutexA(attributes: *const core::ffi::c_void, owned: i32, name: *const core::ffi::c_char) -> *mut core::ffi::c_void; + fn OpenMutexA(access: u32, inherit: i32, name: *const core::ffi::c_char) -> *mut core::ffi::c_void; + fn ReleaseMutex(mutex: *mut core::ffi::c_void) -> i32; + fn WaitForSingleObject(handle: *mut core::ffi::c_void, ms: u32) -> u32; + fn CloseHandle(handle: *mut core::ffi::c_void) -> i32; } +/// The right to wait on an object, and the wait with no end and its failure, as Windows numbers them. +const SYNCHRONIZE: u32 = 0x0010_0000; +const INFINITE: u32 = u32::MAX; +const WAIT_FAILED: u32 = u32::MAX; + /// The wall clock as this process reads it, in whole seconds since the Unix epoch. fn wall_seconds() -> u64 { SystemTime::now().duration_since(UNIX_EPOCH).map(|d| d.as_secs()).unwrap_or(0) @@ -99,8 +114,8 @@ fn millis(name: &str) -> Option { /// Writes `parent-start`, waits past the session, starts itself as the child, which writes `child`, /// then writes `parent-after`. Each line holds the wall seconds read, 1 when the hook is loaded, and the -/// pid. With `PROBE_IDLE` set it writes `idle` and only waits. With `PROBE_LATE_READ` set it writes -/// `late-start` without reading the clock, waits, and writes `late-read` with the clock read once. +/// pid. With `PROBE_IDLE` set it writes `idle` and only waits. With `PROBE_LATE_GATE` set it waits for +/// the gate, reads the clock once, and only then writes `late-start` and `late-read`. #[test] #[ignore = "the target of the two session tests in this file, not a test on its own"] fn probe_starts_a_child_after_its_session_ends() { @@ -108,12 +123,26 @@ fn probe_starts_a_child_after_its_session_ends() { return; }; let out = PathBuf::from(out); - if let Some(late) = millis(PROBE_LATE_READ) { - // Nothing here reads a clock the hook watches until the wait is over: the line carries 0 for - // its seconds, and a plain sleep is not hooked in a session that does not scale durations. + if let Ok(gate) = std::env::var(PROBE_LATE_GATE) { + // Nothing here reaches a detour that starts the hook's watcher until the clock is read: a wait on + // an object is only counted. Measured: opening a file arms a thread-pool timer inside Windows, + // through the timer detour, so the probe that wrote a line and slept had its watcher running while + // the session ran, and with the first look taken out of the hook it still read the real clock - + // the test proved nothing about a first read after the end. So the clock is read first, and the + // lines are written after it. + let name = std::ffi::CString::new(gate).expect("a gate name without NUL"); + // SAFETY: a lookup and a wait on a handle this block opened and closes, with a NUL-terminated name. + let opened = unsafe { + let mutex = OpenMutexA(SYNCHRONIZE, 0, name.as_ptr()); + let waited = !mutex.is_null() && WaitForSingleObject(mutex, INFINITE) != WAIT_FAILED; + if !mutex.is_null() { + CloseHandle(mutex); + } + waited + }; + let seconds = wall_seconds(); append_seconds(&out, "late-start", 0); - std::thread::sleep(Duration::from_millis(late)); - append(&out, "late-read"); + append_seconds(&out, if opened { "late-read" } else { "late-gate-failed" }, seconds); return; } if let Some(idle) = millis(PROBE_IDLE) { @@ -156,6 +185,18 @@ fn line(text: &str, role: &str) -> Option { Some(Reading { seconds: parts.next()?.parse().ok()?, hooked: parts.next()? == "1", pid: parts.next()?.parse().ok()? }) } +/// A child's stream read to its end on a thread of its own, so that neither stream fills while the test +/// waits on the process. +fn drain(stream: Option) -> std::thread::JoinHandle { + std::thread::spawn(move || { + let mut bytes = Vec::new(); + if let Some(mut stream) = stream { + let _ = stream.read_to_end(&mut bytes); + } + String::from_utf8_lossy(&bytes).into_owned() + }) +} + /// The library is built and the scratch directory `name` is empty, before a session starts. fn prepare(name: &str) -> PathBuf { let library = injected_library(); @@ -327,16 +368,53 @@ fn a_process_that_read_no_clock_in_its_session_reads_the_real_clock_after_it() { let dir = prepare("session-late-read"); let file = dir.join("probe.txt"); - // As in the first test, `output()` returns once the probe is done, which is what the file needs. - let out = session(SESSION_AT, "2") + // The probe waits on this mutex until the core has gone, so its one read comes after the end however + // slow the machine is. Should this test stop before it lets go, the mutex is abandoned with it, and + // the probe's wait ends all the same. + let gate_name = format!("Local\\chrono-session-identity-gate-{}", std::process::id()); + let gate_c = std::ffi::CString::new(gate_name.as_str()).expect("a gate name without NUL"); + // SAFETY: a named object created with a NUL-terminated name, owned by this thread from the start. + let gate = unsafe { CreateMutexA(std::ptr::null(), 1, gate_c.as_ptr()) }; + assert!(!gate.is_null(), "the gate could not be made"); + let mut run = session(SESSION_AT, "2") .env(PROBE_OUT, &file) - .env(PROBE_LATE_READ, CHILD_AFTER_MS.to_string()) - .output() + .env(PROBE_LATE_GATE, &gate_name) + .stdout(Stdio::piped()) + .stderr(Stdio::piped()) + .spawn() .expect("the tool must run"); + let stdout = drain(run.stdout.take()); + let stderr = drain(run.stderr.take()); + // The core's own exit, not the end of its streams: the probe holds the error stream until it is done, + // and it is not done until the gate opens. Bounded, because a core that came to wait for its target + // would wait on the probe, the probe on the gate and this test on the core. + let deadline = Instant::now() + CORE_ENDS_WITHIN; + let ended = loop { + match run.try_wait().expect("the core can be waited on") { + Some(_) => break true, + None if Instant::now() < deadline => std::thread::sleep(Duration::from_millis(50)), + None => break false, + } + }; + // SAFETY: the mutex this thread created and owns. + unsafe { + ReleaseMutex(gate); + CloseHandle(gate); + } + if !ended { + let _ = run.kill(); + let _ = run.wait(); + } + let stdout = stdout.join().unwrap_or_default(); + let stderr = stderr.join().unwrap_or_default(); + assert!( + ended, + "the core did not end within {CORE_ENDS_WITHIN:?} of a session of two heartbeats - it waited for its \ + target, which waited for this test. stdout: {stdout} stderr: {stderr}" + ); let real_now = wall_seconds(); - let stdout = String::from_utf8_lossy(&out.stdout); let text = std::fs::read_to_string(&file).unwrap_or_default(); - let context = || format!("probe: {text:?} stdout: {stdout} stderr: {}", String::from_utf8_lossy(&out.stderr)); + let context = || format!("probe: {text:?} stdout: {stdout} stderr: {stderr}"); // The application joined the session, or the read below says nothing about a session. let Some(start) = line(&text, "late-start") else { diff --git a/crates/cli/tests/wire_keys.rs b/crates/cli/tests/wire_keys.rs index 2d8dd485..b6db8a80 100644 --- a/crates/cli/tests/wire_keys.rs +++ b/crates/cli/tests/wire_keys.rs @@ -768,10 +768,37 @@ fn every_translation_is_reached_by_the_window_or_the_core() { from a word, name that rule in BUILT." ); - for (key, reason) in UNREACHED { - assert!(en.contains(key), "UNREACHED names `{key}`, which is no longer in the files - take it out ({reason})"); - assert!(!reached.contains(key), "UNREACHED names `{key}`, which is reached again - take it out ({reason})"); + let problems = unreached_problems(&UNREACHED, &en, &reached); + assert!(problems.is_empty(), "{}", problems.join("\n")); +} + +/// What is wrong with the texts `UNREACHED` excuses, read from both ends: one no longer in the files and +/// one reached again each have to come out. A function of its own so that the check is tested on a list +/// of its own - the list is empty today, and a check over an empty list passes whatever it does. +fn unreached_problems(excused: &[(&str, &str)], in_files: &BTreeSet, reached: &BTreeSet) -> Vec { + let mut problems = Vec::new(); + for (key, reason) in excused { + if !in_files.contains(*key) { + problems.push(format!("UNREACHED names `{key}`, which is no longer in the files - take it out ({reason})")); + } + if reached.contains(*key) { + problems.push(format!("UNREACHED names `{key}`, which is reached again - take it out ({reason})")); + } } + problems +} + +/// The list of unreached texts is checked from both ends: an entry whose text left the files and one whose +/// text is reached again are each named, and an entry that is neither passes. +#[test] +fn the_unreached_list_is_checked_from_both_ends() { + let in_files: BTreeSet = ["kept.text", "back.text"].map(String::from).into(); + let reached: BTreeSet = ["back.text"].map(String::from).into(); + let excused = [("kept.text", "a reason"), ("gone.text", "a reason"), ("back.text", "a reason")]; + let problems = unreached_problems(&excused, &in_files, &reached); + assert_eq!(problems.len(), 2, "{problems:?}"); + assert!(problems[0].contains("`gone.text`") && problems[0].contains("no longer in the files"), "{problems:?}"); + assert!(problems[1].contains("`back.text`") && problems[1].contains("reached again"), "{problems:?}"); } /// The markup scan takes a key from either resource extension and nothing that is not a key. diff --git a/gui/ChronoMock.App.Tests/BackgroundGuardTests.cs b/gui/ChronoMock.App.Tests/BackgroundGuardTests.cs index f928df73..3e00edd8 100644 --- a/gui/ChronoMock.App.Tests/BackgroundGuardTests.cs +++ b/gui/ChronoMock.App.Tests/BackgroundGuardTests.cs @@ -45,9 +45,8 @@ public void The_window_paints_our_palette_over_most_of_its_surface() // 🔴 OUR GROUNDS, not the dependency's default. The trap this guards paints the wpfui #202020 on // every pixel, because a ui:FluentWindow ignores its own Background - our palette never contains that // colour. Which of our grounds dominates is the design's affair - the setup phase covers most of the - // window in cards (BrushBgSurface) over the base (BrushBgBase) - so the measure is how much of the - // surface OUR grounds cover together. That stays above half whether the base or a card wins, and - // collapses the moment #202020 comes back, which is the failure this exists to catch. + // window in cards (BrushBgSurface) over the base (BrushBgBase) - so the first measure is how much of + // the surface OUR grounds cover together, which stays above half whether the base or a card wins. var grounds = WpfTestHost.InvokeSettled(() => new[] { "BrushBgBase", "BrushBgSurface", "BrushBgSurfaceAlt" } .Select(key => Application.Current.TryFindResource(key) as SolidColorBrush) @@ -64,8 +63,25 @@ public void The_window_paints_our_palette_over_most_of_its_surface() covered > 0.5, $"our palette grounds cover only {covered:P1} of the window - something else is painting it, or " + "the content root lost its Background to the FluentWindow trap"); + + // That share alone does not catch the trap. Measured 2026-10-16: the cards cover 46.8% and the base + // 45.5%, so with the base gone the cards and the alternate ground still come to 50.8% (the registry's + // entry painting the base another colour went through). The trap shows as ONE colour that is not ours + // over the base's whole area, while the text, icons and accents spread over many colours of a few + // tenths of a percent each (the largest 0.5%). + var (foreign, share) = counts.Where(pair => !groundKeys.Contains(pair.Key)) + .Select(pair => (pair.Key, Share: pair.Value / (double)sampled)) + .MaxBy(pair => pair.Share); + Assert.True( + share < ForeignCeiling, + $"one colour that is not our ground, #{foreign:X8}, covers {share:P1} of the window - something " + + "else paints a whole area of it, or the content root lost its Background to the FluentWindow trap"); } + // No single colour outside our grounds may cover this share of the window: twenty times the largest one + // measured, and well under the base's area that the trap takes. + private const double ForeignCeiling = 0.10; + [Fact] public void No_view_writes_a_background_onto_a_FluentWindow() { diff --git a/gui/ChronoMock.App.Tests/LayoutGuardTests.cs b/gui/ChronoMock.App.Tests/LayoutGuardTests.cs index 7e83dfbb..41bfd2d7 100644 --- a/gui/ChronoMock.App.Tests/LayoutGuardTests.cs +++ b/gui/ChronoMock.App.Tests/LayoutGuardTests.cs @@ -202,7 +202,8 @@ public void The_spill_rule_fires_on_text_wider_than_the_box_it_was_put_in() { // The exact shape measured while the truncation probe refused to fire: a Grid declared 60 wide // came back holding a TextBlock 285 wide. WPF let it overflow rather than squeezing it, which - // is how text ends up painted over its neighbour. + // is how text ends up painted over its neighbour. The complaint names the words the block shows: + // an unnamed TextBlock is found by them, not by where it sits. var complaints = WpfTestHost.InvokeSettled(() => { var narrow = new Grid { Width = 60 }; @@ -217,7 +218,9 @@ public void The_spill_rule_fires_on_text_wider_than_the_box_it_was_put_in() return LayoutRules.SpillsOutOfItsParent(LayoutProbe.Walk(host)); }); - Assert.NotEmpty(complaints); + Assert.Contains( + complaints, + c => c.StartsWith("TextBlock \"a sentence far longer than sixty pixels of room\" at [", StringComparison.Ordinal)); } [Fact] diff --git a/gui/ChronoMock.App.Tests/SessionCloseTests.cs b/gui/ChronoMock.App.Tests/SessionCloseTests.cs index 429cecae..8229c65e 100644 --- a/gui/ChronoMock.App.Tests/SessionCloseTests.cs +++ b/gui/ChronoMock.App.Tests/SessionCloseTests.cs @@ -49,6 +49,11 @@ public async Task A_close_while_the_start_is_still_preparing_launches_nothing() { var target = SessionPlan.DefaultTargetPath(); Assert.True(target is not null, "the sample target is not built - build the solution first"); + // Without its core the start fails on its own and launches nothing, and this test would pass for + // that reason whatever the close did - measured, with the core taken away. + Assert.True( + File.Exists(AppPaths.SubstitutionCores.CoreForTarget(target)), + "the core for the sample target is not built - build the release cores first"); var store = new InMemorySessionHistoryStore(); var vm = new SessionViewModel(store); vm.SetTarget(target); diff --git a/tests/mutation/entries.json b/tests/mutation/entries.json index c31bd77c..2a7509df 100644 --- a/tests/mutation/entries.json +++ b/tests/mutation/entries.json @@ -453,9 +453,9 @@ "name": "pr-a exception no longer in the files", "edits": [ { - "file": "gui/ChronoMock.App/Localization/Strings.en.json", - "from": " \"target.missing\": \"(missing)\",\n", - "to": "" + "file": "crates/cli/tests/wire_keys.rs", + "from": " if !in_files.contains(*key) {\n", + "to": " if false {\n" } ], "runner": "rust", @@ -464,7 +464,7 @@ "--test", "wire_keys" ], - "test": "every_translation_is_reached_by_the_window_or_the_core", + "test": "the_unreached_list_is_checked_from_both_ends", "match": "exact", "build": "", "notHere": "" @@ -473,9 +473,9 @@ "name": "pr-a exception reached again", "edits": [ { - "file": "gui/ChronoMock.App/Views/SetupPhaseView.xaml", - "from": "ToolTip=\"{DynamicResource setup.tip_recent}\"", - "to": "ToolTip=\"{DynamicResource setup.tip_recent}\" Tag=\"{DynamicResource target.missing}\"" + "file": "crates/cli/tests/wire_keys.rs", + "from": " if reached.contains(*key) {\n", + "to": " if false {\n" } ], "runner": "rust", @@ -484,7 +484,7 @@ "--test", "wire_keys" ], - "test": "every_translation_is_reached_by_the_window_or_the_core", + "test": "the_unreached_list_is_checked_from_both_ends", "match": "exact", "build": "", "notHere": "" @@ -879,7 +879,7 @@ "runner": "cs", "package": "gui/ChronoMock.App.Tests", "target": [], - "test": "ChronoMock.App.Tests.ParameterRowLayoutTests.The_general_layout_rules_find_nothing_in_any_scenarios_parameters_at_the_calculators_narrowest", + "test": "ChronoMock.App.Tests.LayoutGuardTests.The_spill_rule_fires_on_text_wider_than_the_box_it_was_put_in", "match": "method", "build": "", "notHere": "" @@ -1834,7 +1834,7 @@ "target": [], "test": "ChronoMock.App.Tests.SessionCloseTests.A_close_while_the_start_is_still_preparing_launches_nothing", "match": "method", - "build": "", + "build": "release", "notHere": "" }, { @@ -8930,8 +8930,8 @@ "edits": [ { "file": "crates/cli/src/calc.rs", - "from": "chrono_core::calc::DateReading::Iso => time_written,", - "to": "chrono_core::calc::DateReading::Iso => (civil.hour, civil.minute, civil.second) != (0, 0, 0)," + "from": " if reading_shows_time(reading, time_written) {\n", + "to": " if reading_shows_time(reading, time_written && (civil.hour, civil.minute, civil.second) != (0, 0, 0)) {\n" } ], "runner": "rust", diff --git a/tests/mutation/mutate.ps1 b/tests/mutation/mutate.ps1 index dfdac0af..01ce4c47 100644 --- a/tests/mutation/mutate.ps1 +++ b/tests/mutation/mutate.ps1 @@ -123,6 +123,9 @@ $env:CARGO_TERM_COLOR = 'never' # the judge is a change to every judgement. $runnerFiles = @('tests/mutation/mutate.ps1', 'tests/mutation/json.ps1', 'tests/mutation/report.ps1', '.github/workflows/mutation.yml') +# The C# side as one build, the solution CI builds before its C# tests. +$csSolution = 'gui/ChronoMock.slnx' + # --------------------------------------------------------------------------------------------------- # The registry # --------------------------------------------------------------------------------------------------- @@ -1275,8 +1278,11 @@ $csProjects = @($judged | Where-Object { $_.runner -eq 'cs' } | ForEach-Object { $hasRelease = @($judged | Where-Object { $_.build -eq 'release' }).Count -gt 0 # The clean tree first: the debug workspace for the tests that drive a session (cargo test never builds -# chrono_hook.dll), both release cores when an entry's test reads them, and every C# test project of the -# part. A tree that does not build here cannot make a test red because of a mutation. +# chrono_hook.dll), both release cores when an entry's test reads them, and the whole C# solution when the +# part has a C# entry - as CI builds it before its C# tests, not each test project alone, because a test +# reads what another project of the solution builds (the sample target a session test launches). A part +# that built the test projects alone found that test red before any mutation, on its first run in CI. A +# tree that does not build here cannot make a test red because of a mutation. $cleanBuilds = @() if ($hasRust) { $cleanBuilds += 'debug' } if ($hasRelease) { $cleanBuilds += 'release' } @@ -1287,11 +1293,11 @@ foreach ($kind in $cleanBuilds) { Stop-Part @("THE UNMUTATED TREE DOES NOT BUILD ($kind), so no test here can be red because of a mutation. Stopping.") $artifacts.Run } } -foreach ($project in $csProjects) { - $build = Invoke-CsBuild $project +if ($csProjects.Count -gt 0) { + $build = Invoke-CsBuild $csSolution if ($build.Code -ne 0) { $partState.built = $false - Stop-Part @("THE UNMUTATED TREE DOES NOT BUILD ($project), so no test here can be red because of a mutation. Stopping.") $build + Stop-Part @("THE UNMUTATED TREE DOES NOT BUILD ($csSolution), so no test here can be red because of a mutation. Stopping.") $build } }