From b938b0ce72b720060c9b8d893b6562c7ec81c2db Mon Sep 17 00:00:00 2001 From: DonislawDev Date: Thu, 24 Sep 2026 12:34:12 +0200 Subject: [PATCH 1/3] fix(hook,core): let an application that outlives its session go without rewinding its clocks A session often ends while the application keeps running: a --ticks cutoff, a Stop in the panel, a core that died. The hook then handed back the real value of every clock. Under --scale-duration and --scale-qpc at x60 that sent the tick count, the interrupt time, timeGetTime and QPC back by the whole acceleration in one step (316 s after a 5.4 s session, on x64 and x86), on the axis untouchable rule 3 says never rewinds. Web pages inside the application stayed on the session date at the session rate for as long as they were open, with no option set at all. - ctl: release_axes freezes the duration axes where they stand and carries them on at rate 1 (freeze_dur and freeze_qpc, one last time). - hook: the watcher sets RELEASED before it raises DETACHED, and the five duration detours answer from it once the core is gone. The wall clock and the zone still go back to the real ones. - core: when the family outlives a clean end, its pages are let go before their connections close, the family is put to rate 1 before the core leaves so every process freezes on the same line, and session_verdict carries session.left_running. A page that does not confirm raises embedded.pages_not_released. The application is still never stopped. - tests: a unit test for the release, and session_end.rs, which runs a session that ends before its target and asserts no step back on the tick count, the interrupt time and QPC, plus the warning key. Revert probes: without RELEASED all three axes stepped back 138 s, without the key the key assertion failed. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 13 ++ crates/cli/src/cdp_attach.rs | 23 +++ crates/cli/src/cdp_clock.rs | 9 + crates/cli/src/core.rs | 30 ++- crates/cli/src/embedded_bridge.rs | 28 ++- crates/cli/src/report.rs | 10 + crates/cli/tests/network.rs | 7 + crates/cli/tests/session_end.rs | 194 ++++++++++++++++++ crates/ctl/src/lib.rs | 117 +++++++++++ crates/hook/src/lib.rs | 137 +++++++++++-- gui/ChronoMock.App.Tests/LocalizationTests.cs | 4 +- .../Localization/Strings.en.json | 3 + .../Localization/Strings.pl.json | 2 + 13 files changed, 553 insertions(+), 24 deletions(-) create mode 100644 crates/cli/tests/session_end.rs diff --git a/CHANGELOG.md b/CHANGELOG.md index 379afab..c7cd12f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -43,6 +43,19 @@ Notable changes to Chrono Mock, newest first. The format follows ### Fixed +- **Ending a session sent the application's timers back, and left its web pages on the session + date.** A session often ends while the application keeps running: `--ticks` ran out, or the + session was stopped from the window. The application was then handed back the real value of every + clock. For the date that is the point, but with timers sped up (`--scale-duration`, or "Also speed + up timers and countdowns inside the application", and `--scale-qpc`) the tick count, the + interrupt-time counter, `timeGetTime` and the high-resolution counter went back in one step by all + the time the session had added - 316 seconds after a five-second session at x60, on both 32 and + 64 bit. Web pages inside the application (WebView2, Qt WebEngine) stayed on the session date and + kept running at the session speed for as long as they were open, even with no option set. Now the + application is let go properly: the date and the time zone return to the real ones, its timers + and elapsed-time counters carry on at normal speed from where the session left them, and its + pages are handed back to the real clock as well. The session says that it left the application + running and what that means, and names a page that did not confirm it was handed back. - **A screen reader read the result's rows as code.** Every row of the audit's tables, every warning, the cleanup list, the speed and jump buttons and the calculator's lists told assistive technology what the row was built from rather than what it showed: a warning announced itself as diff --git a/crates/cli/src/cdp_attach.rs b/crates/cli/src/cdp_attach.rs index 1d668db..9fab50f 100644 --- a/crates/cli/src/cdp_attach.rs +++ b/crates/cli/src/cdp_attach.rs @@ -337,6 +337,29 @@ impl Attacher { } } + /// Evaluate the release expression in every live context and count the ones that did not confirm + /// it. `ok` is a context let go, `no-shim` one that was never on the shim and has nothing to let go + /// of. Anything else - an error, no answer - is a page that may still be on the session clock, + /// which the caller has to say (rule 6). + pub(crate) fn release(&mut self, expr: &str) -> u32 { + let mut unconfirmed = 0; + for ctx in &self.contexts { + let reply = self.client.call( + "Runtime.evaluate", + json!({ "expression": expr, "returnByValue": true }), + Some(&ctx.session_id), + ); + let confirmed = reply + .ok() + .and_then(|r| r["result"]["value"].as_str().map(|v| v == "ok" || v == "no-shim")) + .unwrap_or(false); + if !confirmed { + unconfirmed += 1; + } + } + unconfirmed + } + /// Evaluate a JS expression in one live context and return the string it produced, if any. /// For a probe reading what a page shows - `document.title` - not for the session. pub(crate) fn evaluate_string(&mut self, index: u32, expr: &str) -> Option { diff --git a/crates/cli/src/cdp_clock.rs b/crates/cli/src/cdp_clock.rs index 78b9ecd..cc00d0c 100644 --- a/crates/cli/src/cdp_clock.rs +++ b/crates/cli/src/cdp_clock.rs @@ -182,6 +182,15 @@ pub(crate) fn cdp_set_multiplier_expr(fake0: i64, real0: i64, mult: i64, dur: i6 ) } +/// The JS that lets a page go when the session ends and the application lives on: the wall back on the +/// real clock and the duration axis on from where it stands at rate 1, the same thing the hook does for +/// the host once its core is gone. It is a rate change like any other, so `performance.now` is +/// re-anchored at the old rate first and never steps back (rule 3). The origin is `0` on both sides on +/// purpose: with the rate at 1, any instant where fake equals real puts the wall on the real clock. +pub(crate) fn cdp_release_expr() -> String { + cdp_set_multiplier_expr(0, 0, 1, 1) +} + /// The JS to push a new wall origin into a context's `__chronomock` for a jump - wall only - the rate /// and the duration axis are untouched, so a backward jump never rewinds elapsed time (rule 3). pub(crate) fn cdp_jump_expr(fake0: i64, real0: i64) -> String { diff --git a/crates/cli/src/core.rs b/crates/cli/src/core.rs index c2c04ae..204e3ae 100644 --- a/crates/cli/src/core.rs +++ b/crates/cli/src/core.rs @@ -579,18 +579,36 @@ pub(crate) fn native_session_warnings( warnings } +/// The application was still running when the session ended: it is back on the real date, and its +/// timers and elapsed-time counters carry on at normal speed from where the session left them. +const KEY_LEFT_RUNNING: &str = "session.left_running"; + +/// Whether any process of the family the hook reached is still running as the session ends - the +/// application the tester is left with. A recycled pid reads as alive, which errs toward saying so +/// once too often, never toward keeping quiet about a process left behind. +fn family_left_running(session: &chrono_mech::Session, family_pids: &HashSet) -> bool { + session.is_alive() || family_pids.iter().any(|&pid| chrono_mech::process_is_alive(pid)) +} + /// End the session and state what it did: one last fold so a late child still counts, the coverage /// every process ENDED with, the family verdict and `ended`. Returns the family's exit code. pub(crate) fn close_session( mut session: chrono_mech::Session, mut ledger: SessionLedger, - bridge: EmbeddedBridge, + mut bridge: EmbeddedBridge, target_exit: Option, ) -> i32 { // Final fold so a child that joined since the last heartbeat still counts in the family. ledger.poll(&mut session); let SessionLedger { mut family, family_pids, uncovered_children, clock_clamped, duration_clamped } = ledger; + // The application may outlive the session - a `--ticks` cutoff, a Stop in the panel - and the + // session does not stop it (docs/01 section 8.4). It lets it go instead, and the pages have to be + // let go while their connections are still open, so this comes before `finish`. + let left_running = family_left_running(&session, &family_pids); + if left_running { + bridge.release_pages(); + } // What the pages inside the application did, folded into the family like any process: a page // shimmed and reading time is covered, one refused or failed is not, and none at all judges // nothing (docs/09 section 12.7). @@ -632,6 +650,13 @@ pub(crate) fn close_session( } } let zone_differs = session.state().tz_bias != chrono_mech::host_tz_bias_min(); + // Rate 1 before the core leaves, after everything `ended` reports has been read. Each process of + // the family freezes its duration axes when its hook sees the core gone (`release_duration_axes`), + // and at rate 1 every one of them freezes on the same line whenever its watcher happens to wake - + // at the session rate they would disagree by the rate times the gap between two wake-ups. + if left_running { + session.set_multiplier(1); + } session.end(); // The sticky flag OR the final sample, so a session too short to have emitted a heartbeat still // reports a clamped clock. @@ -645,6 +670,9 @@ pub(crate) fn close_session( reconcile_engine_warnings(&mut children_warnings, pages.pages_reached()); session_warnings.extend(children_warnings); session_warnings.extend(pages.session_warnings(zone_differs)); + if left_running { + session_warnings.push(KEY_LEFT_RUNNING.to_string()); + } // The wire names the first UNCOVERED_CHILDREN_WIRE_MAX and carries the true total beside them. // The image name is text from the target's world, so it passes the same sieve as everything // else the target writes before it reaches a terminal or the panel. diff --git a/crates/cli/src/embedded_bridge.rs b/crates/cli/src/embedded_bridge.rs index bb05dca..50207d6 100644 --- a/crates/cli/src/embedded_bridge.rs +++ b/crates/cli/src/embedded_bridge.rs @@ -25,7 +25,7 @@ use chrono_proto::{ReachedEngine, TargetSpec}; use crate::cdp; use crate::cdp_attach::{Attacher, AttacherOutcome, Pumped, ShimOrigin}; -use crate::cdp_clock::{cdp_jump_expr, cdp_set_multiplier_expr, drift_ms}; +use crate::cdp_clock::{cdp_jump_expr, cdp_release_expr, cdp_set_multiplier_expr, drift_ms}; use crate::cdp_discover::{Discovered, Discovery, Notice}; use crate::embedded::engine_env; @@ -59,6 +59,9 @@ pub(crate) const KEY_QT_PORT_TAKEN: &str = "embedded.qt_port_taken"; pub(crate) const KEY_ZONE_IS_HOST: &str = "embedded.zone_is_host"; /// A WebView2 policy value in the registry was hidden by the session's variable for its duration. pub(crate) const KEY_REGISTRY_ARGUMENTS_HIDDEN: &str = "embedded.registry_arguments_hidden"; +/// A page still open when the session ended did not confirm it was let go, so it may keep the session +/// clock until it is reloaded or closed. +const KEY_PAGES_NOT_RELEASED: &str = "embedded.pages_not_released"; /// What a native start needs from the channel before the target launches: the variables that make /// an engine open its port, the port reserved for a Qt engine, and what there already is to say. @@ -385,6 +388,23 @@ impl EmbeddedBridge { self.pushed = Some(fresh); } + /// Let every page go before the connections close, the way the hook lets the host go: the wall + /// back on the real clock and the duration axis on from where it stands at rate 1. For a session + /// whose application outlives it - the caller decides that, a page of an application that has + /// exited is gone and has nothing to let go of. + /// + /// Measured before this existed (2026-09-24, WebView2 host at x60): the host went back to the real + /// clock at `end` and its page stayed on the session date, running on at the session rate for as + /// long as it lived - also with no opt-in at all, because this channel is on by default. A page + /// that does not confirm is named in the report rather than assumed let go (rule 6). + pub(crate) fn release_pages(&mut self) { + let expr = cdp_release_expr(); + let unconfirmed: u32 = self.attachers.iter_mut().map(|a| a.release(&expr)).sum(); + if unconfirmed > 0 { + self.warn(KEY_PAGES_NOT_RELEASED); + } + } + fn broadcast(&mut self, expr: &str) { for attacher in &mut self.attachers { attacher.broadcast(expr); @@ -397,8 +417,10 @@ impl EmbeddedBridge { } } - /// Hand over what the channel covered. Closes every connection - the shims stay in the pages, - /// which follow the host, and the host keeps its hooks past `end` as well. + /// Hand over what the channel covered. Closes every connection. A page still open keeps its shim, + /// which is why an application that outlives the session gets `release_pages` first. A document + /// loaded after this starts without the shim: its registration dies with the connection (measured + /// 2026-09-24, a reload after the session came back on the real clock). pub(crate) fn finish(mut self) -> Outcome { self.poll_counts(); let mut outcome = Outcome { diff --git a/crates/cli/src/report.rs b/crates/cli/src/report.rs index 648df0a..6d1504e 100644 --- a/crates/cli/src/report.rs +++ b/crates/cli/src/report.rs @@ -302,6 +302,16 @@ pub(crate) fn describe_warning(key: &str) -> String { "time.duration_axis_clamped" => { "the monotonic counters (tick count, unbiased interrupt time, and QPC when scaled) reached the end of their range and stood there, so elapsed time inside the target stopped advancing even though the session went on" } + // The session does not stop the application (docs/01 section 8.4), so the tester is left with + // one that changed clocks under their hands. Says which way each clock went, because "back to + // real time" alone reads as "the counters went back too" - and it was exactly that, a 316 s + // step back at x60, that letting go used to do. + "session.left_running" => { + "the application was still running when the session ended, so it is back on the real date and time now - its timers and elapsed-time counters carry on at normal speed from where the session left them instead of jumping back, and a restart gives it a clean run on the real clock" + } + "embedded.pages_not_released" => { + "a page inside the application did not confirm it was handed back to the real clock when the session ended, so it may keep the session date until it is reloaded or closed" + } "inheritance.child_not_injected" => { "a child process could not be covered and ran on the REAL clock - usually a child of the other bitness; the process count below is short by that many" } diff --git a/crates/cli/tests/network.rs b/crates/cli/tests/network.rs index f3203ac..2dd7227 100644 --- a/crates/cli/tests/network.rs +++ b/crates/cli/tests/network.rs @@ -184,6 +184,13 @@ const ALLOWED: &[(&str, &str, &str)] = &[ session through the built binary, and reads the tick rate it wrote to a scratch file. \ Neither reaches past this machine", ), + ( + "crates/cli/tests/session_end.rs", + "spawn", + "runs this test binary's own ignored probe twice, once alone as the control and once under a \ + session that ends before the probe does, and reads the rates and steps it wrote to a scratch \ + file. Neither reaches past this machine", + ), ( "crates/cli/tests/network_observer.rs", "spawn", diff --git a/crates/cli/tests/session_end.rs b/crates/cli/tests/session_end.rs new file mode 100644 index 0000000..fc9ad4b --- /dev/null +++ b/crates/cli/tests/session_end.rs @@ -0,0 +1,194 @@ +//! An application that outlives its session is let go without its duration axes stepping back. +//! +//! A session ends while the application keeps running more often than not: a `--ticks` cutoff, a Stop in +//! the panel, a core that died. The hook then lets the application go, and until 2026-09-24 it did that by +//! handing back the real value of every clock. For the wall and the zone that is the point. For the tick +//! count, the unbiased interrupt time and QPC under `--scale-duration` / `--scale-qpc` it was a step BACK +//! by the whole acceleration - measured at x60 after 5.4 s, 316 s in one step, on x64 and x86 alike - +//! on the axis untouchable rule 3 says never rewinds. +//! +//! The target is this test binary itself, as in `duration_axis.rs`: the ignored probe below does its +//! work only when the variable names a file. It samples the three axes for longer than the session lasts +//! and writes the largest step back it saw on each, plus how fast the tick count moved at the start and +//! at the end, against a reference the hook never touches. + +use std::path::PathBuf; +use std::process::Command; +use std::time::{Duration, Instant}; + +/// Where the probe writes what it measured. Unset, the probe returns at once. +const PROBE_OUT: &str = "CHRONO_SESSION_END_PROBE_OUT"; + +/// The probe's own name, which is how the binary is asked to run it and nothing else. +const PROBE: &str = "probe_samples_the_duration_axes_past_the_session_end"; + +/// How long the probe samples, in real milliseconds. The session below ends after two heartbeats, so the +/// probe sees about two seconds of the session and three of what comes after it. +const SAMPLE_MS: f64 = 5_000.0; + +#[cfg_attr(target_arch = "x86", link(name = "kernel32", kind = "raw-dylib", import_name_type = "undecorated"))] +#[cfg_attr(not(target_arch = "x86"), link(name = "kernel32", kind = "raw-dylib"))] +unsafe extern "system" { + fn GetTickCount64() -> u64; + fn QueryUnbiasedInterruptTime(time: *mut u64) -> i32; +} + +#[cfg_attr(target_arch = "x86", link(name = "ntdll", kind = "raw-dylib", import_name_type = "undecorated"))] +#[cfg_attr(not(target_arch = "x86"), link(name = "ntdll", kind = "raw-dylib"))] +unsafe extern "system" { + /// The reference clock. The hook never touches it (ADR-2), so it stays real under any session. + fn NtQueryPerformanceCounter(counter: *mut i64, frequency: *mut i64) -> i32; +} + +/// Real milliseconds by the unhooked reference clock. +fn real_ms() -> f64 { + let (mut counter, mut frequency) = (0i64, 0i64); + // SAFETY: both pointers are to live locals. + unsafe { NtQueryPerformanceCounter(&mut counter, &mut frequency) }; + counter as f64 * 1000.0 / frequency as f64 +} + +/// One reading of the three axes, each in milliseconds: the tick count, the unbiased interrupt time and +/// QPC, which `Instant` reads. +fn axes(origin: Instant) -> [f64; 3] { + let mut quit = 0u64; + // SAFETY: the export's documented signature, no arguments and no state. + let tick = unsafe { GetTickCount64() }; + // SAFETY: the export's documented signature, with a live out pointer. + unsafe { QueryUnbiasedInterruptTime(&mut quit) }; + [tick as f64, quit as f64 / 10_000.0, origin.elapsed().as_secs_f64() * 1000.0] +} + +/// Samples every few milliseconds for `SAMPLE_MS` of real time and writes, space separated: the tick +/// rate over the first real second, the tick rate over the last real second, and the largest step back +/// seen on the tick count, the interrupt time and QPC (0 when an axis never went back). +#[test] +#[ignore = "the target of `an_application_left_running_keeps_its_duration_axes_moving_forward`, not a test on its own"] +fn probe_samples_the_duration_axes_past_the_session_end() { + let Some(out) = std::env::var_os(PROBE_OUT) else { + return; + }; + let origin = Instant::now(); + let start = real_ms(); + let mut last = axes(origin); + let mut worst = [0.0f64; 3]; + let first_tick = last[0]; + let mut head_rate = None; + let mut tail_from = None; + loop { + // A sleep, not a spin: the session shortens it to its floor, which is still a millisecond, and + // once the session is gone it is a plain millisecond again. + std::thread::sleep(Duration::from_millis(5)); + let now = real_ms() - start; + let reading = axes(origin); + for (i, w) in worst.iter_mut().enumerate() { + *w = w.min(reading[i] - last[i]); + } + last = reading; + if head_rate.is_none() && now >= 1_000.0 { + head_rate = Some((reading[0] - first_tick) / now); + } + if tail_from.is_none() && now >= SAMPLE_MS - 1_000.0 { + tail_from = Some((now, reading[0])); + } + if now >= SAMPLE_MS { + let (t0, tick0) = tail_from.unwrap_or((now, reading[0])); + let tail_rate = (reading[0] - tick0) / (now - t0).max(1.0); + let line = format!( + "{:.2} {:.2} {:.1} {:.1} {:.1}", + head_rate.unwrap_or(0.0), + tail_rate, + -worst[0], + -worst[1], + -worst[2] + ); + std::fs::write(&out, line).expect("the probe writes its result"); + return; + } + } +} + +/// The injected library, which `cargo test` does not build (`dry_run.rs` has the whole story). +fn injected_library() -> PathBuf { + PathBuf::from(env!("CARGO_BIN_EXE_chrono")) + .parent() + .expect("the binary under test lives in a directory") + .join("chrono_hook.dll") +} + +/// What the probe wrote: `[head rate, tail rate, step back on tick, on QUIT, on QPC]`. +fn measured(file: &std::path::Path) -> Option<[f64; 5]> { + let text = std::fs::read_to_string(file).ok()?; + let values: Vec = text.split_whitespace().filter_map(|v| v.parse().ok()).collect(); + values.try_into().ok() +} + +/// An application still running when its session ends carries on at rate 1 from where its duration axes +/// stood, and the session says it left it running. +#[test] +fn an_application_left_running_keeps_its_duration_axes_moving_forward() { + let library = injected_library(); + assert!( + library.is_file(), + "this probe drives a real session and needs {}, which `cargo test` does not build. \ + Run `cargo build --workspace` first - CI and tools/gates.ps1 both do that.", + library.display() + ); + let me = std::env::current_exe().expect("the test binary knows its own path"); + let dir = std::env::temp_dir().join(format!("chrono-session-end-{}", std::process::id())); + let _ = std::fs::remove_dir_all(&dir); + std::fs::create_dir_all(&dir).expect("a scratch directory"); + let probe_args = ["--ignored", "--exact", PROBE, "--test-threads", "1"]; + + // The control first: with no session every axis moves at about the real rate and never back. + // Without it a probe that measured nothing would pass everything below. + let control = dir.join("control.txt"); + let run = Command::new(&me) + .args(probe_args) + .env(PROBE_OUT, &control) + .output() + .expect("the probe must run without a session"); + assert!(run.status.success(), "the probe failed without a session: {}", String::from_utf8_lossy(&run.stdout)); + let [head, tail, ..] = measured(&control).expect("the probe wrote nothing without a session"); + assert!(head < 2.0 && tail < 2.0, "without a session the tick count moved x{head} then x{tail}, so this probe cannot tell"); + + // The session ends after two heartbeats. The probe inherits the core's output, so `output()` + // returns once the probe is done as well - which is what the result file needs. + let session = dir.join("session.txt"); + let out = Command::new(env!("CARGO_BIN_EXE_chrono")) + .args([ + "run", + &me.display().to_string(), + "--mode", + "x60", + "--scale-duration", + "--scale-qpc", + "--ticks", + "2", + "--json", + "--args", + &probe_args.join(" "), + ]) + .env(PROBE_OUT, &session) + .output() + .expect("the tool must run"); + let stdout = String::from_utf8_lossy(&out.stdout); + let context = || format!("stdout: {stdout} stderr: {}", String::from_utf8_lossy(&out.stderr)); + let Some([head, tail, tick_back, quit_back, qpc_back]) = measured(&session) else { + panic!("the probe wrote nothing under the session. {}", context()); + }; + assert!(head > 10.0, "the tick count moved x{head} during the session, so the session never scaled it. {}", context()); + assert!(tail < 2.0, "the tick count still moved x{tail} after the session, so the probe did not outlive it. {}", context()); + assert!( + tick_back == 0.0 && quit_back == 0.0 && qpc_back == 0.0, + "letting the application go stepped its duration axes back (tick {tick_back} ms, interrupt time \ + {quit_back} ms, QPC {qpc_back} ms) - untouchable rule 3. {}", + context() + ); + assert!( + stdout.lines().any(|l| l.contains("\"session_verdict\"") && l.contains("\"session.left_running\"")), + "the session let a running application go without saying so. {}", + context() + ); + let _ = std::fs::remove_dir_all(&dir); +} diff --git a/crates/ctl/src/lib.rs b/crates/ctl/src/lib.rs index df5967c..37ff735 100644 --- a/crates/ctl/src/lib.rs +++ b/crates/ctl/src/lib.rs @@ -1116,6 +1116,61 @@ pub fn freeze_qpc(dur_qpc_c0: i64, dur_qpc_q0: i64, old_m: i64, now: i64) -> i64 dur_qpc_at(dur_qpc_c0, dur_qpc_q0, old_m, now) } +/// Where the three duration axes stood when the session let go of a process, and the real instants +/// they carry on from at rate 1. Built by [`release_axes`], read by the hook once its core is gone. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct ReleasedAxes { + tick_c0: u64, + quit_c0: i64, + q0: i64, + qpc_c0: i64, + qpc_q0: i64, +} + +/// Freeze every duration axis at the instant the session lets go of a process, so that it carries on +/// from there at rate 1 instead of snapping back to the real value. +/// +/// Snapping back is what the hook did until 2026-09-24, and it was measured rather than supposed: a +/// session at x60 that ended after 5.4 s while its target kept running sent GetTickCount64, +/// GetTickCount, timeGetTime, QueryUnbiasedInterruptTime and QPC back by 316 s in one step, on x64 and +/// x86 alike. The axis untouchable rule 3 says never rewinds was rewound by the tool leaving. +/// +/// This is `freeze_dur` and `freeze_qpc` applied one last time, with rate 1 for good: the value right +/// after equals the value right before, and from then on it moves at the real speed. The wall clock is +/// not part of it - it goes back to the real one, which a wall may do and the report says it did. +/// +/// `dur` and `qpc` are exactly what [`read_dur`] and [`read_qpc`] return, and `now_quit` / `now_qpc` +/// the real clocks at the instant of the release. +pub fn release_axes(dur: (u64, i64, i64, i64), qpc: (i64, i64, i64), now_quit: i64, now_qpc: i64) -> ReleasedAxes { + let (tick_c0, quit_c0, dur_q0, dur_m) = dur; + let (qpc_c0, qpc_q0, qpc_m) = qpc; + let (tick, quit) = freeze_dur(tick_c0, quit_c0, dur_q0, dur_m, now_quit); + ReleasedAxes { + tick_c0: tick, + quit_c0: quit, + q0: now_quit, + qpc_c0: freeze_qpc(qpc_c0, qpc_q0, qpc_m, now_qpc), + qpc_q0: now_qpc, + } +} + +impl ReleasedAxes { + /// `GetTickCount64` after the release, in milliseconds, from the real QUIT. + pub fn tick_at(&self, real_quit: i64) -> u64 { + dur_tick_at(self.tick_c0, self.q0, 1, real_quit) + } + + /// `QueryUnbiasedInterruptTime` after the release, in 100 ns, from the real QUIT. + pub fn quit_at(&self, real_quit: i64) -> i64 { + dur_quit_at(self.quit_c0, self.q0, 1, real_quit) + } + + /// `QueryPerformanceCounter` after the release, in raw ticks, from the real QPC. + pub fn qpc_at(&self, real_qpc: i64) -> i64 { + dur_qpc_at(self.qpc_c0, self.qpc_q0, 1, real_qpc) + } +} + /// Write the session zone bias (stable field, outside the seqlock). Mechanism side. /// /// # Safety @@ -1755,6 +1810,68 @@ mod tests { assert!(b > a, "a frozen wall clock must not stop the monotonic duration axis (rule 3)"); } + #[test] + fn releasing_a_process_neither_rewinds_nor_stops_its_duration_axes() { + // The measured case (2026-09-24): x60, the session ends after 5.4 s of real time and the target + // lives on. Before the release the axes ran at the session rate, after it they must carry on + // from the same value at the real rate. The real value itself stands 5.4 s x 59 = 318.6 s behind + // by then (the measured run lasted 5.36 s, hence the 316 s on record). + let tick_c0: u64 = 1_000_000; // ms + let quit_c0: i64 = 10_000_000_000; // 100 ns + let q0: i64 = 10_000_000_000; // real QUIT base, 100 ns + let qpc_c0: i64 = 50_000_000; // raw ticks, a 10 MHz counter + let qpc_q0: i64 = 50_000_000; + let end = q0 + 54_000_000; // 5.4 s later + let end_qpc = qpc_q0 + 54_000_000; + for m in [60i64, 1, 0, 1440] { + let r = release_axes((tick_c0, quit_c0, q0, m), (qpc_c0, qpc_q0, m), end, end_qpc); + assert_eq!(r.tick_at(end), dur_tick_at(tick_c0, q0, m, end), "tick jumped at the release (x{m})"); + assert_eq!(r.quit_at(end), dur_quit_at(quit_c0, q0, m, end), "quit jumped at the release (x{m})"); + assert_eq!( + r.qpc_at(end_qpc), + dur_qpc_at(qpc_c0, qpc_q0, m, end_qpc), + "qpc jumped at the release (x{m})" + ); + // Rate 1 afterwards: one real second is one second on every axis, whatever the session ran at. + assert_eq!(r.tick_at(end + 10_000_000) - r.tick_at(end), 1_000, "tick rate after the release (x{m})"); + assert_eq!(r.quit_at(end + 10_000_000) - r.quit_at(end), 10_000_000, "quit rate after the release (x{m})"); + assert_eq!( + r.qpc_at(end_qpc + 10_000_000) - r.qpc_at(end_qpc), + 10_000_000, + "qpc rate after the release (x{m})" + ); + } + + // Dense sampling across the release at x60, 1 ms of real time a step: never a step down. + let r = release_axes((tick_c0, quit_c0, q0, 60), (qpc_c0, qpc_q0, 60), end, end_qpc); + let mut last_tick = 0u64; + let mut last_quit = i64::MIN; + let mut last_qpc = i64::MIN; + for step in 0..10_800i64 { + let now = q0 + step * 10_000; + let now_qpc = qpc_q0 + step * 10_000; + let (tick, quit, qpc) = if now < end { + (dur_tick_at(tick_c0, q0, 60, now), dur_quit_at(quit_c0, q0, 60, now), dur_qpc_at(qpc_c0, qpc_q0, 60, now_qpc)) + } else { + (r.tick_at(now), r.quit_at(now), r.qpc_at(now_qpc)) + }; + assert!(tick >= last_tick, "GetTickCount64 rewound at the release: {last_tick} -> {tick} (step {step})"); + assert!(quit >= last_quit, "QUIT rewound at the release: {last_quit} -> {quit} (step {step})"); + assert!(qpc >= last_qpc, "QPC rewound at the release: {last_qpc} -> {qpc} (step {step})"); + (last_tick, last_quit, last_qpc) = (tick, quit, qpc); + } + // What the old behaviour handed back instead: the base started at the real tick, so the real + // value at the end is the base plus 5.4 s, which is 318.6 s under what the target had just read. + let real_at_end = tick_c0 + 5_400; + assert_eq!(r.tick_at(end) - real_at_end, 318_600, "the gap the release closes (5.4 s x 59)"); + + // An axis already standing at the end of its range stays where it stood and moves on at rate 1, + // rather than wrapping or dropping (see `dur_axis_at_range_end`). + let far = release_axes((tick_c0, quit_c0, 0, i64::MAX), (qpc_c0, 0, i64::MAX), end, end_qpc); + assert!(far.tick_at(end + 10_000_000) > far.tick_at(end), "a saturated tick axis must keep moving after the release"); + assert!(far.quit_at(end + 10_000_000) >= far.quit_at(end), "a saturated quit axis must not drop after the release"); + } + #[test] fn qpc_axis_never_rewinds_across_multiplier_changes() { // ADR-2 reversal (A1): a multiplier change must re-anchor the QPC axis so it stays continuous, diff --git a/crates/hook/src/lib.rs b/crates/hook/src/lib.rs index c5b06ee..1a68c95 100644 --- a/crates/hook/src/lib.rs +++ b/crates/hook/src/lib.rs @@ -64,7 +64,7 @@ use std::sync::OnceLock; use chrono_ctl::{ bump_calls, bump_uninjected_children, cov_at_mut, dur_qpc_at, dur_quit_at, dur_tick_at, - header_is_ours, indirect_jump_slot, record_uncovered_child, + header_is_ours, indirect_jump_slot, record_uncovered_child, release_axes, ReleasedAxes, publish_pid, read_anchor, read_core_pid, read_dur, read_qpc, read_scale_dur, read_scale_qpc, bump_waits_at_floor, delay_hit_floor, read_installed, read_late_installed, read_tz_bias, reserve_cov_slot, scale_delay_interval, scale_timer_due, scale_timer_elapse, scale_timer_period, @@ -344,11 +344,13 @@ const STILL_ACTIVE_CODE: u32 = 259; /// it is wedged, is already broken on its own account. const CHILD_INJECT_TIMEOUT_MS: u32 = 10_000; -// --- Self-detach: revert to real time when the core vanishes -------------------- +// --- Self-detach: let go of the target when the core vanishes ------------------- // The core writes its PID into the control block - we open a SYNCHRONIZE handle to it. // On the first time call we spawn a watcher that blocks on that handle. When the core -// dies (clean end, crash, or kill -9) the OS signals it, we flip DETACHED, and every -// detour falls through to the original - the target's clock returns to real time. +// dies (clean end, crash, or kill -9) the OS signals it, we flip DETACHED, and the +// target is let go: the wall clock and the zone return to the real ones, and the +// duration axes carry on at rate 1 from where they stood (`RELEASED`), because handing +// back the real value there would rewind them (untouchable rule 3, measured 2026-09-24). /// `WAIT_TIMEOUT` as the raw value the wait returns. Spelled out because the wait goes through the /// `WaitForSingleObject` TRAMPOLINE (`O_WFSO`), which hands back a bare `u32`, not the typed @@ -418,10 +420,54 @@ unsafe extern "system" fn watcher_proc(_p: *mut c_void) -> u32 { unsafe { } } } + release_duration_axes(); DETACHED.store(true, Ordering::SeqCst); 0 }} +/// Where the duration axes stood when the core went away, set once by the watcher. `None` for as long +/// as the session holds, and for good when the block had already been reclaimed by the time the watcher +/// read it - then the detours hand back the real value, as they all did before 2026-09-24. +static RELEASED: OnceLock = OnceLock::new(); + +/// Freeze the duration axes where they stand, for good, before the flag that sends every detour to its +/// released branch goes up (untouchable rule 3, `chrono_ctl::release_axes`). +/// +/// Runs on the watcher, once, after the core is gone - so nothing writes the anchors any more and the +/// read cannot race a rate change. What it can race is a NEW core reclaiming the block, which zeroes it: +/// ownership is checked after the read (R2-S6), and a block that is no longer ours releases nothing, so +/// the detours fall back to the real value. Unreachable today by the measurement kept at `still_ours`, +/// and stated because it is the one road left to the old snap-back. +/// +/// The order is the whole guarantee: `RELEASED` is set BEFORE `DETACHED` is raised, so a detour that +/// sees the flag also sees where the axes stood. A detour that read the anchors just before the flag +/// went up may still answer at the session rate for the few instructions between the watcher reading +/// the clock and raising the flag. At a clean end the core has already put the rate to 1, which makes +/// that window answer exactly what the release does. +fn release_duration_axes() { + let Some(p) = ctl_ptr() else { + return; + }; + let p = p as *const Ctl; + let now_quit = real_quit(); + let now_qpc = real_qpc(); + let (dur, qpc) = unsafe { (read_dur(p), read_qpc(p)) }; + if still_ours(p) { + let _ = RELEASED.set(release_axes(dur, qpc, now_quit, now_qpc)); + } +} + +/// `GetTickCount64` after the session let go of this process, or `None` while it holds it (and when +/// nothing could be released). +fn released_tick() -> Option { + RELEASED.get().map(|r| r.tick_at(real_quit())) +} + +/// `QueryUnbiasedInterruptTime` after the session let go of this process, as `released_tick`. +fn released_quit() -> Option { + RELEASED.get().map(|r| r.quit_at(real_quit())) +} + // --- Late module arrival -------------------------------------------------------- // // `make_hook` resolves user32 / winmm / ws2_32 at `DllMain` time and treats a missing module as @@ -696,6 +742,20 @@ fn real_quit() -> i64 { } } +/// The real `QueryPerformanceCounter`, through the trampoline. Only the release reads it, and only a +/// hooked counter has anything to release - an unhooked one is never answered from `RELEASED` - so +/// without the trampoline the answer is 0 rather than a second road to the export. +fn real_qpc() -> i64 { + match O_QPC.get() { + Some(o) => { + let mut t: i64 = 0; + unsafe { o(&mut t) }; + t + } + None => 0, + } +} + fn compute_fake() -> Option { fake_now_and_dur_m().map(|(fake, _)| fake) } @@ -1150,8 +1210,11 @@ unsafe extern "system" fn h_stslex( /// `original` must hold this channel's trampoline, if anything. unsafe fn tick64_or(original: &OnceLock) -> u64 { unsafe { bump(IDX_GTC64); + // Once the session has let go: on from where the axis stood (rule 3), the real value only when + // nothing could be released. + let after = || released_tick().unwrap_or_else(|| original.get().map(|o| o()).unwrap_or(0)); if detached() { - return original.get().map(|o| o()).unwrap_or(0); + return after(); } match ctl_ptr() { Some(p) => { @@ -1162,7 +1225,7 @@ unsafe fn tick64_or(original: &OnceLock) -> u64 { unsafe { if still_ours(p as *const Ctl) { fake } else { - original.get().map(|o| o()).unwrap_or(0) + after() } } None => original.get().map(|o| o()).unwrap_or(0), @@ -1178,8 +1241,10 @@ unsafe fn tick64_or(original: &OnceLock) -> u64 { unsafe { /// `original` must hold this channel's trampoline, if anything. unsafe fn tick32_or(original: &OnceLock) -> u32 { unsafe { bump(IDX_GTC); + // The low 32 bits of the released 64-bit axis, exactly as in session. + let after = || released_tick().map(|t| t as u32).unwrap_or_else(|| original.get().map(|o| o()).unwrap_or(0)); if detached() { - return original.get().map(|o| o()).unwrap_or(0); + return after(); } match ctl_ptr() { Some(p) => { @@ -1188,7 +1253,7 @@ unsafe fn tick32_or(original: &OnceLock) -> u32 { unsafe { if still_ours(p as *const Ctl) { fake } else { - original.get().map(|o| o()).unwrap_or(0) + after() } } None => original.get().map(|o| o()).unwrap_or(0), @@ -1200,10 +1265,25 @@ unsafe extern "system" fn h_tick_kb() -> u64 { unsafe { tick64_or(&O_TICK_KB) } unsafe extern "system" fn h_tick32() -> u32 { unsafe { tick32_or(&O_TICK32) } } unsafe extern "system" fn h_tick32_kb() -> u32 { unsafe { tick32_or(&O_TICK32_KB) } } +/// `QueryUnbiasedInterruptTime` once the session has let go: on from where the axis stood (rule 3), the +/// real call when nothing could be released or there is nowhere to write the answer. +/// +/// # Safety +/// `lp` is the caller's out pointer, null or writable, as the API itself requires. +unsafe fn quit_after_session(lp: *mut u64) -> i32 { unsafe { + match released_quit() { + Some(v) if !lp.is_null() => { + *lp = v as u64; + 1 + } + _ => O_QUIT.get().map(|o| o(lp)).unwrap_or(0), + } +}} + unsafe extern "system" fn h_quit(lp: *mut u64) -> i32 { unsafe { bump(IDX_QUIT); if detached() { - return O_QUIT.get().map(|o| o(lp)).unwrap_or(0); + return quit_after_session(lp); } if !lp.is_null() { match ctl_ptr() { @@ -1211,7 +1291,7 @@ unsafe extern "system" fn h_quit(lp: *mut u64) -> i32 { unsafe { let (_tick_c0, dur_quit_c0, dur_q0, m) = read_dur(p as *const Ctl); let fake = dur_quit_at(dur_quit_c0, dur_q0, m, real_quit()) as u64; if !still_ours(p as *const Ctl) { - return O_QUIT.get().map(|o| o(lp)).unwrap_or(0); + return quit_after_session(lp); } *lp = fake; } @@ -1234,6 +1314,21 @@ unsafe extern "system" fn h_quit(lp: *mut u64) -> i32 { unsafe { type QpcFn = unsafe extern "system" fn(*mut i64) -> i32; static O_QPC: OnceLock = OnceLock::new(); +/// `QueryPerformanceCounter` once the session has let go: on from where the axis stood (rule 3), the +/// real counter when nothing could be released. +/// +/// # Safety +/// `lp` must be non-null and writable - `h_qpc` has already sent a null one to the original. +unsafe fn qpc_after_session(o: QpcFn, lp: *mut i64) -> i32 { unsafe { + let Some(r) = RELEASED.get() else { + return o(lp); + }; + let mut real: i64 = 0; + o(&mut real); + *lp = r.qpc_at(real); + 1 +}} + unsafe extern "system" fn h_qpc(lp: *mut i64) -> i32 { unsafe { // Counted like every other channel (R2-S3). QPC is the hottest clock a process calls, so the cost // was measured rather than assumed - and measured as an INTERLEAVED A/B on two hook builds, because @@ -1256,13 +1351,15 @@ unsafe extern "system" fn h_qpc(lp: *mut i64) -> i32 { unsafe { let (qpc_c0, qpc_q0, m) = read_qpc(p as *const Ctl); let fake = dur_qpc_at(qpc_c0, qpc_q0, m, real); if !still_ours(p as *const Ctl) { - return o(lp); // reclaimed mid-read (R2-S6): real QPC + return qpc_after_session(o, lp); // reclaimed mid-read (R2-S6) } *lp = fake; 1 } - // Detached (core gone) or no control block -> real QPC, so the target reverts to real time cleanly. - _ => o(lp), + // Detached (core gone): on from where the axis stood, never back to the real counter (rule 3). + Some(_) => qpc_after_session(o, lp), + // No control block (unreachable: CTL_PTR is set before these hooks install) - the real counter. + None => o(lp), } }} @@ -1725,22 +1822,24 @@ unsafe extern "system" fn h_timesetevent( // Wraps at 2^32 ms like the real one, and sooner under acceleration, which is the honest behaviour of a // fast 32-bit counter. // -// Detached or without a control block it returns the REAL value through the trampoline, so a target -// reverts cleanly when the core goes away - the same shape as h_tick32. The None arm is unreachable -// (make_hook fills the slot before any hook is enabled) and returns the real value too rather than -// inventing a reading. +// Once the core has gone it carries on from where the shared axis stood, at rate 1 - the same shape as +// h_tick32, so the two still agree after the session. Handing back the real value there rewound it by +// the whole acceleration (rule 3, measured 2026-09-24). The real value only when nothing could be +// released. The None arm is unreachable (make_hook fills the slot before any hook is enabled) and +// returns the real value rather than inventing a reading. unsafe extern "system" fn h_timegettime() -> u32 { unsafe { let real = || O_TIMEGETTIME.get().map(|o| o()).unwrap_or(0); + let after = || released_tick().map(|t| t as u32).unwrap_or_else(real); bump(IDX_TIMEGETTIME); if detached() { - return real(); + return after(); } match ctl_ptr() { Some(p) => { let (dur_tick_c0, _quit_c0, dur_q0, m) = read_dur(p as *const Ctl); let fake = dur_tick_at(dur_tick_c0, dur_q0, m, real_quit()) as u32; // Ownership checked after the read (R2-S6), exactly as the tick detours do. - if still_ours(p as *const Ctl) { fake } else { real() } + if still_ours(p as *const Ctl) { fake } else { after() } } None => real(), } diff --git a/gui/ChronoMock.App.Tests/LocalizationTests.cs b/gui/ChronoMock.App.Tests/LocalizationTests.cs index d3b367d..dbcd499 100644 --- a/gui/ChronoMock.App.Tests/LocalizationTests.cs +++ b/gui/ChronoMock.App.Tests/LocalizationTests.cs @@ -56,8 +56,10 @@ public void Available_cultures_are_discovered_by_scanning_the_folder() // The embedded-engine channel (docs/09 section 12): the pages inside the application. "embedded.web_engine_reached", "embedded.debug_port_open", "embedded.engine_unreachable", "embedded.discovery_unavailable", "embedded.qt_port_taken", "embedded.zone_is_host", - "embedded.registry_arguments_hidden", + "embedded.registry_arguments_hidden", "embedded.pages_not_released", "time.fake_clock_clamped", "time.duration_axis_clamped", + // The application outlived the session and was let go (docs/01 section 8.4). + "session.left_running", "chromium.launched_with_debug_port", "chromium.app_closed_before_audit", "chromium.rate_change_affects_running_timers", "chromium.context_ceiling_reached", // Runtime detection warnings the driver appends to coverage (B1): a Python/.NET/Java target whose diff --git a/gui/ChronoMock.App/Localization/Strings.en.json b/gui/ChronoMock.App/Localization/Strings.en.json index d2a26bd..03f4b16 100644 --- a/gui/ChronoMock.App/Localization/Strings.en.json +++ b/gui/ChronoMock.App/Localization/Strings.en.json @@ -444,6 +444,7 @@ "embedded.qt_port_taken": "The port reserved for the application's Qt web engine was taken by something else before the engine could use it. Its pages could not be reached and ran on the real clock.", "embedded.zone_is_host": "The pages inside this application read this computer's time zone, not the session's. A local time they show differs from the rest of the application by the zone offset.", "embedded.registry_arguments_hidden": "This application has WebView2 browser arguments set in the registry. The session hid them for its duration, so whatever they set up (a debugging port of your own, say) was not applied.", + "embedded.pages_not_released": "A page inside this application did not confirm it was handed back to the real clock when the session ended, so it may keep the session date until you reload or close it.", // R2-S9. Session-level, not per-process: it is about processes that never got a coverage slot, // so it arrives on session_verdict rather than on any one coverage event. "coverage.pid_registry_full": "This session ran more processes than the audit can track (256). Some ran with no fake clock at all and are missing from the process count and the lists above.", @@ -458,6 +459,8 @@ "coverage.session_clock_never_read": "No process in this session ever read a clock the session replaces, so nothing this application did came from the fake date. The channels above are in place and working - the application simply took its time from somewhere else, such as a source outside this computer.", "time.fake_clock_clamped": "The fake clock reached the last date this build can represent (year 30828) and stood there for the rest of the session. Late readings are not the moments the chosen speed would have produced.", "time.duration_axis_clamped": "The monotonic counters (tick count, unbiased interrupt time, and QPC when scaled) reached the end of their range and stood there, so elapsed time inside the application stopped advancing even though the session went on. A lower speed or a shorter session avoids it.", + // The session does not stop the application, so it says which way each clock went once it lets go: "back to real time" alone reads as "the counters went back too", which is what letting go used to do. + "session.left_running": "The application was still running when the session ended. It is back on the real date and time now, and its timers and elapsed-time counters carry on at normal speed from where the session left them instead of jumping back. Restart it for a clean run on the real clock.", "target.single_instance_suspected": "exited right after it started, before the substitution could be confirmed", // Runtime detected statically from the target's files (B1): its monotonic/elapsed clocks stand on QueryPerformanceCounter, which stays real (ADR-2), so a timer built on them does not scale even though the wall clock does. Wording mirrors the CLI describe_warning. diff --git a/gui/ChronoMock.App/Localization/Strings.pl.json b/gui/ChronoMock.App/Localization/Strings.pl.json index d208ebe..3d4b5ce 100644 --- a/gui/ChronoMock.App/Localization/Strings.pl.json +++ b/gui/ChronoMock.App/Localization/Strings.pl.json @@ -425,6 +425,7 @@ "embedded.qt_port_taken": "Port zarezerwowany dla silnika Qt tej aplikacji został zajęty przez coś innego, zanim silnik mógł go użyć. Jego stron nie dało się osiągnąć i biegły na realnym zegarze.", "embedded.zone_is_host": "Strony wewnątrz tej aplikacji czytają strefę czasową tego komputera, nie sesji. Pokazywany przez nie czas lokalny różni się od reszty aplikacji o przesunięcie strefy.", "embedded.registry_arguments_hidden": "Ta aplikacja ma w rejestrze ustawione argumenty przeglądarki WebView2. Sesja przesłoniła je na czas swojego trwania, więc to, co ustawiały (na przykład własny port debugowania), nie zadziałało.", + "embedded.pages_not_released": "Strona wewnątrz tej aplikacji nie potwierdziła powrotu na prawdziwy zegar, gdy sesja się skończyła, więc może trzymać datę sesji, dopóki jej nie odświeżysz albo nie zamkniesz.", "embedded.web_engine_processes_uncovered": "Są wśród nich procesy osadzonego silnika web (WebView2 albo Qt WebEngine), więc część tego silnika działała na prawdziwym zegarze. Czy jego strony też - nie da się ustalić: wśród nazwanych procesów nie było renderera.", // R2-S9. Session-level, not per-process: it is about processes that never got a coverage slot, // so it arrives on session_verdict rather than on any one coverage event. @@ -440,6 +441,7 @@ "coverage.session_clock_never_read": "Żaden proces w tej sesji ani razu nie odczytał zegara, który sesja podmienia, więc nic z tego, co zrobiła aplikacja, nie wzięło się z fałszywej daty. Kanały powyżej są założone i działają - aplikacja po prostu wzięła czas skądinąd, na przykład ze źródła spoza tego komputera.", "time.fake_clock_clamped": "Fałszywy zegar doszedł do ostatniej daty, jaką ta wersja potrafi wyrazić (rok 30828), i stanął tam do końca sesji. Późniejsze odczyty nie są momentami, które dałaby wybrana prędkość.", "time.duration_axis_clamped": "Liczniki monotoniczne (licznik tyknięć, nieobciążony czas przerwań oraz QPC, gdy skalowany) doszły do końca swojego zakresu i stanęły, więc czas, jaki upłynął wewnątrz aplikacji, przestał rosnąć, mimo że sesja trwała dalej. Mniejsza prędkość albo krótsza sesja tego unika.", + "session.left_running": "Aplikacja nadal działała, gdy sesja się skończyła. Jest już z powrotem na prawdziwej dacie i godzinie, a jej liczniki i odliczania biegną dalej w normalnym tempie od miejsca, w którym zostawiła je sesja, zamiast się cofnąć. Żeby wystartowała od zera na prawdziwym zegarze, uruchom ją ponownie.", "target.single_instance_suspected": "zakończył się zaraz po uruchomieniu, zanim podmianę dało się potwierdzić", // Runtime detected statically from the target's files (B1): its monotonic/elapsed clocks stand on QueryPerformanceCounter, which stays real (ADR-2), so a timer built on them does not scale even though the wall clock does. Wording mirrors the CLI describe_warning. From 7316869afbfca6b16d2b6c587cb121bf6ce184cb Mon Sep 17 00:00:00 2001 From: DonislawDev Date: Thu, 24 Sep 2026 13:15:49 +0200 Subject: [PATCH 2/3] fix(report,test): say which timers stay fast after the session, and prove every axis was scaled Three points the review found, all checked against the code first. - The left-running warning said the application's timers carry on at normal speed. Tick counts and elapsed-time counters do, a repeating timer does not: its period was shortened once, when it was set, and the release only changes what is read or set afterwards. The CLI, English and Polish texts and the changelog now say so, for a timer set while timers were sped up, so the sentence stays true for a session that never sped them up. - The changelog said the session names a page that did not confirm it was let go. It raises one warning and names no page. - session_end.rs checked that the session scaled the tick count only, so its no-step-back checks on the interrupt time and QPC could pass over an axis that was never scaled. The probe now reports a starting rate for all three axes and the test requires each above 10 (below 2 in the control). Revert probe: the same session without --scale-qpc now fails with QPC at x1. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 10 ++-- crates/cli/src/report.rs | 6 ++- crates/cli/tests/session_end.rs | 46 +++++++++++++------ .../Localization/Strings.en.json | 2 +- .../Localization/Strings.pl.json | 2 +- 5 files changed, 43 insertions(+), 23 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c7cd12f..37e976d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -52,10 +52,12 @@ Notable changes to Chrono Mock, newest first. The format follows the time the session had added - 316 seconds after a five-second session at x60, on both 32 and 64 bit. Web pages inside the application (WebView2, Qt WebEngine) stayed on the session date and kept running at the session speed for as long as they were open, even with no option set. Now the - application is let go properly: the date and the time zone return to the real ones, its timers - and elapsed-time counters carry on at normal speed from where the session left them, and its - pages are handed back to the real clock as well. The session says that it left the application - running and what that means, and names a page that did not confirm it was handed back. + application is let go properly: the date and the time zone return to the real ones, its tick + counts and elapsed-time counters carry on at normal speed from where the session left them, and + its pages are handed back to the real clock as well. A repeating timer set while timers were sped + up keeps its shorter interval until it is set again. The session says that it left the + application running and what that means, and warns when a page did not confirm it was handed + back. - **A screen reader read the result's rows as code.** Every row of the audit's tables, every warning, the cleanup list, the speed and jump buttons and the calculator's lists told assistive technology what the row was built from rather than what it showed: a warning announced itself as diff --git a/crates/cli/src/report.rs b/crates/cli/src/report.rs index 6d1504e..92e4f56 100644 --- a/crates/cli/src/report.rs +++ b/crates/cli/src/report.rs @@ -305,9 +305,11 @@ pub(crate) fn describe_warning(key: &str) -> String { // The session does not stop the application (docs/01 section 8.4), so the tester is left with // one that changed clocks under their hands. Says which way each clock went, because "back to // real time" alone reads as "the counters went back too" - and it was exactly that, a 316 s - // step back at x60, that letting go used to do. + // step back at x60, that letting go used to do. A repeating timer is the exception, and it is + // named: its period was shortened once, when it was set, and the release changes only what is + // read or set from then on. "session.left_running" => { - "the application was still running when the session ended, so it is back on the real date and time now - its timers and elapsed-time counters carry on at normal speed from where the session left them instead of jumping back, and a restart gives it a clean run on the real clock" + "the application was still running when the session ended, so it is back on the real date and time now - its tick counts and elapsed-time counters carry on at normal speed from where the session left them instead of jumping back, a repeating timer it set while its timers were sped up keeps the shorter interval it was given, and a restart gives it a clean run on the real clock" } "embedded.pages_not_released" => { "a page inside the application did not confirm it was handed back to the real clock when the session ended, so it may keep the session date until it is reloaded or closed" diff --git a/crates/cli/tests/session_end.rs b/crates/cli/tests/session_end.rs index fc9ad4b..8273a90 100644 --- a/crates/cli/tests/session_end.rs +++ b/crates/cli/tests/session_end.rs @@ -59,9 +59,13 @@ fn axes(origin: Instant) -> [f64; 3] { [tick as f64, quit as f64 / 10_000.0, origin.elapsed().as_secs_f64() * 1000.0] } -/// Samples every few milliseconds for `SAMPLE_MS` of real time and writes, space separated: the tick -/// rate over the first real second, the tick rate over the last real second, and the largest step back -/// seen on the tick count, the interrupt time and QPC (0 when an axis never went back). +/// Samples every few milliseconds for `SAMPLE_MS` of real time and writes, space separated: the rate of +/// the tick count, the interrupt time and QPC over the first real second, the tick rate over the last +/// real second, and the largest step back seen on each of the three axes (0 when it never went back). +/// +/// A rate per axis at the start, not the tick count's alone: the step-back check on an axis the session +/// never scaled cannot fail, so without it a session that stopped scaling QUIT or QPC would pass here +/// with nothing measured on those two. #[test] #[ignore = "the target of `an_application_left_running_keeps_its_duration_axes_moving_forward`, not a test on its own"] fn probe_samples_the_duration_axes_past_the_session_end() { @@ -72,8 +76,8 @@ fn probe_samples_the_duration_axes_past_the_session_end() { let start = real_ms(); let mut last = axes(origin); let mut worst = [0.0f64; 3]; - let first_tick = last[0]; - let mut head_rate = None; + let first = last; + let mut head_rates = None; let mut tail_from = None; loop { // A sleep, not a spin: the session shortens it to its floor, which is still a millisecond, and @@ -85,8 +89,8 @@ fn probe_samples_the_duration_axes_past_the_session_end() { *w = w.min(reading[i] - last[i]); } last = reading; - if head_rate.is_none() && now >= 1_000.0 { - head_rate = Some((reading[0] - first_tick) / now); + if head_rates.is_none() && now >= 1_000.0 { + head_rates = Some([0, 1, 2].map(|i| (reading[i] - first[i]) / now)); } if tail_from.is_none() && now >= SAMPLE_MS - 1_000.0 { tail_from = Some((now, reading[0])); @@ -94,9 +98,9 @@ fn probe_samples_the_duration_axes_past_the_session_end() { if now >= SAMPLE_MS { let (t0, tick0) = tail_from.unwrap_or((now, reading[0])); let tail_rate = (reading[0] - tick0) / (now - t0).max(1.0); + let [head_tick, head_quit, head_qpc] = head_rates.unwrap_or([0.0; 3]); let line = format!( - "{:.2} {:.2} {:.1} {:.1} {:.1}", - head_rate.unwrap_or(0.0), + "{head_tick:.2} {head_quit:.2} {head_qpc:.2} {:.2} {:.1} {:.1} {:.1}", tail_rate, -worst[0], -worst[1], @@ -116,8 +120,9 @@ fn injected_library() -> PathBuf { .join("chrono_hook.dll") } -/// What the probe wrote: `[head rate, tail rate, step back on tick, on QUIT, on QPC]`. -fn measured(file: &std::path::Path) -> Option<[f64; 5]> { +/// What the probe wrote: `[head rate of tick, of QUIT, of QPC, tail rate, step back on tick, on QUIT, +/// on QPC]`. +fn measured(file: &std::path::Path) -> Option<[f64; 7]> { let text = std::fs::read_to_string(file).ok()?; let values: Vec = text.split_whitespace().filter_map(|v| v.parse().ok()).collect(); values.try_into().ok() @@ -149,8 +154,13 @@ fn an_application_left_running_keeps_its_duration_axes_moving_forward() { .output() .expect("the probe must run without a session"); assert!(run.status.success(), "the probe failed without a session: {}", String::from_utf8_lossy(&run.stdout)); - let [head, tail, ..] = measured(&control).expect("the probe wrote nothing without a session"); - assert!(head < 2.0 && tail < 2.0, "without a session the tick count moved x{head} then x{tail}, so this probe cannot tell"); + let [head_tick, head_quit, head_qpc, tail, ..] = + measured(&control).expect("the probe wrote nothing without a session"); + assert!( + head_tick < 2.0 && head_quit < 2.0 && head_qpc < 2.0 && tail < 2.0, + "without a session the axes moved x{head_tick} (tick), x{head_quit} (interrupt time), x{head_qpc} \ + (QPC) then x{tail}, so this probe cannot tell" + ); // The session ends after two heartbeats. The probe inherits the core's output, so `output()` // returns once the probe is done as well - which is what the result file needs. @@ -174,10 +184,16 @@ fn an_application_left_running_keeps_its_duration_axes_moving_forward() { .expect("the tool must run"); let stdout = String::from_utf8_lossy(&out.stdout); let context = || format!("stdout: {stdout} stderr: {}", String::from_utf8_lossy(&out.stderr)); - let Some([head, tail, tick_back, quit_back, qpc_back]) = measured(&session) else { + let Some([head_tick, head_quit, head_qpc, tail, tick_back, quit_back, qpc_back]) = measured(&session) else { panic!("the probe wrote nothing under the session. {}", context()); }; - assert!(head > 10.0, "the tick count moved x{head} during the session, so the session never scaled it. {}", context()); + // Every axis the step-back check reads has to have been scaled, or that check proves nothing on it. + assert!( + head_tick > 10.0 && head_quit > 10.0 && head_qpc > 10.0, + "during the session the axes moved x{head_tick} (tick), x{head_quit} (interrupt time), x{head_qpc} \ + (QPC), so the session did not scale all three. {}", + context() + ); assert!(tail < 2.0, "the tick count still moved x{tail} after the session, so the probe did not outlive it. {}", context()); assert!( tick_back == 0.0 && quit_back == 0.0 && qpc_back == 0.0, diff --git a/gui/ChronoMock.App/Localization/Strings.en.json b/gui/ChronoMock.App/Localization/Strings.en.json index 03f4b16..6d62d45 100644 --- a/gui/ChronoMock.App/Localization/Strings.en.json +++ b/gui/ChronoMock.App/Localization/Strings.en.json @@ -460,7 +460,7 @@ "time.fake_clock_clamped": "The fake clock reached the last date this build can represent (year 30828) and stood there for the rest of the session. Late readings are not the moments the chosen speed would have produced.", "time.duration_axis_clamped": "The monotonic counters (tick count, unbiased interrupt time, and QPC when scaled) reached the end of their range and stood there, so elapsed time inside the application stopped advancing even though the session went on. A lower speed or a shorter session avoids it.", // The session does not stop the application, so it says which way each clock went once it lets go: "back to real time" alone reads as "the counters went back too", which is what letting go used to do. - "session.left_running": "The application was still running when the session ended. It is back on the real date and time now, and its timers and elapsed-time counters carry on at normal speed from where the session left them instead of jumping back. Restart it for a clean run on the real clock.", + "session.left_running": "The application was still running when the session ended. It is back on the real date and time now, and its tick counts and elapsed-time counters carry on at normal speed from where the session left them instead of jumping back. A repeating timer it set while its timers were sped up keeps the shorter interval it was given. Restart it for a clean run on the real clock.", "target.single_instance_suspected": "exited right after it started, before the substitution could be confirmed", // Runtime detected statically from the target's files (B1): its monotonic/elapsed clocks stand on QueryPerformanceCounter, which stays real (ADR-2), so a timer built on them does not scale even though the wall clock does. Wording mirrors the CLI describe_warning. diff --git a/gui/ChronoMock.App/Localization/Strings.pl.json b/gui/ChronoMock.App/Localization/Strings.pl.json index 3d4b5ce..e9547b6 100644 --- a/gui/ChronoMock.App/Localization/Strings.pl.json +++ b/gui/ChronoMock.App/Localization/Strings.pl.json @@ -441,7 +441,7 @@ "coverage.session_clock_never_read": "Żaden proces w tej sesji ani razu nie odczytał zegara, który sesja podmienia, więc nic z tego, co zrobiła aplikacja, nie wzięło się z fałszywej daty. Kanały powyżej są założone i działają - aplikacja po prostu wzięła czas skądinąd, na przykład ze źródła spoza tego komputera.", "time.fake_clock_clamped": "Fałszywy zegar doszedł do ostatniej daty, jaką ta wersja potrafi wyrazić (rok 30828), i stanął tam do końca sesji. Późniejsze odczyty nie są momentami, które dałaby wybrana prędkość.", "time.duration_axis_clamped": "Liczniki monotoniczne (licznik tyknięć, nieobciążony czas przerwań oraz QPC, gdy skalowany) doszły do końca swojego zakresu i stanęły, więc czas, jaki upłynął wewnątrz aplikacji, przestał rosnąć, mimo że sesja trwała dalej. Mniejsza prędkość albo krótsza sesja tego unika.", - "session.left_running": "Aplikacja nadal działała, gdy sesja się skończyła. Jest już z powrotem na prawdziwej dacie i godzinie, a jej liczniki i odliczania biegną dalej w normalnym tempie od miejsca, w którym zostawiła je sesja, zamiast się cofnąć. Żeby wystartowała od zera na prawdziwym zegarze, uruchom ją ponownie.", + "session.left_running": "Aplikacja nadal działała, gdy sesja się skończyła. Jest już z powrotem na prawdziwej dacie i godzinie, a jej liczniki czasu biegną dalej w normalnym tempie od miejsca, w którym zostawiła je sesja, zamiast się cofnąć. Timer cykliczny ustawiony, gdy jej timery były przyspieszone, zachowuje skrócony odstęp, który wtedy dostał. Żeby wystartowała od zera na prawdziwym zegarze, uruchom ją ponownie.", "target.single_instance_suspected": "zakończył się zaraz po uruchomieniu, zanim podmianę dało się potwierdzić", // Runtime detected statically from the target's files (B1): its monotonic/elapsed clocks stand on QueryPerformanceCounter, which stays real (ADR-2), so a timer built on them does not scale even though the wall clock does. Wording mirrors the CLI describe_warning. From fb35bc50a74e50cfd8ef190a5ce84ad1c698366b Mon Sep 17 00:00:00 2001 From: DonislawDev Date: Thu, 24 Sep 2026 13:15:49 +0200 Subject: [PATCH 3/3] fix(protocol): keep the core's last events when the panel stops a session Stop disposes the core client, and dispose closed the event stream as soon as the core had exited. The core writes the session verdict and `ended` last, and an event the read loop takes out of the pipe after the close is dropped. Replayed through CoreClient exactly as Stop does it (launch, a few seconds of session, dispose, then read what is left), one run in eight lost the verdict and everything after it and another lost `ended` - so the panel could show a stopped session without its verdict, which is where the new left-running warning is carried. Dispose now waits for the read loop to hand on `ended`, the last line of a clean end, before it closes the stream, and a core that never wrote it costs a bounded 500 ms instead. The same replay after the change: 20 of 20 runs kept the verdict, the warning and `ended`. Co-Authored-By: Claude Opus 5.5 --- gui/ChronoMock.Protocol/CoreClient.cs | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/gui/ChronoMock.Protocol/CoreClient.cs b/gui/ChronoMock.Protocol/CoreClient.cs index ad0bb42..f53e1df 100644 --- a/gui/ChronoMock.Protocol/CoreClient.cs +++ b/gui/ChronoMock.Protocol/CoreClient.cs @@ -49,6 +49,9 @@ public sealed class CoreClient : IAsyncDisposable private readonly object _stdinLock = new(); private readonly Task _readLoop; private readonly Task _stderrDrain; + /// Set once the read loop has handed on the core's ended, the last line a core that + /// ended cleanly writes. Dispose waits on it before it closes the event stream. + private readonly TaskCompletionSource _endedRead = new(TaskCreationOptions.RunContinuationsAsynchronously); private int _disposed; private CoreClient(Process process) @@ -193,6 +196,10 @@ private async Task ReadEventsAsync() if (evt is not null) { await _events.Writer.WriteAsync(evt).ConfigureAwait(false); + if (evt is EndedEvent) + { + _endedRead.TrySetResult(); + } } } } @@ -274,6 +281,14 @@ public async ValueTask DisposeAsync() // ends, then falls back to its 15 s idle watchdog), so the target's lifetime must not be what // decides when a stopped session looks stopped. Already-written events stay readable - completing // a channel closes it to WRITERS, not to a reader draining what is left. + // + // But only once the read loop has taken what the core wrote before it exited. Closing at once + // lost the tail, and the tail is the part that matters: the core writes the session verdict and + // `ended` last, and an event the read loop takes out of the pipe after the close is dropped. + // Measured over this Stop path (2026-09-24, eight runs): one lost the verdict and everything after + // it, another lost `ended`. `ended` is the last line of a clean end, so it is the exact signal, and + // a core that never wrote it costs the bounded wait instead. + await Task.WhenAny(_endedRead.Task, Task.Delay(DrainTimeout)).ConfigureAwait(false); _events.Writer.TryComplete(); // Bounded join for the same reason: the read loop can be parked on ReadLineAsync for as long as @@ -325,6 +340,12 @@ internal static int TrimToCap(ConcurrentQueue queue, int cap) /// reader - the process dispose that follows closes the stream underneath it. private static readonly TimeSpan JoinTimeout = TimeSpan.FromSeconds(2); + /// How long dispose lets the read loop hand on what the core wrote before it exited, when the + /// core's ended has not been read yet. Only a core that was killed, or died, before writing + /// ended waits this long - a core that ended cleanly releases the wait as soon as its last line + /// is read, which is a matter of milliseconds because it is already in the pipe. + private static readonly TimeSpan DrainTimeout = TimeSpan.FromMilliseconds(500); + private async Task AwaitQuietly(Task task, TimeSpan? timeout = null) { try