mirror of
https://github.com/rustfs/rustfs.git
synced 2026-08-22 12:26:37 +00:00
test(ecstore): fix rename_all WARN flake from callsite-interest poisoning
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.
This commit is contained in:
@@ -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)]
|
#[cfg(test)]
|
||||||
mod tests {
|
mod tests {
|
||||||
use super::*;
|
use super::*;
|
||||||
|
|||||||
@@ -23,8 +23,6 @@ pub(crate) mod remote_disk;
|
|||||||
pub(crate) mod remote_locker;
|
pub(crate) mod remote_locker;
|
||||||
pub(crate) mod runtime_sources;
|
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 use background_monitor::shutdown_background_monitors;
|
||||||
pub(crate) use background_monitor::spawn_background_monitor;
|
pub(crate) use background_monitor::spawn_background_monitor;
|
||||||
pub use client::{
|
pub use client::{
|
||||||
|
|||||||
@@ -2745,7 +2745,7 @@ mod tests {
|
|||||||
// `mark_offline_and_spawn_recovery` path that sibling tests exercise from
|
// `mark_offline_and_spawn_recovery` path that sibling tests exercise from
|
||||||
// subscriber-less threads; without this the span can be cached as
|
// subscriber-less threads; without this the span can be cached as
|
||||||
// `Interest::never()` and silently degrade to `Span::none()`.
|
// `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 client = test_peer_client();
|
||||||
let span = tracing::info_span!("request-span", request_id = "req-peer-rest");
|
let span = tracing::info_span!("request-span", request_id = "req-peer-rest");
|
||||||
|
|||||||
@@ -5336,7 +5336,7 @@ mod tests {
|
|||||||
// production callsites that sibling tests exercise from subscriber-less
|
// production callsites that sibling tests exercise from subscriber-less
|
||||||
// threads; without this they can be cached as `Interest::never()` and go
|
// threads; without this they can be cached as `Interest::never()` and go
|
||||||
// silently missing here.
|
// 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 {
|
let endpoint = Endpoint {
|
||||||
url: url::Url::parse("http://127.0.0.1:59996/data").expect("endpoint URL should parse"),
|
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
|
// production callsites that sibling tests exercise from subscriber-less
|
||||||
// threads; without this they can be cached as `Interest::never()` and go
|
// threads; without this they can be cached as `Interest::never()` and go
|
||||||
// silently missing here.
|
// 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 addr = "http://127.0.0.1:59997".to_string();
|
||||||
let endpoint = Endpoint {
|
let endpoint = Endpoint {
|
||||||
|
|||||||
@@ -771,9 +771,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
|
/// 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.
|
/// 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 logs = CapturedLogs::default();
|
||||||
let subscriber = tracing_subscriber::fmt()
|
let subscriber = tracing_subscriber::fmt()
|
||||||
.with_max_level(tracing::Level::WARN)
|
.with_max_level(tracing::Level::WARN)
|
||||||
@@ -781,7 +798,10 @@ mod tests {
|
|||||||
.with_ansi(false)
|
.with_ansi(false)
|
||||||
.without_time()
|
.without_time()
|
||||||
.finish();
|
.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)
|
(logs, guard)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -93,3 +93,6 @@ pub(crate) mod ecstore_validation_blackbox;
|
|||||||
|
|
||||||
#[cfg(test)]
|
#[cfg(test)]
|
||||||
pub(crate) mod test_metrics;
|
pub(crate) mod test_metrics;
|
||||||
|
|
||||||
|
#[cfg(test)]
|
||||||
|
pub(crate) mod test_tracing;
|
||||||
|
|||||||
@@ -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())
|
||||||
|
}
|
||||||
Reference in New Issue
Block a user