spanchecks: Support testing without tracing (#4682)

Tests cannot be ran without configuring tracing. Split from #4678.

Does not nag about the span checks when there is no subscriber
configured, because then the spans will have no links and nothing can be
checked. Sadly the `SpanTrace::status()` cannot be used for this.
`tracing` is always configured in regress testing (running with
`pageserver` binary), which should be enough.

Additionally cleans up the test code in span checks to be in the test
code. Fixes a `#[should_panic]` test which was flaky before these
changes, but the `#[should_panic]` hid the flakyness.

Rationale for need: Unit tests might not be testing only the public or
`feature="testing"` APIs which are only testable within `regress` tests
so not all spans might be configured.

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::<Vec<_>>());
-//!    }
+//! 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<const L: usize> Extractor for MultiNameExtractor<L> {
     }
 }
 
-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<H: Hasher>(&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<const L: usize>(
+/// 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<const L: usize>(
     must_be_present: [&dyn Extractor; L],
-) -> Result<(), Vec<&dyn Extractor>> {
-    let mut missing: HashSet<MemoryIdentity> =
-        HashSet::from_iter(must_be_present.into_iter().map(|r| MemoryIdentity(r)));
+) -> Result<Summary, Vec<&dyn Extractor>> {
+    let mut missing = must_be_present.into_iter().collect::<Vec<_>>();
     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::<tracing::subscriber::NoSubscriber>()
+            .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<H: Hasher>(&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:?}");
+        }
     }
 }

pageserver/src/tenant/span.rs

@@ -11,10 +11,7 @@ pub(crate) static TENANT_ID_EXTRACTOR: once_cell::sync::Lazy<MultiNameExtractor<
 #[cfg(debug_assertions)]
 #[track_caller]
 pub(crate) fn debug_assert_current_span_has_tenant_id() {
-    if let Err(missing) = check_fields_present([&*TENANT_ID_EXTRACTOR]) {
-        panic!(
-            "missing extractors: {:?}",
-            missing.into_iter().map(|e| e.name()).collect::<Vec<_>>()
-        )
+    if let Err(missing) = check_fields_present!([&*TENANT_ID_EXTRACTOR]) {
+        panic!("missing extractors: {missing:?}")
     }
 }

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::<Vec<_>>()
-        )
+    if let Err(missing) = check_fields_present!(fields) {
+        panic!("missing extractors: {missing:?}")
     }
 }