From 422e0ad768faed5fc6db5d71758edb8aee610347 Mon Sep 17 00:00:00 2001 From: Zhengchao An Date: Thu, 30 Jul 2026 07:26:12 +0800 Subject: [PATCH] test(ecstore): fix rename_all WARN flake from callsite-interest poisoning (#5448) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit rename_all_missing_source_still_warns and rename_all_real_failure_still_warns assert that `warn_reliable_rename_failure` emitted its WARN, but that is a single production callsite shared with tests that call rename_all *without* installing a subscriber — rename_all_missing_source_returns_file_not_found, two tests above, is one of them. tracing caches each callsite's Interest process-globally and the first thread to reach a callsite fixes that value; while at most one dispatcher is registered, tracing-core derives it from the registering thread's own subscriber, and registration is once-only. When the subscriber-less sibling wins, the callsite is cached as Interest::never() and the WARN never fires, so the assertion sees empty output: ordinary missing-source failures must keep the WARN, got: Reproduced at 3/25 with `disk::os::tests::rename_all_missing_source` (both tests), against 0/20 for the victim alone. Fixed by pinning callsite interest inside warn_capture(), so every current and future user of that helper is covered rather than just the two tests that happen to fail today. pin_callsite_interest_for_test() moves from cluster::rpc::background_monitor to a new crate-level test_tracing module: it is domain-neutral and now has consumers in two unrelated subsystems, and disk::os should not have to reach into a cluster::rpc test helper. Verified: repro filter 0/30 (was 3/25); disk::os:: 0/12; cluster::rpc:: 0/12 and its poisoner pair 0/15, confirming the moved helper still holds. Follow-up to #5438. Closes the last item in #5439. --- .../src/cluster/rpc/background_monitor.rs | 38 ---------------- crates/ecstore/src/cluster/rpc/mod.rs | 2 - .../src/cluster/rpc/peer_rest_client.rs | 2 +- crates/ecstore/src/cluster/rpc/remote_disk.rs | 4 +- crates/ecstore/src/disk/os.rs | 24 ++++++++++- crates/ecstore/src/lib.rs | 3 ++ crates/ecstore/src/test_tracing.rs | 43 +++++++++++++++++++ 7 files changed, 71 insertions(+), 45 deletions(-) create mode 100644 crates/ecstore/src/test_tracing.rs diff --git a/crates/ecstore/src/cluster/rpc/background_monitor.rs b/crates/ecstore/src/cluster/rpc/background_monitor.rs index 946409943..897b6895e 100644 --- a/crates/ecstore/src/cluster/rpc/background_monitor.rs +++ b/crates/ecstore/src/cluster/rpc/background_monitor.rs @@ -84,44 +84,6 @@ where ) } -/// Stop a sibling test thread from poisoning tracing's process-global callsite -/// interest cache while this test asserts on span or event context. -/// -/// `tracing` caches every callsite's `Interest` in **process-global** state, and -/// the first thread to reach a callsite fixes that value. While at most one -/// dispatcher is registered, tracing-core takes a fast path -/// (`Dispatchers::rebuilder` -> `Rebuilder::JustOne`) that derives a -/// newly-registered callsite's interest from whichever subscriber is current -/// *on the registering thread*. -/// -/// In a multi-threaded `cargo test` binary a sibling test therefore routinely -/// reaches a production callsite first, from a thread with no subscriber -/// installed: the interest is derived from that thread's `NoSubscriber` and -/// cached as `Interest::never()` for the whole process. From then on the -/// callsite is dead for *every* later caller, including a test that installed -/// its own subscriber — an `info_span!` silently evaluates to `Span::none()` -/// (so the monitor's log line lands under the caller's span instead of -/// `recovery-monitor`), and a `warn!`/`info!` event never fires at all. -/// -/// Registering a second, inert dispatcher closes both halves of that race: -/// -/// * constructing it rebuilds every *already-registered* callsite's interest -/// against the live dispatcher set — which includes the caller's subscriber — -/// repairing whatever a sibling may already have poisoned; and -/// * holding it alive keeps tracing-core off the single-dispatcher fast path, so -/// a callsite registered *later* by any thread is resolved against that live -/// set instead of the registering thread's `NoSubscriber`. -/// -/// Call this **after** installing the test's subscriber, and hold the returned -/// guard for the rest of the test. Only the `cargo test` fallback needs it: -/// nextest runs each test in its own process, where there is no sibling thread -/// to lose the race to (see `docs/testing/README.md`). -#[cfg(test)] -#[must_use = "callsite interest is only pinned while the returned guard is held"] -pub(crate) fn pin_callsite_interest_for_test() -> tracing::Dispatch { - tracing::Dispatch::new(tracing_core::subscriber::NoSubscriber::default()) -} - #[cfg(test)] mod tests { use super::*; diff --git a/crates/ecstore/src/cluster/rpc/mod.rs b/crates/ecstore/src/cluster/rpc/mod.rs index 0f5ae5c48..32e2404e9 100644 --- a/crates/ecstore/src/cluster/rpc/mod.rs +++ b/crates/ecstore/src/cluster/rpc/mod.rs @@ -23,8 +23,6 @@ pub(crate) mod remote_disk; pub(crate) mod remote_locker; pub(crate) mod runtime_sources; -#[cfg(test)] -pub(crate) use background_monitor::pin_callsite_interest_for_test; pub use background_monitor::shutdown_background_monitors; pub(crate) use background_monitor::spawn_background_monitor; pub use client::{ diff --git a/crates/ecstore/src/cluster/rpc/peer_rest_client.rs b/crates/ecstore/src/cluster/rpc/peer_rest_client.rs index 741bc628d..10d2b4a3e 100644 --- a/crates/ecstore/src/cluster/rpc/peer_rest_client.rs +++ b/crates/ecstore/src/cluster/rpc/peer_rest_client.rs @@ -2791,7 +2791,7 @@ mod tests { // `mark_offline_and_spawn_recovery` path that sibling tests exercise from // subscriber-less threads; without this the span can be cached as // `Interest::never()` and silently degrade to `Span::none()`. - let _callsite_pin = crate::cluster::rpc::pin_callsite_interest_for_test(); + let _callsite_pin = crate::test_tracing::pin_callsite_interest_for_test(); let client = test_peer_client(); let span = tracing::info_span!("request-span", request_id = "req-peer-rest"); diff --git a/crates/ecstore/src/cluster/rpc/remote_disk.rs b/crates/ecstore/src/cluster/rpc/remote_disk.rs index 3a0926d0b..d5090d54f 100644 --- a/crates/ecstore/src/cluster/rpc/remote_disk.rs +++ b/crates/ecstore/src/cluster/rpc/remote_disk.rs @@ -5336,7 +5336,7 @@ mod tests { // production callsites that sibling tests exercise from subscriber-less // threads; without this they can be cached as `Interest::never()` and go // silently missing here. - let _callsite_pin = crate::cluster::rpc::pin_callsite_interest_for_test(); + let _callsite_pin = crate::test_tracing::pin_callsite_interest_for_test(); let endpoint = Endpoint { url: url::Url::parse("http://127.0.0.1:59996/data").expect("endpoint URL should parse"), @@ -5395,7 +5395,7 @@ mod tests { // production callsites that sibling tests exercise from subscriber-less // threads; without this they can be cached as `Interest::never()` and go // silently missing here. - let _callsite_pin = crate::cluster::rpc::pin_callsite_interest_for_test(); + let _callsite_pin = crate::test_tracing::pin_callsite_interest_for_test(); let addr = "http://127.0.0.1:59997".to_string(); let endpoint = Endpoint { diff --git a/crates/ecstore/src/disk/os.rs b/crates/ecstore/src/disk/os.rs index e19110a35..75da8d0e7 100644 --- a/crates/ecstore/src/disk/os.rs +++ b/crates/ecstore/src/disk/os.rs @@ -957,9 +957,26 @@ mod tests { } } + /// Holds a `warn_capture()` capture alive: the thread-local subscriber, plus + /// the pin that keeps tracing's process-global callsite-interest cache from + /// being decided by some other test's thread. + struct WarnCaptureGuard { + _subscriber: tracing::subscriber::DefaultGuard, + _callsite_pin: tracing::Dispatch, + } + /// Capture WARN-level output on the current thread; tokio tests here run on /// the current-thread runtime, so the guard covers the whole test body. - fn warn_capture() -> (CapturedLogs, tracing::subscriber::DefaultGuard) { + /// + /// The callsite pin matters because `warn_reliable_rename_failure` is a + /// single production callsite shared with tests that call `rename_all` + /// *without* installing a subscriber — `rename_all_missing_source_returns_file_not_found` + /// is one. Whichever thread reaches it first fixes its `Interest` + /// process-wide, so without the pin that sibling can cache + /// `Interest::never()` and the WARN never fires here at all, leaving the + /// "must keep the WARN" assertions staring at empty output. See + /// [`crate::test_tracing::pin_callsite_interest_for_test`]. + fn warn_capture() -> (CapturedLogs, WarnCaptureGuard) { let logs = CapturedLogs::default(); let subscriber = tracing_subscriber::fmt() .with_max_level(tracing::Level::WARN) @@ -967,7 +984,10 @@ mod tests { .with_ansi(false) .without_time() .finish(); - let guard = tracing::subscriber::set_default(subscriber); + let guard = WarnCaptureGuard { + _subscriber: tracing::subscriber::set_default(subscriber), + _callsite_pin: crate::test_tracing::pin_callsite_interest_for_test(), + }; (logs, guard) } diff --git a/crates/ecstore/src/lib.rs b/crates/ecstore/src/lib.rs index 79e779ba8..47d25a03e 100644 --- a/crates/ecstore/src/lib.rs +++ b/crates/ecstore/src/lib.rs @@ -93,3 +93,6 @@ pub(crate) mod ecstore_validation_blackbox; #[cfg(test)] pub(crate) mod test_metrics; + +#[cfg(test)] +pub(crate) mod test_tracing; diff --git a/crates/ecstore/src/test_tracing.rs b/crates/ecstore/src/test_tracing.rs new file mode 100644 index 000000000..cedea0a69 --- /dev/null +++ b/crates/ecstore/src/test_tracing.rs @@ -0,0 +1,43 @@ +//! Test-only guard against tracing's process-global callsite-interest cache. +//! +//! Any test that installs its own subscriber and then asserts on span or event +//! context is asserting on process-global state. See +//! [`pin_callsite_interest_for_test`] for what goes wrong and why holding its +//! guard fixes it. + +/// Stop a sibling test thread from poisoning tracing's process-global callsite +/// interest cache while this test asserts on span or event context. +/// +/// `tracing` caches every callsite's `Interest` in **process-global** state, and +/// the first thread to reach a callsite fixes that value. While at most one +/// dispatcher is registered, tracing-core takes a fast path +/// (`Dispatchers::rebuilder` -> `Rebuilder::JustOne`) that derives a +/// newly-registered callsite's interest from whichever subscriber is current +/// *on the registering thread*, and registration happens exactly once (guarded +/// by a CAS in `DefaultCallsite::register`). +/// +/// In a multi-threaded `cargo test` binary a sibling test therefore routinely +/// reaches a production callsite first, from a thread with no subscriber +/// installed: the interest is derived from that thread's `NoSubscriber` and +/// cached as `Interest::never()` for the whole process. From then on the +/// callsite is dead for *every* later caller, including a test that installed +/// its own subscriber — an `info_span!` silently evaluates to `Span::none()`, and +/// a `warn!`/`info!` event never fires at all. +/// +/// Registering a second, inert dispatcher closes both halves of that race: +/// +/// * constructing it rebuilds every *already-registered* callsite's interest +/// against the live dispatcher set — which includes the caller's subscriber — +/// repairing whatever a sibling may already have poisoned; and +/// * holding it alive keeps tracing-core off the single-dispatcher fast path, so +/// a callsite registered *later* by any thread is resolved against that live +/// set instead of the registering thread's `NoSubscriber`. +/// +/// Call this **after** installing the test's subscriber, and hold the returned +/// guard for the rest of the test. Only the `cargo test` fallback needs it: +/// nextest runs each test in its own process, where there is no sibling thread +/// to lose the race to (see `docs/testing/README.md`). +#[must_use = "callsite interest is only pinned while the returned guard is held"] +pub(crate) fn pin_callsite_interest_for_test() -> tracing::Dispatch { + tracing::Dispatch::new(tracing_core::subscriber::NoSubscriber::default()) +}