diff --git a/libs/utils/src/tracing_span_assert.rs b/libs/utils/src/tracing_span_assert.rs index b9f7986442..02c3ea0361 100644 --- a/libs/utils/src/tracing_span_assert.rs +++ b/libs/utils/src/tracing_span_assert.rs @@ -1,8 +1,15 @@ //! Assert that the current [`tracing::Span`] has a given set of fields. //! +//! Can only produce meaningful positive results when tracing has been configured as in example. +//! Absence of `tracing_error::ErrorLayer` is not detected yet. +//! +//! `#[cfg(test)]` code will get a pass when using the `check_fields_present` macro in case tracing +//! is completly unconfigured. +//! //! # Usage //! -//! ``` +//! ```rust +//! # fn main() { //! use tracing_subscriber::prelude::*; //! let registry = tracing_subscriber::registry() //! .with(tracing_error::ErrorLayer::default()); @@ -20,23 +27,18 @@ //! //! use utils::tracing_span_assert::{check_fields_present, MultiNameExtractor}; //! let extractor = MultiNameExtractor::new("TestExtractor", ["test", "test_id"]); -//! match check_fields_present([&extractor]) { -//! Ok(()) => {}, -//! Err(missing) => { -//! panic!("Missing fields: {:?}", missing.into_iter().map(|f| f.name() ).collect::>()); -//! } +//! if let Err(missing) = check_fields_present!([&extractor]) { +//! // if you copypaste this to a custom assert method, remember to add #[track_caller] +//! // to get the "user" code location for the panic. +//! panic!("Missing fields: {missing:?}"); //! } +//! # } //! ``` //! //! Recommended reading: https://docs.rs/tracing-subscriber/0.3.16/tracing_subscriber/layer/index.html#per-layer-filtering //! -use std::{ - collections::HashSet, - fmt::{self}, - hash::{Hash, Hasher}, -}; - +#[derive(Debug)] pub enum ExtractionResult { Present, Absent, @@ -71,51 +73,105 @@ impl Extractor for MultiNameExtractor { } } -struct MemoryIdentity<'a>(&'a dyn Extractor); - -impl<'a> MemoryIdentity<'a> { - fn as_ptr(&self) -> *const () { - self.0 as *const _ as *const () - } -} -impl<'a> PartialEq for MemoryIdentity<'a> { - fn eq(&self, other: &Self) -> bool { - self.as_ptr() == other.as_ptr() - } -} -impl<'a> Eq for MemoryIdentity<'a> {} -impl<'a> Hash for MemoryIdentity<'a> { - fn hash(&self, state: &mut H) { - self.as_ptr().hash(state); - } -} -impl<'a> fmt::Debug for MemoryIdentity<'a> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> std::fmt::Result { - write!(f, "{:p}: {}", self.as_ptr(), self.0.name()) - } -} - -/// The extractor names passed as keys to [`new`]. -pub fn check_fields_present( +/// Checks that the given extractors are satisfied with the current span hierarchy. +/// +/// This should not be called directly, but used through [`check_fields_present`] which allows +/// `Summary::Unconfigured` only when the calling crate is being `#[cfg(test)]` as a conservative default. +#[doc(hidden)] +pub fn check_fields_present0( must_be_present: [&dyn Extractor; L], -) -> Result<(), Vec<&dyn Extractor>> { - let mut missing: HashSet = - HashSet::from_iter(must_be_present.into_iter().map(|r| MemoryIdentity(r))); +) -> Result> { + let mut missing = must_be_present.into_iter().collect::>(); let trace = tracing_error::SpanTrace::capture(); trace.with_spans(|md, _formatted_fields| { - missing.retain(|extractor| match extractor.0.extract(md.fields()) { + // when trying to understand the inner workings of how does the matching work, note that + // this closure might be called zero times if the span is disabled. normally it is called + // once per span hierarchy level. + missing.retain(|extractor| match extractor.extract(md.fields()) { ExtractionResult::Present => false, ExtractionResult::Absent => true, }); - !missing.is_empty() // continue walking up until we've found all missing + + // continue walking up until we've found all missing + !missing.is_empty() }); if missing.is_empty() { - Ok(()) + Ok(Summary::FoundEverything) + } else if !tracing_subscriber_configured() { + Ok(Summary::Unconfigured) } else { - Err(missing.into_iter().map(|mi| mi.0).collect()) + // we can still hit here if a tracing subscriber has been configured but the ErrorLayer is + // missing, which can be annoying. for this case, we could probably use + // SpanTrace::status(). + // + // another way to end up here is with RUST_LOG=pageserver=off while configuring the + // logging, though I guess in that case the SpanTrace::status() == EMPTY would be valid. + // this case is covered by test `not_found_if_tracing_error_subscriber_has_wrong_filter`. + Err(missing) } } +/// Checks that the given extractors are satisfied with the current span hierarchy. +/// +/// The macro is the preferred way of checking if fields exist while passing checks if a test does +/// not have tracing configured. +/// +/// Why mangled name? Because #[macro_export] will expose it at utils::__check_fields_present. +/// However we can game a module namespaced macro for `use` purposes by re-exporting the +/// #[macro_export] exported name with an alias (below). +#[doc(hidden)] +#[macro_export] +macro_rules! __check_fields_present { + ($extractors:expr) => {{ + { + use $crate::tracing_span_assert::{check_fields_present0, Summary::*, Extractor}; + + match check_fields_present0($extractors) { + Ok(FoundEverything) => Ok(()), + Ok(Unconfigured) if cfg!(test) => { + // allow unconfigured in tests + Ok(()) + }, + Ok(Unconfigured) => { + panic!("utils::tracing_span_assert: outside of #[cfg(test)] expected tracing to be configured with tracing_error::ErrorLayer") + }, + Err(missing) => Err(missing) + } + } + }} +} + +pub use crate::__check_fields_present as check_fields_present; + +/// Explanation for why the check was deemed ok. +/// +/// Mainly useful for testing, or configuring per-crate behaviour as in with +/// [`check_fields_present`]. +#[derive(Debug)] +pub enum Summary { + /// All extractors were found. + /// + /// Should only happen when tracing is properly configured. + FoundEverything, + + /// Tracing has not been configured at all. This is ok for tests running without tracing set + /// up. + Unconfigured, +} + +fn tracing_subscriber_configured() -> bool { + let mut noop_configured = false; + tracing::dispatcher::get_default(|d| { + // it is possible that this closure will not be invoked, but the current implementation + // always invokes it + noop_configured = d + .downcast_ref::() + .is_some(); + }); + + !noop_configured +} + #[cfg(test)] mod tests { @@ -123,6 +179,36 @@ mod tests { use super::*; + use std::{ + collections::HashSet, + fmt::{self}, + hash::{Hash, Hasher}, + }; + + struct MemoryIdentity<'a>(&'a dyn Extractor); + + impl<'a> MemoryIdentity<'a> { + fn as_ptr(&self) -> *const () { + self.0 as *const _ as *const () + } + } + impl<'a> PartialEq for MemoryIdentity<'a> { + fn eq(&self, other: &Self) -> bool { + self.as_ptr() == other.as_ptr() + } + } + impl<'a> Eq for MemoryIdentity<'a> {} + impl<'a> Hash for MemoryIdentity<'a> { + fn hash(&self, state: &mut H) { + self.as_ptr().hash(state); + } + } + impl<'a> fmt::Debug for MemoryIdentity<'a> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "{:p}: {}", self.as_ptr(), self.0.name()) + } + } + struct Setup { _current_thread_subscriber_guard: tracing::subscriber::DefaultGuard, tenant_extractor: MultiNameExtractor<2>, @@ -159,7 +245,8 @@ mod tests { let setup = setup_current_thread(); let span = tracing::info_span!("root", tenant_id = "tenant-1", timeline_id = "timeline-1"); let _guard = span.enter(); - check_fields_present([&setup.tenant_extractor, &setup.timeline_extractor]).unwrap(); + let res = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor]); + assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}"); } #[test] @@ -167,8 +254,8 @@ mod tests { let setup = setup_current_thread(); let span = tracing::info_span!("root", timeline_id = "timeline-1"); let _guard = span.enter(); - let missing = - check_fields_present([&setup.tenant_extractor, &setup.timeline_extractor]).unwrap_err(); + let missing = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor]) + .unwrap_err(); assert_missing(missing, vec![&setup.tenant_extractor]); } @@ -185,7 +272,8 @@ mod tests { let span = tracing::info_span!("grandchild", timeline_id = "timeline-1"); let _guard = span.enter(); - check_fields_present([&setup.tenant_extractor, &setup.timeline_extractor]).unwrap(); + let res = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor]); + assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}"); } #[test] @@ -198,7 +286,7 @@ mod tests { let span = tracing::info_span!("child", timeline_id = "timeline-1"); let _guard = span.enter(); - let missing = check_fields_present([&setup.tenant_extractor]).unwrap_err(); + let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err(); assert_missing(missing, vec![&setup.tenant_extractor]); } @@ -207,7 +295,8 @@ mod tests { let setup = setup_current_thread(); let span = tracing::info_span!("root", tenant_id = "tenant-1", timeline_id = "timeline-1"); let _guard = span.enter(); - check_fields_present([&setup.tenant_extractor]).unwrap(); + let res = check_fields_present0([&setup.tenant_extractor]); + assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}"); } #[test] @@ -223,7 +312,8 @@ mod tests { let span = tracing::info_span!("grandchild", timeline_id = "timeline-1"); let _guard = span.enter(); - check_fields_present([&setup.tenant_extractor]).unwrap(); + let res = check_fields_present0([&setup.tenant_extractor]); + assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}"); } #[test] @@ -231,7 +321,7 @@ mod tests { let setup = setup_current_thread(); let span = tracing::info_span!("root", timeline_id = "timeline-1"); let _guard = span.enter(); - let missing = check_fields_present([&setup.tenant_extractor]).unwrap_err(); + let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err(); assert_missing(missing, vec![&setup.tenant_extractor]); } @@ -245,43 +335,107 @@ mod tests { let span = tracing::info_span!("child", timeline_id = "timeline-1"); let _guard = span.enter(); - let missing = check_fields_present([&setup.tenant_extractor]).unwrap_err(); + let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err(); assert_missing(missing, vec![&setup.tenant_extractor]); } #[test] - fn tracing_error_subscriber_not_set_up() { + fn tracing_error_subscriber_not_set_up_straight_line() { // no setup - let span = tracing::info_span!("foo", e = "some value"); let _guard = span.enter(); let extractor = MultiNameExtractor::new("E", ["e"]); - let missing = check_fields_present([&extractor]).unwrap_err(); - assert_missing(missing, vec![&extractor]); + let res = check_fields_present0([&extractor]); + assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}"); + + // similarly for a not found key + let extractor = MultiNameExtractor::new("F", ["foobar"]); + let res = check_fields_present0([&extractor]); + assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}"); } #[test] - #[should_panic] - fn panics_if_tracing_error_subscriber_has_wrong_filter() { + fn tracing_error_subscriber_not_set_up_with_instrument() { + // no setup + + // demo a case where span entering is used to establish a parent child connection, but + // when we re-enter the subspan SpanTrace::with_spans iterates over nothing. + let span = tracing::info_span!("foo", e = "some value"); + let _guard = span.enter(); + + let subspan = tracing::info_span!("bar", f = "foobar"); + drop(_guard); + + // normally this would work, but without any tracing-subscriber configured, both + // check_field_present find nothing + let _guard = subspan.enter(); + let extractors: [&dyn Extractor; 2] = [ + &MultiNameExtractor::new("E", ["e"]), + &MultiNameExtractor::new("F", ["f"]), + ]; + + let res = check_fields_present0(extractors); + assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}"); + + // similarly for a not found key + let extractor = MultiNameExtractor::new("G", ["g"]); + let res = check_fields_present0([&extractor]); + assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}"); + } + + #[test] + fn tracing_subscriber_configured() { + // this will fail if any utils::logging::init callers appear, but let's hope they do not + // appear. + assert!(!super::tracing_subscriber_configured()); + + let _g = setup_current_thread(); + + assert!(super::tracing_subscriber_configured()); + } + + #[test] + fn not_found_when_disabled_by_filter() { let r = tracing_subscriber::registry().with({ - tracing_error::ErrorLayer::default().with_filter( - tracing_subscriber::filter::dynamic_filter_fn(|md, _| { - if md.is_span() && *md.level() == tracing::Level::INFO { - return false; - } - true - }), - ) + tracing_error::ErrorLayer::default().with_filter(tracing_subscriber::filter::filter_fn( + |md| !(md.is_span() && *md.level() == tracing::Level::INFO), + )) }); let _guard = tracing::subscriber::set_default(r); + // this test is a rather tricky one, it has a number of possible outcomes depending on the + // execution order when executed with other tests even if no test sets the global default + // subscriber. + let span = tracing::info_span!("foo", e = "some value"); let _guard = span.enter(); - let extractor = MultiNameExtractor::new("E", ["e"]); - let missing = check_fields_present([&extractor]).unwrap_err(); - assert_missing(missing, vec![&extractor]); + let extractors: [&dyn Extractor; 1] = [&MultiNameExtractor::new("E", ["e"])]; + + if span.is_disabled() { + // the tests are running single threaded, or we got lucky and no other tests subscriber + // was got to register their per-CALLSITE::META interest between `set_default` and + // creation of the span, thus the filter got to apply and registered interest of Never, + // so the span was never created. + // + // as the span is disabled, no keys were recorded to it, leading check_fields_present0 + // to find an error. + + let missing = check_fields_present0(extractors).unwrap_err(); + assert_missing(missing, vec![extractors[0]]); + } else { + // when the span is enabled, it is because some other test is running at the same time, + // and that tests registry has filters which are interested in our above span. + // + // because the span is now enabled, all keys will be found for it. the + // tracing_error::SpanTrace does not consider layer filters during the span hierarchy + // walk (SpanTrace::with_spans), nor is the SpanTrace::status a reliable indicator in + // this test-induced issue. + + let res = check_fields_present0(extractors); + assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}"); + } } } diff --git a/pageserver/src/tenant/span.rs b/pageserver/src/tenant/span.rs index a65ad6af47..04e92f4096 100644 --- a/pageserver/src/tenant/span.rs +++ b/pageserver/src/tenant/span.rs @@ -11,10 +11,7 @@ pub(crate) static TENANT_ID_EXTRACTOR: once_cell::sync::Lazy>() - ) + if let Err(missing) = check_fields_present!([&*TENANT_ID_EXTRACTOR]) { + panic!("missing extractors: {missing:?}") } } diff --git a/pageserver/src/tenant/timeline/span.rs b/pageserver/src/tenant/timeline/span.rs index 19a7fdb011..3b580c9d1b 100644 --- a/pageserver/src/tenant/timeline/span.rs +++ b/pageserver/src/tenant/timeline/span.rs @@ -14,10 +14,7 @@ pub(crate) fn debug_assert_current_span_has_tenant_and_timeline_id() { &*crate::tenant::span::TENANT_ID_EXTRACTOR, &*TIMELINE_ID_EXTRACTOR, ]; - if let Err(missing) = check_fields_present(fields) { - panic!( - "missing extractors: {:?}", - missing.into_iter().map(|e| e.name()).collect::>() - ) + if let Err(missing) = check_fields_present!(fields) { + panic!("missing extractors: {missing:?}") } }