diff --git a/CHECKLIST-mutation-survivors.md b/CHECKLIST-mutation-survivors.md index 6c6193eb..25fb7403 100644 --- a/CHECKLIST-mutation-survivors.md +++ b/CHECKLIST-mutation-survivors.md @@ -77,15 +77,28 @@ to the engineer, not to whoever picks up this checklist. - [ ] **MS-2.1** -- **`windows-platform-probes`: 511 survivors, 17% caught.** See [windows-platform-probes.md](mutation-sweeps/2026-09-02/windows-platform-probes.md). - Fourteen executable probes you *run* to answer a question about Windows, not a - library with a test surface; `publish = false` at version `0.0.0`. Most of the + Executable probes you *run* to answer a question about Windows, not a library + with a test surface; `publish = false` at version `0.0.0`. Most of the survivors are `main`-adjacent code no test was ever going to reach. Judging this crate by mutation score is measuring the wrong thing. - A related, separately-tracked item: twelve of these probes still print - directly rather than through the `Report` sink, tracked as `SH-13.4` on the - branch that ships the topology and queue crates. That checklist is not in this - repository yet, so this deliberately names the item rather than linking a file - that does not exist. Doing that first would make some of this reachable. + **The sweep measured a fourteen-probe tree, of which eight are in this + repository** -- `core_affinity`, `peer_index_cache`, `doorbell_cost`, + `queue_contention`, `request_cost` and `topology` were only ever on the + originating branch, so six of the fourteen sections in the sweep report have no + counterpart here yet. Read the totals with that in mind before scoping any of + it. + A related, separately-tracked item, **partly discharged**: at sweep time twelve + of those fourteen probes printed directly rather than through a `Report` sink, + tracked as `SH-13.4` on the branch that ships the topology and queue crates. + The sink has since landed here + ([crates/windows-platform-probes/src/report.rs](crates/windows-platform-probes/src/report.rs)) + and all eight probes in this repository route through it, so what remains of + `SH-13.4` is the six branch-only probes, and it stays named rather than linked + because that branch checklist is still not in this repository. The crate's own + durable work now has a home to link: + [crates/windows-platform-probes/CHECKLIST.md](crates/windows-platform-probes/CHECKLIST.md). + For the eight that landed, the "would make some of this reachable" prerequisite + is met -- each `main` is one line and each report is a `String` a test can read. - [ ] **MS-2.2** -- **`windows-file-watcher-example-test-harness`: 69 survivors.** See [windows-file-watcher-example-test-harness.md](mutation-sweeps/2026-09-02/windows-file-watcher-example-test-harness.md). diff --git a/Cargo.lock b/Cargo.lock index 7b40a6ac..176b4850 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -216,6 +216,7 @@ dependencies = [ name = "windows-platform-probes" version = "0.0.0" dependencies = [ + "windows-placement-probe", "windows-sys", "windows-threadpool-sys", ] diff --git a/PLANS.md b/PLANS.md index 99e7599d..3d9617ba 100644 --- a/PLANS.md +++ b/PLANS.md @@ -20,6 +20,7 @@ plans tracker: [crates/windows-file-enumeration-sys/PLANS.md](crates/windows-fil | [CHECKLIST-thread-ambient.md](CHECKLIST-thread-ambient.md) | in progress | M22-M23: extract the captured-context composite into `windows-thread-ambient-sys`, a standalone platform layer that captures a thread's ambient state and applies it on another thread. M24-M26: `windows-namespace-request-sys`, marshalable Win32 namespace call parameter sets, over a round-one entry list audited from three real consumers (this repository's watcher and enumeration crates, and `MikeGrier/Globazog-rs`) rather than guessed. M27: `windows-platform-probes`, a durable home for the measurements this workspace's designs rest on, under a three-tier scheme (asserted / ignored / binary-only) where every tier is compiled by an ordinary build. Feature-scoped and deleted when complete; it is the whole of the `mikegrier/thread-ambient` branch's work, and is deliberately separate from the deferred namespace-facility items in [CHECKLIST.md](CHECKLIST.md). | [crates/windows-thread-ambient-sys/DESIGN-NOTES.md](crates/windows-thread-ambient-sys/DESIGN-NOTES.md) | | [crates/windows-overlapped-io-sys/CHECKLIST.md](crates/windows-overlapped-io-sys/CHECKLIST.md) | not started | M14: finish the contract audit -- categories 1, 2, 6, 8, 9 were not examined -- and sweep `outstanding()` for the advisory-predicate hazard. | [crates/windows-overlapped-io-sys/DESIGN-NOTES.md](crates/windows-overlapped-io-sys/DESIGN-NOTES.md) | | [crates/windows-ioring-sys/CHECKLIST.md](crates/windows-ioring-sys/CHECKLIST.md) | in progress | Memory-safe Rust over the Windows `IoRing` submission/completion ring, as a new crate. M1-M7 (ring lifecycle through the `ring-copy` topology-aligned sample) are complete and archived. The parked, pinned-thread `M6+` work and the new M10 contract audit remain. | [crates/windows-ioring-sys/DESIGN-NOTES.md](crates/windows-ioring-sys/DESIGN-NOTES.md) | +| [crates/windows-platform-probes/CHECKLIST.md](crates/windows-platform-probes/CHECKLIST.md) | not started | M1: stream a probe's report as it is measured. The one-sink refactor has each renderer compose its report into a `String`, which buys the seam that lets a probe's findings be asserted rather than eyeballed, and gives up output appearing as it is measured. `emit_report` recovers that for an unwinding panic only; Ctrl-C and an abort during unwinding still discard the buffer. Costs most on `probe-cancel-io`, which runs about twenty seconds precisely when the wedge it hunts for occurs -- precisely when a reader interrupts. | [crates/windows-platform-probes/DESIGN-NOTES.md](crates/windows-platform-probes/DESIGN-NOTES.md#d-buffered-report) | | [CHECKLIST-mutation-survivors.md](CHECKLIST-mutation-survivors.md) | not started | Work queued from the workspace-wide cargo-mutants sweep of 2026-09-02, whose findings are kept in [mutation-sweeps/2026-09-02/](mutation-sweeps/2026-09-02/README.md) rather than re-derived -- the run took roughly fourteen hours. 2,792 caught, 1,112 survived, 198 timed out. **The headline numbers mislead in three ways and the README says how**: a timeout in a blocking-API crate is usually a detection that lost its name rather than a gap (measured: one of `windows-waitable-queues`' 120 timeouts fails four tests in 0.00s when re-injected alone), a low score on an executable probe crate is measuring the wrong thing, and three kinds of survivor -- equivalent mutants, unreachable code, and constants that want a `const` assertion -- are not missing tests at all. M1 covers the shipping crates; M2 holds the two crates that are not libraries and whose scope is an engineer's decision; M3 re-runs and prunes rather than hand-editing the tool's output into a second source of truth. | [mutation-sweeps/2026-09-02/README.md](mutation-sweeps/2026-09-02/README.md) | Add a row here when new work is planned, against [CHECKLIST.md](CHECKLIST.md) or any crate's. diff --git a/crates/windows-platform-probes/CHECKLIST.md b/crates/windows-platform-probes/CHECKLIST.md new file mode 100644 index 00000000..ea01dcd0 --- /dev/null +++ b/crates/windows-platform-probes/CHECKLIST.md @@ -0,0 +1,55 @@ +# Checklist: windows-platform-probes + +Design decisions are in [DESIGN-NOTES.md](DESIGN-NOTES.md). This crate's *creation* is tracked +separately, in the workspace [CHECKLIST-thread-ambient.md](../../CHECKLIST-thread-ambient.md) milestone +M27; that file is feature-scoped and is deleted when its feature completes, so durable follow-up work +for the crate belongs here instead. + +## M1 -- Stream a probe's report as it is measured + +The report sink introduced with [src/report.rs](src/report.rs) has each renderer compose its whole +report into a `String`, which `emit_report` then hands to a [`Report`]. That buys the seam the crate +wanted -- a probe's findings can be asserted rather than eyeballed -- and it gave up a property the +previous line-by-line `println!` had for free: output appearing as it is measured. + +`emit_report` recovers it for an **unwinding panic** only, by catching, emitting what was composed, and +resuming. A termination that does not unwind still discards the buffer: + +- **Ctrl-C.** The default Windows console handler terminates the process; no unwind runs. +- **Abort from a panic raised while already unwinding.** + +The case that costs most is `probe-cancel-io`: four attempts against a five-second watchdog, so about +twenty seconds, and it runs that long *precisely when the wedge it hunts for occurs* -- which is +precisely when a reader gives up and interrupts. The measurement most worth having is the one most +likely to be thrown away. + +See [DESIGN-NOTES.md](DESIGN-NOTES.md) -> [The report is buffered, and what that +costs](DESIGN-NOTES.md#d-buffered-report) for why it was built this way and why the fix is a separate +piece of work rather than a correction to that one. + +- [ ] **M1.1** -- Decide how a formatted line reaches the sink, because that choice is what makes the + rest mechanical. Every renderer today writes through `let _ = writeln!(out, ...)` against a + `String`'s `fmt::Write` -- roughly 156 sites across the eight probes -- so the sink must accept + *formatted* output, not just `&str`, or every site grows a `format!` and an allocation per line. + The options differ in what they cost callers, and the choice is the engineer's: + (a) give `Report` a method taking `fmt::Arguments` plus a `report_line!` macro, so a call site stays + one line and reads almost as it does now; + (b) implement `fmt::Write` for the sink types, so `writeln!(out, ...)` keeps working verbatim against + a `&mut dyn Report` -- smallest diff at the call sites, but `fmt::Write` is line-agnostic, so the sink + must split on newlines internally and `Captured`'s one-line-per-entry guarantee has to be re-established + rather than assumed; + (c) leave the renderers writing to a `String` and flush it to the sink at each line boundary, which + streams without touching the call sites but keeps two buffers. + +- [ ] **M1.2** -- Convert the eight renderers to write into the sink as they measure, and simplify + `emit_report` accordingly: once lines leave as they are produced, catching the unwind is no longer + what makes partial output work, and the `catch_unwind`/`resume_unwind` pair should be removed rather + than left as machinery that no longer earns its place. Keep `Captured` working -- it is what every + in-process test asserts against. + +- [ ] **M1.3** -- Verify by interruption, not by reasoning. Sending Ctrl-C to a probe part-way through + must leave the already-measured lines on the terminal; today it leaves nothing. Assert the in-process + half (a renderer that panics mid-report still has its finished lines in a `Captured`) as a unit test, + and record the Ctrl-C observation in [DESIGN-NOTES.md](DESIGN-NOTES.md) -- an interactive signal is not + something to assert in CI, but it is the property the milestone exists for, so it must be measured + once rather than assumed. diff --git a/crates/windows-platform-probes/Cargo.toml b/crates/windows-platform-probes/Cargo.toml index 185b2206..b1a41e4e 100644 --- a/crates/windows-platform-probes/Cargo.toml +++ b/crates/windows-platform-probes/Cargo.toml @@ -48,10 +48,26 @@ name = "probe-pool-growth" path = "src/bin/pool_growth.rs" [dependencies] +# **Every workspace dependency below is path-only, with no `version`**, because +# this crate is never distributed at all -- not to a registry, and not as a +# released binary either, unlike `windows-placement-probe` next door. These +# probes are a development instrument, run from a checkout, and `publish = false` +# above is the whole story. +# +# A `version` beside a `path` is consulted only when the depending crate is +# packaged, but cargo still requires the path crate's own version to satisfy it +# at every build -- so a pin left behind by a bump breaks the whole workspace's +# resolution rather than only this crate's. +# # The pool-growth probe measures the shipping API rather than a # reimplementation of the SDK's inline environment helpers, so it depends on the # real crate. -windows-threadpool-sys = { version = "0.1.3", path = "../windows-threadpool-sys" } +windows-threadpool-sys = { path = "../windows-threadpool-sys" } +# Every probe's report opens with a line naming the machine that produced it and +# whether the measurement is tainted, so a captured finding cannot be pasted +# somewhere and compared against something it does not describe. That banner is +# `windows-placement-probe`'s to render, not a second copy here. +windows-placement-probe = { path = "../windows-placement-probe" } [dependencies.windows-sys] version = "0.61.2" diff --git a/crates/windows-platform-probes/DESIGN-NOTES.md b/crates/windows-platform-probes/DESIGN-NOTES.md index b3d530db..5d7b1167 100644 --- a/crates/windows-platform-probes/DESIGN-NOTES.md +++ b/crates/windows-platform-probes/DESIGN-NOTES.md @@ -1,7 +1,9 @@ # Design notes: windows-platform-probes -Decisions for this crate. Pending work is in the workspace -[CHECKLIST-thread-ambient.md](../../CHECKLIST-thread-ambient.md), milestone M27. +Decisions for this crate. Pending work is in [CHECKLIST.md](CHECKLIST.md); the +crate's *creation* is tracked separately in the workspace +[CHECKLIST-thread-ambient.md](../../CHECKLIST-thread-ambient.md), milestone M27, +which is feature-scoped and deleted when that feature completes. ## A probe is a function that returns an observation, never a program that prints one @@ -457,3 +459,42 @@ characters, so no mangling occurred -- an accident of environment, not of architecture. It would fail on any host with a longer user name, on either architecture. Recorded here because it is exactly the kind of result this comparison exists to classify correctly: a red build that is **not** a finding. + +## The report is buffered, and what that costs + + + +Every probe's output goes through one sink: the renderer composes its report into +a `String` and `emit_report` hands it to a [`Report`]. That is what the +repository's architectural pre-step asks for -- the real stream is named in +`report` and nowhere else, so a probe's `main` is one line that chooses no stream +at all -- and it is what lets a test assert a probe's findings instead of a human +reading them off a terminal. + +It also gave something up. Printing line-by-line meant whatever had been measured +was already on the terminal; buffering means nothing is, until the renderer +returns. These probes call into measurements documented to panic -- +`worker_context`'s impersonating observation panics three ways, and its renderer +composes several completed findings before reaching it -- stated without a count +deliberately, because the number moves whenever a line is added, and a stale count +is the drift this repository keeps paying for -- so this is not hypothetical. For an +instrument whose whole purpose is that a failure be diagnosable, how far it got is +exactly the information worth keeping. + +`emit_report` recovers it for an unwinding panic: catch, emit what was composed, +resume, so the exit status and message are unchanged and the partial report is +added to them rather than substituted. **It does not recover it for a termination +that does not unwind** -- Ctrl-C, which the default Windows console handler serves +by terminating the process, and an abort from a panic raised during unwinding. + +That bound is known rather than overlooked, and it is not a defect in +`emit_report` to be patched there: the fix is renderers writing into a [`Report`] +as they measure rather than into a `String`, which restores streaming for *every* +termination mode and makes the catch/resume machinery unnecessary. That changes +every renderer and the shape of the sink trait, so it is queued as its own work -- +[CHECKLIST.md](CHECKLIST.md) milestone M1 -- rather than folded into the commit +that introduced the sink. + +The ordering was deliberate. The sink had to exist before the probes could be +peeled off their originating branch in reviewable stages, and a design that +streams is a different design, not a later revision of this one. diff --git a/crates/windows-platform-probes/PLANS.md b/crates/windows-platform-probes/PLANS.md index 6e557be8..e2aa1b16 100644 --- a/crates/windows-platform-probes/PLANS.md +++ b/crates/windows-platform-probes/PLANS.md @@ -4,4 +4,5 @@ Design decisions are in [DESIGN-NOTES.md](DESIGN-NOTES.md). | Path to CHECKLIST.md | Status | Brief description | Design Notes | |---|---|---|---| +| [CHECKLIST.md](CHECKLIST.md) | not started | M1: stream a probe's report as it is measured. The report sink buffers each report into a `String`, so a termination that does not unwind -- Ctrl-C, or an abort during unwinding -- discards it, where the line-by-line printing it replaced kept it. Costs most on `probe-cancel-io`, which runs about twenty seconds precisely when the wedge it hunts for occurs. | [DESIGN-NOTES.md](DESIGN-NOTES.md#d-buffered-report) | | [../../CHECKLIST-thread-ambient.md](../../CHECKLIST-thread-ambient.md) | in progress | M27: create the crate, migrate this session's probes into it under the three-tier scheme, and queue migration of the nine earlier measurements that still live only in git-ignored scratch. | [DESIGN-NOTES.md](DESIGN-NOTES.md) | diff --git a/crates/windows-platform-probes/src/bin/cancel_io.rs b/crates/windows-platform-probes/src/bin/cancel_io.rs index 013801ae..cbf1c88b 100644 --- a/crates/windows-platform-probes/src/bin/cancel_io.rs +++ b/crates/windows-platform-probes/src/bin/cancel_io.rs @@ -11,9 +11,11 @@ //! is a call that can fail to return, so every case here runs behind a //! watchdog; a wedged `#[test]` would take the whole suite with it. +use std::fmt::Write as _; use windows_platform_probes::cancel_io::{ CancelOutcome, WATCHDOG, cancel_against_busy_thread, cancel_against_idle_thread, }; +use windows_platform_probes::report::emit_report; fn describe(outcome: CancelOutcome) -> String { match outcome { @@ -26,37 +28,91 @@ fn describe(outcome: CancelOutcome) -> String { } fn main() { - println!("== is CancelSynchronousIo safe to point at a shared thread? ==\n"); - println!("watchdog: {WATCHDOG:?} per attempt\n"); + // The probe's whole output policy, and it is one line: hand the renderer to + // the sink. Nothing here or below names a stream -- that is chosen once, in + // `report`, so retargeting a probe is not a rewrite. + emit_report(render); +} + +/// The probe's whole report, as text. +fn render(out: &mut String) { + // First line of the report, and part of the returned text rather than + // written out here: a captured report must carry the line naming the + // machine that produced it, and the taint marker with it. Without it a + // finding can be pasted anywhere and compared against anything. + let _ = writeln!( + out, + "{}", + windows_placement_probe::fingerprint::banner_line() + ); + let _ = writeln!( + out, + "== is CancelSynchronousIo safe to point at a shared thread? ==\n" + ); + let _ = writeln!(out, "watchdog: {WATCHDOG:?} per attempt\n"); - println!("case 1: cancel against a thread with no I/O outstanding"); + let _ = writeln!( + out, + "case 1: cancel against a thread with no I/O outstanding" + ); let idle = cancel_against_idle_thread(); - println!(" {}", describe(idle)); - println!( + let _ = writeln!(out, " {}", describe(idle)); + let _ = writeln!( + out, " -> a point-in-time cancel finds nothing here; a standing request\n against the thread would not." ); - println!("\ncase 2: cancel against a thread hammering synchronous reads"); + let _ = writeln!( + out, + "\ncase 2: cancel against a thread hammering synchronous reads" + ); let busy = cancel_against_busy_thread(4); for (attempt, outcome) in busy.iter().enumerate() { - println!(" attempt {}: {}", attempt + 1, describe(*outcome)); + let _ = writeln!(out, " attempt {}: {}", attempt + 1, describe(*outcome)); } let wedged = busy.iter().any(|outcome| !outcome.returned()); - println!("\nconclusion:"); + let _ = writeln!(out, "\nconclusion:"); if wedged { - println!(" CancelSynchronousIo DID NOT RETURN against a thread that keeps"); - println!(" re-entering synchronous I/O. In the proposed mid-flight"); - println!(" cancellation design the canceller is a control-plane thread and"); - println!(" the target is a shared pool worker -- so a control plane can be"); - println!(" wedged by the very thing it is trying to rescue."); - println!(" This is why mid-flight cancellation stays deferred."); + let _ = writeln!( + out, + " CancelSynchronousIo DID NOT RETURN against a thread that keeps" + ); + let _ = writeln!( + out, + " re-entering synchronous I/O. In the proposed mid-flight" + ); + let _ = writeln!( + out, + " cancellation design the canceller is a control-plane thread and" + ); + let _ = writeln!( + out, + " the target is a shared pool worker -- so a control plane can be" + ); + let _ = writeln!(out, " wedged by the very thing it is trying to rescue."); + let _ = writeln!(out, " This is why mid-flight cancellation stays deferred."); } else { - println!(" every attempt returned on this host and this Windows build."); - println!(" That does NOT clear the design: the original measurement wedged"); - println!(" with four identical noninvasive samples over twelve seconds, so"); - println!(" a non-wedge here is a timing difference rather than a refutation."); - println!(" Re-run, and vary the hammer loop, before concluding otherwise."); + let _ = writeln!( + out, + " every attempt returned on this host and this Windows build." + ); + let _ = writeln!( + out, + " That does NOT clear the design: the original measurement wedged" + ); + let _ = writeln!( + out, + " with four identical noninvasive samples over twelve seconds, so" + ); + let _ = writeln!( + out, + " a non-wedge here is a timing difference rather than a refutation." + ); + let _ = writeln!( + out, + " Re-run, and vary the hammer loop, before concluding otherwise." + ); } } diff --git a/crates/windows-platform-probes/src/bin/completion_port.rs b/crates/windows-platform-probes/src/bin/completion_port.rs index 3b67a218..2b3a9977 100644 --- a/crates/windows-platform-probes/src/bin/completion_port.rs +++ b/crates/windows-platform-probes/src/bin/completion_port.rs @@ -13,11 +13,14 @@ //! completion arrived, and so read a clean failure -- result code //! `ERROR_INVALID_PARAMETER`, zero bytes -- as a success. +use std::fmt::Write as _; use windows_platform_probes::completion_port::{CompletionPortFinding, ReadAttempt, measure}; use windows_platform_probes::ioring::IoRingSupport; +use windows_platform_probes::report::emit_report; -fn describe(label: &str, attempt: ReadAttempt) { - println!( +fn describe(out: &mut String, label: &str, attempt: ReadAttempt) { + let _ = writeln!( + out, " {label:<46} result={:#010x} bytes={} first={:#04x} [{}]", attempt.result_code, attempt.bytes, @@ -26,26 +29,34 @@ fn describe(label: &str, attempt: ReadAttempt) { ); } -fn report(finding: CompletionPortFinding) { - println!("a PASS needs all three: success code, full byte count, and the fill byte.\n"); +fn report(out: &mut String, finding: CompletionPortFinding) { + let _ = writeln!( + out, + "a PASS needs all three: success code, full byte count, and the fill byte.\n" + ); describe( + out, "case 1 CONTROL: no association at all", finding.control_unassociated, ); describe( + out, "case 2 TEST: associated, then IoRing read", finding.after_iocp_association, ); describe( + out, "case 3a: IoRing read BEFORE association", finding.before_late_association, ); describe( + out, "case 3b: IoRing read AFTER association", finding.after_late_association, ); - println!( + let _ = writeln!( + out, " {:<46} [{}]", "case 4 CONTROL: overlapped read via the port", if finding.port_still_works { @@ -55,54 +66,115 @@ fn report(finding: CompletionPortFinding) { } ); describe( + out, "case 5a: IoRing BEFORE CreateThreadpoolIo", finding.before_threadpool_io, ); describe( + out, "case 5b: IoRing AFTER CreateThreadpoolIo", finding.after_threadpool_io, ); - println!("\n--- verdict ---"); + let _ = writeln!(out, "\n--- verdict ---"); if !finding.is_valid() { - println!(" INVALID: a negative control failed, so nothing can be concluded."); - println!(" The probe is broken rather than the platform answering."); + let _ = writeln!( + out, + " INVALID: a negative control failed, so nothing can be concluded." + ); + let _ = writeln!( + out, + " The probe is broken rather than the platform answering." + ); return; } if finding.association_forecloses_ioring() { - println!(" IOCP association FORECLOSES IoRing use of the same handle."); + let _ = writeln!( + out, + " IOCP association FORECLOSES IoRing use of the same handle." + ); if finding.port_still_works { - println!(" The handle is still healthy -- it completes through the port -- so it"); - println!(" is the IoRing path specifically that is refused, not the handle."); + let _ = writeln!( + out, + " The handle is still healthy -- it completes through the port -- so it" + ); + let _ = writeln!( + out, + " is the IoRing path specifically that is refused, not the handle." + ); } else { - println!(" NOTE: the port control also failed, so the handle may be broken"); - println!(" outright rather than only the IoRing path being refused."); + let _ = writeln!( + out, + " NOTE: the port control also failed, so the handle may be broken" + ); + let _ = writeln!( + out, + " outright rather than only the IoRing path being refused." + ); } } else { - println!(" COEXIST: association does NOT prevent IoRing use of the handle."); - println!(" This contradicts the reading windows-namespace-request-sys rests on;"); - println!(" the handle-destination fork would need revisiting."); + let _ = writeln!( + out, + " COEXIST: association does NOT prevent IoRing use of the handle." + ); + let _ = writeln!( + out, + " This contradicts the reading windows-namespace-request-sys rests on;" + ); + let _ = writeln!(out, " the handle-destination fork would need revisiting."); } if finding.threadpool_io_forecloses_ioring() { - println!("\n CreateThreadpoolIo forecloses it the SAME way. That is the path this"); - println!(" workspace actually uses, so the consequence lands on"); - println!(" windows-threadpool-sys's own users."); + let _ = writeln!( + out, + "\n CreateThreadpoolIo forecloses it the SAME way. That is the path this" + ); + let _ = writeln!( + out, + " workspace actually uses, so the consequence lands on" + ); + let _ = writeln!(out, " windows-threadpool-sys's own users."); } else { - println!("\n CreateThreadpoolIo does NOT foreclose it, which differs from raw IOCP."); - println!(" Worth knowing: the two are not interchangeable for this purpose."); + let _ = writeln!( + out, + "\n CreateThreadpoolIo does NOT foreclose it, which differs from raw IOCP." + ); + let _ = writeln!( + out, + " Worth knowing: the two are not interchangeable for this purpose." + ); } } fn main() { - println!("== IOCP association vs IoRing, on one handle ==\n"); + // The probe's whole output policy, and it is one line: hand the renderer to + // the sink. Nothing here or below names a stream -- that is chosen once, in + // `report`, so retargeting a probe is not a rewrite. + emit_report(render); +} + +/// The probe's whole report, as text. +fn render(out: &mut String) { + // First line of the report, and part of the returned text rather than + // written out here: a captured report must carry the line naming the + // machine that produced it, and the taint marker with it. Without it a + // finding can be pasted anywhere and compared against anything. + let _ = writeln!( + out, + "{}", + windows_placement_probe::fingerprint::banner_line() + ); + let _ = writeln!(out, "== IOCP association vs IoRing, on one handle ==\n"); match measure() { IoRingSupport::Unavailable => { - println!("this host has no usable IoRing, so nothing was measured."); - println!("('cannot ask' is not 'the answer is no'.)"); + let _ = writeln!( + out, + "this host has no usable IoRing, so nothing was measured." + ); + let _ = writeln!(out, "('cannot ask' is not 'the answer is no'.)"); } - IoRingSupport::Measured(finding) => report(finding), + IoRingSupport::Measured(finding) => report(out, finding), } } diff --git a/crates/windows-platform-probes/src/bin/device_map.rs b/crates/windows-platform-probes/src/bin/device_map.rs index 6e26ea40..f087a068 100644 --- a/crates/windows-platform-probes/src/bin/device_map.rs +++ b/crates/windows-platform-probes/src/bin/device_map.rs @@ -13,65 +13,128 @@ //! path resolved on a submitting thread and opened on a worker under a captured //! token can name a different device. +use std::fmt::Write as _; use windows_platform_probes::device_map::{SubstDrive, measure_with_subst}; +use windows_platform_probes::report::emit_report; fn main() { - println!("== does impersonation change the DOS device map? ==\n"); + // The probe's whole output policy, and it is one line: hand the renderer to + // the sink. Nothing here or below names a stream -- that is chosen once, in + // `report`, so retargeting a probe is not a rewrite. + emit_report(render); +} + +/// The probe's whole report, as text. +fn render(out: &mut String) { + // First line of the report, and part of the returned text rather than + // written out here: a captured report must carry the line naming the + // machine that produced it, and the taint marker with it. Without it a + // finding can be pasted anywhere and compared against anything. + let _ = writeln!( + out, + "{}", + windows_placement_probe::fingerprint::banner_line() + ); + let _ = writeln!(out, "== does impersonation change the DOS device map? ==\n"); let Some(drive) = SubstDrive::claim("binary") else { - println!("no free drive letter on this host, so the probe cannot run."); - println!("(Reported rather than measured: a probe that cannot set up its"); - println!("fixture must say so instead of producing a misleading negative.)"); + let _ = writeln!( + out, + "no free drive letter on this host, so the probe cannot run." + ); + let _ = writeln!( + out, + "(Reported rather than measured: a probe that cannot set up its" + ); + let _ = writeln!( + out, + "fixture must say so instead of producing a misleading negative.)" + ); return; }; - println!( + let _ = writeln!( + out, "using {} as a subst-style link to {}\n", drive.letter(), drive.target() ); let finding = measure_with_subst(&drive); - let describe = - |label: &str, observation: &windows_platform_probes::device_map::MapObservation| { - println!("{label}"); - println!( - " {} -> {}", - observation.letter, - observation - .target - .as_deref() - .unwrap_or("(not found in this map)") - ); - match observation.logon_session { - Some((low, high)) => println!(" logon session LUID: {high:08x}:{low:08x}"), - None => println!(" logon session LUID: (not impersonating)"), + // Takes the buffer as an argument rather than capturing it, so that `out` + // stays available to the lines below. A closure capturing it mutably would + // hold the borrow across every later write. + fn describe( + out: &mut String, + label: &str, + observation: &windows_platform_probes::device_map::MapObservation, + ) { + let _ = writeln!(out, "{label}"); + let _ = writeln!( + out, + " {} -> {}", + observation.letter, + observation + .target + .as_deref() + .unwrap_or("(not found in this map)") + ); + match observation.logon_session { + Some((low, high)) => { + let _ = writeln!(out, " logon session LUID: {high:08x}:{low:08x}"); } - }; + None => { + let _ = writeln!(out, " logon session LUID: (not impersonating)"); + } + } + } - describe("our own session:", &finding.own_session); - println!(); + describe(out, "our own session:", &finding.own_session); + let _ = writeln!(out); describe( + out, "impersonating the anonymous session:", &finding.anonymous_session, ); - println!("\ncontrol:"); - println!( + let _ = writeln!(out, "\ncontrol:"); + let _ = writeln!( + out, " the two contexts are different logon sessions: {}", finding.sessions_differ() ); - println!("\nconclusion:"); + let _ = writeln!(out, "\nconclusion:"); if finding.impersonation_changes_the_map() { - println!(" the SAME drive letter, on the SAME thread, resolves differently"); - println!(" depending on the token in effect. A path resolved on a submitter"); - println!(" and opened on a worker under a captured token can name a"); - println!(" different device -- which is why lexical resolution does not"); - println!(" close that hazard."); + let _ = writeln!( + out, + " the SAME drive letter, on the SAME thread, resolves differently" + ); + let _ = writeln!( + out, + " depending on the token in effect. A path resolved on a submitter" + ); + let _ = writeln!( + out, + " and opened on a worker under a captured token can name a" + ); + let _ = writeln!( + out, + " different device -- which is why lexical resolution does not" + ); + let _ = writeln!(out, " close that hazard."); } else { - println!(" the letter resolved the same way in both contexts. Either the"); - println!(" finding has changed, or the impersonation did not take effect --"); - println!(" check the control above before believing the former."); + let _ = writeln!( + out, + " the letter resolved the same way in both contexts. Either the" + ); + let _ = writeln!( + out, + " finding has changed, or the impersonation did not take effect --" + ); + let _ = writeln!( + out, + " check the control above before believing the former." + ); } } diff --git a/crates/windows-platform-probes/src/bin/error_mode.rs b/crates/windows-platform-probes/src/bin/error_mode.rs index 43a01611..71078ef3 100644 --- a/crates/windows-platform-probes/src/bin/error_mode.rs +++ b/crates/windows-platform-probes/src/bin/error_mode.rs @@ -13,10 +13,13 @@ //! the one observation a test must not: the alignment bit's process-scope //! stickiness is irreversible, so it is demonstrated here and nowhere else. +use std::fmt::Write as _; + use windows_platform_probes::error_mode::{ alignment_bit_is_sticky_at_process_scope, bits, combined_invalid_installs_nothing, probe_bit, settable_bits, thread_mode_independent_of_process, }; +use windows_platform_probes::report::emit_report; fn name(bit: u32) -> &'static str { match bit { @@ -29,7 +32,31 @@ fn name(bit: u32) -> &'static str { } fn main() { - println!("--- each bit on its own, set then read back ---"); + // The probe's whole output policy, and it is one line: hand the renderer to + // the sink. Nothing here or below names a stream -- that is chosen once, in + // `report`, so retargeting a probe is not a rewrite. + emit_report(render); +} + +/// The probe's whole report, as text. +/// +/// **This one measures as it renders**, unlike its siblings, and the coupling is +/// real rather than laziness: the last observation permanently alters this +/// process (see `alignment_bit_is_sticky_at_process_scope`), so the order in +/// which the observations are taken is part of what is being reported. Splitting +/// measurement from rendering would invite a later reordering that silently +/// changes the result. +fn render(out: &mut String) { + // First line of the report, and part of the returned text rather than + // written out here: a captured report must carry the line naming the + // machine that produced it, and the taint marker with it. Without it a + // finding can be pasted anywhere and compared against anything. + let _ = writeln!( + out, + "{}", + windows_placement_probe::fingerprint::banner_line() + ); + let _ = writeln!(out, "--- each bit on its own, set then read back ---"); for bit in [ bits::FAIL_CRITICAL_ERRORS, bits::NO_GP_FAULT_ERROR_BOX, @@ -44,7 +71,8 @@ fn main() { } else { "REJECTED" }; - println!( + let _ = writeln!( + out, "{} ok={} last_error={:<5} read_back=0x{:04X} -> {verdict}", name(bit), outcome.set_ok, @@ -53,11 +81,12 @@ fn main() { ); } - println!("\nsettable mask: 0x{:04X}", settable_bits()); + let _ = writeln!(out, "\nsettable mask: 0x{:04X}", settable_bits()); let (installed_nothing, read_back) = combined_invalid_installs_nothing(); - println!("\n--- one invalid bit alongside two valid ones ---"); - println!( + let _ = writeln!(out, "\n--- one invalid bit alongside two valid ones ---"); + let _ = writeln!( + out, "read back 0x{read_back:04X} -> {}", if installed_nothing { "the WHOLE call failed; none of the valid bits was installed" @@ -67,8 +96,9 @@ fn main() { ); let observation = thread_mode_independent_of_process(); - println!("\n--- process mode versus thread mode ---"); - println!( + let _ = writeln!(out, "\n--- process mode versus thread mode ---"); + let _ = writeln!( + out, "process=0x{:04X} thread=0x{:04X} -> {}", observation.process_mode, observation.thread_mode, @@ -79,10 +109,17 @@ fn main() { } ); - println!("\n--- irreversible: the alignment bit at process scope ---"); - println!("(this permanently alters this process, which is why no test does it)"); + let _ = writeln!( + out, + "\n--- irreversible: the alignment bit at process scope ---" + ); + let _ = writeln!( + out, + "(this permanently alters this process, which is why no test does it)" + ); let (before, after) = alignment_bit_is_sticky_at_process_scope(); - println!( + let _ = writeln!( + out, "before=0x{before:04X} after restore attempt=0x{after:04X} -> {}", if after & bits::NO_ALIGNMENT_FAULT_EXCEPT != 0 { "STICKY: the restore was ignored" diff --git a/crates/windows-platform-probes/src/bin/handle_state.rs b/crates/windows-platform-probes/src/bin/handle_state.rs index b2eadbaa..c7570ec9 100644 --- a/crates/windows-platform-probes/src/bin/handle_state.rs +++ b/crates/windows-platform-probes/src/bin/handle_state.rs @@ -11,22 +11,42 @@ //! observations themselves -- the actual file names each handle returned -- //! which is what makes a surprising result diagnosable rather than merely red. +use std::fmt::Write as _; use windows_platform_probes::handle_state::{ Fixture, SingleShot, closing_duplicate_preserves_source, duplicate_shares_cursor, ground_truth, query_disturbs_cursor, separate_opens_are_independent, }; +use windows_platform_probes::report::emit_report; fn main() { + // The probe's whole output policy, and it is one line: hand the renderer to + // the sink. Nothing here or below names a stream -- that is chosen once, in + // `report`, so retargeting a probe is not a rewrite. + emit_report(render); +} + +/// The probe's whole report, as text. +fn render(out: &mut String) { + // First line of the report, and part of the returned text rather than + // written out here: a captured report must carry the line naming the + // machine that produced it, and the taint marker with it. Without it a + // finding can be pasted anywhere and compared against anything. + let _ = writeln!( + out, + "{}", + windows_placement_probe::fingerprint::banner_line() + ); let fixture = Fixture::new("bin"); let truth = ground_truth(&fixture); - println!("--- ground truth (one handle, start to finish) ---"); - println!("{} entries: {truth:?}\n", truth.len()); + let _ = writeln!(out, "--- ground truth (one handle, start to finish) ---"); + let _ = writeln!(out, "{} entries: {truth:?}\n", truth.len()); let observation = duplicate_shares_cursor(&fixture); - println!("--- does a duplicate share the cursor? ---"); - println!("source (restart) -> {:?}", observation.source_first); - println!("duplicate (continue) -> {:?}", observation.other_next); - println!( + let _ = writeln!(out, "--- does a duplicate share the cursor? ---"); + let _ = writeln!(out, "source (restart) -> {:?}", observation.source_first); + let _ = writeln!(out, "duplicate (continue) -> {:?}", observation.other_next); + let _ = writeln!( + out, " -> {}\n", if observation.continued(&truth) { "SHARED: the duplicate continued where the source stopped" @@ -38,10 +58,11 @@ fn main() { ); let control = separate_opens_are_independent(&fixture); - println!("--- control: two separate opens ---"); - println!("open #1 (restart) -> {:?}", control.source_first); - println!("open #2 (continue) -> {:?}", control.other_next); - println!( + let _ = writeln!(out, "--- control: two separate opens ---"); + let _ = writeln!(out, "open #1 (restart) -> {:?}", control.source_first); + let _ = writeln!(out, "open #2 (continue) -> {:?}", control.other_next); + let _ = writeln!( + out, " -> {}\n", if control.restarted() { "INDEPENDENT, as expected -- so the result above is attributable to duplication" @@ -50,8 +71,9 @@ fn main() { } ); - println!("--- does closing the duplicate break the source? ---"); - println!( + let _ = writeln!(out, "--- does closing the duplicate break the source? ---"); + let _ = writeln!( + out, " -> {}\n", if closing_duplicate_preserves_source(&fixture) { "no: the source kept enumerating" @@ -60,7 +82,10 @@ fn main() { } ); - println!("--- does an interleaved single-shot query move the cursor? ---"); + let _ = writeln!( + out, + "--- does an interleaved single-shot query move the cursor? ---" + ); for (query, on_duplicate) in [ (SingleShot::BasicInfo, false), (SingleShot::IdInfo, false), @@ -68,7 +93,8 @@ fn main() { (SingleShot::BasicInfo, true), ] { let (succeeded, disturbed) = query_disturbs_cursor(&fixture, query, on_duplicate, &truth); - println!( + let _ = writeln!( + out, "{query:?}{} succeeded={succeeded} -> {}", if on_duplicate { " (on the duplicate)" diff --git a/crates/windows-platform-probes/src/bin/ioring.rs b/crates/windows-platform-probes/src/bin/ioring.rs index 929dfbee..862490b7 100644 --- a/crates/windows-platform-probes/src/bin/ioring.rs +++ b/crates/windows-platform-probes/src/bin/ioring.rs @@ -11,62 +11,123 @@ //! this reports "cannot measure" rather than a false negative on a host that //! has no ring. +use std::fmt::Write as _; use windows_platform_probes::ioring::{ IoRingSupport, is_available, measure_registration, measure_thread_agnosticism, }; +use windows_platform_probes::report::emit_report; fn main() { - println!("== IoRing registration and thread agnosticism ==\n"); + // The probe's whole output policy, and it is one line: hand the renderer to + // the sink. Nothing here or below names a stream -- that is chosen once, in + // `report`, so retargeting a probe is not a rewrite. + emit_report(render); +} + +/// The probe's whole report, as text. +fn render(out: &mut String) { + // First line of the report, and part of the returned text rather than + // written out here: a captured report must carry the line naming the + // machine that produced it, and the taint marker with it. Without it a + // finding can be pasted anywhere and compared against anything. + let _ = writeln!( + out, + "{}", + windows_placement_probe::fingerprint::banner_line() + ); + let _ = writeln!(out, "== IoRing registration and thread agnosticism ==\n"); if !is_available() { - println!("this host has no usable IoRing, so nothing was measured."); - println!("(Reported rather than measured: 'we could not ask' and 'the answer"); - println!("is no' are different facts, and conflating them is how a design note"); - println!("ends up citing a measurement that never ran.)"); + let _ = writeln!( + out, + "this host has no usable IoRing, so nothing was measured." + ); + let _ = writeln!( + out, + "(Reported rather than measured: 'we could not ask' and 'the answer" + ); + let _ = writeln!( + out, + "is no' are different facts, and conflating them is how a design note" + ); + let _ = writeln!(out, "ends up citing a measurement that never ran.)"); return; } - println!("registration semantics:"); + let _ = writeln!(out, "registration semantics:"); match measure_registration() { - IoRingSupport::Unavailable => println!(" (no ring)"), + IoRingSupport::Unavailable => { + let _ = writeln!(out, " (no ring)"); + } IoRingSupport::Measured(observed) => { - println!( + let _ = writeln!( + out, " after re-registering ONE handle: index 0 usable {}, index 1 usable {}", observed.index_zero_usable_after_second, observed.index_one_usable_after_second ); if observed.replaces() { - println!(" -> REPLACES the whole table, which is what"); - println!(" windows-ioring-sys assumes and refuses a second call on."); + let _ = writeln!(out, " -> REPLACES the whole table, which is what"); + let _ = writeln!( + out, + " windows-ioring-sys assumes and refuses a second call on." + ); } else if observed.appends() { - println!(" -> APPENDS. windows-ioring-sys's index bookkeeping would be"); - println!(" WRONG and its refusal a needless restriction."); + let _ = writeln!( + out, + " -> APPENDS. windows-ioring-sys's index bookkeeping would be" + ); + let _ = writeln!(out, " WRONG and its refusal a needless restriction."); } else { - println!(" -> neither: even index 0 stopped working, so the probe"); - println!(" broke rather than the platform answering."); + let _ = writeln!( + out, + " -> neither: even index 0 stopped working, so the probe" + ); + let _ = writeln!(out, " broke rather than the platform answering."); } } } - println!("\nthread agnosticism:"); + let _ = writeln!(out, "\nthread agnosticism:"); match measure_thread_agnosticism() { - IoRingSupport::Unavailable => println!(" (no ring)"), + IoRingSupport::Unavailable => { + let _ = writeln!(out, " (no ring)"); + } IoRingSupport::Measured(observed) => { - println!( + let _ = writeln!( + out, " pending at submitter exit: {} | result code: {:#010x} | \ transferred the fill byte: {}", observed.pending_at_submitter_exit, observed.result_code, observed.filled ); if !observed.pending_at_submitter_exit { - println!(" -> the read had ALREADY completed, so this run measured"); - println!(" nothing about thread affinity either way."); + let _ = writeln!( + out, + " -> the read had ALREADY completed, so this run measured" + ); + let _ = writeln!(out, " nothing about thread affinity either way."); } if observed.survives_submitter_exit() { - println!(" -> an operation OUTLIVES the thread that submitted it, so a"); - println!(" design whose threads are transient by construction is safe."); + let _ = writeln!( + out, + " -> an operation OUTLIVES the thread that submitted it, so a" + ); + let _ = writeln!( + out, + " design whose threads are transient by construction is safe." + ); } else { - println!(" -> the operation did NOT survive its submitter. Every thread"); - println!(" in the proposed design is transient, so this would fail"); - println!(" only under load -- the worst place to discover it."); + let _ = writeln!( + out, + " -> the operation did NOT survive its submitter. Every thread" + ); + let _ = writeln!( + out, + " in the proposed design is transient, so this would fail" + ); + let _ = writeln!( + out, + " only under load -- the worst place to discover it." + ); } } } diff --git a/crates/windows-platform-probes/src/bin/pool_growth.rs b/crates/windows-platform-probes/src/bin/pool_growth.rs index 88ad8fe6..7d73e1ae 100644 --- a/crates/windows-platform-probes/src/bin/pool_growth.rs +++ b/crates/windows-platform-probes/src/bin/pool_growth.rs @@ -11,57 +11,97 @@ //! exceed it, and gets there promptly); this binary prints the numbers, which //! is what a new architecture actually needs to be re-measured against. +use std::fmt::Write as _; use windows_platform_probes::pool_growth::{measure_growth, measure_raise_while_saturated}; +use windows_platform_probes::report::emit_report; -fn report(label: &str, maximum: u32, submissions: usize, runs_long: bool) { +/// Measure one configuration and append its block to `out`. +/// +/// Takes the buffer rather than printing: a helper that wrote to stdout while +/// its caller composed a string would emit its lines *before* the caller's, +/// reordering the report even though every line still appeared. +fn report(out: &mut String, label: &str, maximum: u32, submissions: usize, runs_long: bool) { let observed = measure_growth(maximum, submissions, runs_long); - println!("{label}"); - println!( + let _ = writeln!(out, "{label}"); + let _ = writeln!( + out, " max {} / submitted {} -> started while blocked {}, distinct threads {}", observed.maximum, observed.submitted, observed.started_while_blocked, observed.distinct_threads ); - println!( + let _ = writeln!( + out, " saturated {} | one thread each {} | slowest arrival {:?}", observed.saturated(), observed.one_thread_each(), observed.slowest_arrival() ); - println!(" arrivals (us): {:?}", observed.arrivals_us); + let _ = writeln!(out, " arrivals (us): {:?}", observed.arrivals_us); } fn main() { - println!("== how a blocked pool grows ==\n"); + // The probe's whole output policy, and it is one line: hand the renderer to + // the sink. Nothing here or below names a stream -- that is chosen once, in + // `report`, so retargeting a probe is not a rewrite. + emit_report(render); +} + +/// The probe's whole report, as text. +fn render(out: &mut String) { + // First line of the report, and part of the returned text rather than + // written out here: a captured report must carry the line naming the + // machine that produced it, and the taint marker with it. Without it a + // finding can be pasted anywhere and compared against anything. + let _ = writeln!( + out, + "{}", + windows_placement_probe::fingerprint::banner_line() + ); + let _ = writeln!(out, "== how a blocked pool grows ==\n"); - report("P1 growth curve, max 4:", 4, 8, false); - println!(); - report("P1 growth curve, max 8:", 8, 16, false); - println!(); - report("P2 the same, runs-long:", 4, 8, true); - println!(); + report(out, "P1 growth curve, max 4:", 4, 8, false); + let _ = writeln!(out); + report(out, "P1 growth curve, max 8:", 8, 16, false); + let _ = writeln!(out); + report(out, "P2 the same, runs-long:", 4, 8, true); + let _ = writeln!(out); let raise = measure_raise_while_saturated(2, 6, 8); - println!("P3 raise while saturated (2 -> 6):"); + let _ = writeln!(out, "P3 raise while saturated (2 -> 6):"); if raise.saturated_before_raise() { - println!( + let _ = writeln!( + out, " extra work started {:?} after the maximum was raised", raise.delay ); } else { - println!( + let _ = writeln!( + out, " NOT saturated before the raise ({} of {} started), so the delay", raise.started_before_raise, raise.base_max ); - println!(" below times growth toward the base maximum, not the raise."); - println!(" elapsed: {:?}", raise.delay); + let _ = writeln!( + out, + " below times growth toward the base maximum, not the raise." + ); + let _ = writeln!(out, " elapsed: {:?}", raise.delay); } if !raise.took_effect { - println!(" the settle window expired with no extra callback started."); + let _ = writeln!( + out, + " the settle window expired with no extra callback started." + ); } - println!("\nnote: every number here is from this host and this Windows build."); - println!("Re-run on another architecture rather than assuming they carry over."); + let _ = writeln!( + out, + "\nnote: every number here is from this host and this Windows build." + ); + let _ = writeln!( + out, + "Re-run on another architecture rather than assuming they carry over." + ); } diff --git a/crates/windows-platform-probes/src/bin/worker_context.rs b/crates/windows-platform-probes/src/bin/worker_context.rs index d51ff3ab..b1352d72 100644 --- a/crates/windows-platform-probes/src/bin/worker_context.rs +++ b/crates/windows-platform-probes/src/bin/worker_context.rs @@ -12,55 +12,96 @@ //! measurement can be eyeballed on a new host or a new Windows build without //! reading a test's output. +use std::fmt::Write as _; +use windows_platform_probes::report::emit_report; use windows_platform_probes::worker_context::{ observe_on_worker, observe_on_worker_while_impersonating, }; fn main() { - println!("== what a thread-pool worker is handed ==\n"); + // The probe's whole output policy, and it is one line: hand the renderer to + // the sink. Nothing here or below names a stream -- that is chosen once, in + // `report`, so retargeting a probe is not a rewrite. + emit_report(render); +} + +/// The probe's whole report, as text. +fn render(out: &mut String) { + // First line of the report, and part of the returned text rather than + // written out here: a captured report must carry the line naming the + // machine that produced it, and the taint marker with it. Without it a + // finding can be pasted anywhere and compared against anything. + let _ = writeln!( + out, + "{}", + windows_placement_probe::fingerprint::banner_line() + ); + let _ = writeln!(out, "== what a thread-pool worker is handed ==\n"); let plain = observe_on_worker(); - println!("submitted with no impersonation:"); - println!(" has thread token : {}", plain.has_thread_token); - println!(" OpenThreadToken err: {}", plain.open_token_error); - println!(" thread error mode : {:#06x}", plain.error_mode); - println!(" -> unimpersonated : {}", plain.is_unimpersonated()); - println!( + let _ = writeln!(out, "submitted with no impersonation:"); + let _ = writeln!(out, " has thread token : {}", plain.has_thread_token); + let _ = writeln!(out, " OpenThreadToken err: {}", plain.open_token_error); + let _ = writeln!(out, " thread error mode : {:#06x}", plain.error_mode); + let _ = writeln!(out, " -> unimpersonated : {}", plain.is_unimpersonated()); + let _ = writeln!( + out, " -> critical-error handler enabled: {}", plain.critical_error_handler_enabled() ); let impersonating = observe_on_worker_while_impersonating(); let worker = impersonating.worker; - println!( + let _ = writeln!( + out, " submitted WHILE the submitter impersonates:" ); - println!( + let _ = writeln!( + out, " submitter has token: {}", impersonating.submitter.has_thread_token ); - println!(" worker has token : {}", worker.has_thread_token); - println!(" OpenThreadToken err: {}", worker.open_token_error); - println!(" thread error mode : {:#06x}", worker.error_mode); - println!(" -> unimpersonated : {}", worker.is_unimpersonated()); - println!(" -> they disagree : {}", impersonating.disagree()); + let _ = writeln!(out, " worker has token : {}", worker.has_thread_token); + let _ = writeln!(out, " OpenThreadToken err: {}", worker.open_token_error); + let _ = writeln!(out, " thread error mode : {:#06x}", worker.error_mode); + let _ = writeln!(out, " -> unimpersonated : {}", worker.is_unimpersonated()); + let _ = writeln!(out, " -> they disagree : {}", impersonating.disagree()); - println!( + let _ = writeln!( + out, " conclusion:" ); if impersonating.disagree() { - println!(" a worker does NOT inherit the submitter's token, so identity"); - println!(" must be captured and applied explicitly."); + let _ = writeln!( + out, + " a worker does NOT inherit the submitter's token, so identity" + ); + let _ = writeln!(out, " must be captured and applied explicitly."); } else { - println!(" UNEXPECTED: the worker inherited a token. The ambient crate's"); - println!(" premise no longer holds and its design needs revisiting."); + let _ = writeln!( + out, + " UNEXPECTED: the worker inherited a token. The ambient crate's" + ); + let _ = writeln!( + out, + " premise no longer holds and its design needs revisiting." + ); } if plain.critical_error_handler_enabled() { - println!(" a worker's critical-error handler is ENABLED, so a hard device"); - println!(" error can put a modal dialog on shared infrastructure."); + let _ = writeln!( + out, + " a worker's critical-error handler is ENABLED, so a hard device" + ); + let _ = writeln!( + out, + " error can put a modal dialog on shared infrastructure." + ); } else { - println!(" UNEXPECTED: a worker starts with the handler suppressed."); + let _ = writeln!( + out, + " UNEXPECTED: a worker starts with the handler suppressed." + ); } } diff --git a/crates/windows-platform-probes/src/lib.rs b/crates/windows-platform-probes/src/lib.rs index f809ab72..bc3e537f 100644 --- a/crates/windows-platform-probes/src/lib.rs +++ b/crates/windows-platform-probes/src/lib.rs @@ -116,6 +116,7 @@ pub mod error_mode; pub mod handle_state; pub mod ioring; pub mod pool_growth; +pub mod report; pub mod worker_context; #[cfg(test)] diff --git a/crates/windows-platform-probes/src/report.rs b/crates/windows-platform-probes/src/report.rs new file mode 100644 index 00000000..d2402a19 --- /dev/null +++ b/crates/windows-platform-probes/src/report.rs @@ -0,0 +1,173 @@ +// Copyright (c) Mike Grier. +//! The one place a probe writes. +//! +//! # Why an abstraction for something as simple as printing +//! +//! The repository's rule is that a tool introduces an output abstraction at its +//! *first* output site, so that the storage target and the formatting stay +//! separable from the call sites that compose the content. A probe that calls +//! `println!` from fifty places has welded the two together: its findings can +//! only be observed by running the process and capturing a stream, so nothing +//! about its report can be asserted, diffed against a previous run, or written +//! anywhere but a terminal. +//! +//! That is a real loss for a probe specifically. These binaries exist so a +//! claim in a design note can be **re-run rather than re-argued**, which means +//! their output is evidence -- and evidence that can only be eyeballed is +//! weaker than evidence a test can read. +//! +//! # What this is, and what it deliberately is not +//! +//! A sink, not a logging framework: one method, no levels, no filtering, no +//! formatting policy. Callers still own their text. +//! +//! Only one stream, unlike the placement probe's near-identical sink, because +//! nothing a probe puts in its *report* is a diagnostic: every line of it is a +//! finding, so a `problem` method would have no callers here. +//! +//! The crate does emit one diagnostic, and it is the exception that shows why +//! the split is unnecessary rather than one that undermines it. +//! `Impersonation::drop` warns on stderr when `RevertToSelf` fails during an +//! unwind, because panicking from `Drop` mid-unwind would abort and replace a +//! diagnosable failure with one that explains nothing. That warning is not part +//! of any report and must not be: it belongs to the process, not to the +//! measurement, and stderr already separates it. Routing it through this sink +//! would mix it into the evidence stdout carries. +//! +//! # Every probe routes through this +//! +//! Every probe in this crate, with no exceptions -- stated without a count on +//! purpose, so the claim stays true as probes are added. Each conversion was +//! checked by capturing the probe's output before and after and requiring every +//! pre-existing line to match, in the same order. Not byte-for-byte: the +//! conversion also prepends the host banner, which is the one deliberate +//! difference and the only one permitted. +//! +//! **That check has to be positional**, which is worth recording because the +//! obvious tool is not. The defect a conversion introduces is a helper that +//! still writes to stdout while its caller composes a string: every line still +//! appears, but the helper's lines arrive *first*, so the report is reordered. +//! PowerShell's `Compare-Object` compares collections as sets and calls that +//! identical -- it passed three genuinely broken probes here before the +//! comparison was redone line-by-line. + +use std::panic::{AssertUnwindSafe, catch_unwind, resume_unwind}; + +/// Somewhere a probe's report can go. +pub trait Report { + /// Emit one line. + fn line(&mut self, text: &str); +} + +/// The real stream. +pub struct Stdout; + +impl Report for Stdout { + fn line(&mut self, text: &str) { + println!("{text}"); + } +} + +/// A report that keeps what it was given. +/// +/// The point of the whole abstraction: a probe's findings become a value a test +/// can read, rather than bytes only a terminal ever sees. +#[derive(Debug, Default)] +pub struct Captured { + /// Lines written, in order. + pub lines: Vec, +} + +impl Report for Captured { + fn line(&mut self, text: &str) { + self.lines.push(text.to_owned()); + } +} + +impl Captured { + /// The report as one string, as a reader would see it. + #[must_use] + pub fn text(&self) -> String { + self.lines.join("\n") + } +} + +/// Write a rendered block to `report`, one line at a time. +/// +/// A `render_*` function produces a whole block with embedded newlines and a +/// [`Report`] speaks in lines, so this is the join between them. Splitting +/// rather than passing the block through keeps [`Captured`] line-addressable, +/// which is what lets a test name a row instead of searching the whole document +/// for a substring. +/// +/// A trailing newline does not produce an extra empty line, because +/// `str::lines` does not yield one -- so a renderer may end its block either way +/// without changing what a reader sees. +pub fn emit(report: &mut impl Report, block: &str) { + for line in block.lines() { + report.line(line); + } +} + +/// Compose a report and emit it, **including when composing it panics**. +/// +/// Every probe's `main` is one call to this. The buffer is owned here rather +/// than inside the renderer so that a measurement which aborts part-way still +/// prints what it had already established. +/// +/// That is not hypothetical bookkeeping. These probes call into measurements +/// documented to panic -- `worker_context`'s impersonating observation panics if +/// the token cannot be duplicated or applied, or if the worker never reports -- +/// and each renderer composes several completed findings *before* reaching one. +/// Printing line-by-line used to make that automatic: whatever had been measured +/// was already on the terminal. Buffering the whole report to hand it to a +/// [`Report`] silently gave that up, and for an instrument the point of which is +/// that a failure be diagnosable, how far it got is exactly the information +/// worth keeping. +/// +/// The panic is resumed afterwards, so the exit status and the message are +/// unchanged; the partial report is added to them, not substituted for them. +/// +/// **This restores the streaming property for unwinding panics only, and that +/// bound is known rather than overlooked.** A termination that does not unwind +/// still loses the buffer, where printing line-by-line would have kept it: Ctrl-C +/// (the default Windows console handler terminates the process outright), and an +/// abort from a panic raised during unwinding. The case that costs most is +/// `probe-cancel-io`, which can run four attempts at a five-second watchdog -- +/// so about twenty seconds, precisely when the wedge it hunts for occurs, which +/// is precisely when a reader interrupts it. +/// +/// Fixing it properly means the renderers writing into a [`Report`] as they go +/// rather than into a `String`, which keeps [`Captured`] working for tests and +/// streams for real runs. That is a different design rather than an oversight in +/// this one -- it changes every renderer -- so it is queued as its own work: +/// milestone `M1` of [CHECKLIST.md](../CHECKLIST.md), with the reasoning in +/// [DESIGN-NOTES.md](../DESIGN-NOTES.md#d-buffered-report). +pub fn emit_report(render: impl FnOnce(&mut String)) { + emit_report_to(&mut Stdout, render); +} + +/// [`emit_report`] against an arbitrary sink. +/// +/// Exists so the catch-emit-resume logic is what a test executes, rather than a +/// second copy of that shape written in the test. The first version of the test +/// re-implemented it against a [`Captured`] and so would have passed with the +/// `resume_unwind` below deleted -- which would leave a probe printing a partial +/// report and exiting **0**, the failure that looks most like success. +pub fn emit_report_to(report: &mut impl Report, render: impl FnOnce(&mut String)) { + let mut out = String::new(); + + // `AssertUnwindSafe` because the only state crossing the boundary is this + // buffer, and a partially written report is precisely what is wanted here + // rather than a hazard to be guarded against. + let outcome = catch_unwind(AssertUnwindSafe(|| render(&mut out))); + + emit(report, &out); + + if let Err(payload) = outcome { + resume_unwind(payload); + } +} + +#[cfg(test)] +mod tests; diff --git a/crates/windows-platform-probes/src/report/tests.rs b/crates/windows-platform-probes/src/report/tests.rs new file mode 100644 index 00000000..384490c0 --- /dev/null +++ b/crates/windows-platform-probes/src/report/tests.rs @@ -0,0 +1,110 @@ +// Copyright (c) Mike Grier. +//! Tests for the report sink. +//! +//! These are small, and that is the point: the sink's whole job is to be the +//! seam that lets a probe's *findings* be asserted rather than eyeballed. What +//! is worth pinning here is the seam's own behaviour, so that a test written +//! against a probe's report can trust what it is reading. + +use std::fmt::Write as _; +use std::panic::{AssertUnwindSafe, catch_unwind}; + +use super::{Captured, Report, emit, emit_report_to}; + +#[test] +fn a_captured_report_keeps_its_lines_in_order() { + // Order is the property a probe's report depends on most: its tables are + // rows under a header, and a sink that reordered them would turn a correct + // measurement into a wrong one. + let mut captured = Captured::default(); + captured.line("header"); + captured.line("row one"); + captured.line("row two"); + + assert_eq!(captured.lines, ["header", "row one", "row two"]); + assert_eq!(captured.text(), "header\nrow one\nrow two"); +} + +#[test] +fn emitting_a_block_gives_the_report_one_line_at_a_time() { + // What makes a captured report addressable by line rather than by substring + // search -- so a test can say "the third row" instead of hoping a phrase is + // unique in the document. + let mut captured = Captured::default(); + emit(&mut captured, "one\ntwo\nthree"); + + assert_eq!(captured.lines, ["one", "two", "three"]); +} + +#[test] +fn a_trailing_newline_does_not_become_an_extra_blank_line() { + // A renderer may end its block with a newline or without one, and the two + // must look the same to a reader. Otherwise every `render_*` function would + // have to agree on a convention that nothing enforces, and the first one to + // drift would add a blank line nobody could account for. + let mut with = Captured::default(); + let mut without = Captured::default(); + emit(&mut with, "one\ntwo\n"); + emit(&mut without, "one\ntwo"); + + assert_eq!(with.lines, without.lines); +} + +#[test] +fn an_interior_blank_line_survives() { + // The other side of the previous test, and the reason it cannot simply + // filter empties: these reports use blank lines to separate sections, so a + // sink that swallowed them would run the tables together. + let mut captured = Captured::default(); + emit(&mut captured, "section\n\nnext"); + + assert_eq!(captured.lines, ["section", "", "next"]); +} + +#[test] +fn a_renderer_that_panics_still_has_its_finished_lines_emitted() { + // The property `emit_report` exists for, exercised through the real + // function rather than through a second copy of its shape. + // + // An earlier version of this test re-implemented catch-emit-resume against a + // `Captured` and never called into `report` at all. It would have passed + // with the `resume_unwind` deleted -- and a probe that swallowed its panic + // would print a partial report and exit **0**, which is the failure that + // looks most like success. Hence `emit_report_to`: same logic, injectable + // sink. + let mut captured = Captured::default(); + + let outcome = catch_unwind(AssertUnwindSafe(|| { + emit_report_to(&mut captured, |out| { + let _ = writeln!(out, "measured before the failure"); + panic!("a measurement aborted"); + }); + })); + + // Both halves matter, and each fails a different mutation. Without the + // first, deleting the `emit` leaves the test green; without the second, + // deleting the `resume_unwind` does. + assert_eq!( + captured.lines, + ["measured before the failure"], + "what was already established must survive the abort" + ); + assert!( + outcome.is_err(), + "the panic must reach the caller, or the probe exits 0 having failed" + ); +} + +#[test] +fn a_renderer_that_returns_normally_reports_every_line_and_does_not_panic() { + // The other side of the same function: the ordinary path must be unaffected + // by the machinery that exists for the failing one. + let mut captured = Captured::default(); + + emit_report_to(&mut captured, |out| { + let _ = writeln!(out, "first"); + let _ = writeln!(out, "second"); + }); + + assert_eq!(captured.lines, ["first", "second"]); +} diff --git a/crates/windows-platform-probes/tests/a_probe_writes_its_report_to_stdout.rs b/crates/windows-platform-probes/tests/a_probe_writes_its_report_to_stdout.rs new file mode 100644 index 00000000..e93ac68e --- /dev/null +++ b/crates/windows-platform-probes/tests/a_probe_writes_its_report_to_stdout.rs @@ -0,0 +1,72 @@ +// Copyright (c) Mike Grier. + +//! The one thing the unit tests cannot reach: that `Stdout` actually writes. +//! +//! `report::Captured` makes a probe's findings a value a test can read, and the +//! unit tests use it for everything. But that means every in-process test passes +//! whether or not `report::Stdout` -- the implementation every probe uses in +//! production -- emits anything at all. +//! +//! Found by mutation testing rather than by inspection: replacing +//! `::line` with `()` survived the whole suite. A no-op +//! there means every probe in this crate runs, exits zero, and prints nothing, +//! which is the failure mode that looks most like success. +//! +//! Stable Rust cannot redirect this process's own stdout, so covering it needs a +//! real child process. That makes this an integration test by the repository's +//! own criterion -- it crosses a process boundary -- rather than by preference. + +use std::process::Command; + +/// A probe is exercised rather than the sink tested directly, because the sink +/// is only interesting as the thing a probe uses. +/// +/// `probe-error-mode` is the one picked: it needs no privileges, no particular +/// hardware, and no device, so it behaves the same on a developer's machine and +/// on a CI runner. `CARGO_BIN_EXE_*` is set by cargo for integration tests, so +/// the path is the binary this build produced rather than whatever is on PATH. +#[test] +fn a_probe_run_as_a_process_prints_its_report() { + let output = Command::new(env!("CARGO_BIN_EXE_probe-error-mode")) + .output() + .expect("run the probe"); + + assert!( + output.status.success(), + "the probe exited with {:?}; stderr: {}", + output.status.code(), + String::from_utf8_lossy(&output.stderr) + ); + + let stdout = String::from_utf8(output.stdout).expect("a probe's report is UTF-8"); + + // The assertion that kills the mutant. Everything below it is about the + // report being *right*; this one is about it existing at all. + assert!( + !stdout.trim().is_empty(), + "the probe produced no output, so nothing it measured reached anyone" + ); + + let lines: Vec<&str> = stdout.lines().collect(); + + // The banner is rendered into the report rather than printed beside it, so + // that a captured report carries the machine it describes. If it ever stops + // being the first line, a pasted finding can be compared against hardware it + // was not measured on. + // + // Matched on the `host:` prefix alone, which `banner_line` emits on both its + // success and its topology-discovery-failed paths -- so this holds on a + // machine where discovery fails, and does not encode this machine's shape. + assert!( + lines[0].starts_with("host:"), + "the report's first line should be the host banner, was: {:?}", + lines[0] + ); + + // A banner and nothing else would satisfy everything above while the + // findings themselves went missing. + assert!( + lines.len() > 1, + "the report was only its banner; the probe's own findings are missing" + ); +}