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