Line data Source code
1 : //! Assert that the current [`tracing::Span`] has a given set of fields.
2 : //!
3 : //! Can only produce meaningful positive results when tracing has been configured as in example.
4 : //! Absence of `tracing_error::ErrorLayer` is not detected yet.
5 : //!
6 : //! `#[cfg(test)]` code will get a pass when using the `check_fields_present` macro in case tracing
7 : //! is completly unconfigured.
8 : //!
9 : //! # Usage
10 : //!
11 : //! ```rust
12 : //! # fn main() {
13 : //! use tracing_subscriber::prelude::*;
14 : //! let registry = tracing_subscriber::registry()
15 : //! .with(tracing_error::ErrorLayer::default());
16 : //!
17 : //! // Register the registry as the global subscriber.
18 : //! // In this example, we'll only use it as a thread-local subscriber.
19 : //! let _guard = tracing::subscriber::set_default(registry);
20 : //!
21 : //! // Then, in the main code:
22 : //!
23 : //! let span = tracing::info_span!("TestSpan", test_id = 1);
24 : //! let _guard = span.enter();
25 : //!
26 : //! // ... down the call stack
27 : //!
28 : //! use utils::tracing_span_assert::{check_fields_present, MultiNameExtractor};
29 : //! let extractor = MultiNameExtractor::new("TestExtractor", ["test", "test_id"]);
30 : //! if let Err(missing) = check_fields_present!([&extractor]) {
31 : //! // if you copypaste this to a custom assert method, remember to add #[track_caller]
32 : //! // to get the "user" code location for the panic.
33 : //! panic!("Missing fields: {missing:?}");
34 : //! }
35 : //! # }
36 : //! ```
37 : //!
38 : //! Recommended reading: <https://docs.rs/tracing-subscriber/0.3.16/tracing_subscriber/layer/index.html#per-layer-filtering>
39 : //!
40 :
41 0 : #[derive(Debug)]
42 : pub enum ExtractionResult {
43 : Present,
44 : Absent,
45 : }
46 :
47 : pub trait Extractor: Send + Sync + std::fmt::Debug {
48 : fn name(&self) -> &str;
49 : fn extract(&self, fields: &tracing::field::FieldSet) -> ExtractionResult;
50 : }
51 :
52 0 : #[derive(Debug)]
53 : pub struct MultiNameExtractor<const L: usize> {
54 : name: &'static str,
55 : field_names: [&'static str; L],
56 : }
57 :
58 : impl<const L: usize> MultiNameExtractor<L> {
59 1147 : pub fn new(name: &'static str, field_names: [&'static str; L]) -> MultiNameExtractor<L> {
60 1147 : MultiNameExtractor { name, field_names }
61 1147 : }
62 : }
63 : impl<const L: usize> Extractor for MultiNameExtractor<L> {
64 0 : fn name(&self) -> &str {
65 0 : self.name
66 0 : }
67 70816 : fn extract(&self, fields: &tracing::field::FieldSet) -> ExtractionResult {
68 77411 : if fields.iter().any(|f| self.field_names.contains(&f.name())) {
69 37239 : ExtractionResult::Present
70 : } else {
71 33577 : ExtractionResult::Absent
72 : }
73 70816 : }
74 : }
75 :
76 : /// Checks that the given extractors are satisfied with the current span hierarchy.
77 : ///
78 : /// This should not be called directly, but used through [`check_fields_present`] which allows
79 : /// `Summary::Unconfigured` only when the calling crate is being `#[cfg(test)]` as a conservative default.
80 : #[doc(hidden)]
81 20122 : pub fn check_fields_present0<const L: usize>(
82 20122 : must_be_present: [&dyn Extractor; L],
83 20122 : ) -> Result<Summary, Vec<&dyn Extractor>> {
84 20122 : let mut missing = must_be_present.into_iter().collect::<Vec<_>>();
85 20122 : let trace = tracing_error::SpanTrace::capture();
86 37768 : trace.with_spans(|md, _formatted_fields| {
87 37768 : // when trying to understand the inner workings of how does the matching work, note that
88 37768 : // this closure might be called zero times if the span is disabled. normally it is called
89 37768 : // once per span hierarchy level.
90 70816 : missing.retain(|extractor| match extractor.extract(md.fields()) {
91 37239 : ExtractionResult::Present => false,
92 33577 : ExtractionResult::Absent => true,
93 70816 : });
94 37768 :
95 37768 : // continue walking up until we've found all missing
96 37768 : !missing.is_empty()
97 37768 : });
98 20122 : if missing.is_empty() {
99 20114 : Ok(Summary::FoundEverything)
100 8 : } else if !tracing_subscriber_configured() {
101 4 : Ok(Summary::Unconfigured)
102 : } else {
103 : // we can still hit here if a tracing subscriber has been configured but the ErrorLayer is
104 : // missing, which can be annoying. for this case, we could probably use
105 : // SpanTrace::status().
106 : //
107 : // another way to end up here is with RUST_LOG=pageserver=off while configuring the
108 : // logging, though I guess in that case the SpanTrace::status() == EMPTY would be valid.
109 : // this case is covered by test `not_found_if_tracing_error_subscriber_has_wrong_filter`.
110 4 : Err(missing)
111 : }
112 20122 : }
113 :
114 : /// Checks that the given extractors are satisfied with the current span hierarchy.
115 : ///
116 : /// The macro is the preferred way of checking if fields exist while passing checks if a test does
117 : /// not have tracing configured.
118 : ///
119 : /// Why mangled name? Because #[macro_export] will expose it at utils::__check_fields_present.
120 : /// However we can game a module namespaced macro for `use` purposes by re-exporting the
121 : /// #[macro_export] exported name with an alias (below).
122 : #[doc(hidden)]
123 : #[macro_export]
124 : macro_rules! __check_fields_present {
125 : ($extractors:expr) => {{
126 : {
127 : use $crate::tracing_span_assert::{check_fields_present0, Summary::*, Extractor};
128 :
129 : match check_fields_present0($extractors) {
130 : Ok(FoundEverything) => Ok(()),
131 : Ok(Unconfigured) if cfg!(test) => {
132 : // allow unconfigured in tests
133 : Ok(())
134 : },
135 : Ok(Unconfigured) => {
136 : panic!("utils::tracing_span_assert: outside of #[cfg(test)] expected tracing to be configured with tracing_error::ErrorLayer")
137 : },
138 : Err(missing) => Err(missing)
139 : }
140 : }
141 : }}
142 : }
143 :
144 : pub use crate::__check_fields_present as check_fields_present;
145 :
146 : /// Explanation for why the check was deemed ok.
147 : ///
148 : /// Mainly useful for testing, or configuring per-crate behaviour as in with
149 : /// [`check_fields_present`].
150 0 : #[derive(Debug)]
151 : pub enum Summary {
152 : /// All extractors were found.
153 : ///
154 : /// Should only happen when tracing is properly configured.
155 : FoundEverything,
156 :
157 : /// Tracing has not been configured at all. This is ok for tests running without tracing set
158 : /// up.
159 : Unconfigured,
160 : }
161 :
162 10 : fn tracing_subscriber_configured() -> bool {
163 10 : let mut noop_configured = false;
164 10 : tracing::dispatcher::get_default(|d| {
165 10 : // it is possible that this closure will not be invoked, but the current implementation
166 10 : // always invokes it
167 10 : noop_configured = d.is::<tracing::subscriber::NoSubscriber>();
168 10 : });
169 10 :
170 10 : !noop_configured
171 10 : }
172 :
173 : #[cfg(test)]
174 : mod tests {
175 :
176 : use tracing_subscriber::prelude::*;
177 :
178 : use super::*;
179 :
180 : use std::{
181 : collections::HashSet,
182 : fmt::{self},
183 : hash::{Hash, Hasher},
184 : };
185 :
186 : struct MemoryIdentity<'a>(&'a dyn Extractor);
187 :
188 : impl<'a> MemoryIdentity<'a> {
189 20 : fn as_ptr(&self) -> *const () {
190 20 : self.0 as *const _ as *const ()
191 20 : }
192 : }
193 : impl<'a> PartialEq for MemoryIdentity<'a> {
194 4 : fn eq(&self, other: &Self) -> bool {
195 4 : self.as_ptr() == other.as_ptr()
196 4 : }
197 : }
198 : impl<'a> Eq for MemoryIdentity<'a> {}
199 : impl<'a> Hash for MemoryIdentity<'a> {
200 12 : fn hash<H: Hasher>(&self, state: &mut H) {
201 12 : self.as_ptr().hash(state);
202 12 : }
203 : }
204 : impl<'a> fmt::Debug for MemoryIdentity<'a> {
205 0 : fn fmt(&self, f: &mut fmt::Formatter<'_>) -> std::fmt::Result {
206 0 : write!(f, "{:p}: {}", self.as_ptr(), self.0.name())
207 0 : }
208 : }
209 :
210 : struct Setup {
211 : _current_thread_subscriber_guard: tracing::subscriber::DefaultGuard,
212 : tenant_extractor: MultiNameExtractor<2>,
213 : timeline_extractor: MultiNameExtractor<2>,
214 : }
215 :
216 9 : fn setup_current_thread() -> Setup {
217 9 : let tenant_extractor = MultiNameExtractor::new("TenantId", ["tenant_id", "tenant"]);
218 9 : let timeline_extractor = MultiNameExtractor::new("TimelineId", ["timeline_id", "timeline"]);
219 9 :
220 9 : let registry = tracing_subscriber::registry()
221 9 : .with(tracing_subscriber::fmt::layer())
222 9 : .with(tracing_error::ErrorLayer::default());
223 9 :
224 9 : let guard = tracing::subscriber::set_default(registry);
225 9 :
226 9 : Setup {
227 9 : _current_thread_subscriber_guard: guard,
228 9 : tenant_extractor,
229 9 : timeline_extractor,
230 9 : }
231 9 : }
232 :
233 4 : fn assert_missing(missing: Vec<&dyn Extractor>, expected: Vec<&dyn Extractor>) {
234 4 : let missing: HashSet<MemoryIdentity> =
235 4 : HashSet::from_iter(missing.into_iter().map(MemoryIdentity));
236 4 : let expected: HashSet<MemoryIdentity> =
237 4 : HashSet::from_iter(expected.into_iter().map(MemoryIdentity));
238 4 : assert_eq!(missing, expected);
239 4 : }
240 :
241 1 : #[test]
242 1 : fn positive_one_level() {
243 1 : let setup = setup_current_thread();
244 1 : let span = tracing::info_span!("root", tenant_id = "tenant-1", timeline_id = "timeline-1");
245 1 : let _guard = span.enter();
246 1 : let res = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor]);
247 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
248 1 : }
249 :
250 1 : #[test]
251 1 : fn negative_one_level() {
252 1 : let setup = setup_current_thread();
253 1 : let span = tracing::info_span!("root", timeline_id = "timeline-1");
254 1 : let _guard = span.enter();
255 1 : let missing = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor])
256 1 : .unwrap_err();
257 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
258 1 : }
259 :
260 1 : #[test]
261 1 : fn positive_multiple_levels() {
262 1 : let setup = setup_current_thread();
263 :
264 1 : let span = tracing::info_span!("root");
265 1 : let _guard = span.enter();
266 :
267 1 : let span = tracing::info_span!("child", tenant_id = "tenant-1");
268 1 : let _guard = span.enter();
269 :
270 1 : let span = tracing::info_span!("grandchild", timeline_id = "timeline-1");
271 1 : let _guard = span.enter();
272 1 :
273 1 : let res = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor]);
274 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
275 1 : }
276 :
277 1 : #[test]
278 1 : fn negative_multiple_levels() {
279 1 : let setup = setup_current_thread();
280 :
281 1 : let span = tracing::info_span!("root");
282 1 : let _guard = span.enter();
283 :
284 1 : let span = tracing::info_span!("child", timeline_id = "timeline-1");
285 1 : let _guard = span.enter();
286 1 :
287 1 : let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err();
288 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
289 1 : }
290 :
291 1 : #[test]
292 1 : fn positive_subset_one_level() {
293 1 : let setup = setup_current_thread();
294 1 : let span = tracing::info_span!("root", tenant_id = "tenant-1", timeline_id = "timeline-1");
295 1 : let _guard = span.enter();
296 1 : let res = check_fields_present0([&setup.tenant_extractor]);
297 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
298 1 : }
299 :
300 1 : #[test]
301 1 : fn positive_subset_multiple_levels() {
302 1 : let setup = setup_current_thread();
303 :
304 1 : let span = tracing::info_span!("root");
305 1 : let _guard = span.enter();
306 :
307 1 : let span = tracing::info_span!("child", tenant_id = "tenant-1");
308 1 : let _guard = span.enter();
309 :
310 1 : let span = tracing::info_span!("grandchild", timeline_id = "timeline-1");
311 1 : let _guard = span.enter();
312 1 :
313 1 : let res = check_fields_present0([&setup.tenant_extractor]);
314 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
315 1 : }
316 :
317 1 : #[test]
318 1 : fn negative_subset_one_level() {
319 1 : let setup = setup_current_thread();
320 1 : let span = tracing::info_span!("root", timeline_id = "timeline-1");
321 1 : let _guard = span.enter();
322 1 : let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err();
323 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
324 1 : }
325 :
326 1 : #[test]
327 1 : fn negative_subset_multiple_levels() {
328 1 : let setup = setup_current_thread();
329 :
330 1 : let span = tracing::info_span!("root");
331 1 : let _guard = span.enter();
332 :
333 1 : let span = tracing::info_span!("child", timeline_id = "timeline-1");
334 1 : let _guard = span.enter();
335 1 :
336 1 : let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err();
337 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
338 1 : }
339 :
340 1 : #[test]
341 1 : fn tracing_error_subscriber_not_set_up_straight_line() {
342 : // no setup
343 1 : let span = tracing::info_span!("foo", e = "some value");
344 1 : let _guard = span.enter();
345 1 :
346 1 : let extractor = MultiNameExtractor::new("E", ["e"]);
347 1 : let res = check_fields_present0([&extractor]);
348 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
349 :
350 : // similarly for a not found key
351 1 : let extractor = MultiNameExtractor::new("F", ["foobar"]);
352 1 : let res = check_fields_present0([&extractor]);
353 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
354 1 : }
355 :
356 1 : #[test]
357 1 : fn tracing_error_subscriber_not_set_up_with_instrument() {
358 : // no setup
359 :
360 : // demo a case where span entering is used to establish a parent child connection, but
361 : // when we re-enter the subspan SpanTrace::with_spans iterates over nothing.
362 1 : let span = tracing::info_span!("foo", e = "some value");
363 1 : let _guard = span.enter();
364 :
365 1 : let subspan = tracing::info_span!("bar", f = "foobar");
366 1 : drop(_guard);
367 1 :
368 1 : // normally this would work, but without any tracing-subscriber configured, both
369 1 : // check_field_present find nothing
370 1 : let _guard = subspan.enter();
371 1 : let extractors: [&dyn Extractor; 2] = [
372 1 : &MultiNameExtractor::new("E", ["e"]),
373 1 : &MultiNameExtractor::new("F", ["f"]),
374 1 : ];
375 1 :
376 1 : let res = check_fields_present0(extractors);
377 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
378 :
379 : // similarly for a not found key
380 1 : let extractor = MultiNameExtractor::new("G", ["g"]);
381 1 : let res = check_fields_present0([&extractor]);
382 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
383 1 : }
384 :
385 1 : #[test]
386 1 : fn tracing_subscriber_configured() {
387 1 : // this will fail if any utils::logging::init callers appear, but let's hope they do not
388 1 : // appear.
389 1 : assert!(!super::tracing_subscriber_configured());
390 :
391 1 : let _g = setup_current_thread();
392 1 :
393 1 : assert!(super::tracing_subscriber_configured());
394 1 : }
395 :
396 1 : #[test]
397 1 : fn not_found_when_disabled_by_filter() {
398 1 : let r = tracing_subscriber::registry().with({
399 1 : tracing_error::ErrorLayer::default().with_filter(tracing_subscriber::filter::filter_fn(
400 42 : |md| !(md.is_span() && *md.level() == tracing::Level::INFO),
401 1 : ))
402 1 : });
403 1 :
404 1 : let _guard = tracing::subscriber::set_default(r);
405 :
406 : // this test is a rather tricky one, it has a number of possible outcomes depending on the
407 : // execution order when executed with other tests even if no test sets the global default
408 : // subscriber.
409 :
410 1 : let span = tracing::info_span!("foo", e = "some value");
411 1 : let _guard = span.enter();
412 1 :
413 1 : let extractors: [&dyn Extractor; 1] = [&MultiNameExtractor::new("E", ["e"])];
414 1 :
415 1 : if span.is_disabled() {
416 0 : // the tests are running single threaded, or we got lucky and no other tests subscriber
417 0 : // was got to register their per-CALLSITE::META interest between `set_default` and
418 0 : // creation of the span, thus the filter got to apply and registered interest of Never,
419 0 : // so the span was never created.
420 0 : //
421 0 : // as the span is disabled, no keys were recorded to it, leading check_fields_present0
422 0 : // to find an error.
423 0 :
424 0 : let missing = check_fields_present0(extractors).unwrap_err();
425 0 : assert_missing(missing, vec![extractors[0]]);
426 0 : } else {
427 : // when the span is enabled, it is because some other test is running at the same time,
428 : // and that tests registry has filters which are interested in our above span.
429 : //
430 : // because the span is now enabled, all keys will be found for it. the
431 : // tracing_error::SpanTrace does not consider layer filters during the span hierarchy
432 : // walk (SpanTrace::with_spans), nor is the SpanTrace::status a reliable indicator in
433 : // this test-induced issue.
434 :
435 1 : let res = check_fields_present0(extractors);
436 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
437 : }
438 1 : }
439 : }
|
