From a8faafbe317335e99c623d5517b86836cc13108a Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Wed, 9 Sep 2026 23:58:29 +0300 Subject: [PATCH 01/19] ci: add a manual Linux watch-soak workflow (#129, #318, #320) A `workflow_dispatch`-only ubuntu-latest instrument that runs `cargo test -p mds-cli --test cli_watch` N times (1-200) across two legs, `default` and `startup-race-probe`, and tallies a pass/fail RATE rather than aborting on the first red. It is NOT a gate: dispatch-only means zero check-runs on any PR head, so it cannot enter branch protection, is not a required context, is not a release-surface path, and is invisible to scripts/verify-pr-checks.mjs and all 212 gate specs. Pins mirror ci.yml/release.yml byte-for-byte (PF-040); per-leg rust-cache key because the legs build different feature sets (PF-041); no `${{ }}` inside any `run:` block -- every value crosses via `env:` (PF-045); the artifact uses `if-no-files-found: error` against an always-written summary.txt (PF-016). --- .github/workflows/watch-soak.yml | 194 +++++++++++++++++++++++++++++++ CHANGELOG.md | 1 + 2 files changed, 195 insertions(+) create mode 100644 .github/workflows/watch-soak.yml diff --git a/.github/workflows/watch-soak.yml b/.github/workflows/watch-soak.yml new file mode 100644 index 00000000..0ae4bb4c --- /dev/null +++ b/.github/workflows/watch-soak.yml @@ -0,0 +1,194 @@ +name: Watch soak (manual) + +# MANUAL reproduction instrument for the cli_watch flake family (#129 / #318 / #320). +# +# NOT a gate. `workflow_dispatch` is the only trigger, so this workflow publishes +# zero check-runs on any pull-request head: it cannot enter branch protection and +# cannot appear in scripts/verify-pr-checks.mjs's tally. It touches none of the six +# release-surface paths and does not modify release.yml. +# +# It runs CI's exact command -- `cargo test`, deliberately NOT nextest, because the +# process-per-test model nextest uses is a different execution environment and this +# suite's failures are environment-sensitive. ubuntu-latest only: macOS FSEvents +# cannot reproduce this bug class at all (see .devflow/learning/pitfalls.md PF-026 +# and the project-watch-tests-flaky memory -- a green macOS run proves nothing). +# +# Runs every iteration and tallies, rather than aborting on the first red, because +# the quantity of interest is a RATE. "Failed at iteration 3" cannot distinguish +# 1/20 from 20/20, and the before/after control this instrument exists to serve +# (PF-027 resolution 6) needs both numbers. + +on: + workflow_dispatch: + inputs: + iterations: + description: 'How many times to run the cli_watch suite (1-200)' + type: string + default: '20' + filter: + description: 'Optional cargo-test name filter (empty = the whole suite)' + type: string + default: '' + +permissions: + contents: read + +# cancel-in-progress: false is load-bearing. A soak run is a MEASUREMENT; cancelling +# one halfway leaves a partial tally indistinguishable from a clean run with fewer +# iterations. run_id is in the group key so two deliberate dispatches on the same +# ref never evict each other. +concurrency: + group: watch-soak-${{ github.ref }}-${{ github.run_id }} + cancel-in-progress: false + +env: + CARGO_TERM_COLOR: always + RUST_BACKTRACE: 1 + +jobs: + soak: + name: Watch soak (${{ matrix.label }}) + runs-on: ubuntu-latest + # The loop is bounded by `iterations`, but a hung child inside cargo test is not. + timeout-minutes: 120 + strategy: + fail-fast: false + matrix: + include: + # Default features: the same build CI's `rust` job runs. + - label: default + feature: '' + # The #317 probe widens the publish->arm window to 200ms; N iterations turn + # "6/6 green with the probe on" into a rate. + - label: startup-race-probe + feature: 'startup-race-probe' + steps: + - uses: actions/checkout@v7 + + - uses: dtolnay/rust-toolchain@4360b52568e2003a75bf9bc1d59f33a8e3fc893c # stable + + - uses: Swatinem/rust-cache@v2 + with: + # Per-leg key (PF-041): the two legs build different feature sets. + key: watch-soak-${{ matrix.label }} + + - name: Validate the iterations input + env: + ITERATIONS: ${{ inputs.iterations }} + run: | + set -euo pipefail + case "$ITERATIONS" in + ''|*[!0-9]*) + echo "::error::iterations must be a positive integer; got '$ITERATIONS'" + exit 1 + ;; + esac + if [ "$ITERATIONS" -lt 1 ] || [ "$ITERATIONS" -gt 200 ]; then + echo "::error::iterations must be between 1 and 200; got $ITERATIONS" + exit 1 + fi + echo "iterations validated: $ITERATIONS" + + # Compile once so the loop measures the SUITE and not rustc. + - name: Build the test binary once + env: + FEATURE: ${{ matrix.feature }} + run: | + set -euo pipefail + args=(build -p mds-cli --tests) + if [ -n "$FEATURE" ]; then + args+=(--features "$FEATURE") + fi + echo "cargo ${args[*]}" + cargo "${args[@]}" + + - name: Soak + id: soak + env: + ITERATIONS: ${{ inputs.iterations }} + FILTER: ${{ inputs.filter }} + FEATURE: ${{ matrix.feature }} + LABEL: ${{ matrix.label }} + run: | + # -e is DELIBERATELY omitted: a non-zero `cargo test` is the DATA this + # step collects, not an error that should abort it. -u and pipefail stay. + set -uo pipefail + + mkdir -p soak + + args=(test -p mds-cli --test cli_watch) + if [ -n "$FEATURE" ]; then + args+=(--features "$FEATURE") + fi + if [ -n "$FILTER" ]; then + args+=(-- "$FILTER") + fi + echo "command: cargo ${args[*]}" + + pass=0 + fail=0 + failed_iters="" + i=1 + while [ "$i" -le "$ITERATIONS" ]; do + log="soak/iter-$(printf '%03d' "$i").log" + if cargo "${args[@]}" > "$log" 2>&1; then + pass=$((pass + 1)) + rm -f "$log" + printf 'iter %3d PASS\n' "$i" + else + fail=$((fail + 1)) + failed_iters="$failed_iters $i" + printf 'iter %3d FAIL\n' "$i" + echo "::warning title=watch-soak::iteration $i failed on leg $LABEL" + # Surface the discriminator inline (PF-026: the panic's file:line, not + # the test's name, is the diagnosis). + grep -E 'panicked at|\.\.\. FAILED|test result: FAILED' "$log" || true + fi + i=$((i + 1)) + done + + # The summary file is ALWAYS written, so the artifact is never empty (PF-016). + { + echo "leg: $LABEL" + echo "ref: $GITHUB_REF" + echo "sha: $GITHUB_SHA" + echo "command: cargo ${args[*]}" + echo "iterations: $ITERATIONS" + echo "passed: $pass" + echo "failed: $fail" + echo "failed at: $failed_iters" + } > soak/summary.txt + cat soak/summary.txt + + { + echo "### Watch soak - $LABEL" + echo "" + echo "| metric | value |" + echo "| --- | --- |" + echo "| ref | \`$GITHUB_REF\` |" + echo "| sha | \`$GITHUB_SHA\` |" + echo "| command | \`cargo ${args[*]}\` |" + echo "| iterations | $ITERATIONS |" + echo "| passed | $pass |" + echo "| **failed** | **$fail** |" + if [ "$fail" -gt 0 ]; then + echo "| failing iterations |$failed_iters |" + fi + } >> "$GITHUB_STEP_SUMMARY" + + if [ "$fail" -gt 0 ]; then + echo "::error::$fail of $ITERATIONS iterations failed on leg $LABEL" + exit 1 + fi + echo "clean soak: $pass/$ITERATIONS passed on leg $LABEL" + + - name: Upload failing logs and the tally + if: always() + uses: actions/upload-artifact@v7 + with: + name: watch-soak-${{ matrix.label }}-${{ github.run_id }} + path: soak/ + # `error`, not `ignore`: summary.txt is always written, so an empty upload + # means the glob is wrong, not that the soak was clean (PF-016). + if-no-files-found: error + retention-days: 14 diff --git a/CHANGELOG.md b/CHANGELOG.md index e2d49396..8977c2de 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -60,6 +60,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - `build-napi` per-leg rust-cache key: adds `key: ${{ matrix.settings.target }}` to the `Swatinem/rust-cache` step so each cross-compile leg's target artifacts stay isolated (PF-041; without the key all four ubuntu legs and both macOS legs restored one shared blob, confirmed live in run 34065573775); `build-python`'s existing `key: matrix.target-matrix.manylinux` (#347) unchanged; spec S20 in `release-auth-probe.spec.mjs` pins both and fails `Version gate` if a key is dropped; spec S3 extended to pin the `-z` CARGO_REG_TOKEN guard in executable code; #345 verified that crates.io `GET /api/v1/me` is `AuthCheck::only_cookie()` (HTTP 403 for any API token) and the only token-accepting read route rejects scoped tokens — non-empty guard is the strongest check available, durable fix tracked in #368; #345 closed won't-fix-as-filed (#345 #352). - Alpine `node:22-alpine` load tests for both musl napi addons gate `publish-crates`: x64 (`linux-x64-musl`) as the last step of `stage-and-verify-napi` (after the staged artifact upload, so the artifact is never suppressed by an x64 failure), arm64 (`linux-arm64-musl`) in a new unguarded `load-test-musl-arm64` job on a native `ubuntu-24.04-arm` runner using the `napi-staged` artifact; both use `scripts/musl-load-probe.cjs` in a `docker run --network none` step with a positive control; `publish-crates` blocks on both via `needs:` AND its `if:` conjunct (PF-047); spec S21 in `release-auth-probe.spec.mjs` pins job existence, runner, guard shape, wiring, step order, and run-block byte-equality (#340); the first CI run surfaced #371 (string compile fails when the base directory is a filesystem root — `node:22-alpine` has no `WORKDIR` so the default container cwd is `/`); the gate now runs the container from `/w` (`docker run -w /w`) and the probe asserts its cwd so a dropped flag fails loudly. - Both musl napi legs (`x86_64-unknown-linux-musl`, `aarch64-unknown-linux-musl`) now cross-compile with `napi build … -x` / cargo-zigbuild 0.23.0: the SHA-pinned `taiki-e/install-action` (v2.85.10, `fallback: none`) installs cargo-zigbuild before `Swatinem/rust-cache` (rust-cache deletes `~/.cargo/bin` on save; napi's detector is presence-only and would `cargo install` an unpinned copy mid-build otherwise); the hand-written zig cc wrappers, fake-zig self-check, and both `CARGO_TARGET_*_MUSL_LINKER` exports are deleted; three new steps assert the pinned version (before and after the build) and the no-op detector reads both musl linker vars inside `[ -z ]` guards to confirm none is set; the readelf gate adds `ALLOWED_NEEDED='libc\.so|libgcc_s\.so\.1'` with a planted `libunwind.so.1` control; `mlugg/setup-zig` SHA-pinned (v2.2.1) in the same step; spec S22 in `release-auth-probe.spec.mjs` pins all of the above (#339). +- manual `watch-soak.yml` Linux soak instrument for the cli_watch flake family (#129 #318 #320); `workflow_dispatch` only, not a gate, not a required context, not release-surface ## [0.4.2] — 2026-09-03 From fc83b1d2b90ead2ae546352e70667a54007f4edb Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:08:58 +0300 Subject: [PATCH 02/19] =?UTF-8?q?test(watch):=20RED=20=E2=80=94=20rename-i?= =?UTF-8?q?nto-place=20must=20trigger=20a=20rebuild;=20temp=20files=20must?= =?UTF-8?q?=20be=20invisible?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An editor (and the `write_atomic` helper the next commit adds) replaces a file by writing a sibling temp file and renaming it over the target. That is ONE filesystem event on the destination — notify 8 surfaces inotify's IN_MOVED_TO as `Modify(Name(RenameMode::To))` — not the truncate-then-write pair `std::fs::write` produces. Nothing in the suite pinned that the watcher treats it as a content edit, nor that the in-flight temp file stays invisible to both watch modes. Three integration tests in cli_watch.rs: R1 watch_file_mode_rename_into_place_triggers_rebuild R2 watch_dir_mode_rename_into_place_triggers_rebuild R3 watch_dir_mode_write_atomic_temp_file_is_never_compiled R3 carries its own non-vacuity control inside the same test: a REAL second source (`u.mds`) is created through the same rename path and must be compiled, so the two "no temp artefact" assertions cannot pass on a watcher that is simply compiling nothing. One unit test in src/output.rs: collect_mds_files_ignores_write_atomic_temp_names — the `..tmp--` shape puts the suffix AFTER the `.mds`, so `Path::extension()` is not `mds` and the shared walker's gate drops it. Second half inverts the name to prove the first assertion is not passing on an empty walk. RED observed (cargo nextest run -p mds-cli --test cli_watch): error[E0432]: unresolved import `common::write_atomic` --> crates/mds-cli/tests/cli_watch.rs:24:84 | 24 | dup_vars_file_warning, mds_bin, spawn_watch_ready, spawn_watch_unsynchronized, write_atomic, | ^^^^^^^^^^^^ no `write_atomic` in `common` error: could not compile `mds-cli` (test "cli_watch") due to 1 previous error This is the intended RED: the helper does not exist yet. Consequently `cargo clippy -p mds-cli --all-targets` does not pass at this commit either — it cannot build the cli_watch test target. The next commit adds the helper and both clippy variants are clean from there on. GREEN already, as expected (the walker gate is pre-existing behaviour; the test pins it): PASS [0.013s] mds-cli::bin/mds output::tests::collect_mds_files_ignores_write_atomic_temp_names Summary [0.014s] 1 test run: 1 passed, 137 skipped Refs #320. --- crates/mds-cli/src/output.rs | 19 ++++ crates/mds-cli/tests/cli_watch.rs | 166 +++++++++++++++++++++++++++++- 2 files changed, 184 insertions(+), 1 deletion(-) diff --git a/crates/mds-cli/src/output.rs b/crates/mds-cli/src/output.rs index 74e4a82a..95e64eec 100644 --- a/crates/mds-cli/src/output.rs +++ b/crates/mds-cli/src/output.rs @@ -1371,6 +1371,25 @@ mod tests { assert_eq!(result, PathBuf::from("/out/page.md")); } + /// The `..tmp--` temp files an atomic write leaves in flight must + /// never be collected as sources. The suffix sits AFTER the `.mds`, so + /// `Path::extension()` is the `tmp-…` component and the walker's extension gate + /// rejects it — the same gate the dir-mode watch filter uses. + /// + /// The second half is the non-vacuity control: a name whose `.mds` is genuinely + /// last IS collected, so the first assertion is not passing on an empty walk. + #[test] + fn collect_mds_files_ignores_write_atomic_temp_names() { + let dir = tempfile::tempdir().unwrap(); + std::fs::write(dir.path().join("t.mds"), "real").unwrap(); + std::fs::write(dir.path().join(".t.mds.tmp-4242-7"), "in flight").unwrap(); + let files = collect_mds_files(dir.path(), 64, None); + assert_eq!(files.len(), 1, "temp file must not be collected: {files:?}"); + // Non-vacuity: the inverted name IS collected. + std::fs::write(dir.path().join(".tmp-4242-8.t.mds"), "wrong shape").unwrap(); + assert_eq!(collect_mds_files(dir.path(), 64, None).len(), 2); + } + #[test] fn is_partial_detects_underscore_prefix() { assert!(is_partial(Path::new("/dir/_partial.mds"))); diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index 1d936373..16a95dbc 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -21,7 +21,8 @@ mod common; use common::{ - dup_vars_file_warning, mds_bin, spawn_watch_ready, spawn_watch_unsynchronized, StderrTap, + dup_vars_file_warning, mds_bin, spawn_watch_ready, spawn_watch_unsynchronized, write_atomic, + StderrTap, }; use std::path::Path; @@ -4617,3 +4618,166 @@ fn i20_watch_quiet_suppresses_vars_file_duplicate_warning_on_every_rebuild() { drop(child); } + +// ── R1-R3: rename-into-place (atomic write) is a first-class edit (#320) ───── +// +// Editors and `write_atomic` replace a file by writing a sibling temp file and +// renaming it over the target. That is ONE filesystem event on the destination +// (`Modify(Name(RenameMode::To))` under notify 8 / inotify `IN_MOVED_TO`), not the +// truncate-then-write pair `std::fs::write` produces. These three tests pin that the +// watcher treats it as a content edit and that the in-flight temp file is invisible +// to both watch modes. + +/// R1: file mode must rebuild when the watched source is replaced by a rename. +#[test] +fn watch_file_mode_rename_into_place_triggers_rebuild() { + let dir = tempfile::tempdir().unwrap(); + let src = dir.path().join("t.mds"); + std::fs::write(&src, "version 1").unwrap(); + let out = dir.path().join("t.md"); + + let (child, stderr_tap) = spawn_ready( + mds_bin() + .args(["watch", src.to_str().unwrap(), "--debounce", "0"]) + .stdout(Stdio::null()), + ); + + assert!( + wait_for_file_contains(&out, "version 1", TIMEOUT), + "R1: startup compile must complete" + ); + + write_atomic(&src, "version 2"); + + assert!( + wait_for_file_contains(&out, "version 2", TIMEOUT), + "R1: a rename-into-place edit must trigger a rebuild" + ); + let stderr = wait_for_stderr_contains_str(&stderr_tap, "Recompiled", TIMEOUT); + assert!( + stderr.contains("Recompiled"), + "R1: the rebuild must announce itself; stderr:\n{stderr}" + ); + + drop(child); +} + +/// R2: dir mode must rebuild when a watched source is replaced by a rename. +#[test] +fn watch_dir_mode_rename_into_place_triggers_rebuild() { + let base = tempfile::tempdir().unwrap(); + let src_dir = base.path().join("src"); + let out_dir = base.path().join("out"); + std::fs::create_dir_all(&src_dir).unwrap(); + std::fs::create_dir_all(&out_dir).unwrap(); + + let src = src_dir.join("t.mds"); + std::fs::write(&src, "version 1").unwrap(); + let out = out_dir.join("t.md"); + + let (child, stderr_tap) = spawn_ready( + mds_bin() + .args([ + "watch", + src_dir.to_str().unwrap(), + "--out-dir", + out_dir.to_str().unwrap(), + "--debounce", + "0", + ]) + .stdout(Stdio::null()), + ); + + assert!( + wait_for_file_contains(&out, "version 1", TIMEOUT), + "R2: startup compile must complete" + ); + + write_atomic(&src, "version 2"); + + assert!( + wait_for_file_contains(&out, "version 2", TIMEOUT), + "R2: a rename-into-place edit must trigger a rebuild" + ); + let stderr = wait_for_stderr_contains_str(&stderr_tap, "Recompiled", TIMEOUT); + assert!( + stderr.contains("Recompiled"), + "R2: the rebuild must announce itself; stderr:\n{stderr}" + ); + + drop(child); +} + +/// R3: the temp file an atomic write leaves in flight is never compiled. +/// +/// The `..tmp--` shape puts the suffix AFTER the `.mds`, so +/// `Path::extension()` is not `mds` and both the dir-mode event filter and +/// `collect_mds_files` drop it. Asserting only that absence would be vacuous if the +/// watcher were simply not compiling anything, so the same test writes a REAL second +/// source through `write_atomic` and requires that one to be compiled. +#[test] +fn watch_dir_mode_write_atomic_temp_file_is_never_compiled() { + let base = tempfile::tempdir().unwrap(); + let src_dir = base.path().join("src"); + let out_dir = base.path().join("out"); + std::fs::create_dir_all(&src_dir).unwrap(); + std::fs::create_dir_all(&out_dir).unwrap(); + + let src = src_dir.join("t.mds"); + std::fs::write(&src, "version 1").unwrap(); + + let (child, stderr_tap) = spawn_ready( + mds_bin() + .args([ + "watch", + src_dir.to_str().unwrap(), + "--out-dir", + out_dir.to_str().unwrap(), + "--debounce", + "0", + ]) + .stdout(Stdio::null()), + ); + + assert!( + wait_for_file_contains(&out_dir.join("t.md"), "version 1", TIMEOUT), + "R3: startup compile must complete" + ); + + // Atomic edit of the existing source, then a brand-new source — also atomic. + write_atomic(&src, "version 2"); + assert!( + wait_for_file_contains(&out_dir.join("t.md"), "version 2", TIMEOUT), + "R3: the atomic edit must rebuild t.md" + ); + + // Positive control: a genuine new source written the same way IS compiled, so the + // "temp file produced nothing" assertions below cannot pass vacuously. + write_atomic(&src_dir.join("u.mds"), "brand new"); + assert!( + wait_for_file_contains(&out_dir.join("u.md"), "brand new", TIMEOUT), + "R3 (positive control): a real source created by a rename must be compiled" + ); + + // No output derives from any temp name, in either directory. + for dir in [&out_dir, &src_dir] { + for entry in std::fs::read_dir(dir).unwrap() { + let name = entry.unwrap().file_name().to_string_lossy().into_owned(); + assert!( + !name.contains(".tmp-"), + "R3: no file derived from a write_atomic temp name may survive in {}; \ + found {name}", + dir.display() + ); + } + } + + // And nothing announced compiling one. + let stderr = stderr_tap.text(); + assert!( + !stderr.contains(".tmp-"), + "R3: no status line may mention a write_atomic temp file; stderr:\n{stderr}" + ); + + drop(child); +} From b055957d00ac81fcdd5f2e27238757b390e8ecec Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:09:48 +0300 Subject: [PATCH 03/19] test(watch): add common::write_atomic (temp + rename, one FS event) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit GREEN for the R1-R3 tests added in the previous commit. `std::fs::write` truncates before it writes, so a watcher running at `--debounce 0` can observe — and compile — the 0-byte intermediate. CI run 34366009518 on 2b91850 printed two `Recompiled` lines for a single write for exactly this reason. Every real editor replaces a file by writing a sibling temp and renaming it over the target, which is one event on the destination; `write_atomic` does the same so the suite's writes look like an editor's rather than like a truncate. Temp name shape is load-bearing: `..tmp--` puts the suffix AFTER the name, so `Path::extension()` is the `tmp-…` component and never `mds`. Both `collect_mds_files_inner` (output.rs) and the dir-mode event filter (watch.rs) gate on exactly that extension, so an in-flight temp file is invisible to both. A `debug_assert_ne!` in the helper pins the shape at its source. A process-local `AtomicU64` plus the pid makes the temp name unique across the suite's parallel tests. No fsync — `rename` orders the replacement for every live process, which is all a watcher needs, and the product's own readiness marker is written the same way. GREEN observed (cargo nextest run -p mds-cli --test cli_watch, filtered): PASS [0.590s] (1/3) mds-cli::cli_watch watch_dir_mode_rename_into_place_triggers_rebuild PASS [0.590s] (2/3) mds-cli::cli_watch watch_file_mode_rename_into_place_triggers_rebuild PASS [0.647s] (3/3) mds-cli::cli_watch watch_dir_mode_write_atomic_temp_file_is_never_compiled Summary [0.648s] 3 tests run: 3 passed, 72 skipped No product change was needed: `Modify(Name(RenameMode::To))` already passes `is_content_event` and the destination path is already in the watch set, so both modes saw the rename as a content edit on the first try. cargo fmt --all --check clean; cargo clippy -p mds-cli --all-targets -- -D warnings and the same with --features startup-race-probe both clean. Refs #320. --- crates/mds-cli/tests/common/mod.rs | 69 ++++++++++++++++++++++++++++++ 1 file changed, 69 insertions(+) diff --git a/crates/mds-cli/tests/common/mod.rs b/crates/mds-cli/tests/common/mod.rs index 613b73ae..3860fdd5 100644 --- a/crates/mds-cli/tests/common/mod.rs +++ b/crates/mds-cli/tests/common/mod.rs @@ -1,6 +1,7 @@ use std::io::Read; use std::path::{Path, PathBuf}; use std::process::{Child, Command, Stdio}; +use std::sync::atomic::{AtomicU64, Ordering}; use std::sync::{Arc, Mutex}; use std::time::Duration; @@ -70,6 +71,74 @@ pub fn count_occurrences(haystack: &str, needle: &str) -> usize { count } +// ── Atomic file replacement ────────────────────────────────────────────────── + +/// Monotonic counter making every [`write_atomic`] temp name unique within a +/// process; the pid disambiguates across processes. +static WRITE_ATOMIC_SEQ: AtomicU64 = AtomicU64::new(0); + +/// Replace `path`'s contents in ONE filesystem event, the way an editor does: write a +/// fresh temp file in the same directory, then `rename` it over `path`. +/// +/// Why: `std::fs::write` truncates before it writes, so a zero-debounce watcher can +/// compile the 0-byte intermediate — CI run 34366009518 on 2b91850 printed two +/// `Recompiled` lines for one write. notify 8 surfaces the rename as +/// `Modify(Name(RenameMode::To))` on the destination path, which the watcher treats +/// as a content event. +/// +/// The temp name is `..tmp--` — the suffix goes AFTER the name so +/// `Path::extension()` is never `mds`: `collect_mds_files_inner` (output.rs) and the +/// dir-mode event filter (watch.rs) gate on exactly that, so an in-flight temp file +/// is invisible to both. +/// +/// No fsync: `rename` orders the replacement for every live process, which is all a +/// watcher needs. The product's own readiness marker is written the same way. +/// +/// Deliberate non-user: `watch_single_status_line_per_rebuild`, whose subject IS the +/// coalescing of the truncate+write pair. +/// +/// The Windows sharing-violation caveat (a rename over a file another process holds +/// open can fail) is developer-machine only; CI runs this suite on ubuntu. +/// +/// # Panics +/// Panics if `path` has no parent or no file name, or if either filesystem step +/// fails — a test whose edit did not land is a defect, not a slow machine. +#[allow(dead_code)] +pub fn write_atomic(path: &Path, contents: impl AsRef<[u8]>) { + let dir = path + .parent() + .unwrap_or_else(|| panic!("write_atomic: path has no parent: {}", path.display())); + let name = path + .file_name() + .unwrap_or_else(|| panic!("write_atomic: path has no file name: {}", path.display())); + let seq = WRITE_ATOMIC_SEQ.fetch_add(1, Ordering::Relaxed); + let tmp = dir.join(format!( + ".{}.tmp-{}-{}", + name.to_string_lossy(), + std::process::id(), + seq + )); + debug_assert_ne!( + tmp.extension().and_then(|e| e.to_str()), + Some("mds"), + "write_atomic temp name must never end in .mds; it would be collected as a source" + ); + if let Err(e) = std::fs::write(&tmp, contents.as_ref()) { + panic!( + "write_atomic: cannot write temp file {}: {e}", + tmp.display() + ); + } + if let Err(e) = std::fs::rename(&tmp, path) { + let _ = std::fs::remove_file(&tmp); + panic!( + "write_atomic: cannot rename {} -> {}: {e}", + tmp.display(), + path.display() + ); + } +} + // ── Watch readiness handshake ──────────────────────────────────────────────── /// Contents `mds watch` writes to the file named by `MDS_TEST_READY`. From 04b01a6313b10a89beeff41ebba9c4ae108aee80 Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:11:54 +0300 Subject: [PATCH 04/19] test(watch): route every watched write through write_atomic MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Mechanical rule, stated here and in the file's doc comment so a reviewer can reproduce the exact set: convert a `std::fs::write(` call iff it occurs AFTER the `spawn_ready`/`spawn_unsynchronized` call in the same test fn AND targets a path the watcher is watching (the `.mds` source, an imported partial, the `--vars` file, an external dependency). Everything else keeps `std::fs::write`: pre-spawn fixture writes, `.git` markers, `mds.json`, and output files. 45 conversions. Counts in crates/mds-cli/tests/cli_watch.rs: std::fs::write( 156 -> 114 (159 -> 114 counting the 3 added by the RED commit) write_atomic( 0 -> 49 (45 conversions + 4 call sites in R1-R3) Two post-spawn writes are deliberate exceptions and now say so inline: - watch_single_status_line_per_rebuild (--debounce 100) — its subject IS the coalescing of the truncate+write pair; an atomic write would remove the thing being tested. - watch_debounce_single_rebuild_from_burst — same reason across a 10-edit burst; a later phase rewrites this test. Why this matters: `std::fs::write` truncates first, so at `--debounce 0` the watcher can see and compile a 0-byte file and then the real content — two rebuilds for one logical edit. That is the shape behind the i17 over-counts in CI run 34366009518 (left 3 / right 2 at cli_watch.rs:4370). Routing the writes through a rename makes every watched edit exactly one event, which is also what a real editor does. GREEN, three consecutive full runs of `cargo nextest run -p mds-cli --test cli_watch`: Summary [3.910s] 75 tests run: 75 passed, 0 skipped Summary [3.930s] 75 tests run: 75 passed, 0 skipped Summary [3.938s] 75 tests run: 75 passed, 0 skipped macOS cannot reproduce the Linux inotify tearing class this guards against, so this is green locally and the Linux soak is the instrument. cargo fmt --all --check clean; both clippy variants clean. Refs #320. --- crates/mds-cli/tests/cli_watch.rs | 156 +++++++++++++++--------------- 1 file changed, 79 insertions(+), 77 deletions(-) diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index 16a95dbc..8b394ba4 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -13,6 +13,16 @@ //! a self-heal idle tick, [`STARTUP_WINDOW_TIMEOUT`] for the deliberately //! unsynchronized startup-window tests. See each constant's docs. //! +//! Writes to watched paths go through `common::write_atomic`. The rule is mechanical, +//! so a reviewer can reproduce the set exactly: a write is converted iff it occurs +//! AFTER the `spawn_ready`/`spawn_unsynchronized` call in the same test fn AND targets +//! a path the watcher is watching (the `.mds` source, an imported partial, the +//! `--vars` file, an external dependency). Pre-spawn fixture writes, `.git` markers, +//! `mds.json`, and output files keep `std::fs::write`. Two post-spawn writes are +//! deliberate exceptions and say so inline: `watch_single_status_line_per_rebuild` +//! and `watch_debounce_single_rebuild_from_burst`, whose subject IS the truncate+write +//! pair that `write_atomic` collapses. +//! //! Flakiness mitigations: //! - Assert on output FILE content rather than stderr ordering. //! - Write dependency files BEFORE adding the `@import` that references them. @@ -248,7 +258,7 @@ fn watch_edit_entry_updates_output() { ); // Edit the source. - std::fs::write(&src, "---\nname: Bob\n---\nHello {{name}}!\n").unwrap(); + write_atomic(&src, "---\nname: Bob\n---\nHello {{name}}!\n"); // Wait for rebuild. assert!( @@ -294,11 +304,10 @@ fn watch_edit_imported_dep_updates_entry() { ); // Edit the helper to change the greeting. - std::fs::write( + write_atomic( &helper, "@define greet(name):\nHi there {{name}}!\n@end\n\n@export greet\n", - ) - .unwrap(); + ); assert!( wait_for_file_contains(&out, "Hi there World!", TIMEOUT), @@ -330,7 +339,7 @@ fn watch_compile_error_keeps_watcher_alive() { ); // Introduce a compile error. - std::fs::write(&src, "Hello {{undefined_var_xyz}}!\n").unwrap(); + write_atomic(&src, "Hello {{undefined_var_xyz}}!\n"); // Give the watcher time to attempt rebuild. std::thread::sleep(Duration::from_millis(500)); @@ -343,7 +352,7 @@ fn watch_compile_error_keeps_watcher_alive() { ); // Fix the error — watcher should recover. - std::fs::write(&src, "---\nname: Charlie\n---\nHello {{name}}!\n").unwrap(); + write_atomic(&src, "---\nname: Charlie\n---\nHello {{name}}!\n"); assert!( wait_for_file_contains(&out, "Hello Charlie!", TIMEOUT), "fixing the error should trigger a successful rebuild" @@ -394,11 +403,10 @@ fn watch_dir_mode_compiles_all_on_startup() { ); // Edit a.mds → only a.md should update. - std::fs::write( - dir.path().join("a.mds"), + write_atomic( + &dir.path().join("a.mds"), "---\nname: A-edited\n---\nFile A: {{name}}\n", - ) - .unwrap(); + ); assert!( wait_for_file_contains(&out_dir.join("a.md"), "File A: A-edited", TIMEOUT), "editing a.mds should update a.md" @@ -443,11 +451,10 @@ fn watch_dir_mode_picks_up_new_files() { ); // Create a new file AFTER the watcher is running. - std::fs::write( - dir.path().join("c.mds"), + write_atomic( + &dir.path().join("c.mds"), "---\nname: C\n---\nNew file {{name}}\n", - ) - .unwrap(); + ); assert!( wait_for_file_contains(&out_dir.join("c.md"), "New file C", TIMEOUT), @@ -540,7 +547,7 @@ fn watch_vars_file_change_triggers_recompile() { ); // Edit the vars file. - std::fs::write(&vars, r#"{"name": "Bob"}"#).unwrap(); + write_atomic(&vars, r#"{"name": "Bob"}"#); assert!( wait_for_file_contains(&out, "Hello Bob!", TIMEOUT), @@ -576,7 +583,7 @@ fn watch_clear_non_tty_no_ansi_escape() { // Edit the source to trigger a rebuild — this is the path that calls // clear_terminal(). On a non-TTY pipe it must be a no-op. - std::fs::write(&src, "---\nname: There\n---\nHello {{name}}!\n").unwrap(); + write_atomic(&src, "---\nname: There\n---\nHello {{name}}!\n"); assert!( wait_for_file_contains(&out, "Hello There!", TIMEOUT), "rebuild should occur after editing source" @@ -677,7 +684,7 @@ fn watch_set_vars_applied_on_rebuild() { ); // Edit to trigger rebuild — --set should still apply. - std::fs::write(&src, "Greetings {{name}}!\n").unwrap(); + write_atomic(&src, "Greetings {{name}}!\n"); assert!( wait_for_file_contains(&out, "Greetings Alice!", TIMEOUT), "--set name=Alice should persist across rebuilds" @@ -850,7 +857,7 @@ fn watch_debounce_final_value_wins_after_rapid_edits() { // Write 10 rapid edits within the debounce window. for i in 1..=10 { - std::fs::write(&src, format!("---\nname: v{i}\n---\nHello {{{{name}}}}!\n")).unwrap(); + write_atomic(&src, format!("---\nname: v{i}\n---\nHello {{{{name}}}}!\n")); // Tiny sleep to ensure filesystem registers the write, but // well within the 200ms debounce window. std::thread::sleep(Duration::from_millis(5)); @@ -936,11 +943,10 @@ fn watch_import_removal_stops_tracking_dep() { // STEP 1 (add direction, already covered by T-I3 but verified here too): // Edit helper — entry output should update because helper is tracked. - std::fs::write( + write_atomic( &helper, "@define greet(name):\nHi {{name}}!\n@end\n\n@export greet\n", - ) - .unwrap(); + ); assert!( wait_for_file_contains(&out, "Hi World!", TIMEOUT), "editing helper while imported should trigger a rebuild" @@ -948,7 +954,7 @@ fn watch_import_removal_stops_tracking_dep() { // STEP 2 (removal direction): rewrite entry to remove the @import. // The entry now produces static output that does NOT reference helper. - std::fs::write(&entry, "Static content\n").unwrap(); + write_atomic(&entry, "Static content\n"); assert!( wait_for_file_contains(&out, "Static content", TIMEOUT), "removing @import should rebuild entry with static content" @@ -959,11 +965,10 @@ fn watch_import_removal_stops_tracking_dep() { // STEP 3: Edit helper again — entry output must NOT change because the dep // was removed from the watch set after the resync in step 2. - std::fs::write( + write_atomic( &helper, "@define greet(name):\nBye {{name}}!\n@end\n\n@export greet\n", - ) - .unwrap(); + ); // Wait long enough for any spurious rebuild to materialize (500ms >> debounce 0). std::thread::sleep(Duration::from_millis(500)); @@ -1029,7 +1034,7 @@ fn watch_dir_mode_vars_change_recompiles_all() { ); // Edit vars.json — BOTH outputs should update. - std::fs::write(&vars, r#"{"greeting": "Goodbye"}"#).unwrap(); + write_atomic(&vars, r#"{"greeting": "Goodbye"}"#); assert!( wait_for_file_contains(&out_dir_path.join("a.md"), "Goodbye from A", TIMEOUT), @@ -1066,7 +1071,7 @@ fn watch_quiet_keeps_errors_visible() { ); // Introduce a compile error (reference an undefined variable with no frontmatter default). - std::fs::write(&src, "Hello {{__undefined_xyz__}}!\n").unwrap(); + write_atomic(&src, "Hello {{__undefined_xyz__}}!\n"); // Give the watcher time to attempt rebuild and emit error. std::thread::sleep(Duration::from_millis(500)); @@ -1094,7 +1099,7 @@ fn watch_quiet_keeps_errors_visible() { ); // Fix the error — watcher should recover. - std::fs::write(&src, "---\nname: Fixed\n---\nHello {{name}}!\n").unwrap(); + write_atomic(&src, "---\nname: Fixed\n---\nHello {{name}}!\n"); assert!( wait_for_file_contains(&out, "Hello Fixed!", TIMEOUT), "after fixing the compile error, watcher should rebuild successfully" @@ -1188,6 +1193,9 @@ fn watch_debounce_single_rebuild_from_burst() { ); // Write 10 rapid edits within the 250ms debounce window. + // DELIBERATE: this test's subject is the debounce window collapsing a burst of + // truncate+write pairs, so it keeps plain writes. Every other post-spawn write in + // this file goes through `write_atomic`. for i in 1..=10u32 { std::fs::write(&src, format!("---\nname: v{i}\n---\nBurst {{{{name}}}}!\n")).unwrap(); std::thread::sleep(Duration::from_millis(5)); @@ -1552,6 +1560,9 @@ fn watch_single_status_line_per_rebuild() { ); // Make ONE real content-changing edit. + // DELIBERATE: this test's subject is coalescing the truncate+write pair at + // --debounce 100, so it keeps the plain write. Every other post-spawn write in + // this file goes through `write_atomic`. std::fs::write(&src, "---\nname: v1\n---\nStatus {{name}}!\n").unwrap(); // Wait for the rebuild to appear in the output. @@ -1737,11 +1748,10 @@ fn watch_dir_mode_shared_partial_rebuilds_importers() { ); // Edit the partial — both importers must rebuild. - std::fs::write( + write_atomic( &partial, "@define greet(name):\nHi {{name}}!\n@end\n\n@export greet\n", - ) - .unwrap(); + ); assert!( wait_for_file_contains(&out_dir.join("a.md"), "Hi A!", TIMEOUT), @@ -1801,7 +1811,7 @@ fn watch_dir_mode_chain_rebuild() { ); // Edit C — A must update. - std::fs::write(&c, "@define val():\nV2\n@end\n\n@export val\n").unwrap(); + write_atomic(&c, "@define val():\nV2\n@end\n\n@export val\n"); assert!( wait_for_file_contains(&out_dir.join("a.md"), "V2", TIMEOUT), "a.md should update to V2 after editing _c.mds (transitive chain)" @@ -1840,7 +1850,7 @@ fn watch_poll_interval_zero_works() { ); // Verify a real edit also works. - std::fs::write(&src, "---\nname: Poll\n---\nHello {{name}}!\n").unwrap(); + write_atomic(&src, "---\nname: Poll\n---\nHello {{name}}!\n"); assert!( wait_for_file_contains(&out, "Hello Poll!", TIMEOUT), "--poll-interval 0: edit should still trigger rebuild via native event" @@ -2095,7 +2105,7 @@ fn watch_file_mode_parent_dir_delete_recreate_recovers() { // Recreate the parent dir and the source file with new content. std::fs::create_dir(&src_dir).unwrap(); - std::fs::write(&src, "---\nname: After\n---\nEntry {{name}}\n").unwrap(); + write_atomic(&src, "---\nname: After\n---\nEntry {{name}}\n"); // TICK-DEPENDENT: `remove_dir_all(&src_dir)` destroyed the inotify watch on the old // inode, and the recreated dir is a new inode nothing is watching — so the write @@ -2150,11 +2160,10 @@ fn watch_dir_mode_root_delete_recreate_recovers() { // Recreate the root with a brand-new file (init-gap case). std::fs::create_dir(&root).unwrap(); - std::fs::write( - root.join("new.mds"), + write_atomic( + &root.join("new.mds"), "---\nname: N\n---\nNew file {{name}}\n", - ) - .unwrap(); + ); // TICK-DEPENDENT: the recursive watch died with the old root inode, so the create // above is unobservable; the liveness probe's re-arm + reconcile is the only path. @@ -2229,7 +2238,7 @@ fn watch_file_mode_entry_deleted_settles_then_recovers() { ); // Recreate the file with different content. - std::fs::write(&src, "---\nname: Recovered\n---\nHello {{name}}!\n").unwrap(); + write_atomic(&src, "---\nname: Recovered\n---\nHello {{name}}!\n"); // Wait for recompile after recovery. assert!( @@ -2308,7 +2317,7 @@ fn watch_vars_dir_delete_recreate_rearms() { std::thread::sleep(Duration::from_millis(300)); // Now write new vars — the re-armed watcher should catch this event. - std::fs::write(&vars_file, r#"{"greeting": "Goodbye"}"#).unwrap(); + write_atomic(&vars_file, r#"{"greeting": "Goodbye"}"#); // TICK-DEPENDENT: whether the write above is delivered as an event depends on the // probe having already re-armed the recreated vars dir. If it has not, the fallback @@ -2395,11 +2404,10 @@ fn watch_dir_mode_cross_root_partial_edit_rebuilds_importer() { ); // Edit the external partial. - std::fs::write( + write_atomic( &partial, "@define greet():\nExternal V2\n@end\n\n@export greet\n", - ) - .unwrap(); + ); // In-root importer output must update. assert!( @@ -2533,7 +2541,7 @@ fn watch_dir_mode_create_missing_partial_heals_importer() { // Now create the previously-missing partial. let partial = dir.path().join("_missing.mds"); - std::fs::write(&partial, "@define val():\nHealed!\n@end\n\n@export val\n").unwrap(); + write_atomic(&partial, "@define val():\nHealed!\n@end\n\n@export val\n"); // The importer should heal and produce output. assert!( @@ -2594,11 +2602,10 @@ fn watch_dir_mode_dual_role_node_edit_and_delete() { // Edit dual.mds — both dual.md and consumer.md should update. // Use a longer content to force a size delta. - std::fs::write( + write_atomic( &dual, "@define greet():\nDual V2 (updated)\n@end\n\n@export greet\n\nStandalone updated content\n", - ) - .unwrap(); + ); assert!( wait_for_file_contains( @@ -2885,11 +2892,10 @@ fn watch_dir_mode_partial_edit_rebuilds_exactly_n_importers() { let independent_before = std::fs::read_to_string(out_dir.join("independent.md")).unwrap(); // Edit the partial with different-length content to force a deterministic (mtime,size) delta. - std::fs::write( + write_atomic( &partial, "@define val():\nV2 updated\n@end\n\n@export val\n", - ) - .unwrap(); + ); // All three importers must update. assert!( @@ -2959,11 +2965,10 @@ fn watch_dir_mode_soak_50_edits_bounded_and_clean_exit() { for i in 1_u32..=50 { // Pad with spaces to ensure each round has a unique byte count. let padding = " ".repeat(i as usize); - std::fs::write( + write_atomic( &partial, format!("@define val():\nSoak V{i}{padding}\n@end\n\n@export val\n"), - ) - .unwrap(); + ); // Wait for this round's rebuild to propagate. let expected = format!("Soak V{i}"); @@ -3066,7 +3071,7 @@ fn watch_file_mode_parent_dir_deleted_bounded_errors_then_recovers() { // Recreate the parent directory and write the file with new content. std::fs::create_dir(&src_dir).unwrap(); - std::fs::write(&src, "V2-recovered\n").unwrap(); + write_atomic(&src, "V2-recovered\n"); // TICK-DEPENDENT: same as AC-W1 — the parent dir was removed, so the watch on it is // gone and the recreated dir is unwatched. Recovery is the vanish→reappear edge in @@ -3552,7 +3557,7 @@ fn watch_file_mode_edit_during_startup_window_is_not_lost() { ); // Edit now — inside the window under the defective ordering. - std::fs::write(&src, "---\nname: After\n---\nEntry {{name}}\n").unwrap(); + write_atomic(&src, "---\nname: After\n---\nEntry {{name}}\n"); assert!( wait_for_file_contains(&out, "Entry After", STARTUP_WINDOW_TIMEOUT), @@ -3596,7 +3601,7 @@ fn watch_dir_mode_edit_during_startup_window_is_not_lost() { "startup compile should publish 'Dir Before'" ); - std::fs::write(&src, "---\nname: After\n---\nDir {{name}}\n").unwrap(); + write_atomic(&src, "---\nname: After\n---\nDir {{name}}\n"); assert!( wait_for_file_contains(&out, "Dir After", STARTUP_WINDOW_TIMEOUT), @@ -3676,11 +3681,10 @@ fn watch_dir_mode_cross_root_edit_during_startup_window_is_not_lost() { ); // Edit the cross-root partial now — inside the window where nothing is watching it. - std::fs::write( + write_atomic( &partial, "@define greet():\nWindow V2\n@end\n\n@export greet\n", - ) - .unwrap(); + ); // TICK-DEPENDENT: no filesystem event announces this edit, so recovery is the idle // tick's `(mtime, size)` diff against the baseline captured before the first read. @@ -3752,11 +3756,10 @@ fn watch_file_mode_dep_edit_during_startup_window_is_not_lost() { "startup compile should publish 'Dep V1'" ); - std::fs::write( + write_atomic( &partial, "@define greet():\nDep V2\n@end\n\n@export greet\n", - ) - .unwrap(); + ); assert!( wait_for_file_contains(&out, "Dep V2", TICK_TIMEOUT), @@ -3853,7 +3856,7 @@ fn watch_dir_mode_idle_tick_fires_under_event_flood() { std::fs::remove_dir_all(&root).unwrap(); std::thread::sleep(Duration::from_millis(200)); std::fs::create_dir(&root).unwrap(); - std::fs::write(root.join("new.mds"), "---\nname: N\n---\nFlood {{name}}\n").unwrap(); + write_atomic(&root.join("new.mds"), "---\nname: N\n---\nFlood {{name}}\n"); let recovered = wait_for_file_contains(&out_dir.join("new.md"), "Flood N", TICK_TIMEOUT); @@ -4149,14 +4152,14 @@ fn i8_file_watch_duplicate_set_warns_exactly_once_across_two_edits() { ); // Edit 1: trigger a rebuild. - std::fs::write(&src, "version 2").unwrap(); + write_atomic(&src, "version 2"); assert!( wait_for_file_contains(&out, "version 2", TIMEOUT), "I8: rebuild after edit 1 must complete" ); // Edit 2: trigger another rebuild. - std::fs::write(&src, "version 3").unwrap(); + write_atomic(&src, "version 3"); assert!( wait_for_file_contains(&out, "version 3", TIMEOUT), "I8: rebuild after edit 2 must complete" @@ -4223,7 +4226,7 @@ fn i9_dir_watch_duplicate_set_warns_exactly_once_at_startup() { ); // Trigger a rebuild to exercise the :1914 path (handle_dir_event). - std::fs::write(&src, "version 2").unwrap(); + write_atomic(&src, "version 2"); assert!( wait_for_file_contains(&out, "version 2", TIMEOUT), "I9: rebuild after edit must complete" @@ -4289,7 +4292,7 @@ fn i16_file_watch_vars_file_duplicate_warns_at_startup_and_on_every_rebuild() { // Edit 1: trigger a rebuild — ADR-016 reloads the vars file, re-reporting the // duplicate. - std::fs::write(&src, "version 2").unwrap(); + write_atomic(&src, "version 2"); assert!( wait_for_file_contains(&out, "version 2", TIMEOUT), "I16: rebuild after edit 1 must complete" @@ -4302,7 +4305,7 @@ fn i16_file_watch_vars_file_duplicate_warns_at_startup_and_on_every_rebuild() { ); // Edit 2: trigger another rebuild. - std::fs::write(&src, "version 3").unwrap(); + write_atomic(&src, "version 3"); assert!( wait_for_file_contains(&out, "version 3", TIMEOUT), "I16: rebuild after edit 2 must complete" @@ -4362,7 +4365,7 @@ fn i17_dir_watch_vars_file_duplicate_warns_once_per_rebuild() { // One rebuild: the count must rise to exactly 2, proving exactly one of // :1793/:1919 fires per rebuild (not both). - std::fs::write(&src, "version 2").unwrap(); + write_atomic(&src, "version 2"); assert!( wait_for_file_contains(&out, "version 2", TIMEOUT), "I17: rebuild after edit must complete" @@ -4425,7 +4428,7 @@ fn i18_duplicate_introduced_mid_session_is_reported_on_the_next_rebuild() { ); // First rebuild, still clean: still no warning. - std::fs::write(&src, "version 2").unwrap(); + write_atomic(&src, "version 2"); assert!( wait_for_file_contains(&out, "version 2", TIMEOUT), "I18: first rebuild must complete" @@ -4439,8 +4442,8 @@ fn i18_duplicate_introduced_mid_session_is_reported_on_the_next_rebuild() { ); // Introduce a duplicate mid-session, then trigger the next rebuild. - std::fs::write(&vars_file, r#"{"x": 1, "x": 2}"#).unwrap(); - std::fs::write(&src, "version 3").unwrap(); + write_atomic(&vars_file, r#"{"x": 1, "x": 2}"#); + write_atomic(&src, "version 3"); assert!( wait_for_file_contains(&out, "version 3", TIMEOUT), "I18: rebuild after introducing the duplicate must complete" @@ -4526,11 +4529,10 @@ fn i19_dir_watch_liveness_self_heal_rebuild_warns_about_vars_file_duplicate() { // warning per observable rebuild, which is what the count assertion below // pins. std::fs::create_dir(&root).unwrap(); - std::fs::write( - root.join("new.mds"), + write_atomic( + &root.join("new.mds"), "---\nname: N\n---\nNew file {{name}}\n", - ) - .unwrap(); + ); assert!( wait_for_file_contains(&out_dir.join("new.md"), "New file N", TICK_TIMEOUT), @@ -4602,7 +4604,7 @@ fn i20_watch_quiet_suppresses_vars_file_duplicate_warning_on_every_rebuild() { stderr:\n{startup_stderr}" ); - std::fs::write(&src, "version 2").unwrap(); + write_atomic(&src, "version 2"); assert!( wait_for_file_contains(&out, "version 2", TIMEOUT), "I20: rebuild after edit must complete even under --quiet" From fb3cd9bc9f90f0bbb68bd2a0e297cdd58bc40723 Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:12:35 +0300 Subject: [PATCH 05/19] =?UTF-8?q?test(watch):=20RED=20=E2=80=94=20StderrTa?= =?UTF-8?q?p::bytes=20can=20read=20a=20truncated=20buffer=20(#320)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `StderrTap::bytes` clones the shared buffer with no happens-before edge to the drain thread's last write. Reaping the child closes its write end and ends the drain loop, but nothing makes the reader observe that the loop finished, so a snapshot taken right after `kill` + `wait` can be a truncated prefix. The suite papered over this with a `thread::sleep` at every such site — 13 of them — and the `JoinHandle` for the drain thread is discarded at spawn, so joining is not even possible today. New test: stderr_tap_finish_captures_every_line_the_child_wrote. A dir watcher over 500 sources announces `Compiled to` once per file during the startup batch, and the readiness handshake fires only after that batch completes, so the expected count is exact (500) at the moment the child is killed. Written deliberately against the current `bytes()` path with NO sleep, so the next commit's `finish` has something to convert. The `Compiled to` count is its own positive control: a shortfall means a lost tail, and a count of 0 would mean the watcher compiled nothing rather than that the tap is sound. Observed locally (3 consecutive runs): PASS [0.678s] (1/1) mds-cli::cli_watch stderr_tap_finish_captures_every_line_the_child_wrote PASS [0.683s] (1/1) ... PASS [0.696s] (1/1) ... So this is GREEN on macOS. That is the honest result and it is expected: the field signature for this defect is Linux — `watch_clear_non_tty_no_ansi_escape` panicking at cli_watch.rs:520 in CI runs 32954883014 and 32954876042, a kill-then-snapshot site with the same unjoined-drain shape. macOS pipe timing has not been observed to tear here. The Linux soak is the instrument; the test pins the property either way. cargo fmt --all --check clean; both clippy variants clean. Refs #320. --- crates/mds-cli/tests/cli_watch.rs | 61 +++++++++++++++++++++++++++++++ 1 file changed, 61 insertions(+) diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index 8b394ba4..4233b033 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -4783,3 +4783,64 @@ fn watch_dir_mode_write_atomic_temp_file_is_never_compiled() { drop(child); } + +// ── Stderr capture completeness (#320) ────────────────────────────────────── + +/// The tap must hand back every byte the child wrote, not a prefix of it. +/// +/// `StderrTap::bytes` clones the shared buffer without any happens-before edge to the +/// drain thread's last write. Reaping the child closes its write end and ends the +/// drain loop, but nothing makes the reader observe that the loop has finished, so a +/// snapshot taken right after `kill` + `wait` can be a truncated prefix. The suite hid +/// that behind a `thread::sleep` at every such site. +/// +/// A dir watcher over 500 sources announces `Compiled to` once per file at startup, so +/// the expected count is exact and any lost tail shows up as a shortfall rather than +/// as a vague "looks empty". The `Compiled to` lines are also the positive control: +/// a count of 0 would mean the watcher compiled nothing, not that the tap is sound. +/// +/// macOS has not been observed to lose the tail; the field signature is Linux +/// (`cli_watch.rs:520` in CI runs 32954883014 and 32954876042). The Linux soak is the +/// instrument for this one. +#[test] +fn stderr_tap_finish_captures_every_line_the_child_wrote() { + const FILE_COUNT: usize = 500; + let dir = tempfile::tempdir().unwrap(); + let out_dir = dir.path().join("out"); + std::fs::create_dir(&out_dir).unwrap(); + + for i in 1..=FILE_COUNT { + std::fs::write( + dir.path().join(format!("file_{i:04}.mds")), + format!("drain-{i}\n"), + ) + .unwrap(); + } + + // No -q: the startup compile announces `Compiled to` once per file. + let (mut child, stderr_tap) = spawn_ready( + mds_bin() + .args([ + "watch", + dir.path().to_str().unwrap(), + "--out-dir", + out_dir.to_str().unwrap(), + "--debounce", + "0", + ]) + .stdout(Stdio::null()), + ); + + // Readiness fires only after the whole startup batch, so all FILE_COUNT lines + // have been written by the child by the time this returns. + let _ = child.0.kill(); + let _ = child.0.wait(); + + let stderr = stderr_tap.text(); + let announced = count_occurrences(&stderr, "Compiled to"); + assert_eq!( + announced, FILE_COUNT, + "the tap must return every `Compiled to` line the child wrote; got {announced} \ + of {FILE_COUNT}" + ); +} From 5b343fc7ab037d78b242dca35f3df4d17d0c56e8 Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:14:02 +0300 Subject: [PATCH 06/19] =?UTF-8?q?test(watch):=20join=20the=20drain=20threa?= =?UTF-8?q?d=20=E2=80=94=20PipeTap::finish;=20ChildGuard=20moves=20to=20co?= =?UTF-8?q?mmon=20(#320)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit GREEN for stderr_tap_finish_captures_every_line_the_child_wrote. `StderrTap` becomes `PipeTap`, a drained capture of ONE of the child's pipes, with `StderrTap`/`StdoutTap` as aliases so every existing call site keeps reading the way it did. The drain thread's `JoinHandle` — previously discarded at spawn, so joining was impossible — is now kept in the tap behind `Arc>>` (the `Option` so `finish` can take it; the `Arc>` so `PipeTap` stays `Clone`). New end-of-test read: #[must_use] fn finish(self, child: &mut ChildGuard) -> Vec #[must_use] fn finish_text(self, child: &mut ChildGuard) -> String Termination is proved rather than bounded: the drain loop exits only at EOF, EOF arrives only when the child's write end closes, and `finish` reaps the child before it joins — so no timeout is needed and none is used. Taking `&mut ChildGuard` puts "reaped before join" in the signature instead of in a comment. `bytes()`/`text()` stay NON-blocking and keep their documented caveat: no happens-before edge to the child's last write. The live-poll sites (`wait_for_stderr_contains_str`, the mid-test snapshots) need exactly that. `ChildGuard` moves from cli_watch.rs to tests/common/mod.rs — it has to live where `finish` can name it — and gains `kill_and_wait` alongside the existing `id` and `wait_status`. It stays `pub struct ChildGuard(pub Child)` so the `child.0` field accesses across the suite are unaffected. cli_build.rs keeps its own private copy; the two are in separate test binaries and cli_watch.rs imports by name, not by glob, so nothing conflicts and cli_build.rs is untouched. GREEN: cargo nextest run -p mds-cli --test cli_watch Summary [3.936s] 76 tests run: 76 passed, 0 skipped cargo fmt --all --check clean; both clippy variants clean. Refs #320. --- crates/mds-cli/tests/cli_watch.rs | 31 +----- crates/mds-cli/tests/common/mod.rs | 145 +++++++++++++++++++++++------ 2 files changed, 121 insertions(+), 55 deletions(-) diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index 4233b033..ce9c4d37 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -32,34 +32,15 @@ mod common; use common::{ dup_vars_file_warning, mds_bin, spawn_watch_ready, spawn_watch_unsynchronized, write_atomic, - StderrTap, + ChildGuard, StderrTap, }; use std::path::Path; -use std::process::{Child, Command, Stdio}; +use std::process::{Command, Stdio}; use std::time::{Duration, Instant}; // ── Helpers ──────────────────────────────────────────────────────────────── -/// RAII guard that kills + waits the child process on drop. -struct ChildGuard(Child); - -impl Drop for ChildGuard { - fn drop(&mut self) { - let _ = self.0.kill(); - let _ = self.0.wait(); - } -} - -impl ChildGuard { - fn id(&self) -> u32 { - self.0.id() - } - fn wait_status(&mut self) -> std::process::ExitStatus { - self.0.wait().expect("wait failed") - } -} - /// Spawn a watcher, block until it reports readiness, and wrap it in a `ChildGuard`. /// /// Every test that edits files under an `mds watch` must go through this: it returns @@ -4832,11 +4813,9 @@ fn stderr_tap_finish_captures_every_line_the_child_wrote() { ); // Readiness fires only after the whole startup batch, so all FILE_COUNT lines - // have been written by the child by the time this returns. - let _ = child.0.kill(); - let _ = child.0.wait(); - - let stderr = stderr_tap.text(); + // have been written by the child by the time this returns. `finish` reaps the + // child and then joins the drain, so what comes back is the complete stream. + let stderr = stderr_tap.finish_text(&mut child); let announced = count_occurrences(&stderr, "Compiled to"); assert_eq!( announced, FILE_COUNT, diff --git a/crates/mds-cli/tests/common/mod.rs b/crates/mds-cli/tests/common/mod.rs index 3860fdd5..8591996d 100644 --- a/crates/mds-cli/tests/common/mod.rs +++ b/crates/mds-cli/tests/common/mod.rs @@ -161,29 +161,133 @@ const READY_POLL: Duration = Duration::from_millis(2); /// every source in the tree while the suite runs at full parallelism. const READY_TIMEOUT: Duration = Duration::from_secs(10); -/// Captured stderr of a watcher spawned by [`spawn_watch_ready`] or -/// [`spawn_watch_unsynchronized`]. +/// RAII guard that kills + waits the child on drop. +/// +/// Lives here rather than in `cli_watch.rs` so [`PipeTap::finish`] can take +/// `&mut ChildGuard` and thereby establish "reaped before join" in the type, not in a +/// comment: the drain thread's loop ends at EOF, and EOF arrives only once the child's +/// write end is closed. +#[allow(dead_code)] +pub struct ChildGuard(pub Child); + +impl Drop for ChildGuard { + fn drop(&mut self) { + let _ = self.0.kill(); + let _ = self.0.wait(); + } +} + +#[allow(dead_code)] +impl ChildGuard { + pub fn id(&self) -> u32 { + self.0.id() + } + + /// Reap an already-exiting child. `Child::wait` caches its status, so calling this + /// and then letting `Drop` run is safe. + pub fn wait_status(&mut self) -> std::process::ExitStatus { + self.0.wait().expect("wait failed") + } + + /// Kill (best-effort) and reap. Idempotent — a second call returns the cached + /// status. + pub fn kill_and_wait(&mut self) -> std::process::ExitStatus { + let _ = self.0.kill(); + self.0.wait().expect("wait failed") + } +} + +/// A background-drained capture of one of the child's output pipes. /// /// Holds **exactly** what the child wrote and nothing else — the readiness handshake -/// travels over a file, not this stream. That is load-bearing: tests assert that a -/// compile error reaches stderr through `--quiet` and that no raw ESC byte appears in -/// a diagnostic, and both assertions become unfalsifiable if the harness itself -/// contributes bytes here. +/// travels over a file, not over these streams. That is load-bearing: tests assert +/// that a compile error reaches stderr through `--quiet` and that no raw ESC byte +/// appears in a diagnostic, and both assertions become unfalsifiable if the harness +/// itself contributes bytes here. +/// +/// [`PipeTap::bytes`] stays NON-blocking so the live-poll sites keep working; +/// [`PipeTap::finish`] is the end-of-test read that is guaranteed complete. #[allow(dead_code)] #[derive(Clone)] -pub struct StderrTap(Arc>>); +pub struct PipeTap { + buf: Arc>>, + /// `Option` because `finish` takes the handle out; behind `Arc>` so + /// `PipeTap` stays `Clone` (several tests hand a clone to a helper). + drain: Arc>>>, +} + +/// A [`PipeTap`] over the child's stderr. +#[allow(dead_code)] +pub type StderrTap = PipeTap; +/// A [`PipeTap`] over the child's stdout. #[allow(dead_code)] -impl StderrTap { - /// Raw bytes written to stderr so far. +pub type StdoutTap = PipeTap; + +#[allow(dead_code)] +impl PipeTap { + /// Bytes written so far. + /// + /// Non-blocking, and therefore carries **no** happens-before edge to the child's + /// last write: a snapshot taken right after the child is reaped can be a truncated + /// prefix. Use it only while polling a live child; use [`PipeTap::finish`] for the + /// final read. pub fn bytes(&self) -> Vec { - self.0.lock().expect("stderr tap poisoned").clone() + self.buf.lock().expect("pipe tap poisoned").clone() } - /// Lossy-UTF8 view of [`StderrTap::bytes`]. + /// Lossy-UTF8 view of [`PipeTap::bytes`], with the same caveat. pub fn text(&self) -> String { String::from_utf8_lossy(&self.bytes()).into_owned() } + + /// Stop the child, JOIN the drain thread, and return everything it wrote. + /// + /// Termination is proved, not bounded: the drain loop exits only at EOF, EOF + /// arrives when the child's write end closes, and the child is reaped here first — + /// so the join cannot hang on a live writer. A clone calling `finish` concurrently + /// blocks on the drain slot and then observes a fully drained buffer. + #[must_use] + pub fn finish(self, child: &mut ChildGuard) -> Vec { + child.kill_and_wait(); + { + let mut slot = self.drain.lock().expect("pipe tap drain slot poisoned"); + if let Some(handle) = slot.take() { + handle.join().expect("pipe drain thread panicked"); + } + } + self.bytes() + } + + /// Lossy-UTF8 view of [`PipeTap::finish`]. + #[must_use] + pub fn finish_text(self, child: &mut ChildGuard) -> String { + String::from_utf8_lossy(&self.finish(child)).into_owned() + } +} + +/// Spawn a background thread that drains `reader` into a fresh [`PipeTap`]. +fn tap_reader(reader: R) -> PipeTap { + let buf = Arc::new(Mutex::new(Vec::::new())); + let sink = buf.clone(); + let handle = std::thread::spawn(move || { + let mut reader = reader; + let mut chunk = [0u8; 512]; + // Bounded by EOF: the loop ends when the child's pipe closes. + loop { + match reader.read(&mut chunk) { + Ok(0) | Err(_) => break, + Ok(n) => sink + .lock() + .expect("pipe tap poisoned") + .extend_from_slice(&chunk[..n]), + } + } + }); + PipeTap { + buf, + drain: Arc::new(Mutex::new(Some(handle))), + } } /// Spawn a `mds watch` command and drain its stderr, WITHOUT waiting for readiness. @@ -202,24 +306,7 @@ pub fn spawn_watch_unsynchronized(cmd: &mut Command) -> (Child, StderrTap) { .spawn() .expect("failed to spawn mds watch"); - let handle = child.stderr.take().expect("stderr must be piped"); - let buf = Arc::new(Mutex::new(Vec::::new())); - let tap = StderrTap(buf.clone()); - - std::thread::spawn(move || { - let mut handle = handle; - let mut chunk = [0u8; 512]; - // Bounded by EOF: the loop ends when the child's stderr closes. - loop { - match handle.read(&mut chunk) { - Ok(0) | Err(_) => break, - Ok(n) => buf - .lock() - .expect("stderr tap poisoned") - .extend_from_slice(&chunk[..n]), - } - } - }); + let tap = tap_reader(child.stderr.take().expect("stderr must be piped")); (child, tap) } From cffb95172fea53c9f79e04589de6d71d26092be4 Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:16:41 +0300 Subject: [PATCH 07/19] test(watch): replace 12 of the 13 post-kill flush sleeps with finish (#320) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Every "kill, wait, sleep 50-100ms, then snapshot the tap" site was compensating for the same missing edge: `bytes()` has no happens-before relationship with the drain thread's last write, so the sleep was the only thing making the snapshot usually complete. `finish`/`finish_text` reap the child and then JOIN the drain, so the snapshot is complete by construction and the sleep is not a bound that might be too short on a loaded runner — it is gone. 12 sites converted, thread::sleep count 55 -> 43 (the file now also mentions `thread::sleep` once in a doc comment, so `grep -c` reads 44). Two sites are not plain `kill/sleep/snapshot` and were converted by hand: - watch_clear_non_tty_no_ansi_escape — keeps `finish` (raw bytes, not text): its assertions hunt for raw ESC sequences. This is the site whose Linux field signature is the panic at cli_watch.rs:520 in CI runs 32954883014 and 32954876042 — a kill-then-snapshot with the unjoined drain. - watch_esc_in_initial_compile_error_is_sanitized — was `drop(child)` followed by a snapshot, which reaps the child but can never join the drain. Now holds the guard mutable and uses `finish`. - watch_ctrl_c_prints_stopped_watching — the child has already exited via SIGINT; `finish_text` reaps it again (harmless, `wait` caches the status) and joins. The 13th, in `watch_stdout_no_duplicate_write_on_startup`, drains stdout through a hand-rolled reader thread rather than a tap. It is converted in the commit that adds the stdout tap, where that reader thread is deleted. NOT touched — these are observation windows, not flush waits, and removing them would change what each test observes: - idle-observation sleeps: 400ms after the burst, 1500ms x3 in the no-spurious-recompile / single-status-line tests, 2500ms x2 in the idle_no_recompile_across_ticks pair, 600ms in the 500-file idle test - post-`remove_dir_all` settle waits (200-500ms) in the delete/recreate tests - burst pacing (5ms between rapid edits) - poll granularity inside bounded loops (1ms / 20ms / 50ms in wait_for_file_contains, wait_for_stderr_contains_str, try_wait loops) - the 500ms "give the watcher time to attempt a rebuild" waits in the compile-error tests, where the expectation is that nothing is produced GREEN, three consecutive full runs: Summary [4.000s] 76 tests run: 76 passed, 0 skipped Summary [3.858s] 76 tests run: 76 passed, 0 skipped Summary [3.859s] 76 tests run: 76 passed, 0 skipped cargo fmt --all --check clean; both clippy variants clean. Refs #320. --- crates/mds-cli/tests/cli_watch.rs | 105 ++++++++---------------------- 1 file changed, 26 insertions(+), 79 deletions(-) diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index ce9c4d37..2def0717 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -570,10 +570,11 @@ fn watch_clear_non_tty_no_ansi_escape() { "rebuild should occur after editing source" ); - // Stop the child and collect everything it wrote to stderr. - let _ = child.0.kill(); - let _ = child.0.wait(); - let stderr_bytes = stderr_tap.bytes(); + // Stop the child and collect everything it wrote to stderr. `finish` reaps the + // child and then JOINS the drain thread, so the snapshot cannot be a truncated + // prefix — this site is where the Linux tearing was first observed. Raw bytes, + // not text: the assertions below hunt for raw ESC sequences. + let stderr_bytes = stderr_tap.finish(&mut child); // AC-F6: the ANSI clear/home sequences emitted by clear_terminal() // (\x1b[2J, \x1b[3J, \x1b[H) must be ABSENT when stderr is not a TTY. @@ -1136,11 +1137,10 @@ fn watch_ctrl_c_prints_stopped_watching() { "exit code should be 0 after Ctrl+C, got: {status:?}" ); - // Give the reader thread a moment to flush remaining bytes. - std::thread::sleep(Duration::from_millis(100)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + // The child has already exited; `finish_text` reaps it again (harmless — `wait` + // caches the status) and then joins the drain thread, which is what actually + // guarantees every byte has been copied. + let stderr_str = stderr_tap.finish_text(&mut guard); assert!( stderr_str.contains("Stopped watching."), "stderr should contain 'Stopped watching.' after Ctrl+C, got: {stderr_str:?}" @@ -1192,12 +1192,7 @@ fn watch_debounce_single_rebuild_from_burst() { std::thread::sleep(Duration::from_millis(400)); // Kill child and collect all stderr. - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(100)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); // Count "Recompiled " lines (each rebuild emits exactly one such line). let rebuild_count = stderr_str.matches("Recompiled ").count(); @@ -1313,12 +1308,7 @@ fn watch_startup_no_spurious_recompile() { std::thread::sleep(Duration::from_millis(1500)); // Stop the child and collect all stderr. - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(50)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); // There must be exactly ONE "Compiled to" message (the initial compile). let compiled_count = stderr_str.matches("Compiled to").count(); @@ -1467,12 +1457,7 @@ fn watch_dir_mode_no_spurious_startup_recompile() { std::thread::sleep(Duration::from_millis(1500)); // Stop the child and collect all stderr. - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(50)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); // There must be ZERO "Recompiled" lines — no rebuild without edits. let recompiled_count = stderr_str.matches("Recompiled").count(); @@ -1556,12 +1541,7 @@ fn watch_single_status_line_per_rebuild() { std::thread::sleep(Duration::from_millis(500)); // Stop the child and collect all stderr. - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(50)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); // Exactly ONE "Recompiled" line (the real edit). let recompiled_count = stderr_str.matches("Recompiled").count(); @@ -1939,12 +1919,7 @@ fn watch_file_mode_idle_no_recompile_across_ticks() { // Idle for 2.5s (≥2 ticks at 100ms poll-interval — well above the minimum). std::thread::sleep(Duration::from_millis(2500)); - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(100)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); let recompiled_count = stderr_str.matches("Recompiled").count(); assert_eq!( @@ -2013,12 +1988,7 @@ fn watch_dir_mode_idle_no_recompile_across_ticks() { // Idle for 2.5s (≥2 ticks at 100ms). std::thread::sleep(Duration::from_millis(2500)); - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(100)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); let recompiled_count = stderr_str.matches("Recompiled").count(); assert_eq!( @@ -2230,12 +2200,7 @@ fn watch_file_mode_entry_deleted_settles_then_recovers() { // Give the watcher a moment to settle after recovery before killing. std::thread::sleep(Duration::from_millis(200)); - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(100)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); // Sanity: error count across the FULL test run must still be small — rules out a // burst of errors that somehow all arrived in window 1. @@ -2305,11 +2270,7 @@ fn watch_vars_dir_delete_recreate_rearms() { // is the probe's own `(mtime, size)` comparison — another tick. Either way the // recovery is denominated in ticks, not in event latency. let got = wait_for_file_contains(&out, "Goodbye", TICK_TIMEOUT); - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(100)); - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); assert!( got, "watcher must re-arm vars dir watch after delete+recreate and recompile on edit; \ @@ -2690,12 +2651,7 @@ fn watch_dir_mode_persistent_error_bounded_count() { "watcher must stay alive with persistent syntax error in bad.mds" ); - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(100)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); assert_eq!( count_w1, count_w2, @@ -3065,12 +3021,7 @@ fn watch_file_mode_parent_dir_deleted_bounded_errors_then_recovers() { // Watcher must still be alive after recovery. let still_alive = child.0.try_wait().unwrap().is_none(); - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(100)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); assert!( still_alive, @@ -3162,12 +3113,7 @@ fn watch_dir_mode_idle_500_files_no_recompile() { // (ADR-021) must emit zero "Recompiled" lines during this window. std::thread::sleep(Duration::from_millis(600)); - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(100)); - - let stderr_bytes = stderr_tap.bytes(); - let stderr_str = String::from_utf8_lossy(&stderr_bytes); + let stderr_str = stderr_tap.finish_text(&mut child); let recompiled_count = stderr_str.matches("Recompiled").count(); assert_eq!( @@ -3442,16 +3388,17 @@ fn watch_esc_in_initial_compile_error_is_sanitized() { // The readiness handshake already implies the initial compile ran to completion: // the error is printed on the startup path, and the marker is only emitted after // it. No sleep needed to "give it time". - let (child, stderr_tap) = spawn_ready( + let (mut child, stderr_tap) = spawn_ready( mds_bin() .args(["watch", src.to_str().unwrap(), "--debounce", "0"]) .stdout(Stdio::null()), ); - // Kill the watch process (ChildGuard.drop → kill + wait) to close the pipe. - drop(child); - - let stderr_bytes = stderr_tap.bytes(); + // Kill the watch process to close the pipe, then join the drain: `finish` does + // both in that order, so the snapshot is the complete stream rather than whatever + // the drain thread happened to have copied by then. Raw bytes, because assertion + // 2 below hunts for a raw ESC byte. + let stderr_bytes = stderr_tap.finish(&mut child); let stderr_str = String::from_utf8_lossy(&stderr_bytes); // Assertion 1: the initial-compile error was rendered (non-vacuous guard for From f14506772bcab3457d3e9e1b10703018648047ed Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:17:54 +0300 Subject: [PATCH 08/19] =?UTF-8?q?test(watch):=20RED=20=E2=80=94=20spawn=5F?= =?UTF-8?q?watch=5Fready=20deadlocks=20on=20a=20large=20piped=20stdout=20(?= =?UTF-8?q?#320)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `spawn_watch_ready` pipes stderr and drains it, but a caller that also passes `.stdout(Stdio::piped())` gets an undrained stdout pipe. `mds watch -o -` publishes the startup output to stdout BEFORE it writes the readiness marker — the marker is emitted after the compile, the arming and the publish — so once the pipe fills (~64 KiB) the child blocks in `write` while the harness sits in the marker poll loop. Neither side can move. Today the suite only gets away with this because its two piped-stdout tests produce a handful of bytes. Any test whose startup output is larger deadlocks, and the failure surfaces as "the watcher never reported readiness" — which reads like a watcher defect rather than a harness one. New test: watch_ready_with_large_piped_stdout_does_not_deadlock. 512 KiB of body, several pipe buffers on both Linux and macOS, so the block is a certainty rather than a timing question. It also asserts the full byte count arrives, so the property stays pinned once the deadlock is fixed. RED observed (cargo nextest run -p mds-cli --test cli_watch -E 'test(large_piped_stdout)'): thread 'watch_ready_with_large_piped_stdout_does_not_deadlock' panicked at crates/mds-cli/tests/common/mod.rs:371:13: mds watch did not signal readiness within 10s; stderr so far was: test result: FAILED. 0 passed; 1 failed; ... finished in 10.01s The panic is the READY_TIMEOUT bound firing after the full 10s with an empty stderr — exactly the shape predicted: the child is blocked before it ever reaches the marker write. cargo fmt --all --check clean. Clippy is clean on the code; the test target builds, it just fails at runtime. Refs #320. --- crates/mds-cli/tests/cli_watch.rs | 58 +++++++++++++++++++++++++++++++ 1 file changed, 58 insertions(+) diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index 2def0717..32268b2d 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -4770,3 +4770,61 @@ fn stderr_tap_finish_captures_every_line_the_child_wrote() { of {FILE_COUNT}" ); } + +// ── R4: readiness must not depend on someone draining stdout (#320) ───────── + +/// A watcher whose stdout is piped but undrained must still signal readiness. +/// +/// `mds watch -o -` publishes the startup output to stdout BEFORE it writes the +/// readiness marker (watch.rs: the marker is emitted after the compile, the arming and +/// the publish). A pipe holds ~64 KiB; once it is full the child blocks in `write`, so +/// if the harness is sitting in the marker poll loop with nothing draining stdout, +/// neither side can move and the spawn helper times out. +/// +/// 256 KiB of body is several pipe buffers on both Linux and macOS, so the block is a +/// certainty, not a matter of timing. +#[test] +fn watch_ready_with_large_piped_stdout_does_not_deadlock() { + let dir = tempfile::tempdir().unwrap(); + let src = dir.path().join("big.mds"); + // Plain text is valid MDS; short lines keep the compile trivial. + let body: String = std::iter::repeat_n("x".repeat(63) + "\n", 8192).collect(); + assert!( + body.len() > 256 * 1024, + "fixture must exceed several pipe buffers; got {} bytes", + body.len() + ); + std::fs::write(&src, &body).unwrap(); + + let (mut child, _stderr_tap) = spawn_ready( + mds_bin() + .args([ + "watch", + src.to_str().unwrap(), + "-o", + "-", + "--debounce", + "0", + "-q", + ]) + .stdout(Stdio::piped()), + ); + + // Readiness returned, so the startup publish got through. Prove the bytes really + // travelled rather than the marker having been written before any output. + use std::io::Read as _; + let mut stdout = Vec::new(); + child + .0 + .stdout + .take() + .expect("stdout must be piped") + .read_to_end(&mut stdout) + .expect("reading the child's stdout must succeed"); + assert!( + stdout.len() >= body.len(), + "the whole startup output must reach stdout; got {} bytes of {}", + stdout.len(), + body.len() + ); +} From 11c8a43894b3968e02aec8e4341b3b83d7c97bdd Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:20:11 +0300 Subject: [PATCH 09/19] test(watch): drain stdout before the readiness wait (#320) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit GREEN for watch_ready_with_large_piped_stdout_does_not_deadlock. `spawn_watch_unsynchronized` now returns `(Child, StderrTap, Option)` and drains a piped stdout the same way it drains stderr. `child.stdout.is_some()` is exactly "the caller piped stdout" — `Command` inherits stdout by default — so no flag is needed. `spawn_watch_ready` destructures the triple and returns it unchanged; its marker poll loop is untouched and now simply runs with both drains live. Wrappers in cli_watch.rs: spawn_ready(cmd) -> (ChildGuard, StderrTap) spawn_ready_piped_stdout(cmd) -> (ChildGuard, StderrTap, StdoutTap) spawn_unsynchronized(cmd) -> (ChildGuard, StderrTap) The two non-piped wrappers assert `stdout_tap.is_none()`, so a test that pipes stdout and reaches for `child.0.stdout` fails with a message naming the right helper instead of finding a `None` it cannot explain. `spawn_unsynchronized_piped_stdout` is deliberately NOT added: no unsynchronized test pipes stdout, so it would be dead code, and `#[allow(dead_code)]` is confined to tests/common/mod.rs in this crate. `spawn_unsynchronized`'s assertion message says so and tells the next author to mirror `spawn_ready_piped_stdout`. Three tests move to the piped-stdout wrapper and their hand-rolled plumbing is deleted: - watch_stdout_contains_content_when_o_stdout — its manual read loop over `child.0.stdout` becomes a poll of `stdout_tap.text()` - watch_stdout_no_duplicate_write_on_startup — its own 17-line reader thread and `Arc>>` are gone, and its post-kill flush sleep with them. This is the 13th of the 13 sleeps identified in the previous commit. - watch_ready_with_large_piped_stdout_does_not_deadlock — the RED test thread::sleep sites: 42 real, plus one mention inside a doc comment, so `grep -c 'thread::sleep' crates/mds-cli/tests/cli_watch.rs` reads 43 (was 55 before this phase). GREEN, three consecutive full runs: Summary [3.828s] 77 tests run: 77 passed, 0 skipped Summary [3.822s] 77 tests run: 77 passed, 0 skipped Summary [3.825s] 77 tests run: 77 passed, 0 skipped cargo fmt --all --check clean; both clippy variants clean. Refs #320. --- crates/mds-cli/tests/cli_watch.rs | 98 ++++++++++++------------------ crates/mds-cli/tests/common/mod.rs | 26 ++++++-- 2 files changed, 58 insertions(+), 66 deletions(-) diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index 32268b2d..beb14a56 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -32,7 +32,7 @@ mod common; use common::{ dup_vars_file_warning, mds_bin, spawn_watch_ready, spawn_watch_unsynchronized, write_atomic, - ChildGuard, StderrTap, + ChildGuard, StderrTap, StdoutTap, }; use std::path::Path; @@ -50,17 +50,40 @@ use std::time::{Duration, Instant}; /// The returned [`StderrTap`] holds everything the child wrote to stderr, including /// the startup lines printed before the readiness marker. fn spawn_ready(cmd: &mut Command) -> (ChildGuard, StderrTap) { - let (child, tap) = spawn_watch_ready(cmd); + let (child, tap, stdout_tap) = spawn_watch_ready(cmd); + assert!( + stdout_tap.is_none(), + "this spawn piped stdout; use spawn_ready_piped_stdout so the drained stdout \ + is handed back instead of discarded" + ); (ChildGuard(child), tap) } +/// [`spawn_ready`] for a command that set `.stdout(Stdio::piped())`. +/// +/// The stdout pipe is drained by the harness — it has to be, or the child blocks on a +/// full pipe before it can write the readiness marker — so the tap is the only way to +/// read it. Tests must not take `child.0.stdout` themselves; it is already gone. +fn spawn_ready_piped_stdout(cmd: &mut Command) -> (ChildGuard, StderrTap, StdoutTap) { + let (child, tap, stdout_tap) = spawn_watch_ready(cmd); + let stdout_tap = stdout_tap.expect("caller must set .stdout(Stdio::piped())"); + (ChildGuard(child), tap, stdout_tap) +} + /// Spawn a watcher WITHOUT the readiness handshake and wrap it in a `ChildGuard`. /// /// Reserved for the tests that exist precisely to exercise startup: a test that /// synchronises on "startup finished" can never observe anything that happens /// *during* startup. Every other test must use [`spawn_ready`]. fn spawn_unsynchronized(cmd: &mut Command) -> (ChildGuard, StderrTap) { - let (child, tap) = spawn_watch_unsynchronized(cmd); + let (child, tap, stdout_tap) = spawn_watch_unsynchronized(cmd); + assert!( + stdout_tap.is_none(), + "this spawn piped stdout, and the harness has already drained it — the tap \ + would be discarded here. Add a `spawn_unsynchronized_piped_stdout` wrapper \ + mirroring `spawn_ready_piped_stdout` and use that instead; none exists yet \ + because no unsynchronized test pipes stdout." + ); (ChildGuard(child), tap) } @@ -726,8 +749,8 @@ fn watch_stdout_contains_content_when_o_stdout() { let src = dir.path().join("hello.mds"); std::fs::write(&src, "---\nname: World\n---\nHello {{name}}!\n").unwrap(); - // -o - forces stdout output. - let (mut child, _stderr_tap) = spawn_ready( + // -o - forces stdout output. The harness drains the pipe, so poll the tap. + let (child, _stderr_tap, stdout_tap) = spawn_ready_piped_stdout( mds_bin() .args([ "watch", @@ -741,25 +764,13 @@ fn watch_stdout_contains_content_when_o_stdout() { .stdout(Stdio::piped()), ); - // Read from stdout with a timeout. - use std::io::Read as _; + // Bounded by TIMEOUT: at most TIMEOUT / 50ms iterations. let deadline = Instant::now() + TIMEOUT; - let mut buf = String::new(); let mut found = false; - // Give the child time to produce output. while Instant::now() < deadline { - let mut tmp = [0u8; 256]; - if let Some(stdout) = child.0.stdout.as_mut() { - match stdout.read(&mut tmp) { - Ok(0) | Err(_) => {} - Ok(n) => { - buf.push_str(&String::from_utf8_lossy(&tmp[..n])); - if buf.contains("Hello World!") { - found = true; - break; - } - } - } + if stdout_tap.text().contains("Hello World!") { + found = true; + break; } std::thread::sleep(Duration::from_millis(50)); } @@ -1340,7 +1351,7 @@ fn watch_stdout_no_duplicate_write_on_startup() { // Use a distinctive marker so we can count occurrences. std::fs::write(&src, "UNIQUE_MARKER_XYZ\n").unwrap(); - let (mut child, _stderr_tap) = spawn_ready( + let (mut child, _stderr_tap, stdout_tap) = spawn_ready_piped_stdout( mds_bin() .args([ "watch", @@ -1354,37 +1365,12 @@ fn watch_stdout_no_duplicate_write_on_startup() { .stdout(Stdio::piped()), ); - // Drain stdout on a background thread. - let stdout_handle = child.0.stdout.take().expect("piped stdout"); - let stdout_buf = std::sync::Arc::new(std::sync::Mutex::new(Vec::::new())); - let stdout_buf_clone = stdout_buf.clone(); - let _reader_thread = std::thread::spawn(move || { - use std::io::Read as _; - let mut handle = stdout_handle; - let mut tmp = [0u8; 512]; - loop { - match handle.read(&mut tmp) { - Ok(0) | Err(_) => break, - Ok(n) => { - stdout_buf_clone - .lock() - .unwrap() - .extend_from_slice(&tmp[..n]); - } - } - } - }); - // Let the watcher run long enough to capture initial compile + any spurious second write. std::thread::sleep(Duration::from_millis(1500)); - // Stop the child and collect all stdout. - let _ = child.0.kill(); - let _ = child.0.wait(); - std::thread::sleep(Duration::from_millis(50)); - - let stdout_bytes = stdout_buf.lock().unwrap().clone(); - let stdout_str = String::from_utf8_lossy(&stdout_bytes); + // Stop the child and collect all stdout. `finish_text` reaps the child and then + // joins the drain, so no flush sleep is needed to make the snapshot complete. + let stdout_str = stdout_tap.finish_text(&mut child); // The marker should appear at least once (the initial compile wrote it). assert!( @@ -4796,7 +4782,7 @@ fn watch_ready_with_large_piped_stdout_does_not_deadlock() { ); std::fs::write(&src, &body).unwrap(); - let (mut child, _stderr_tap) = spawn_ready( + let (mut child, _stderr_tap, stdout_tap) = spawn_ready_piped_stdout( mds_bin() .args([ "watch", @@ -4812,15 +4798,7 @@ fn watch_ready_with_large_piped_stdout_does_not_deadlock() { // Readiness returned, so the startup publish got through. Prove the bytes really // travelled rather than the marker having been written before any output. - use std::io::Read as _; - let mut stdout = Vec::new(); - child - .0 - .stdout - .take() - .expect("stdout must be piped") - .read_to_end(&mut stdout) - .expect("reading the child's stdout must succeed"); + let stdout = stdout_tap.finish(&mut child); assert!( stdout.len() >= body.len(), "the whole startup output must reach stdout; got {} bytes of {}", diff --git a/crates/mds-cli/tests/common/mod.rs b/crates/mds-cli/tests/common/mod.rs index 8591996d..69a596c0 100644 --- a/crates/mds-cli/tests/common/mod.rs +++ b/crates/mds-cli/tests/common/mod.rs @@ -298,17 +298,25 @@ fn tap_reader(reader: R) -> PipeTap { /// must act *inside* the startup window, so they cannot synchronise on it closing. /// /// stderr is piped and drained on a background thread so the pipe can never fill and -/// block the child. +/// block the child. If the caller also piped stdout, that pipe is drained the same +/// way and the tap is returned as the third element; `Command` inherits stdout by +/// default, so `child.stdout.is_some()` is exactly "the caller asked for a pipe". +/// +/// Draining stdout here rather than in the caller is what keeps the readiness wait +/// sound: `mds watch -o -` publishes its startup output before it writes the marker, +/// so an undrained stdout pipe fills and blocks the child while the poller waits for +/// a marker that can never be written. #[allow(dead_code)] -pub fn spawn_watch_unsynchronized(cmd: &mut Command) -> (Child, StderrTap) { +pub fn spawn_watch_unsynchronized(cmd: &mut Command) -> (Child, StderrTap, Option) { let mut child = cmd .stderr(Stdio::piped()) .spawn() .expect("failed to spawn mds watch"); let tap = tap_reader(child.stderr.take().expect("stderr must be piped")); + let stdout_tap = child.stdout.take().map(tap_reader); - (child, tap) + (child, tap, stdout_tap) } /// Spawn a `mds watch` command and block until the watcher is **fully armed**. @@ -331,12 +339,17 @@ pub fn spawn_watch_unsynchronized(cmd: &mut Command) -> (Child, StderrTap) { /// stderr is still piped and drained on a background thread so the pipe can never /// fill and block the child. Use the returned [`StderrTap`] to inspect it. /// +/// A piped stdout is drained too, and its tap handed back as the third element. That +/// ordering is load-bearing, not a convenience: `mds watch -o -` publishes its startup +/// output before it writes the marker, so leaving stdout undrained would let the child +/// block on a full pipe while this function waits for a marker that can never arrive. +/// /// # Panics /// Panics if the child cannot be spawned, or if readiness is not signalled within /// [`READY_TIMEOUT`] — a watcher that never reports readiness is a defect, not a /// slow machine. #[allow(dead_code)] -pub fn spawn_watch_ready(cmd: &mut Command) -> (Child, StderrTap) { +pub fn spawn_watch_ready(cmd: &mut Command) -> (Child, StderrTap, Option) { // A private directory per spawn: the suite runs at full parallelism, so a shared // path would let one watcher's marker satisfy another's wait. Dropped — and so // deleted — when this function returns, by which point the marker has been read. @@ -347,13 +360,14 @@ pub fn spawn_watch_ready(cmd: &mut Command) -> (Child, StderrTap) { "MDS_TEST_READY must be absolute; mds watch ignores relative values" ); - let (mut child, tap) = spawn_watch_unsynchronized(cmd.env("MDS_TEST_READY", &ready_path)); + let (mut child, tap, stdout_tap) = + spawn_watch_unsynchronized(cmd.env("MDS_TEST_READY", &ready_path)); // Bounded by READY_TIMEOUT: at most READY_TIMEOUT / READY_POLL iterations. let deadline = std::time::Instant::now() + READY_TIMEOUT; loop { if std::fs::read(&ready_path).is_ok_and(|b| b == READY_MARKER.as_bytes()) { - return (child, tap); + return (child, tap, stdout_tap); } // Check liveness before the deadline so a watcher that failed at startup is // reported as "exited", not as "timed out". From 0b959b27ee9a0f181dba1170e975420c1927117e Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:21:45 +0300 Subject: [PATCH 10/19] =?UTF-8?q?test(watch):=20RED=20=E2=80=94=20i16?= =?UTF-8?q?=E2=80=93i20=20sample=20stderr=20before=20the=20dir-mode=20emit?= =?UTF-8?q?=20can=20land?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The i16–i20 family asserts exact occurrence counts of the duplicate-vars-key warning, and every one of them samples `stderr_tap.text()` immediately after a `wait_for_file_contains`. Those two events are unordered: dir mode emits the warning AFTER the output write (`handle_fs_event_dir`, and the same shape in `liveness_probe_dir`), so the output file being complete says nothing about whether the warning has been written yet. The race has been observed in both directions in CI, which is what rules out "just add a bigger timeout" as a fix: run 34366009518 (main 2b91850) i17 cli_watch.rs:4370 left 3 / right 2 run 34404318888 attempt 1 i17 cli_watch.rs:4370 left 1 / right 2 i18 cli_watch.rs:4448 left 2 / right 1 run 34404318888 attempt 2 i18 cli_watch.rs:4448 left 2 / right 1 New helper next to `wait_for_stderr_contains_str`: fn wait_for_stderr_count(tap, needle, n, timeout) -> String 20ms poll; returns as soon as the count reaches `n`; PANICS on timeout naming the count it actually saw. That last part is the difference from `wait_for_stderr_contains_str`, which RETURNS its text on timeout and so lets the caller's `assert_eq!` report a timeout as though it were a settled answer. That helper is left as-is — changing it is tracked separately as issue I3. This commit adds the helper, wires it into i17's startup assertion (the site with the CI evidence above), and rewrites i17's doc comment: the stale `:1793` / `:1919` / `:2196` line references are replaced with the function names they now live in (`liveness_probe_dir`, `handle_fs_event_dir`, `dir_watch_startup`), which do not drift. The remaining i16–i20 sites migrate in the next commit. RED evidence is the CI race above, not a local run: this does not reproduce deterministically on macOS, where the emit and the sample happen to order correctly. i17 is green here before and after: PASS [0.597s] (1/1) mds-cli::cli_watch i17_dir_watch_vars_file_duplicate_warns_once_per_rebuild cargo fmt --all --check clean; both clippy variants clean. Refs #320, #318. --- crates/mds-cli/tests/cli_watch.rs | 54 +++++++++++++++++++++++++++---- 1 file changed, 48 insertions(+), 6 deletions(-) diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index beb14a56..2e9b7dad 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -4028,6 +4028,38 @@ fn wait_for_stderr_contains_str(tap: &StderrTap, needle: &str, timeout: Duration } } +/// Wait until the stderr tap holds at least `n` occurrences of `needle`. +/// +/// Returns the tap's contents as soon as the count is reached. Unlike +/// [`wait_for_stderr_contains_str`], which returns the text on timeout and so lets the +/// caller's assertion report the shortfall as if it were a final answer, this one +/// PANICS on timeout and names the count it actually saw. +/// +/// Why a count and not "contains": a stderr line the watcher emits AFTER the output +/// write has no ordering relationship with the output file the test waited on. +/// Dir-mode emits the duplicate-vars-key warning after the write (watch.rs +/// `handle_fs_event_dir`), so a snapshot taken the instant `wait_for_file_contains` +/// returns can legitimately be one warning short — or, if the previous rebuild's +/// warning has not been sampled yet, one long. Waiting for the expected count first +/// turns the assertion that follows into a genuine over-count check instead of a race. +fn wait_for_stderr_count(tap: &StderrTap, needle: &str, n: usize, timeout: Duration) -> String { + let deadline = Instant::now() + timeout; + // Bounded by `timeout`: at most timeout / 20ms iterations. + loop { + let text = tap.text(); + let seen = count_occurrences(&text, needle); + if seen >= n { + return text; + } + assert!( + Instant::now() < deadline, + "expected at least {n} occurrences of {needle:?} within {timeout:?}; \ + saw {seen}; stderr was:\n{text}" + ); + std::thread::sleep(Duration::from_millis(20)); + } +} + #[test] fn i8_file_watch_duplicate_set_warns_exactly_once_across_two_edits() { // I8: mds watch (file mode) with --set x=1 --set x=2 must print the @@ -4235,9 +4267,18 @@ fn i16_file_watch_vars_file_duplicate_warns_at_startup_and_on_every_rebuild() { } /// I17: mds watch (dir mode) reports the vars-file duplicate exactly once per -/// rebuild: once at startup (proving the `:2196` dedup-baseline second read does -/// NOT double-print), and once more per subsequent rebuild (proving exactly one -/// of `:1793`/`:1919` emits, not both). +/// rebuild: once at startup (proving the dedup-baseline second read in +/// `dir_watch_startup` does NOT double-print), and once more per subsequent rebuild +/// (proving exactly one of `liveness_probe_dir` / `handle_fs_event_dir` emits, not +/// both). +/// +/// Sampling hazard this test has to defend against: dir mode emits the warning AFTER +/// the output write, so `wait_for_file_contains` returning tells you nothing about +/// whether the warning has been written yet. Sampling `stderr_tap.text()` right there +/// is a race in both directions, and CI has shown both — run 34404318888 attempt 1 +/// saw left 1 / right 2 here, while run 34366009518 saw left 3 / right 2. The wait +/// for the expected count has to come first; the exact-count assertion then means +/// "not more than expected" rather than "happened to be sampled at the right moment". #[test] fn i17_dir_watch_vars_file_duplicate_warns_once_per_rebuild() { let base = tempfile::tempdir().unwrap(); @@ -4268,13 +4309,14 @@ fn i17_dir_watch_vars_file_duplicate_warns_once_per_rebuild() { ); // No edits yet: the startup count must be exactly 1, proving the dedup-baseline - // second read at :2196 does not also emit. - let stderr_startup = wait_for_stderr_contains_str(&stderr_tap, &expected, TIMEOUT); + // second read in `dir_watch_startup` does not also emit. + let stderr_startup = wait_for_stderr_count(&stderr_tap, &expected, 1, TIMEOUT); assert_eq!( count_occurrences(&stderr_startup, &expected), 1, "I17: dir-watch startup must emit the vars-file warning exactly once \ - (guards :2196); stderr:\n{stderr_startup}" + (guards the dedup-baseline second read in dir_watch_startup); \ + stderr:\n{stderr_startup}" ); // One rebuild: the count must rise to exactly 2, proving exactly one of From 57084a872d3f0f729b8596d1fec135ad0041a058 Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:23:45 +0300 Subject: [PATCH 11/19] =?UTF-8?q?test(watch):=20wait=20for=20the=20expecte?= =?UTF-8?q?d=20warning=20count=20before=20asserting=20it=20(i16=E2=80=93i2?= =?UTF-8?q?0)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit GREEN for the sampling race described in the previous commit. Every count assertion in i16–i20 whose expectation is non-zero now runs `wait_for_stderr_count(&stderr_tap, &expected, N, TIMEOUT)` first, so the assertion that follows means "never MORE than N" rather than "happened to be N at the instant the tap was sampled". The final assertion in each test also switches from `stderr_tap.text()` to `stderr_tap.finish_text(&mut child)`, which reaps the child and joins the drain — so a warning the child wrote but the drain had not yet copied is in the snapshot rather than lost. Sites changed: i16 startup / after edit 1 / after edit 2 -> wait for 1 / 2 / 3, finish at the end i17 startup (previous commit) / after edit -> wait for 1 / 2, finish at the end i18 final assertion -> wait for 1, finish i19 startup / after self-heal -> wait for 1 / 2, finish at the end i20 final assertion -> finish (see below) Two kinds of site do NOT get a wait, because "at least 0 occurrences" is satisfied immediately and a wait there would be theatre: i18's two zero-count assertions and i20's pair under `--quiet`. Both already carry a positive control — a `wait_for_file_contains` proving the rebuild really happened — so the zero is not vacuous, and the final one in each now uses `finish_text`, the strongest snapshot available. Stale source references in the assertion messages and doc comments are replaced with function names, which do not drift: `:1793` -> `liveness_probe_dir`, `:1919` -> `handle_fs_event_dir`, `:2196` -> the dedup-baseline second read in `dir_watch_startup`, `watch.rs:936` -> `rebuild_file`. RESIDUAL, not closed by this commit and worth naming: i18's over-count exposure (CI run 34404318888, `:4448` left 2 / right 1) is not a sampling race. i18 writes the vars file and then the source; in file mode the vars file is watched, so at `--debounce 0` those two writes can be serviced as two rebuilds, and two rebuilds legitimately emit two warnings. Waiting for the count does not close that, and neither does the atomic write — the events are on different paths. The exact count is left as-is rather than weakened to `>= 1`, since that would drop the double-emit-per-rebuild guard; the i-family's design is a later phase's problem. GREEN, i16–i20 eight consecutive times: 5 tests run: 5 passed, 72 skipped (x8, 0.667s-0.882s) and three consecutive full runs: Summary [3.818s] 77 tests run: 77 passed, 0 skipped Summary [3.849s] 77 tests run: 77 passed, 0 skipped Summary [3.840s] 77 tests run: 77 passed, 0 skipped macOS orders the emit and the sample correctly, so the race this fixes does not reproduce locally — green here, and the Linux soak is the instrument. cargo fmt --all --check clean; both clippy variants clean. Refs #320, #318. --- crates/mds-cli/tests/cli_watch.rs | 52 ++++++++++++++++--------------- 1 file changed, 27 insertions(+), 25 deletions(-) diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index 2e9b7dad..c9df9e39 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -4199,7 +4199,11 @@ fn i9_dir_watch_duplicate_set_warns_exactly_once_at_startup() { // re-reported each time (D9). /// I16: mds watch (file mode) with a duplicated top-level key in the vars file -/// warns at STARTUP and on EVERY rebuild. Guards `watch.rs:936`. +/// warns at STARTUP and on EVERY rebuild. Guards the emit in `rebuild_file`. +/// +/// Each count assertion is preceded by a bounded wait for that count, so it reads +/// "never more than N", not "happened to be N when sampled". The warning is written +/// to stderr with no ordering relationship to the output file the test waits on. #[test] fn i16_file_watch_vars_file_duplicate_warns_at_startup_and_on_every_rebuild() { let base = tempfile::tempdir().unwrap(); @@ -4216,7 +4220,7 @@ fn i16_file_watch_vars_file_duplicate_warns_at_startup_and_on_every_rebuild() { let expected = dup_vars_file_warning("x", &vars_file); - let (child, stderr_tap) = spawn_ready( + let (mut child, stderr_tap) = spawn_ready( mds_bin() .args([ "watch", @@ -4229,7 +4233,7 @@ fn i16_file_watch_vars_file_duplicate_warns_at_startup_and_on_every_rebuild() { .stdout(Stdio::null()), ); - let stderr_after_start = wait_for_stderr_contains_str(&stderr_tap, &expected, TIMEOUT); + let stderr_after_start = wait_for_stderr_count(&stderr_tap, &expected, 1, TIMEOUT); assert_eq!( count_occurrences(&stderr_after_start, &expected), 1, @@ -4243,7 +4247,7 @@ fn i16_file_watch_vars_file_duplicate_warns_at_startup_and_on_every_rebuild() { wait_for_file_contains(&out, "version 2", TIMEOUT), "I16: rebuild after edit 1 must complete" ); - let after_edit_1 = stderr_tap.text(); + let after_edit_1 = wait_for_stderr_count(&stderr_tap, &expected, 2, TIMEOUT); assert_eq!( count_occurrences(&after_edit_1, &expected), 2, @@ -4256,14 +4260,13 @@ fn i16_file_watch_vars_file_duplicate_warns_at_startup_and_on_every_rebuild() { wait_for_file_contains(&out, "version 3", TIMEOUT), "I16: rebuild after edit 2 must complete" ); - let after_edit_2 = stderr_tap.text(); + let _ = wait_for_stderr_count(&stderr_tap, &expected, 3, TIMEOUT); + let after_edit_2 = stderr_tap.finish_text(&mut child); assert_eq!( count_occurrences(&after_edit_2, &expected), 3, "I16: a second rebuild must report the duplicate again; stderr:\n{after_edit_2}" ); - - drop(child); } /// I17: mds watch (dir mode) reports the vars-file duplicate exactly once per @@ -4295,7 +4298,7 @@ fn i17_dir_watch_vars_file_duplicate_warns_once_per_rebuild() { let expected = dup_vars_file_warning("x", &vars_file); - let (child, stderr_tap) = spawn_ready( + let (mut child, stderr_tap) = spawn_ready( mds_bin() .args([ "watch", @@ -4326,15 +4329,15 @@ fn i17_dir_watch_vars_file_duplicate_warns_once_per_rebuild() { wait_for_file_contains(&out, "version 2", TIMEOUT), "I17: rebuild after edit must complete" ); - let stderr_after_edit = stderr_tap.text(); + let _ = wait_for_stderr_count(&stderr_tap, &expected, 2, TIMEOUT); + let stderr_after_edit = stderr_tap.finish_text(&mut child); assert_eq!( count_occurrences(&stderr_after_edit, &expected), 2, "I17: one rebuild must add exactly one more warning (guards a double-emit \ - between :1793 and :1919); stderr:\n{stderr_after_edit}" + between liveness_probe_dir and handle_fs_event_dir); \ + stderr:\n{stderr_after_edit}" ); - - drop(child); } /// I18 (user decision, positive control first): a vars file that starts clean @@ -4357,7 +4360,7 @@ fn i18_duplicate_introduced_mid_session_is_reported_on_the_next_rebuild() { let expected = dup_vars_file_warning("x", &vars_file); - let (child, stderr_tap) = spawn_ready( + let (mut child, stderr_tap) = spawn_ready( mds_bin() .args([ "watch", @@ -4404,15 +4407,14 @@ fn i18_duplicate_introduced_mid_session_is_reported_on_the_next_rebuild() { wait_for_file_contains(&out, "version 3", TIMEOUT), "I18: rebuild after introducing the duplicate must complete" ); - let final_stderr = stderr_tap.text(); + let _ = wait_for_stderr_count(&stderr_tap, &expected, 1, TIMEOUT); + let final_stderr = stderr_tap.finish_text(&mut child); assert_eq!( count_occurrences(&final_stderr, &expected), 1, "I18: the duplicate introduced mid-session must be reported on the next \ rebuild, naming the key; stderr:\n{final_stderr}" ); - - drop(child); } // ── I19-I20: liveness self-heal rebuild and --quiet regressions (#326) ─────── @@ -4442,7 +4444,7 @@ fn i19_dir_watch_liveness_self_heal_rebuild_warns_about_vars_file_duplicate() { let expected = dup_vars_file_warning("x", &vars_file); - let (child, stderr_tap) = spawn_ready( + let (mut child, stderr_tap) = spawn_ready( mds_bin() .args([ "watch", @@ -4460,7 +4462,7 @@ fn i19_dir_watch_liveness_self_heal_rebuild_warns_about_vars_file_duplicate() { ); // Startup: exactly 1 warning (dir-mode startup, unaffected by this fix). - let startup_stderr = wait_for_stderr_contains_str(&stderr_tap, &expected, TIMEOUT); + let startup_stderr = wait_for_stderr_count(&stderr_tap, &expected, 1, TIMEOUT); assert_eq!( count_occurrences(&startup_stderr, &expected), 1, @@ -4498,15 +4500,14 @@ fn i19_dir_watch_liveness_self_heal_rebuild_warns_about_vars_file_duplicate() { // The self-heal recompile must ALSO re-warn about the vars-file duplicate — // proves liveness_probe_dir no longer discards the resolved vars, matching // handle_fs_event_dir's gate (emit iff the rebuild was observable). - let final_stderr = stderr_tap.text(); + let _ = wait_for_stderr_count(&stderr_tap, &expected, 2, TIMEOUT); + let final_stderr = stderr_tap.finish_text(&mut child); assert_eq!( count_occurrences(&final_stderr, &expected), 2, "I19: the liveness self-heal rebuild must warn about the vars-file \ duplicate too, not only at startup; stderr:\n{final_stderr}" ); - - drop(child); } /// I20: `mds watch --quiet` suppresses the vars-file duplicate-key warning on @@ -4532,7 +4533,7 @@ fn i20_watch_quiet_suppresses_vars_file_duplicate_warning_on_every_rebuild() { let expected = dup_vars_file_warning("x", &vars_file); - let (child, stderr_tap) = spawn_ready( + let (mut child, stderr_tap) = spawn_ready( mds_bin() .args([ "watch", @@ -4566,15 +4567,16 @@ fn i20_watch_quiet_suppresses_vars_file_duplicate_warning_on_every_rebuild() { "I20: rebuild after edit must complete even under --quiet" ); - let after_edit = stderr_tap.text(); + // No count to wait for — the expectation is zero — so this one takes the + // strongest snapshot available instead: `finish_text` joins the drain, so a + // warning the child wrote and the drain had not yet copied would still be here. + let after_edit = stderr_tap.finish_text(&mut child); assert_eq!( count_occurrences(&after_edit, &expected), 0, "I20: --quiet must suppress the vars-file duplicate warning on rebuild \ too; stderr:\n{after_edit}" ); - - drop(child); } // ── R1-R3: rename-into-place (atomic write) is a first-class edit (#320) ───── From 3373f1f6379be50d72e7dc79b0b52adb79ae39c1 Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:35:36 +0300 Subject: [PATCH 12/19] test(watch): pin quiet-period and capped debounce semantics (#379) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit RED for behavioural reasons only: `drain_debounce` is restructured to return a typed outcome, but its semantics are unchanged — the deadline is still a FIXED offset from the first event, never extended, and the `Cap` / `MessageLimit` exits are wired into the classification with their bounds set beyond reach. New in watch.rs (temporary bodies, marked TEMPORARY in their doc comments): enum DebounceEnd { Disabled, Quiet, Cap, MessageLimit, Interrupted, Disconnected } struct DebounceOutcome { paths, end } + fn interrupted() fn clamp_debounce(u64) -> Option // no clamp yet fn debounce_cap(Duration) -> Duration // returns u32::MAX seconds const MAX_DEBOUNCE_MESSAGES: usize = 1_000_000 // unreachable at this size Both callers move to the new return type: file mode discards the drained paths (it has already decided relevance and rebuilds its single entry regardless), dir mode extends `changed` with them after the interrupt check. Deviation from the plan: MAX_DEBOUNCE_MS / DEBOUNCE_CAP_FACTOR / DEBOUNCE_CAP_FLOOR are NOT introduced here. Nothing uses them until the real clamp and cap land, and an unused const is a `dead_code` warning in a non-test build — the repo's zero-warnings policy leaves no way to carry them through this commit honestly. MAX_DEBOUNCE_MESSAGES is 1_000_000 rather than usize::MAX because clippy::absurd_extreme_comparisons denies `>= usize::MAX`. Observed RED (macOS, `cargo nextest run -p mds-cli`, 7 of 11 selected tests fail): clamp_debounce_contract left: Some(18446744073709551.615s) right: Some(60s) debounce_cap_contract left: 4294967295s right: 1s ("the floor binds for small windows") debounce_quiet_period_extends_on_content_events left: 18 right: 40 paths — the fixed 100ms window closed a third of the way through a 200ms burst debounce_cap_ends_a_continuous_stream left: Quiet right: Cap debounce_message_limit_bounds_one_window left: Quiet right: MessageLimit watch_debounce_single_rebuild_from_burst left: "---\nname: v8\n---\nBurst v8!\n" right: "Burst v12!\n" — one Recompiled line, but it compiled v8: the 250ms window expired four writes before the burst ended watch_debounce_cap_rebuilds_while_writes_never_stop Got 14 Recompiled lines (expected 1..=4) from 3s of writes under a 200ms window Observed GREEN, as expected — these pin behaviour that is already correct: debounce_zero_is_disabled_and_leaves_the_channel_untouched, debounce_interrupt_returns_immediately, debounce_access_events_do_not_extend. `cargo nextest run -p mds-cli --test cli_watch`: 78 tests run, 76 passed, 2 failed — exactly the two integration tests above, so the caller refactor broke nothing. cargo fmt --all --check clean; `cargo clippy -p mds-cli --all-targets -- -D warnings` and the same with --features startup-race-probe both clean. The integration side: `watch_debounce_single_rebuild_from_burst` keeps its name (three CI runs and the issue comments cite it) and is rewritten so its burst is LONGER than the window — 12 plain writes 30ms apart against `--debounce 250` — with self-diagnosing preconditions (span > 250ms, max gap < 250ms) asserted before the outcome, so a scheduler artefact cannot masquerade as a product failure. `--poll-interval` stays at its default, leaving the idle-tick probe live. The new `watch_debounce_cap_rebuilds_while_writes_never_stop` runs with `--poll-interval 0`, so the cap is the only mechanism that could rebuild during a continuous stream. Refs #379. --- crates/mds-cli/src/watch.rs | 472 +++++++++++++++++++++++++++--- crates/mds-cli/tests/cli_watch.rs | 174 +++++++++-- 2 files changed, 578 insertions(+), 68 deletions(-) diff --git a/crates/mds-cli/src/watch.rs b/crates/mds-cli/src/watch.rs index acc66f29..b7cedd56 100644 --- a/crates/mds-cli/src/watch.rs +++ b/crates/mds-cli/src/watch.rs @@ -592,48 +592,138 @@ impl TickClock { // ── Debounce loop ───────────────────────────────────────────────────────────── -/// Drain the channel for `debounce_ms` milliseconds, collecting all changed paths. +/// Upper bound on the messages one window will drain. +/// +/// TEMPORARY: set so high that the bound is unreachable, which is exactly today's +/// behaviour — one window drains however many messages arrive in it. +const MAX_DEBOUNCE_MESSAGES: usize = 1_000_000; + +/// Why a debounce window ended. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +enum DebounceEnd { + /// `--debounce 0`: coalescing is off; no window was ever opened. + Disabled, + /// A full window passed with no further content event: the intended exit. + Quiet, + /// The absolute cap elapsed while events were still arriving. + Cap, + /// `MAX_DEBOUNCE_MESSAGES` messages were drained in this window. + MessageLimit, + /// Ctrl+C. The caller must stop, not rebuild. + Interrupted, + /// The watcher's sender was dropped. + Disconnected, +} + +/// Result of one debounce window. +struct DebounceOutcome { + /// Every path seen in a content event during the window. + paths: BTreeSet, + /// Why the window ended. + end: DebounceEnd, +} + +impl DebounceOutcome { + fn interrupted(&self) -> bool { + self.end == DebounceEnd::Interrupted + } +} + +/// Convert a raw `--debounce` value (milliseconds) into a quiet-period window. /// -/// Returns `(paths, interrupted)`. -/// - `paths`: all file paths seen in notify events during the window. -/// - `interrupted`: true if an Interrupt message was received. +/// - `0` -> `None`: coalescing disabled, every event rebuilds immediately. +/// - nonzero -> `Some(min(value, 60s))`. /// -/// The loop is bounded: it ends when `Instant::now() >= deadline` or when -/// `interrupted` is true. -fn drain_debounce(rx: &mpsc::Receiver, debounce_ms: u64) -> (BTreeSet, bool) { - let mut paths = BTreeSet::new(); +/// Extracted so the clamp contract is verifiable without the watch loop, exactly as +/// [`clamp_poll_interval`] is. +/// +/// TEMPORARY: the clamp is not applied yet; the raw value is passed through. +fn clamp_debounce(debounce_ms: u64) -> Option { if debounce_ms == 0 { - return (paths, false); + None + } else { + Some(Duration::from_millis(debounce_ms)) } - let deadline = Instant::now() + Duration::from_millis(debounce_ms); - loop { +} + +/// Absolute bound on one debounce window. +/// +/// TEMPORARY: returns a value so large that today's fixed window is always the binding +/// deadline, which makes the current (uncapped, non-extending) behaviour observable +/// through the same code shape the real cap will use. +fn debounce_cap(_window: Duration) -> Duration { + Duration::from_secs(u32::MAX as u64) +} + +/// Coalesce a burst of filesystem events into one rebuild. +/// +/// TEMPORARY: the window is still a FIXED offset from the first event — `deadline` is +/// computed once and never extended — so a burst longer than `debounce_ms` is split +/// across two or more windows and rebuilt once per window. The `Cap` and +/// `MessageLimit` exits are wired into the classification but their bounds are set +/// beyond reach, so they cannot be taken. +fn drain_debounce(rx: &mpsc::Receiver, debounce_ms: u64) -> DebounceOutcome { + let mut paths = BTreeSet::new(); + + let Some(window) = clamp_debounce(debounce_ms) else { + // `--debounce 0`: no coalescing. The channel is left untouched, so the next + // event is delivered to the loop as its own batch. + return DebounceOutcome { + paths, + end: DebounceEnd::Disabled, + }; + }; + + let start = Instant::now(); + let hard_cap = start + debounce_cap(window); + let deadline = start + window; + let mut messages: usize = 0; + + let end = loop { + if messages >= MAX_DEBOUNCE_MESSAGES { + break DebounceEnd::MessageLimit; + } + let now = Instant::now(); if now >= deadline { - break; + break if deadline == hard_cap { + DebounceEnd::Cap + } else { + DebounceEnd::Quiet + }; } - let remaining = deadline - now; - match rx.recv_timeout(remaining) { - Ok(Msg::Fs(Ok(event))) => { - // Drop Access events (inotify IN_ACCESS/IN_OPEN/IN_CLOSE_NOWRITE) - // — reads must not trigger recompiles; see is_content_event. - if is_content_event(&event.kind) { - for p in event.paths { - paths.insert(p); + + match rx.recv_timeout(deadline - now) { + Ok(msg) => { + messages += 1; + match msg { + Msg::Fs(Ok(event)) => { + // Drop Access events (inotify IN_ACCESS/IN_OPEN/IN_CLOSE_NOWRITE) + // — reads must not trigger recompiles; see is_content_event. + if !is_content_event(&event.kind) { + continue; + } + for p in event.paths { + paths.insert(p); + } + } + Msg::Fs(Err(e)) => { + eprint_warning(&format!( + "warning: watch error during debounce: {}", + safe_inline(&e) + )); } + Msg::Interrupt => break DebounceEnd::Interrupted, } } - Ok(Msg::Fs(Err(e))) => { - eprint_warning(&format!( - "warning: watch error during debounce: {}", - safe_inline(&e) - )); - } - Ok(Msg::Interrupt) => return (paths, true), - Err(mpsc::RecvTimeoutError::Timeout) => break, - Err(mpsc::RecvTimeoutError::Disconnected) => break, + // The deadline is the single decision point: re-loop and let the checks + // above classify the exit. + Err(mpsc::RecvTimeoutError::Timeout) => {} + Err(mpsc::RecvTimeoutError::Disconnected) => break DebounceEnd::Disconnected, } - } - (paths, false) + }; + + DebounceOutcome { paths, end } } // ── Poll-interval clamp (ADR-021) ───────────────────────────────────────────── @@ -908,8 +998,9 @@ fn handle_fs_event_file( } // Drain the debounce window. - let (_extra_paths, interrupted2) = drain_debounce(rx, debounce_ms); - if interrupted2 { + // The drained paths are discarded: file mode has already decided relevance above + // and rebuilds its single entry regardless of which path moved. + if drain_debounce(rx, debounce_ms).interrupted() { return FileEventAction::Stop; } @@ -1932,11 +2023,11 @@ fn handle_fs_event_dir( } // Drain debounce window. - let (extra, interrupted2) = drain_debounce(rx, ctx.debounce_ms); - changed.extend(extra); - if interrupted2 { + let drained = drain_debounce(rx, ctx.debounce_ms); + if drained.interrupted() { return DirEventOutcome::Stop; } + changed.extend(drained.paths); // Defense-in-depth: ignore events from inside the out-dir subtree. if let OutputBase::Dir(ref od) = ctx.output_base { @@ -3402,6 +3493,315 @@ mod tests { ); } + // ── Debounce window domain (#379) ──────────────────────────────────────── + + /// A minimal content event on `path`, shaped like the ones notify delivers. + fn modify_event(path: &str) -> Msg { + Msg::Fs(Ok(notify::Event { + kind: notify::EventKind::Modify(notify::event::ModifyKind::Any), + paths: vec![PathBuf::from(path)], + attrs: Default::default(), + })) + } + + /// A read event — the kind `is_content_event` drops. + fn access_event(path: &str) -> Msg { + Msg::Fs(Ok(notify::Event { + kind: notify::EventKind::Access(notify::event::AccessKind::Read), + paths: vec![PathBuf::from(path)], + attrs: Default::default(), + })) + } + + /// Run `drain_debounce` on a worker thread and refuse to wait past `bound`. + /// + /// The function under test is meant to be bounded. A mutation that removes the + /// bound would otherwise hang the test binary until the harness's own timeout, + /// which reports as an infrastructure problem rather than as a failed contract. + /// Collecting the result through a `recv_timeout` turns that mutation into a + /// clean, named failure at `bound`. + /// + /// The worker thread is deliberately not joined on the timeout path: it is + /// blocked precisely because the bound it should have honoured is gone, so + /// joining it would reintroduce the hang this exists to prevent. + fn drain_bounded( + rx: mpsc::Receiver, + debounce_ms: u64, + bound: Duration, + why: &str, + ) -> DebounceOutcome { + let (done_tx, done_rx) = mpsc::channel(); + std::thread::spawn(move || { + let outcome = drain_debounce(&rx, debounce_ms); + // The receiver may already have given up; the send failing is fine. + let _ = done_tx.send(outcome); + }); + done_rx.recv_timeout(bound).unwrap_or_else(|e| { + panic!("drain_debounce did not return within {bound:?} ({e:?}): {why}") + }) + } + + /// Every content event restarts the window: a burst longer than the window + /// coalesces into ONE result, not one per window's worth of burst. + /// + /// A window that expired at a fixed offset from the FIRST event splits any burst + /// longer than `debounce_ms`; each piece rebuilds separately, against a different + /// intermediate state of the file. + #[test] + fn debounce_quiet_period_extends_on_content_events() { + let (tx, rx) = mpsc::channel::(); + // 40 events, 5ms apart: a ~200ms burst under a 100ms window. + let sender = std::thread::spawn(move || { + for i in 0..40u32 { + if tx.send(modify_event(&format!("/w/f{i}.mds"))).is_err() { + return; + } + std::thread::sleep(Duration::from_millis(5)); + } + }); + + let t0 = Instant::now(); + let outcome = drain_bounded( + rx, + 100, + Duration::from_secs(3), + "a burst of content events must not postpone the window forever", + ); + let elapsed = t0.elapsed(); + sender.join().expect("sender thread panicked"); + + assert_eq!( + outcome.end, + DebounceEnd::Quiet, + "a 200ms burst under a 100ms window must end quiet, not capped" + ); + assert_eq!( + outcome.paths.len(), + 40, + "every path in the burst must be collected into the one window; got {:?}", + outcome.paths + ); + assert!( + elapsed >= Duration::from_millis(240) && elapsed <= Duration::from_millis(900), + "the window must outlast the burst (>=200ms) and then close one window \ + later (~100ms), so ~300ms; got {elapsed:?}" + ); + } + + /// The cap ends a stream that never goes quiet. + /// + /// Without it an extendable window is unbounded: a file written to continuously + /// postpones its own rebuild — and the idle-tick backstop behind it — for as long + /// as the writing lasts. + #[test] + fn debounce_cap_ends_a_continuous_stream() { + let (tx, rx) = mpsc::channel::(); + // Events every 2ms for ~2s: never a 50ms gap, so the window never goes quiet. + let sender = std::thread::spawn(move || { + // Bounded: at most 1000 iterations regardless of timing. + for _ in 0..1000u32 { + if tx.send(modify_event("/w/hot.mds")).is_err() { + return; + } + std::thread::sleep(Duration::from_millis(2)); + } + }); + + let t0 = Instant::now(); + let outcome = drain_bounded( + rx, + 50, + Duration::from_secs(3), + "an unbounded window never returns while writes continue", + ); + let elapsed = t0.elapsed(); + sender.join().expect("sender thread panicked"); + + assert_eq!( + outcome.end, + DebounceEnd::Cap, + "a continuous stream must end the window at the cap, not quiet" + ); + assert!( + elapsed >= Duration::from_millis(900) && elapsed < Duration::from_millis(1600), + "cap for a 50ms window is max(500ms, 1s) = 1s; got {elapsed:?}" + ); + } + + /// `--debounce 0` opens no window and consumes nothing. + #[test] + fn debounce_zero_is_disabled_and_leaves_the_channel_untouched() { + let (tx, rx) = mpsc::channel::(); + tx.send(modify_event("/w/a.mds")).expect("send failed"); + + let t0 = Instant::now(); + let outcome = drain_debounce(&rx, 0); + let elapsed = t0.elapsed(); + + assert_eq!(outcome.end, DebounceEnd::Disabled); + assert!( + outcome.paths.is_empty(), + "a disabled window must collect nothing" + ); + assert!( + elapsed < Duration::from_millis(50), + "a disabled window must return immediately; got {elapsed:?}" + ); + assert!( + matches!(rx.try_recv(), Ok(Msg::Fs(Ok(_)))), + "the queued event must still be in the channel: with coalescing off the \ + loop delivers it as its own batch" + ); + } + + /// Ctrl+C ends the window at once, however long the window had left. + #[test] + fn debounce_interrupt_returns_immediately() { + let (tx, rx) = mpsc::channel::(); + let sender = std::thread::spawn(move || { + std::thread::sleep(Duration::from_millis(20)); + let _ = tx.send(Msg::Interrupt); + }); + + let t0 = Instant::now(); + let outcome = drain_bounded( + rx, + 5_000, + Duration::from_secs(2), + "Ctrl+C must not wait out the window", + ); + let elapsed = t0.elapsed(); + sender.join().expect("sender thread panicked"); + + assert_eq!(outcome.end, DebounceEnd::Interrupted); + assert!( + outcome.interrupted(), + "interrupted() must agree with the end reason" + ); + assert!( + elapsed < Duration::from_millis(500), + "an interrupt must end a 5s window immediately; got {elapsed:?}" + ); + } + + /// Reads do not extend the window. + /// + /// The compile reads its own sources, so an extending `Access` event would let the + /// watcher hold its own window open. + #[test] + fn debounce_access_events_do_not_extend() { + let (tx, rx) = mpsc::channel::(); + let sender = std::thread::spawn(move || { + if tx.send(modify_event("/w/a.mds")).is_err() { + return; + } + // Bounded: at most 60 iterations (~300ms) regardless of timing. + for _ in 0..60u32 { + if tx.send(access_event("/w/a.mds")).is_err() { + return; + } + std::thread::sleep(Duration::from_millis(5)); + } + }); + + let t0 = Instant::now(); + let outcome = drain_bounded( + rx, + 100, + Duration::from_secs(3), + "a stream of reads must not hold the window open", + ); + let elapsed = t0.elapsed(); + sender.join().expect("sender thread panicked"); + + assert_eq!(outcome.end, DebounceEnd::Quiet); + assert_eq!( + outcome.paths.len(), + 1, + "only the one content event contributes a path; got {:?}", + outcome.paths + ); + assert!( + elapsed < Duration::from_millis(250), + "300ms of reads must not extend a 100ms window past ~100ms; got {elapsed:?}" + ); + } + + /// One window drains a bounded number of messages. + /// + /// The cap bounds the window's duration; this bounds its work and its memory. A + /// sender faster than the drain would otherwise grow `paths` without limit inside + /// a single window. + #[test] + fn debounce_message_limit_bounds_one_window() { + let (tx, rx) = mpsc::channel::(); + // Pre-queued so the drain is never waiting on the sender. + for _ in 0..12_000u32 { + tx.send(modify_event("/w/same.mds")).expect("send failed"); + } + + let t0 = Instant::now(); + let outcome = drain_bounded( + rx, + 100, + Duration::from_secs(5), + "an unbounded message count lets a fast sender own the window", + ); + let elapsed = t0.elapsed(); + drop(tx); + + assert_eq!( + outcome.end, + DebounceEnd::MessageLimit, + "12 000 queued events must hit the message bound, not the quiet period" + ); + assert_eq!( + outcome.paths.len(), + 1, + "all 12 000 events name the same path; got {:?}", + outcome.paths + ); + assert!( + elapsed < Duration::from_secs(2), + "the bound must be reached promptly; got {elapsed:?}" + ); + } + + /// The clamp contract, verifiable without the watch loop. + #[test] + fn clamp_debounce_contract() { + assert_eq!( + clamp_debounce(0), + None, + "0 disables coalescing; it does not mean a 0ms window" + ); + assert_eq!(clamp_debounce(100), Some(Duration::from_millis(100))); + assert_eq!( + clamp_debounce(u64::MAX), + Some(Duration::from_secs(60)), + "an unclamped u64::MAX window does not overflow on a monotonic clock — it \ + lands ~585 million years out, so the watcher silently never rebuilds" + ); + } + + /// The cap contract: `max(10 x window, 1s)`. + #[test] + fn debounce_cap_contract() { + assert_eq!( + debounce_cap(Duration::from_millis(10)), + Duration::from_secs(1), + "the floor binds for small windows" + ); + assert_eq!( + debounce_cap(Duration::from_millis(250)), + Duration::from_millis(2_500) + ); + assert_eq!( + debounce_cap(Duration::from_millis(1_000)), + Duration::from_secs(10) + ); + } + // ── Content backstop domain (#321) ─────────────────────────────────────── /// `tracked_set` covers cross-root dependencies, which `known_files` never can. diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index c9df9e39..c3ab9018 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -19,9 +19,10 @@ //! a path the watcher is watching (the `.mds` source, an imported partial, the //! `--vars` file, an external dependency). Pre-spawn fixture writes, `.git` markers, //! `mds.json`, and output files keep `std::fs::write`. Two post-spawn writes are -//! deliberate exceptions and say so inline: `watch_single_status_line_per_rebuild` -//! and `watch_debounce_single_rebuild_from_burst`, whose subject IS the truncate+write -//! pair that `write_atomic` collapses. +//! deliberate exceptions and say so inline: `watch_single_status_line_per_rebuild`, +//! whose subject IS the truncate+write pair that `write_atomic` collapses, and +//! `watch_debounce_single_rebuild_from_burst`, which keeps plain writes because they +//! double the event load its coalescing claim has to survive. //! //! Flakiness mitigations: //! - Assert on output FILE content rather than stderr ordering. @@ -1160,10 +1161,20 @@ fn watch_ctrl_c_prints_stopped_watching() { // ── AC-P1: Debounce coalesces burst — count rebuild summary lines ────────── -/// Burst of ~10 writes within a 250ms debounce window must produce exactly 1 -/// "Recompiled " line in stderr. 250ms is large enough to be reliable on CI; -/// if the filesystem splits the burst into two windows, the test permits <= 2 -/// rebuilds (documented below) but asserts == 1 as the expected case. +/// A save burst LONGER than the debounce window is still one rebuild (#379). +/// +/// The old shape of this test wrote a burst that fit inside the window and then +/// tolerated a second rebuild, so the property it advertised — one rebuild per burst — +/// was never actually pinned. It failed as `got 3` on loaded CI runners (runs +/// 33996153739, 33976595173, 33753123463), each of the three compiles seeing a +/// different intermediate state of the file. +/// +/// The burst here is deliberately longer than the window: 12 writes, 30ms apart, so at +/// least 330ms against a 250ms window. Under a window that expires at a fixed offset from +/// the FIRST event that is two or three rebuilds; under a quiet period it is one, +/// because no gap between writes ever reaches 250ms. `--poll-interval` is left at its +/// default so the idle-tick liveness probe stays live — a stronger claim than +/// disabling it. #[test] fn watch_debounce_single_rebuild_from_burst() { let dir = tempfile::tempdir().unwrap(); @@ -1171,7 +1182,6 @@ fn watch_debounce_single_rebuild_from_burst() { std::fs::write(&src, "---\nname: v0\n---\nBurst {{name}}!\n").unwrap(); let out = dir.path().join("burst.md"); - // Use a 250ms debounce — large enough to reliably swallow the ~10 × 5ms burst. let (mut child, stderr_tap) = spawn_ready( mds_bin() .args(["watch", src.to_str().unwrap(), "--debounce", "250"]) @@ -1184,43 +1194,143 @@ fn watch_debounce_single_rebuild_from_burst() { "initial compile should produce Burst v0!" ); - // Write 10 rapid edits within the 250ms debounce window. // DELIBERATE: this test's subject is the debounce window collapsing a burst of - // truncate+write pairs, so it keeps plain writes. Every other post-spawn write in - // this file goes through `write_atomic`. - for i in 1..=10u32 { + // truncate+write pairs, so it keeps plain writes — they double the event load + // that `write_atomic` would collapse into one rename. Every other post-spawn write + // in this file goes through `write_atomic`. + let mut stamps: Vec = Vec::with_capacity(12); + for i in 1..=12u32 { std::fs::write(&src, format!("---\nname: v{i}\n---\nBurst {{{{name}}}}!\n")).unwrap(); - std::thread::sleep(Duration::from_millis(5)); + stamps.push(Instant::now()); + std::thread::sleep(Duration::from_millis(30)); } - // Wait for the debounced rebuild to settle (debounce window + generous FSEvent latency). + // Self-diagnosing preconditions, asserted BEFORE the outcome: if the burst this + // process actually produced was not longer than the window, or had a gap wide + // enough to legitimately close it, the outcome assertion below would be measuring + // the scheduler rather than the watcher. + let span = stamps[stamps.len() - 1].duration_since(stamps[0]); + let max_gap = stamps + .windows(2) + .map(|w| w[1].duration_since(w[0])) + .max() + .expect("burst has at least two writes"); + assert!( + span > Duration::from_millis(250), + "precondition: the burst must outlast the 250ms window, else the test proves \ + nothing about extension; span was {span:?}" + ); assert!( - wait_for_file_contains(&out, "Burst v10!", TIMEOUT), - "after burst, output should reflect final value v10" + max_gap < Duration::from_millis(250), + "precondition: no gap between writes may reach the 250ms window, else the \ + window is entitled to close mid-burst; largest gap was {max_gap:?}" ); - // Wait an extra moment to ensure no trailing rebuilds are in-flight. - std::thread::sleep(Duration::from_millis(400)); + // WAIT ONLY — the assertion is the count below, taken from the joined tap. + wait_for_stderr_contains_str(&stderr_tap, "Recompiled ", TIMEOUT); + let stderr = stderr_tap.finish_text(&mut child); - // Kill child and collect all stderr. - let stderr_str = stderr_tap.finish_text(&mut child); + assert_eq!( + count_occurrences(&stderr, "Recompiled "), + 1, + "a {span:?} burst with a largest gap of {max_gap:?} must coalesce into exactly \ + one rebuild under a 250ms quiet period; stderr was:\n{stderr}" + ); + assert_eq!( + count_occurrences(&stderr, "Compiled to"), + 1, + "the startup compile is the only 'Compiled to' line; stderr was:\n{stderr}" + ); + assert_eq!( + std::fs::read_to_string(&out).unwrap(), + "Burst v12!\n", + "the single rebuild must compile the FINAL state of the burst, not an \ + intermediate one; stderr was:\n{stderr}" + ); +} - // Count "Recompiled " lines (each rebuild emits exactly one such line). - let rebuild_count = stderr_str.matches("Recompiled ").count(); +/// The cap rebuilds a file that is never left alone (#379). +/// +/// A quiet period that can always be extended is unbounded: a writer that never +/// pauses postpones its own rebuild for as long as it keeps writing. `--poll-interval 0` +/// turns the idle-tick liveness probe off, so within this test the cap is the ONLY +/// mechanism that can produce a rebuild while the stream is running — and it is also +/// the reason the probe cannot be starved in the configurations that do enable it, +/// since the loop never reaches `TickClock::recv_next` while a window is open. +#[test] +fn watch_debounce_cap_rebuilds_while_writes_never_stop() { + let dir = tempfile::tempdir().unwrap(); + let src = dir.path().join("hot.mds"); + std::fs::write(&src, "---\nname: v0\n---\nHot {{name}}!\n").unwrap(); + let out = dir.path().join("hot.md"); - // Expected: exactly 1 rebuild from the burst. - // Allow <= 2 as a documented tolerance: on a heavily loaded CI machine the - // 250ms window may occasionally be split by an FSEvent scheduling gap, yielding - // a second rebuild for the tail of the burst. The important property is that - // we do NOT get 10 individual rebuilds. + // --debounce 200 => cap = max(10 x 200ms, 1s) = 2s. + let (mut child, stderr_tap) = spawn_ready( + mds_bin() + .args([ + "watch", + src.to_str().unwrap(), + "--debounce", + "200", + "--poll-interval", + "0", + ]) + .stdout(Stdio::null()), + ); + + assert!( + wait_for_file_contains(&out, "Hot v0!", TIMEOUT), + "initial compile should produce Hot v0!" + ); + + let writing = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(true)); + let writer_flag = std::sync::Arc::clone(&writing); + let writer_src = src.clone(); + let writer = std::thread::spawn(move || { + let stop_at = Instant::now() + Duration::from_secs(3); + let mut max_gap = Duration::ZERO; + let mut last = Instant::now(); + // Doubly bounded: <= 3s of wall clock AND <= 2000 iterations. + for i in 1..=2_000u32 { + if Instant::now() >= stop_at { + break; + } + write_atomic( + &writer_src, + format!("---\nname: v{i}\n---\nHot {{{{name}}}}!\n"), + ); + let now = Instant::now(); + max_gap = max_gap.max(now.duration_since(last)); + last = now; + std::thread::sleep(Duration::from_millis(5)); + } + writer_flag.store(false, std::sync::atomic::Ordering::SeqCst); + max_gap + }); + + // The cap is 2s; allow the compile that follows it to land inside the bound. + wait_for_stderr_contains_str(&stderr_tap, "Recompiled ", Duration::from_millis(3500)); + let rebuilt_while_writing = writing.load(std::sync::atomic::Ordering::SeqCst); + + let max_gap = writer.join().expect("writer thread panicked"); + assert!( + max_gap < Duration::from_millis(200), + "precondition: no gap in the write stream may reach the 200ms window, else a \ + quiet period could legitimately have ended it; largest gap was {max_gap:?}" + ); assert!( - rebuild_count >= 1, - "at least one rebuild must have occurred, got 0; stderr: {stderr_str}" + rebuilt_while_writing, + "a rebuild must happen WHILE the writes are still arriving — that is what the \ + cap is for; nothing was seen until the stream stopped" ); + + let stderr = stderr_tap.finish_text(&mut child); + let rebuilds = count_occurrences(&stderr, "Recompiled "); assert!( - rebuild_count <= 2, - "debounce should coalesce burst into <= 2 rebuilds, got {rebuild_count}; \ - stderr: {stderr_str}" + (1..=4).contains(&rebuilds), + "3s of writes under a 200ms window with a 2s cap is one capped rebuild plus \ + the quiet-period rebuild that follows the last write; a fixed 200ms window \ + would give ~15. Got {rebuilds}; stderr was:\n{stderr}" ); } From f3fb1a055bc9daf8ea4bfecd85384ed0b4e7a703 Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:42:32 +0300 Subject: [PATCH 13/19] fix(watch): make --debounce a quiet period with a hard cap (#379) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `--debounce` was a window that expired at a FIXED offset from the first event. Any save burst longer than the window was split across two or three windows and rebuilt once per window, each compile seeing a different intermediate state of the file — `watch_debounce_single_rebuild_from_burst` failed as `got 3` with three `Recompiled` lines (40ms / 80ms / 3ms) on loaded CI runners, in runs 33996153739, 33976595173 and 33753123463 (11 occurrences across 146 ci.yml runs since 2026-08-26). The size of the burst a user can produce is not a property `debounce_ms` can predict; the size of the GAP between saves is. Now the first relevant event opens the window and every further CONTENT event restarts it, so the window ends when the writing goes quiet. An extendable window with no bound is unbounded, so two bounds come with it: - an absolute cap of `max(10 x window, 1s)` measured from the first event. A file written to continuously would otherwise postpone its own rebuild for as long as the writing lasts — and, because the loop never reaches `TickClock::recv_next` while a window is open, would starve the idle-tick content backstop through a door the absolute tick deadline does not cover. The floor matches the default `--poll-interval`, so it is also the bound on how late the probe can run under a continuous stream. - `MAX_DEBOUNCE_MESSAGES = 10_000` drained messages per window, bounding the window's work and `paths`' memory against a sender faster than the drain. Messages left in the channel are not lost: the next event opens a new window. `deadline <= hard_cap` is an unconditional `assert!`, not a `debug_assert!` — it is the bound's release-build enforcement, and it is pure arithmetic, so a descheduled runner cannot trip it, only a defect can. Asserting on MEASURED elapsed time instead would panic a shipped watcher whenever `recv_timeout` overshoots. `deadline == hard_cap` is a sound `Cap` discriminator because the cap is at least 10x the window, so the initial deadline never equals it. `window * DEBOUNCE_CAP_FACTOR` cannot overflow `Duration`: the clamp caps the window at 60s, so the product is at most 600s. Raw values are clamped to 60s. Observed at 2b91850: `--debounce 18446744073709551615` does NOT panic — `Instant::now() + Duration::from_millis( u64::MAX)` lands ~585 million years out on the i64-second monotonic clocks of macOS and Linux, so the window never closes and the watcher silently never rebuilds (two edits, 13s, no `Recompiled`; SIGINT still exits 0 with `Stopped watching.`). `--debounce 18446744073709551616` is rejected by clap (exit 2). The clamp therefore prevents a silent infinite window, not a crash. Unchanged: `--debounce 0` still means no coalescing and leaves the channel untouched; `Access` events and watch errors still do not extend; relevance is still decided by the caller, not here (an editor's atomic save renames a temp path that is in no watch set — ending the window on it would split the very burst this exists to coalesce). No new output: a cap hit prints nothing. GREEN: the 8 new unit tests and the 2 debounce integration tests all pass; `cargo nextest run -p mds-cli --test cli_watch` 78/78 x3 (4.168s / 5.167s / 4.085s); `cargo nextest run -p mds-cli` 832 tests run: 832 passed. cargo fmt --all --check clean; both clippy variants clean. Two unit tests gained a `tx.clone()` keepalive (quiet-period and access-event): once the window outlives the burst, the sender being dropped ends it as `Disconnected` and the failure names the channel's lifetime instead of the property under test. In production the notify sender lives as long as the watcher. MUTATION TABLE — each a scratch edit, run, then restored and verified with `cmp` against a pristine copy (RESTORED_OK for all eleven): M1 fixed deadline restored (drop the reassignment) debounce_quiet_period_extends_on_content_events left: 17 right: 40 paths watch_debounce_single_rebuild_from_burst left: "---\nname: v8\n---\nBurst v8!\n" right: "...v12..." RED M2 `.min(hard_cap)` dropped watch.rs:742 "debounce deadline escaped its cap: a file written to continuously would postpone its own rebuild (and the idle-tick backstop behind it) for as long as the writing lasts" — the assert fires on the worker thread; drain_bounded then reports "did not return within 3s" RED M3 DEBOUNCE_CAP_FLOOR = 3600s debounce_cap_ends_a_continuous_stream left: Disconnected right: Cap watch_debounce_cap_rebuilds_while_writes_never_stop "a rebuild must happen WHILE the writes are still arriving" RED M4 Access events extend (drop the is_content_event guard) debounce_access_events_do_not_extend "300ms of reads must not extend a 100ms window past ~100ms; got 468.653875ms" RED M5 Msg::Interrupt keeps draining (continue instead of break) debounce_interrupt_returns_immediately left: Disconnected right: Interrupted RED M6 clamp_debounce(0) = Some(1ms) clamp_debounce_contract left: Some(1ms) right: None debounce_zero_is_disabled_... left: Quiet right: Disabled RED M7 message bound removed (100_000_000) debounce_message_limit_bounds_one_window left: Quiet right: MessageLimit RED M8 Cap classification inverted debounce_cap_ends_a_continuous_stream left: Quiet right: Cap RED M9 clamp dropped (`.min` removed) clamp_debounce_contract left: Some(18446744073709551.615s) right: Some(60s) RED M10 dir caller drops `changed.extend(drained.paths)` FINDING — WEAK CONTROL. watch_dir_mode_shared_partial_rebuilds_importers, watch_dir_mode_partial_edit_rebuilds_exactly_n_importers and watch_dir_mode_soak_50_edits_bounded_and_clean_exit all PASS, and so does the whole suite: 78 tests run: 78 passed. The drained paths are redundant with the initial batch whenever the first event of a burst already names every file the burst touches, which is what every dir-mode test does. The line is kept — a burst that starts on one file and continues on another needs it — but nothing in the suite pins it. M11 file caller ignores interrupted() FINDING — WEAK CONTROL. watch_ctrl_c_exits_cleanly, watch_ctrl_c_prints_stopped_watching and watch_file_mode_ctrl_c_during_startup_compile_terminates all PASS, and so does the whole suite: 78 tests run: 78 passed. Cause: all three spawn with `--debounce 0`, so drain_debounce returns Disabled without ever seeing a message, and the outer loop's own interrupt handling is what exits. No ctrl-c test runs with coalescing on. Refs #379. --- crates/mds-cli/src/watch.rs | 117 +++++++++++++++++++++++++----- crates/mds-cli/tests/cli_watch.rs | 3 +- 2 files changed, 99 insertions(+), 21 deletions(-) diff --git a/crates/mds-cli/src/watch.rs b/crates/mds-cli/src/watch.rs index b7cedd56..298c360d 100644 --- a/crates/mds-cli/src/watch.rs +++ b/crates/mds-cli/src/watch.rs @@ -29,6 +29,16 @@ //! The tick is scheduled against an absolute deadline (`TickClock`), so a stream of //! filesystem events cannot postpone the backstop indefinitely (#319). //! +//! # Coalescing +//! +//! `--debounce` is a **quiet period**: the first relevant event opens a window and +//! every further content event restarts it, so a save burst longer than the window is +//! still one rebuild. The window is itself bounded — by an absolute cap of +//! `max(10 x window, 1s)` measured from the first event, and by 10 000 drained +//! messages — because the loop does not consult the idle tick while a window is open, +//! so an unbounded window would starve the content backstop as well as the rebuild +//! (#379). +//! //! # Key invariants //! //! - All content output → stdout ONLY when output resolves to stdout. @@ -36,7 +46,9 @@ //! - `--quiet` suppresses status + warnings but NOT compile errors. //! - Exit 0 on clean Ctrl+C; non-zero only on startup failure. //! - Compile errors during watching never terminate the watcher. -//! - All loops have fixed upper bounds (ADR-021 / reliability.md). +//! - All loops have fixed upper bounds (ADR-021 / reliability.md): the idle tick +//! against an absolute deadline, and the debounce window against an absolute cap +//! (window <= cap) and a message bound (<= 10 000 per window). //! - All `.mds` reads go through `compile_to_content` (PF-004). use std::collections::{BTreeSet, HashMap, HashSet}; @@ -592,11 +604,32 @@ impl TickClock { // ── Debounce loop ───────────────────────────────────────────────────────────── +/// Largest accepted `--debounce` window; larger values are clamped to it. +/// +/// `Instant::now() + Duration::from_millis(u64::MAX)` does not overflow on the +/// i64-second monotonic clocks of macOS and Linux: the deadline lands roughly 585 +/// million years out, so an unclamped `--debounce 18446744073709551615` watches +/// forever and silently never rebuilds (observed). 60s is orders of magnitude past +/// any editor save burst. +const MAX_DEBOUNCE_MS: u64 = 60_000; + +/// Absolute cap on one debounce window, as a multiple of the window. +const DEBOUNCE_CAP_FACTOR: u32 = 10; + +/// Floor under the absolute cap. +/// +/// Matches the default `--poll-interval`: while a window is open the loop never +/// reaches `TickClock::recv_next`, so this floor is also the bound on how late the +/// idle-tick backstop can run under a continuous event stream. +const DEBOUNCE_CAP_FLOOR: Duration = Duration::from_millis(1_000); + /// Upper bound on the messages one window will drain. /// -/// TEMPORARY: set so high that the bound is unreachable, which is exactly today's -/// behaviour — one window drains however many messages arrive in it. -const MAX_DEBOUNCE_MESSAGES: usize = 1_000_000; +/// The cap bounds the window's DURATION; this bounds its work and its memory. A +/// sender faster than the drain would otherwise grow `paths` without limit inside a +/// single window. Messages left in the channel are not lost: the caller's next +/// event opens a new window and drains them. +const MAX_DEBOUNCE_MESSAGES: usize = 10_000; /// Why a debounce window ended. #[derive(Debug, Clone, Copy, PartialEq, Eq)] @@ -632,36 +665,58 @@ impl DebounceOutcome { /// Convert a raw `--debounce` value (milliseconds) into a quiet-period window. /// /// - `0` -> `None`: coalescing disabled, every event rebuilds immediately. -/// - nonzero -> `Some(min(value, 60s))`. +/// - nonzero -> `Some(min(value, MAX_DEBOUNCE_MS))`. /// /// Extracted so the clamp contract is verifiable without the watch loop, exactly as /// [`clamp_poll_interval`] is. -/// -/// TEMPORARY: the clamp is not applied yet; the raw value is passed through. fn clamp_debounce(debounce_ms: u64) -> Option { if debounce_ms == 0 { None } else { - Some(Duration::from_millis(debounce_ms)) + Some(Duration::from_millis(debounce_ms.min(MAX_DEBOUNCE_MS))) } } -/// Absolute bound on one debounce window. +/// Absolute bound on one debounce window: `max(10 x window, 1s)`. /// -/// TEMPORARY: returns a value so large that today's fixed window is always the binding -/// deadline, which makes the current (uncapped, non-extending) behaviour observable -/// through the same code shape the real cap will use. -fn debounce_cap(_window: Duration) -> Duration { - Duration::from_secs(u32::MAX as u64) +/// `window * DEBOUNCE_CAP_FACTOR` cannot overflow `Duration`: [`clamp_debounce`] caps +/// the window at 60s, so the product is at most 600s. +fn debounce_cap(window: Duration) -> Duration { + (window * DEBOUNCE_CAP_FACTOR).max(DEBOUNCE_CAP_FLOOR) } /// Coalesce a burst of filesystem events into one rebuild. /// -/// TEMPORARY: the window is still a FIXED offset from the first event — `deadline` is -/// computed once and never extended — so a burst longer than `debounce_ms` is split -/// across two or more windows and rebuilt once per window. The `Cap` and -/// `MessageLimit` exits are wired into the classification but their bounds are set -/// beyond reach, so they cannot be taken. +/// # Quiet period, not a fixed window +/// +/// The first relevant event opens a window of `debounce_ms`; every further **content** +/// event restarts it. A window that expired at a fixed offset from the FIRST event +/// split any burst longer than `debounce_ms` across two or three windows and rebuilt +/// once per window, each compile seeing a different intermediate state of the file: +/// visible as three `Recompiled` lines from one ten-write burst on a loaded CI runner. +/// The size of the burst a user can produce is not a property `debounce_ms` can +/// predict; the size of the GAP between saves is. +/// +/// # Why the cap is mandatory +/// +/// An extendable window with no bound is unbounded: a file written to continuously +/// postpones its own rebuild for as long as the writing lasts. Worse, the idle-tick +/// liveness probe is not consulted while a window is open ([`TickClock::recv_next`] is +/// only reached between batches), so an endless stream would starve the content +/// backstop through a door the absolute tick deadline does not cover. The cap +/// (`max(10 x window, 1s)`) bounds both: the rebuild, and the probe behind it. +/// +/// # What does NOT extend +/// +/// `Access` events (inotify reads; see [`is_content_event`]) and watch errors. The +/// compile reads its own sources, so an extending `Access` event would let the watcher +/// hold its own window open. +/// +/// Relevance is deliberately NOT filtered here. An editor's atomic save writes a temp +/// file and renames it; that temp path is in no watch set, and ending the window on it +/// would split the very burst this exists to coalesce. Relevance decides whether to +/// rebuild ([`event_is_relevant`] in file mode, the `.mds`/root filter in dir mode); +/// this decides when. fn drain_debounce(rx: &mpsc::Receiver, debounce_ms: u64) -> DebounceOutcome { let mut paths = BTreeSet::new(); @@ -676,10 +731,21 @@ fn drain_debounce(rx: &mpsc::Receiver, debounce_ms: u64) -> DebounceOutcome let start = Instant::now(); let hard_cap = start + debounce_cap(window); - let deadline = start + window; + let mut deadline = start + window; let mut messages: usize = 0; let end = loop { + // The bound, enforced in release too: a window may be extended by further + // events, never past `start + cap`. Pure arithmetic: a descheduled runner + // cannot trip it, only a defect can. Asserting on MEASURED elapsed time + // instead would panic a shipped watcher whenever `recv_timeout` overshoots. + assert!( + deadline <= hard_cap, + "debounce deadline escaped its cap: a file written to continuously would \ + postpone its own rebuild (and the idle-tick backstop behind it) for as \ + long as the writing lasts" + ); + if messages >= MAX_DEBOUNCE_MESSAGES { break DebounceEnd::MessageLimit; } @@ -706,6 +772,7 @@ fn drain_debounce(rx: &mpsc::Receiver, debounce_ms: u64) -> DebounceOutcome for p in event.paths { paths.insert(p); } + deadline = (Instant::now() + window).min(hard_cap); } Msg::Fs(Err(e)) => { eprint_warning(&format!( @@ -3550,6 +3617,10 @@ mod tests { #[test] fn debounce_quiet_period_extends_on_content_events() { let (tx, rx) = mpsc::channel::(); + // The window now outlives the burst, so the test must too: in production the + // notify sender lives as long as the watcher, and a dropped sender means + // "the watcher is gone", not "the burst ended". + let keepalive = tx.clone(); // 40 events, 5ms apart: a ~200ms burst under a 100ms window. let sender = std::thread::spawn(move || { for i in 0..40u32 { @@ -3568,6 +3639,7 @@ mod tests { "a burst of content events must not postpone the window forever", ); let elapsed = t0.elapsed(); + drop(keepalive); sender.join().expect("sender thread panicked"); assert_eq!( @@ -3691,6 +3763,10 @@ mod tests { #[test] fn debounce_access_events_do_not_extend() { let (tx, rx) = mpsc::channel::(); + // Outlive the read stream, so a window that DID extend ends on its own + // elapsed time rather than on the sender being dropped — the failure then + // names the property under test instead of the channel's lifetime. + let keepalive = tx.clone(); let sender = std::thread::spawn(move || { if tx.send(modify_event("/w/a.mds")).is_err() { return; @@ -3712,6 +3788,7 @@ mod tests { "a stream of reads must not hold the window open", ); let elapsed = t0.elapsed(); + drop(keepalive); sender.join().expect("sender thread panicked"); assert_eq!(outcome.end, DebounceEnd::Quiet); diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index c3ab9018..5053419c 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -1241,9 +1241,10 @@ fn watch_debounce_single_rebuild_from_burst() { 1, "the startup compile is the only 'Compiled to' line; stderr was:\n{stderr}" ); + // `mds` copies the frontmatter block through verbatim and interpolates the body. assert_eq!( std::fs::read_to_string(&out).unwrap(), - "Burst v12!\n", + "---\nname: v12\n---\nBurst v12!\n", "the single rebuild must compile the FINAL state of the burst, not an \ intermediate one; stderr was:\n{stderr}" ); From 3caf62970b061ca9ad5b83d65985170361c7edb1 Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:43:24 +0300 Subject: [PATCH 14/19] docs(watch): document the debounce quiet period and cap (#379) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `--debounce` is no longer "how long to wait after the first event", so the clap help, the README option block and the CHANGELOG all said the wrong thing. Rendered help (`cargo run -p mds-cli -- watch --help`): --debounce Quiet period in milliseconds before a rebuild (default 100). Each file change restarts the window, so a save burst longer than MS still coalesces into one rebuild; the window is capped at max(10 x MS, 1000) ms so continuous writes still rebuild. Use 0 to disable coalescing. Values above 60000 are clamped [default: 100] The clap help stays ASCII-only; the README block uses `×` to match the `≥50ms` in the `--poll-interval` block directly below it. The CHANGELOG bullet goes in a new `### Changed` section ahead of `### Fixed` (Keep a Changelog order) and names the known cost: in directory mode every event opens a window, including events under excluded directories that are only filtered afterwards, so `npm install` churn can delay a real edit — and the idle tick — by up to the cap. node scripts/verify-no-control-bytes.mjs: scanned 559 files, 6532099 bytes, clean. cargo fmt --all --check clean; both clippy variants clean; `cargo nextest run -p mds-cli` 832 tests run: 832 passed. Refs #379. --- CHANGELOG.md | 13 +++++++++++++ README.md | 7 ++++++- crates/mds-cli/src/main.rs | 7 +++++-- 3 files changed, 24 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8977c2de..f45bbdb8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,19 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Changed + +- **`mds watch --debounce` is now a quiet period with a hard cap (#379).** + Each content event restarts the window instead of the window expiring at a fixed + offset from the first event, so a save burst longer than the window coalesces into + one rebuild; the window is bounded by `max(10 x window, 1 s)` and 10 000 events so a + file written to continuously still rebuilds and the idle-tick liveness probe cannot + be starved; raw values are clamped to 60 s (`--debounce 18446744073709551615` + previously watched forever without ever rebuilding); `--debounce 0` still means no + coalescing. No new output. Known cost: in directory mode every event opens a window, + including events under excluded directories that are filtered afterwards, so + `npm install` churn can delay a real edit and the idle tick by up to the cap. + ### Fixed - **Warn on duplicate keys in `--vars` JSON files, at every depth, on every `mds watch` rebuild that writes output (#326).** diff --git a/README.md b/README.md index 5b594863..6ba0659e 100644 --- a/README.md +++ b/README.md @@ -113,7 +113,12 @@ Build/Watch options: Watch-only options: --clear Clear terminal before each rebuild (only when stderr is a TTY) - --debounce Debounce window in milliseconds (default: 100) + --debounce Quiet period in milliseconds before a rebuild (default: 100). + Each file change restarts the window, so a save burst longer + than MS still coalesces into a single rebuild. The window is + capped at max(10 × MS, 1000) ms, so a file written to + continuously still rebuilds. 0 disables coalescing (every + event rebuilds). Values above 60000 are clamped. --poll-interval Liveness-probe interval in milliseconds (default: 1000). 0 disables self-heal (native events only). Clamped to ≥50ms. The watcher self-heals after a watched dir/root is deleted and diff --git a/crates/mds-cli/src/main.rs b/crates/mds-cli/src/main.rs index db9b32a3..bb846fcb 100644 --- a/crates/mds-cli/src/main.rs +++ b/crates/mds-cli/src/main.rs @@ -220,8 +220,11 @@ enum Commands { /// Clear the terminal before each rebuild (only when stderr is a TTY) #[arg(long)] clear: bool, - /// Debounce window in milliseconds (default 100; use 0 for immediate rebuilds). - /// Controls how long to wait for burst coalescing after the first event. + /// Quiet period in milliseconds before a rebuild (default 100). + /// Each file change restarts the window, so a save burst longer than MS still + /// coalesces into one rebuild; the window is capped at max(10 x MS, 1000) ms so + /// continuous writes still rebuild. Use 0 to disable coalescing. + /// Values above 60000 are clamped. #[arg(long = "debounce", value_name = "MS", default_value = "100")] debounce: u64, /// Self-heal poll interval in milliseconds (default 1000). From f78dd7cf785eb9d64503a2c75a054b9a7d980d2a Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:51:24 +0300 Subject: [PATCH 15/19] test(watch): prove the readiness handshake makes ctrl-c deterministic (#129) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Surface 1 of #129 was "SIGINT can land before `ctrlc::set_handler` runs". The #323 ordering closed it — `set_handler` precedes `emit_ready_marker` in both watch modes — but nothing in the suite pinned that the handshake is what makes a post-SIGINT `status.success()` deterministic rather than luck. `watch_readiness_handshake_makes_ctrl_c_exit_deterministic` is a two-arm control: same signal, opposite verdicts, 20 iterations. - CONTROL: `spawn_unsynchronized` + SIGINT gated on the `Watching …` line, which `run_watch_file` prints before it creates the watcher and long before the handler is installed -> death by SIGINT. A clean exit in this arm would mean the pre-handler window is no longer being hit, and the treatment arm would then prove nothing. - TREATMENT: `spawn_ready` + immediate SIGINT -> exit 0 and "Stopped watching.". N = 20 is a live discriminator, not a rate bound (the manual Linux soak workflow is the rate instrument). Every wait is bounded; none is a sleep standing in for a synchroniser. `wait_bounded` is a new 1ms-granularity try_wait loop that panics naming the arm. `#[cfg(unix)]`: SIGINT has no Windows analogue. The control fixture reuses the verified shape from `watch_file_mode_ctrl_c_during_startup_compile_terminates` (400 partials, `@define`/`@end`/`@export`, one `@import` each), built once for the whole run. Surface 2 needed no change here: `watch_ctrl_c_prints_stopped_watching` already reads its final stderr through `finish_text` (the post-kill flush sleep was replaced in cffb951), so no sleep gates its assertion. Also documents why i18 expects exactly 1 warning: the warning is gated in `rebuild_file` on an observable output-content change, the fixture never interpolates `x`, so the vars-file rebuild produces byte-identical output and reports nothing — only the `version 3` rebuild is observable. Atomic writes removed the 0-byte intermediate that used to add a second transition. Observed: - new test alone x4: `1 test run: 1 passed, 78 skipped` (0.889 / 0.785 / 0.791 / 0.771s) — 20/20 both arms every run - non-vacuity mutation (control arm `spawn_unsynchronized` -> `spawn_ready`, applied to a scratch copy, restored + `cmp` RESTORED_OK): RED at `cli_watch.rs:4213` `left: None right: Some(2)` with the intended message - `cargo nextest run -p mds-cli --test cli_watch` x3: `79 tests run: 79 passed, 0 skipped` (4.033 / 4.085 / 4.428s) - `cargo fmt --all --check` clean; clippy clean with and without `--features startup-race-probe` Refs #129 --- crates/mds-cli/tests/cli_watch.rs | 158 ++++++++++++++++++++++++++++++ 1 file changed, 158 insertions(+) diff --git a/crates/mds-cli/tests/cli_watch.rs b/crates/mds-cli/tests/cli_watch.rs index 5053419c..f4c8dd85 100644 --- a/crates/mds-cli/tests/cli_watch.rs +++ b/crates/mds-cli/tests/cli_watch.rs @@ -4108,6 +4108,155 @@ fn watch_file_mode_ctrl_c_during_startup_compile_terminates() { ); } +/// Bounded wait for a child that has already been signalled. +/// +/// A **bound, not a synchroniser**: a signalled child exits in milliseconds, and one +/// that has not exited by the deadline is the defect the caller is asserting against. +/// `what` names the arm so the panic is self-describing. +#[cfg(unix)] +fn wait_bounded(guard: &mut ChildGuard, timeout: Duration, what: &str) -> std::process::ExitStatus { + let deadline = Instant::now() + timeout; + while Instant::now() < deadline { + if let Some(status) = guard.0.try_wait().expect("try_wait failed") { + return status; + } + std::thread::sleep(Duration::from_millis(1)); + } + panic!("{what}: the process did not exit within {timeout:?} of the signal"); +} + +/// Control for #129 surface 1: the readiness handshake — not luck — is what makes a +/// post-SIGINT `status.success()` deterministic. +/// +/// Two arms, the same signal, opposite verdicts: +/// +/// - **CONTROL.** [`spawn_unsynchronized`], with SIGINT gated on the `Watching …` +/// line. `run_watch_file` prints that line before it even creates the watcher, and +/// therefore long before `ctrlc::set_handler`, so the signal lands in the +/// pre-handler window where the default disposition still applies: death by SIGINT. +/// If this arm ever exits cleanly, the window is no longer being hit and the +/// treatment arm below proves nothing. +/// - **TREATMENT.** [`spawn_ready`], with SIGINT sent the instant the handshake +/// returns. `set_handler` precedes `emit_ready_marker` in `run_watch_file`, so once +/// the marker exists the handler provably does too: exit 0 and `Stopped watching.`. +/// +/// `N = 20` is a live discriminator, not a rate bound — a single clean control exit +/// fails the run. The manual Linux soak workflow is the rate instrument. Every wait +/// here is bounded and none of them is a sleep standing in for a synchroniser. +/// `#[cfg(unix)]` because SIGINT has no Windows analogue; the test compiles out there. +#[test] +#[cfg(unix)] +fn watch_readiness_handshake_makes_ctrl_c_exit_deterministic() { + use std::os::unix::process::ExitStatusExt; + + const N: usize = 20; + /// Imports in the control entry. Same fixture shape as + /// `watch_file_mode_ctrl_c_during_startup_compile_terminates`: enough work that + /// the startup compile is demonstrably still running when the signal lands. + const PARTIALS: usize = 400; + + // Both fixtures are built ONCE. No watcher in this test ever edits a watched file, + // so rebuilding them per iteration would buy nothing but wall clock. + let slow_dir = tempfile::tempdir().unwrap(); + let mut entry = String::new(); + for i in 0..PARTIALS { + let name = format!("_p{i:04}"); + std::fs::write( + slow_dir.path().join(format!("{name}.mds")), + format!("@define v{i}():\nP{i}\n@end\n\n@export v{i}\n"), + ) + .unwrap(); + entry.push_str(&format!("@import \"./{name}.mds\" as p{i}\n")); + } + entry.push_str("done\n"); + let slow_src = slow_dir.path().join("entry.mds"); + std::fs::write(&slow_src, &entry).unwrap(); + + let fast_dir = tempfile::tempdir().unwrap(); + let fast_src = fast_dir.path().join("hello.mds"); + std::fs::write(&fast_src, "---\nname: World\n---\nHello {{name}}!\n").unwrap(); + + for iteration in 0..N { + // ── CONTROL arm: signal delivered before the handler is installed ─────── + let (mut guard, tap) = spawn_unsynchronized( + // No -q: the `Watching …` line is the gate. + mds_bin() + .args(["watch", slow_src.to_str().unwrap(), "--debounce", "0"]) + .stdout(Stdio::null()), + ); + let pid = guard.id(); + + let deadline = Instant::now() + STARTUP_WINDOW_TIMEOUT; + let mut saw_watching = false; + while Instant::now() < deadline { + if tap.text().contains("Watching ") { + saw_watching = true; + break; + } + std::thread::sleep(Duration::from_millis(1)); + } + assert!( + saw_watching, + "control arm, iteration {iteration}: expected the `Watching …` startup \ + line before signalling; stderr:\n{}", + tap.text() + ); + + unsafe { + libc::kill(pid as libc::pid_t, libc::SIGINT); + } + let status = wait_bounded( + &mut guard, + Duration::from_secs(20), + "control arm (SIGINT before the handler is installed)", + ); + assert_eq!( + status.signal(), + Some(libc::SIGINT), + "control arm, iteration {iteration}: SIGINT delivered before \ + `ctrlc::set_handler` runs must terminate the process. A clean exit here \ + means the signal no longer lands in the pre-handler window, and the \ + treatment arm below then proves nothing; got {status:?}" + ); + assert!( + !status.success(), + "control arm, iteration {iteration}: death by signal is not a success \ + status; got {status:?}" + ); + + // ── TREATMENT arm: signal delivered after the readiness handshake ─────── + let (mut guard, tap) = spawn_ready( + mds_bin() + .args(["watch", fast_src.to_str().unwrap(), "--debounce", "0"]) + .stdout(Stdio::null()), + ); + let pid = guard.id(); + + unsafe { + libc::kill(pid as libc::pid_t, libc::SIGINT); + } + let status = wait_bounded( + &mut guard, + Duration::from_secs(5), + "treatment arm (SIGINT after the readiness handshake)", + ); + assert!( + status.success(), + "treatment arm, iteration {iteration}: after the readiness handshake the \ + ctrl-c handler provably exists (`set_handler` precedes \ + `emit_ready_marker` in `run_watch_file`), so SIGINT must exit 0; got \ + {status:?}; stderr:\n{}", + tap.text() + ); + let stderr = tap.finish_text(&mut guard); + assert!( + stderr.contains("Stopped watching."), + "treatment arm, iteration {iteration}: a clean SIGINT exit must also print \ + `Stopped watching.`; stderr:\n{stderr}" + ); + } +} + // ── I8: file-watch mode warns exactly ONCE across two edits (#200) ────────── /// Count non-overlapping occurrences of `needle` in `haystack`. @@ -4512,6 +4661,15 @@ fn i18_duplicate_introduced_mid_session_is_reported_on_the_next_rebuild() { ); // Introduce a duplicate mid-session, then trigger the next rebuild. + // + // Two watched files are written here, yet the expected count below is exactly 1. + // The warning is gated in `rebuild_file` on an OBSERVABLE output-content change — + // the same signal that gates the "Recompiled" line — and this fixture never + // interpolates `x`, so the rebuild the vars-file write triggers produces + // byte-identical output and reports nothing. Only the `version 3` rebuild is + // observable. The atomic writes are what make that exact: a truncate-then-write + // published a 0-byte intermediate, which was itself an observable transition and + // could contribute a second warning. write_atomic(&vars_file, r#"{"x": 1, "x": 2}"#); write_atomic(&src, "version 3"); assert!( From a27bac9b355182475b354b1b0012b539636a029e Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:52:43 +0300 Subject: [PATCH 16/19] test(build): synchronise the bare-filename watch test on MDS_TEST_READY (#318) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `watch_bare_filename_from_cwd_succeeds` was the last "poll the artifact instead of synchronising on readiness" site outside cli_watch.rs, and the Rust half of #318. It spawned `mds watch hello.mds` from a cwd and polled `hello.md` for up to 10s. Polling is the defect, not the bound: it turns "the startup compile wrote the file" into "something wrote the file eventually", so a startup path that resolved the bare filename only on a later retry or rebuild still passed. A shorter loop would preserve that; only deleting the loop removes it. `run_watch_file` publishes the startup output at the arm-before-publish point, well before `emit_ready_marker`, so once `spawn_watch_ready` returns the file is on disk. It is now read ONCE, directly. Also: the private `ChildGuard` copy is replaced by `common::ChildGuard`, the `Duration`/`Instant` imports are gone with the loop, and `.stderr(Stdio::null())` is dropped in favour of the drained `StderrTap` — `-q` still lets a compile error through, so both failure paths now name their own cause instead of being silent. The issue's line refs (`cli_build.rs:1138-1148`) had drifted; the site was `:1309-1356` on main 2b91850. Observed: - `cargo nextest run -p mds-cli --test cli_build` x3: `46 tests run: 46 passed, 0 skipped` (1.349 / 1.372 / 1.359s) - the test alone: `PASS [0.430s]` (was a 10s-bounded poll) - `cargo fmt --all --check` clean; clippy clean with and without `--features startup-race-probe` Refs #318 --- crates/mds-cli/tests/cli_build.rs | 74 ++++++++++++++++--------------- 1 file changed, 38 insertions(+), 36 deletions(-) diff --git a/crates/mds-cli/tests/cli_build.rs b/crates/mds-cli/tests/cli_build.rs index 84262524..90b48b14 100644 --- a/crates/mds-cli/tests/cli_build.rs +++ b/crates/mds-cli/tests/cli_build.rs @@ -1,5 +1,8 @@ mod common; -use common::{count_occurrences, dup_vars_file_omitted, dup_vars_file_warning, fixture, mds_bin}; +use common::{ + count_occurrences, dup_vars_file_omitted, dup_vars_file_warning, fixture, mds_bin, + spawn_watch_ready, ChildGuard, +}; #[test] fn build_to_file() { @@ -1303,55 +1306,54 @@ fn check_stdin_resource_limit_exits_3() { /// (build / check / fmt / lint) are above. Watch is the one subcommand that /// resolves parents through its own call sites; this test locks in that startup path. /// -/// Only asserts the INITIAL BUILD (bounded 10-second wait) — no event-timing -/// assertions that would be timing-flaky on Linux CI. +/// Only asserts the INITIAL BUILD — no event-timing assertions that would be +/// timing-flaky on Linux CI. +/// +/// Synchronised on the `MDS_TEST_READY` handshake (#318), not on the artifact. +/// `run_watch_file` publishes the startup output well before it writes the marker, so +/// once [`spawn_watch_ready`] returns, `hello.md` is already on disk and is read +/// **once**, directly. The previous shape polled the output file for up to 10s, which +/// is the defect the issue names: polling turns "the startup compile wrote the file" +/// into "something wrote the file eventually", so a startup path that resolved the +/// bare filename only on a later retry — or a rebuild — still passed. A shorter poll +/// would preserve that; only removing the loop removes it. #[test] fn watch_bare_filename_from_cwd_succeeds() { use std::process::Stdio; - use std::time::{Duration, Instant}; - - // RAII guard — kills + waits the child on drop so the test never leaks processes. - struct ChildGuard(std::process::Child); - impl Drop for ChildGuard { - fn drop(&mut self) { - let _ = self.0.kill(); - let _ = self.0.wait(); - } - } let dir = tempfile::tempdir().unwrap(); // Use a distinguishable sentinel so "exit 0 + empty file" can't pass. std::fs::write(dir.path().join("hello.mds"), "Hello from watch!\n").unwrap(); let out = dir.path().join("hello.md"); - let _child = ChildGuard( + let (child, tap, stdout_tap) = spawn_watch_ready( mds_bin() .current_dir(dir.path()) .args(["watch", "hello.mds", "--debounce", "0", "-q"]) - .stdout(Stdio::null()) - .stderr(Stdio::null()) - .spawn() - .expect("failed to spawn mds watch"), - ); - - // Poll until the output file appears and contains the compiled content. - // Bounded to 10 s; the initial compile typically finishes in < 100 ms. - let deadline = Instant::now() + Duration::from_secs(10); - let found = loop { - if let Ok(content) = std::fs::read_to_string(&out) { - if content.contains("Hello from watch!") { - break true; - } - } - if Instant::now() >= deadline { - break false; - } - std::thread::sleep(Duration::from_millis(50)); - }; + .stdout(Stdio::null()), + ); assert!( - found, + stdout_tap.is_none(), + "stdout is null here; a tap would mean the command piped it" + ); + // RAII guard — kills + waits the child on drop so the test never leaks processes. + let _child = ChildGuard(child); + + // stderr is drained rather than discarded: `-q` still lets a compile error + // through, so a failure here names its own cause instead of being silent. + let content = std::fs::read_to_string(&out).unwrap_or_else(|e| { + panic!( + "mds watch from cwd must have written {} before signalling \ + readiness: {e}; stderr:\n{}", + out.display(), + tap.text() + ) + }); + assert!( + content.contains("Hello from watch!"), "mds watch from cwd should complete initial compile and write hello.md \ - containing 'Hello from watch!'" + containing 'Hello from watch!'; got: {content:?}; stderr:\n{}", + tap.text() ); } From 214ff3046ebd9b6524d4dfad56dc209d9f2de73c Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 21:53:14 +0300 Subject: [PATCH 17/19] docs: record the C2 evidence (#129, #318, #320) Seven `### Internal` bullets under `[Unreleased]`, one per harness or test change on this branch, alongside the existing soak-workflow bullet: atomic writes, joinable drains, stdout drained before the readiness wait, bounded warning-count waits for i16-i20, the #129 handshake control test, and the #318 cli_build.rs site. Observed: `node scripts/verify-no-control-bytes.mjs` clean. Refs #129 #318 #320 --- CHANGELOG.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index f45bbdb8..bfde5eaf 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -74,6 +74,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Alpine `node:22-alpine` load tests for both musl napi addons gate `publish-crates`: x64 (`linux-x64-musl`) as the last step of `stage-and-verify-napi` (after the staged artifact upload, so the artifact is never suppressed by an x64 failure), arm64 (`linux-arm64-musl`) in a new unguarded `load-test-musl-arm64` job on a native `ubuntu-24.04-arm` runner using the `napi-staged` artifact; both use `scripts/musl-load-probe.cjs` in a `docker run --network none` step with a positive control; `publish-crates` blocks on both via `needs:` AND its `if:` conjunct (PF-047); spec S21 in `release-auth-probe.spec.mjs` pins job existence, runner, guard shape, wiring, step order, and run-block byte-equality (#340); the first CI run surfaced #371 (string compile fails when the base directory is a filesystem root — `node:22-alpine` has no `WORKDIR` so the default container cwd is `/`); the gate now runs the container from `/w` (`docker run -w /w`) and the probe asserts its cwd so a dropped flag fails loudly. - Both musl napi legs (`x86_64-unknown-linux-musl`, `aarch64-unknown-linux-musl`) now cross-compile with `napi build … -x` / cargo-zigbuild 0.23.0: the SHA-pinned `taiki-e/install-action` (v2.85.10, `fallback: none`) installs cargo-zigbuild before `Swatinem/rust-cache` (rust-cache deletes `~/.cargo/bin` on save; napi's detector is presence-only and would `cargo install` an unpinned copy mid-build otherwise); the hand-written zig cc wrappers, fake-zig self-check, and both `CARGO_TARGET_*_MUSL_LINKER` exports are deleted; three new steps assert the pinned version (before and after the build) and the no-op detector reads both musl linker vars inside `[ -z ]` guards to confirm none is set; the readelf gate adds `ALLOWED_NEEDED='libc\.so|libgcc_s\.so\.1'` with a planted `libunwind.so.1` control; `mlugg/setup-zig` SHA-pinned (v2.2.1) in the same step; spec S22 in `release-auth-probe.spec.mjs` pins all of the above (#339). - manual `watch-soak.yml` Linux soak instrument for the cli_watch flake family (#129 #318 #320); `workflow_dispatch` only, not a gate, not a required context, not release-surface +- `cli_watch` harness: every post-spawn write to a watched path goes through `common::write_atomic` (temp + rename, one FS event instead of the truncate-then-write pair whose 0-byte intermediate was compiled at `--debounce 0`); 45 sites converted by a mechanical rule stated in the file's doc comment, with two `// DELIBERATE:` plain-write exceptions whose subject IS the truncate+write pair (#318). +- `cli_watch` harness: the pipe drain thread is now joinable — `PipeTap::finish`/`finish_text` reap the child and then JOIN the drain, so the final stderr read carries a happens-before edge to the child's last write; 13 of 13 post-kill flush sleeps deleted and `ChildGuard` moved to `tests/common` so `finish` can name it (#320). +- `cli_watch` harness: a piped stdout is drained *before* the readiness wait, not after (`spawn_watch_ready` returns the tap as a third element; `spawn_ready_piped_stdout` hands it to the caller). `mds watch -o -` publishes its startup output before it writes the readiness marker, so an undrained pipe filled and blocked the child while the poller waited for a marker that could never arrive — reproduced locally as a deterministic 10s `READY_TIMEOUT` failure on 512 KiB of stdout (#320). +- `cli_watch` harness: the i16–i20 duplicate-vars-warning family waits for the expected warning count with a bounded `wait_for_stderr_count` before asserting it. In directory mode the warning is emitted after the output write, so sampling stderr the instant the artifact appeared could read one warning short (CI runs 34366009518, 34404318888) (#326 #320). +- `cli_watch`: `watch_readiness_handshake_makes_ctrl_c_exit_deterministic` is a two-arm control (20 iterations) proving the `MDS_TEST_READY` handshake, not luck, is what makes a post-SIGINT `status.success()` deterministic — unsynchronized spawn signalled on the `Watching …` line dies by SIGINT; a spawn signalled after the handshake exits 0 and prints `Stopped watching.` (#129). +- `cli_build`: `watch_bare_filename_from_cwd_succeeds` is synchronised on the readiness handshake and reads `hello.md` once, instead of polling the output artifact for up to 10s; the private `ChildGuard` copy is replaced by `common::ChildGuard` and stderr is drained rather than discarded (#318). ## [0.4.2] — 2026-09-03 From d4bdd2cd616c00ba290c0b1c0d8191eeb6521353 Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 22:11:06 +0300 Subject: [PATCH 18/19] fix(watch): cover the Disconnected debounce exit (scrutinize) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `DebounceEnd::Disconnected` was the only variant of the new debounce outcome with no test. It is not cosmetic: without the early break the drain busy-spins on `recv_timeout` until the full window elapses, so a watcher whose sender has been dropped delays its own shutdown by up to the window (and, with the sender gone, for no possible gain — no further event can ever arrive). Positive control (PF-013): replacing the break with `{}` makes the new test fail `left: Quiet / right: Disconnected` after exactly 5.00s, which is both the wrong exit reason and the spin it describes. Refs #379 --- crates/mds-cli/src/watch.rs | 30 ++++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/crates/mds-cli/src/watch.rs b/crates/mds-cli/src/watch.rs index 298c360d..88a86569 100644 --- a/crates/mds-cli/src/watch.rs +++ b/crates/mds-cli/src/watch.rs @@ -3844,6 +3844,36 @@ mod tests { ); } + /// A dropped sender ends the window at once rather than waiting it out. + /// + /// The sender lives as long as the watcher, so a disconnect means the watcher is + /// gone. Sitting out the remaining window there would delay shutdown by up to the + /// cap for no possible gain: no further event can ever arrive. + #[test] + fn debounce_disconnected_ends_the_window_immediately() { + let (tx, rx) = mpsc::channel::(); + // One event already queued, so the drain has something to collect before it + // reaches the disconnect — the exit must not discard it. + tx.send(modify_event("/w/a.mds")).expect("send failed"); + drop(tx); + + let t0 = Instant::now(); + let outcome = drain_debounce(&rx, 5_000); + let elapsed = t0.elapsed(); + + assert_eq!(outcome.end, DebounceEnd::Disconnected); + assert_eq!( + outcome.paths.len(), + 1, + "messages queued before the disconnect must still be collected; got {:?}", + outcome.paths + ); + assert!( + elapsed < Duration::from_millis(500), + "a disconnect must end a 5s window immediately; got {elapsed:?}" + ); + } + /// The clamp contract, verifiable without the watch loop. #[test] fn clamp_debounce_contract() { From b53707848c97c1696dc38e63bccf3e7539041d02 Mon Sep 17 00:00:00 2001 From: Dean Sharon Date: Sun, 13 Sep 2026 22:23:03 +0300 Subject: [PATCH 19/19] docs(watch): correct two C2 notes (scrutinize P2) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `PipeTap`'s drain-slot comment claimed "several tests hand a clone to a helper"; no call site clones a tap. Reword to say what the shape is actually for: `Clone` is harness API, and the mutex is what makes a concurrent `finish` from a clone safe. The CHANGELOG's debounce "known cost" was scoped to directory mode. It applies in both: `drain_debounce` extends the deadline on any content event without re-deriving relevance, and file mode watches the entry's parent directory non-recursively, so a sibling scratch write extends a window a real edit has already opened. Dir mode differs only in that an irrelevant event can also *open* one — file mode checks relevance first. --- CHANGELOG.md | 10 +++++++--- crates/mds-cli/tests/common/mod.rs | 5 ++++- 2 files changed, 11 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index bfde5eaf..7a06b943 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,9 +16,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 file written to continuously still rebuilds and the idle-tick liveness probe cannot be starved; raw values are clamped to 60 s (`--debounce 18446744073709551615` previously watched forever without ever rebuilding); `--debounce 0` still means no - coalescing. No new output. Known cost: in directory mode every event opens a window, - including events under excluded directories that are filtered afterwards, so - `npm install` churn can delay a real edit and the idle tick by up to the cap. + coalescing. No new output. Known cost, in both modes: an event that is not the edit + you care about can still extend an open window, because relevance is not re-derived + per message inside it — in directory mode every event also *opens* one (events under + excluded directories are filtered only afterwards), while in file mode the entry's + parent directory is watched non-recursively, so a sibling scratch write by an editor + extends a window a real edit has already opened. Either way `npm install` churn or a + noisy editor can delay a real edit and the idle tick by up to the cap. ### Fixed diff --git a/crates/mds-cli/tests/common/mod.rs b/crates/mds-cli/tests/common/mod.rs index 69a596c0..35c38c5f 100644 --- a/crates/mds-cli/tests/common/mod.rs +++ b/crates/mds-cli/tests/common/mod.rs @@ -212,7 +212,10 @@ impl ChildGuard { pub struct PipeTap { buf: Arc>>, /// `Option` because `finish` takes the handle out; behind `Arc>` so - /// `PipeTap` stays `Clone` (several tests hand a clone to a helper). + /// `PipeTap` stays `Clone`. `Clone` is harness API — it lets a tap be shared with + /// a helper thread — and the mutex is what makes that safe: a clone calling + /// `finish` concurrently blocks on this slot until the drain has been joined, and + /// then observes the fully drained buffer. No call site clones a tap today. drain: Arc>>>, }