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 24 : pub const fn new(field_name: &'static str) -> ConstExtractor {
59 24 : ConstExtractor { field_name }
60 24 : }
61 : }
62 : impl Extractor for ConstExtractor {
63 0 : fn id(&self) -> &str {
64 0 : self.field_name
65 0 : }
66 25419 : fn extract(&self, fields: &tracing::field::FieldSet) -> ExtractionResult {
67 36056 : if fields.iter().any(|f| f.name() == self.field_name) {
68 13249 : ExtractionResult::Present
69 : } else {
70 12170 : ExtractionResult::Absent
71 : }
72 25419 : }
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 4831 : pub fn check_fields_present0<const L: usize>(
81 4831 : must_be_present: [&dyn Extractor; L],
82 4831 : ) -> Result<Summary, Vec<&dyn Extractor>> {
83 4831 : let mut missing = must_be_present.into_iter().collect::<Vec<_>>();
84 4831 : let trace = tracing_error::SpanTrace::capture();
85 9144 : trace.with_spans(|md, _formatted_fields| {
86 9144 : // when trying to understand the inner workings of how does the matching work, note that
87 9144 : // this closure might be called zero times if the span is disabled. normally it is called
88 9144 : // once per span hierarchy level.
89 25419 : missing.retain(|extractor| match extractor.extract(md.fields()) {
90 13249 : ExtractionResult::Present => false,
91 12170 : ExtractionResult::Absent => true,
92 25419 : });
93 9144 :
94 9144 : // continue walking up until we've found all missing
95 9144 : !missing.is_empty()
96 9144 : });
97 4831 : if missing.is_empty() {
98 4822 : Ok(Summary::FoundEverything)
99 9 : } else if !tracing_subscriber_configured() {
100 4 : 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 5 : Err(missing)
110 : }
111 4831 : }
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 11 : fn tracing_subscriber_configured() -> bool {
162 11 : let mut noop_configured = false;
163 11 : tracing::dispatcher::get_default(|d| {
164 11 : // it is possible that this closure will not be invoked, but the current implementation
165 11 : // always invokes it
166 11 : noop_configured = d.is::<tracing::subscriber::NoSubscriber>();
167 11 : });
168 11 :
169 11 : !noop_configured
170 11 : }
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 25 : fn as_ptr(&self) -> *const () {
189 25 : self.0 as *const _ as *const ()
190 25 : }
191 : }
192 : impl<'a> PartialEq for MemoryIdentity<'a> {
193 5 : fn eq(&self, other: &Self) -> bool {
194 5 : self.as_ptr() == other.as_ptr()
195 5 : }
196 : }
197 : impl<'a> Eq for MemoryIdentity<'a> {}
198 : impl<'a> Hash for MemoryIdentity<'a> {
199 15 : fn hash<H: Hasher>(&self, state: &mut H) {
200 15 : self.as_ptr().hash(state);
201 15 : }
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 9 : fn setup_current_thread() -> Setup {
216 9 : let tenant_extractor = ConstExtractor::new("tenant_id");
217 9 : let timeline_extractor = ConstExtractor::new("timeline_id");
218 9 :
219 9 : let registry = tracing_subscriber::registry()
220 9 : .with(tracing_subscriber::fmt::layer())
221 9 : .with(tracing_error::ErrorLayer::default());
222 9 :
223 9 : let guard = tracing::subscriber::set_default(registry);
224 9 :
225 9 : Setup {
226 9 : _current_thread_subscriber_guard: guard,
227 9 : tenant_extractor,
228 9 : timeline_extractor,
229 9 : }
230 9 : }
231 :
232 5 : fn assert_missing(missing: Vec<&dyn Extractor>, expected: Vec<&dyn Extractor>) {
233 5 : let missing: HashSet<MemoryIdentity> =
234 5 : HashSet::from_iter(missing.into_iter().map(MemoryIdentity));
235 5 : let expected: HashSet<MemoryIdentity> =
236 5 : HashSet::from_iter(expected.into_iter().map(MemoryIdentity));
237 5 : assert_eq!(missing, expected);
238 5 : }
239 :
240 : #[test]
241 1 : fn positive_one_level() {
242 1 : let setup = setup_current_thread();
243 1 : let span = tracing::info_span!("root", tenant_id = "tenant-1", timeline_id = "timeline-1");
244 1 : let _guard = span.enter();
245 1 : let res = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor]);
246 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
247 1 : }
248 :
249 : #[test]
250 1 : fn negative_one_level() {
251 1 : let setup = setup_current_thread();
252 1 : let span = tracing::info_span!("root", timeline_id = "timeline-1");
253 1 : let _guard = span.enter();
254 1 : let missing = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor])
255 1 : .unwrap_err();
256 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
257 1 : }
258 :
259 : #[test]
260 1 : fn positive_multiple_levels() {
261 1 : let setup = setup_current_thread();
262 :
263 1 : let span = tracing::info_span!("root");
264 1 : let _guard = span.enter();
265 :
266 1 : let span = tracing::info_span!("child", tenant_id = "tenant-1");
267 1 : let _guard = span.enter();
268 :
269 1 : let span = tracing::info_span!("grandchild", timeline_id = "timeline-1");
270 1 : let _guard = span.enter();
271 1 :
272 1 : let res = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor]);
273 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
274 1 : }
275 :
276 : #[test]
277 1 : fn negative_multiple_levels() {
278 1 : let setup = setup_current_thread();
279 :
280 1 : let span = tracing::info_span!("root");
281 1 : let _guard = span.enter();
282 :
283 1 : let span = tracing::info_span!("child", timeline_id = "timeline-1");
284 1 : let _guard = span.enter();
285 1 :
286 1 : let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err();
287 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
288 1 : }
289 :
290 : #[test]
291 1 : fn positive_subset_one_level() {
292 1 : let setup = setup_current_thread();
293 1 : let span = tracing::info_span!("root", tenant_id = "tenant-1", timeline_id = "timeline-1");
294 1 : let _guard = span.enter();
295 1 : let res = check_fields_present0([&setup.tenant_extractor]);
296 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
297 1 : }
298 :
299 : #[test]
300 1 : fn positive_subset_multiple_levels() {
301 1 : let setup = setup_current_thread();
302 :
303 1 : let span = tracing::info_span!("root");
304 1 : let _guard = span.enter();
305 :
306 1 : let span = tracing::info_span!("child", tenant_id = "tenant-1");
307 1 : let _guard = span.enter();
308 :
309 1 : let span = tracing::info_span!("grandchild", timeline_id = "timeline-1");
310 1 : let _guard = span.enter();
311 1 :
312 1 : let res = check_fields_present0([&setup.tenant_extractor]);
313 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
314 1 : }
315 :
316 : #[test]
317 1 : fn negative_subset_one_level() {
318 1 : let setup = setup_current_thread();
319 1 : let span = tracing::info_span!("root", timeline_id = "timeline-1");
320 1 : let _guard = span.enter();
321 1 : let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err();
322 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
323 1 : }
324 :
325 : #[test]
326 1 : fn negative_subset_multiple_levels() {
327 1 : let setup = setup_current_thread();
328 :
329 1 : let span = tracing::info_span!("root");
330 1 : let _guard = span.enter();
331 :
332 1 : let span = tracing::info_span!("child", timeline_id = "timeline-1");
333 1 : let _guard = span.enter();
334 1 :
335 1 : let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err();
336 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
337 1 : }
338 :
339 : #[test]
340 1 : fn tracing_error_subscriber_not_set_up_straight_line() {
341 : // no setup
342 1 : let span = tracing::info_span!("foo", e = "some value");
343 1 : let _guard = span.enter();
344 1 :
345 1 : let extractor = ConstExtractor::new("e");
346 1 : let res = check_fields_present0([&extractor]);
347 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
348 :
349 : // similarly for a not found key
350 1 : let extractor = ConstExtractor::new("foobar");
351 1 : let res = check_fields_present0([&extractor]);
352 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
353 1 : }
354 :
355 : #[test]
356 1 : 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 1 : let span = tracing::info_span!("foo", e = "some value");
362 1 : let _guard = span.enter();
363 :
364 1 : let subspan = tracing::info_span!("bar", f = "foobar");
365 1 : drop(_guard);
366 1 :
367 1 : // normally this would work, but without any tracing-subscriber configured, both
368 1 : // check_field_present find nothing
369 1 : let _guard = subspan.enter();
370 1 : let extractors: [&dyn Extractor; 2] =
371 1 : [&ConstExtractor::new("e"), &ConstExtractor::new("f")];
372 1 :
373 1 : let res = check_fields_present0(extractors);
374 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
375 :
376 : // similarly for a not found key
377 1 : let extractor = ConstExtractor::new("g");
378 1 : let res = check_fields_present0([&extractor]);
379 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
380 1 : }
381 :
382 : #[test]
383 1 : fn tracing_subscriber_configured() {
384 1 : // this will fail if any utils::logging::init callers appear, but let's hope they do not
385 1 : // appear.
386 1 : assert!(!super::tracing_subscriber_configured());
387 :
388 1 : let _g = setup_current_thread();
389 1 :
390 1 : assert!(super::tracing_subscriber_configured());
391 1 : }
392 :
393 : #[test]
394 1 : fn not_found_when_disabled_by_filter() {
395 1 : let r = tracing_subscriber::registry().with({
396 1 : tracing_error::ErrorLayer::default().with_filter(tracing_subscriber::filter::filter_fn(
397 1 : |md| !(md.is_span() && *md.level() == tracing::Level::INFO),
398 1 : ))
399 1 : });
400 1 :
401 1 : 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 1 : let span = tracing::info_span!("foo", e = "some value");
408 1 : let _guard = span.enter();
409 1 :
410 1 : let extractors: [&dyn Extractor; 1] = [&ConstExtractor::new("e")];
411 1 :
412 1 : if span.is_disabled() {
413 1 : // the tests are running single threaded, or we got lucky and no other tests subscriber
414 1 : // was got to register their per-CALLSITE::META interest between `set_default` and
415 1 : // creation of the span, thus the filter got to apply and registered interest of Never,
416 1 : // so the span was never created.
417 1 : //
418 1 : // as the span is disabled, no keys were recorded to it, leading check_fields_present0
419 1 : // to find an error.
420 1 :
421 1 : let missing = check_fields_present0(extractors).unwrap_err();
422 1 : assert_missing(missing, vec![extractors[0]]);
423 1 : } 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 1 : }
436 : }
|
