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 131391 : fn extract(&self, fields: &tracing::field::FieldSet) -> ExtractionResult {
67 248750 : if fields.iter().any(|f| f.name() == self.field_name) {
68 120879 : ExtractionResult::Present
69 : } else {
70 10512 : ExtractionResult::Absent
71 : }
72 131391 : }
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 40789 : pub fn check_fields_present0<const L: usize>(
81 40789 : must_be_present: [&dyn Extractor; L],
82 40789 : ) -> Result<Summary, Vec<&dyn Extractor>> {
83 40789 : let mut missing = must_be_present.into_iter().collect::<Vec<_>>();
84 40789 : let trace = tracing_error::SpanTrace::capture();
85 44820 : trace.with_spans(|md, _formatted_fields| {
86 44820 : // when trying to understand the inner workings of how does the matching work, note that
87 44820 : // this closure might be called zero times if the span is disabled. normally it is called
88 44820 : // once per span hierarchy level.
89 131391 : missing.retain(|extractor| match extractor.extract(md.fields()) {
90 120879 : ExtractionResult::Present => false,
91 10512 : ExtractionResult::Absent => true,
92 44820 : });
93 44820 :
94 44820 : // continue walking up until we've found all missing
95 44820 : !missing.is_empty()
96 44820 : });
97 40789 : if missing.is_empty() {
98 40780 : 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 13 : }
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 std::collections::HashSet;
176 : use std::fmt::{self};
177 : use std::hash::{Hash, Hasher};
178 :
179 : use tracing_subscriber::prelude::*;
180 :
181 : use super::*;
182 :
183 : struct MemoryIdentity<'a>(&'a dyn Extractor);
184 :
185 : impl MemoryIdentity<'_> {
186 25 : fn as_ptr(&self) -> *const () {
187 25 : self.0 as *const _ as *const ()
188 25 : }
189 : }
190 : impl PartialEq for MemoryIdentity<'_> {
191 5 : fn eq(&self, other: &Self) -> bool {
192 5 : self.as_ptr() == other.as_ptr()
193 5 : }
194 : }
195 : impl Eq for MemoryIdentity<'_> {}
196 : impl Hash for MemoryIdentity<'_> {
197 15 : fn hash<H: Hasher>(&self, state: &mut H) {
198 15 : self.as_ptr().hash(state);
199 15 : }
200 : }
201 : impl fmt::Debug for MemoryIdentity<'_> {
202 0 : fn fmt(&self, f: &mut fmt::Formatter<'_>) -> std::fmt::Result {
203 0 : write!(f, "{:p}: {}", self.as_ptr(), self.0.id())
204 0 : }
205 : }
206 :
207 : struct Setup {
208 : _current_thread_subscriber_guard: tracing::subscriber::DefaultGuard,
209 : tenant_extractor: ConstExtractor,
210 : timeline_extractor: ConstExtractor,
211 : }
212 :
213 9 : fn setup_current_thread() -> Setup {
214 9 : let tenant_extractor = ConstExtractor::new("tenant_id");
215 9 : let timeline_extractor = ConstExtractor::new("timeline_id");
216 9 :
217 9 : let registry = tracing_subscriber::registry()
218 9 : .with(tracing_subscriber::fmt::layer())
219 9 : .with(tracing_error::ErrorLayer::default());
220 9 :
221 9 : let guard = tracing::subscriber::set_default(registry);
222 9 :
223 9 : Setup {
224 9 : _current_thread_subscriber_guard: guard,
225 9 : tenant_extractor,
226 9 : timeline_extractor,
227 9 : }
228 9 : }
229 :
230 5 : fn assert_missing(missing: Vec<&dyn Extractor>, expected: Vec<&dyn Extractor>) {
231 5 : let missing: HashSet<MemoryIdentity> =
232 5 : HashSet::from_iter(missing.into_iter().map(MemoryIdentity));
233 5 : let expected: HashSet<MemoryIdentity> =
234 5 : HashSet::from_iter(expected.into_iter().map(MemoryIdentity));
235 5 : assert_eq!(missing, expected);
236 5 : }
237 :
238 : #[test]
239 1 : fn positive_one_level() {
240 1 : let setup = setup_current_thread();
241 1 : let span = tracing::info_span!("root", tenant_id = "tenant-1", timeline_id = "timeline-1");
242 1 : let _guard = span.enter();
243 1 : let res = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor]);
244 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
245 1 : }
246 :
247 : #[test]
248 1 : fn negative_one_level() {
249 1 : let setup = setup_current_thread();
250 1 : let span = tracing::info_span!("root", timeline_id = "timeline-1");
251 1 : let _guard = span.enter();
252 1 : let missing = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor])
253 1 : .unwrap_err();
254 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
255 1 : }
256 :
257 : #[test]
258 1 : fn positive_multiple_levels() {
259 1 : let setup = setup_current_thread();
260 :
261 1 : let span = tracing::info_span!("root");
262 1 : let _guard = span.enter();
263 :
264 1 : let span = tracing::info_span!("child", tenant_id = "tenant-1");
265 1 : let _guard = span.enter();
266 :
267 1 : let span = tracing::info_span!("grandchild", timeline_id = "timeline-1");
268 1 : let _guard = span.enter();
269 1 :
270 1 : let res = check_fields_present0([&setup.tenant_extractor, &setup.timeline_extractor]);
271 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
272 1 : }
273 :
274 : #[test]
275 1 : fn negative_multiple_levels() {
276 1 : let setup = setup_current_thread();
277 :
278 1 : let span = tracing::info_span!("root");
279 1 : let _guard = span.enter();
280 :
281 1 : let span = tracing::info_span!("child", timeline_id = "timeline-1");
282 1 : let _guard = span.enter();
283 1 :
284 1 : let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err();
285 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
286 1 : }
287 :
288 : #[test]
289 1 : fn positive_subset_one_level() {
290 1 : let setup = setup_current_thread();
291 1 : let span = tracing::info_span!("root", tenant_id = "tenant-1", timeline_id = "timeline-1");
292 1 : let _guard = span.enter();
293 1 : let res = check_fields_present0([&setup.tenant_extractor]);
294 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
295 1 : }
296 :
297 : #[test]
298 1 : fn positive_subset_multiple_levels() {
299 1 : let setup = setup_current_thread();
300 :
301 1 : let span = tracing::info_span!("root");
302 1 : let _guard = span.enter();
303 :
304 1 : let span = tracing::info_span!("child", tenant_id = "tenant-1");
305 1 : let _guard = span.enter();
306 :
307 1 : let span = tracing::info_span!("grandchild", timeline_id = "timeline-1");
308 1 : let _guard = span.enter();
309 1 :
310 1 : let res = check_fields_present0([&setup.tenant_extractor]);
311 1 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
312 1 : }
313 :
314 : #[test]
315 1 : fn negative_subset_one_level() {
316 1 : let setup = setup_current_thread();
317 1 : let span = tracing::info_span!("root", timeline_id = "timeline-1");
318 1 : let _guard = span.enter();
319 1 : let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err();
320 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
321 1 : }
322 :
323 : #[test]
324 1 : fn negative_subset_multiple_levels() {
325 1 : let setup = setup_current_thread();
326 :
327 1 : let span = tracing::info_span!("root");
328 1 : let _guard = span.enter();
329 :
330 1 : let span = tracing::info_span!("child", timeline_id = "timeline-1");
331 1 : let _guard = span.enter();
332 1 :
333 1 : let missing = check_fields_present0([&setup.tenant_extractor]).unwrap_err();
334 1 : assert_missing(missing, vec![&setup.tenant_extractor]);
335 1 : }
336 :
337 : #[test]
338 1 : fn tracing_error_subscriber_not_set_up_straight_line() {
339 : // no setup
340 1 : let span = tracing::info_span!("foo", e = "some value");
341 1 : let _guard = span.enter();
342 1 :
343 1 : let extractor = ConstExtractor::new("e");
344 1 : let res = check_fields_present0([&extractor]);
345 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
346 :
347 : // similarly for a not found key
348 1 : let extractor = ConstExtractor::new("foobar");
349 1 : let res = check_fields_present0([&extractor]);
350 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
351 1 : }
352 :
353 : #[test]
354 1 : fn tracing_error_subscriber_not_set_up_with_instrument() {
355 : // no setup
356 :
357 : // demo a case where span entering is used to establish a parent child connection, but
358 : // when we re-enter the subspan SpanTrace::with_spans iterates over nothing.
359 1 : let span = tracing::info_span!("foo", e = "some value");
360 1 : let _guard = span.enter();
361 :
362 1 : let subspan = tracing::info_span!("bar", f = "foobar");
363 1 : drop(_guard);
364 1 :
365 1 : // normally this would work, but without any tracing-subscriber configured, both
366 1 : // check_field_present find nothing
367 1 : let _guard = subspan.enter();
368 1 : let extractors: [&dyn Extractor; 2] =
369 1 : [&ConstExtractor::new("e"), &ConstExtractor::new("f")];
370 1 :
371 1 : let res = check_fields_present0(extractors);
372 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
373 :
374 : // similarly for a not found key
375 1 : let extractor = ConstExtractor::new("g");
376 1 : let res = check_fields_present0([&extractor]);
377 1 : assert!(matches!(res, Ok(Summary::Unconfigured)), "{res:?}");
378 1 : }
379 :
380 : #[test]
381 1 : fn tracing_subscriber_configured() {
382 1 : // this will fail if any utils::logging::init callers appear, but let's hope they do not
383 1 : // appear.
384 1 : assert!(!super::tracing_subscriber_configured());
385 :
386 1 : let _g = setup_current_thread();
387 1 :
388 1 : assert!(super::tracing_subscriber_configured());
389 1 : }
390 :
391 : #[test]
392 1 : fn not_found_when_disabled_by_filter() {
393 1 : let r = tracing_subscriber::registry().with({
394 1 : tracing_error::ErrorLayer::default().with_filter(tracing_subscriber::filter::filter_fn(
395 1 : |md| !(md.is_span() && *md.level() == tracing::Level::INFO),
396 1 : ))
397 1 : });
398 1 :
399 1 : let _guard = tracing::subscriber::set_default(r);
400 :
401 : // this test is a rather tricky one, it has a number of possible outcomes depending on the
402 : // execution order when executed with other tests even if no test sets the global default
403 : // subscriber.
404 :
405 1 : let span = tracing::info_span!("foo", e = "some value");
406 1 : let _guard = span.enter();
407 1 :
408 1 : let extractors: [&dyn Extractor; 1] = [&ConstExtractor::new("e")];
409 1 :
410 1 : if span.is_disabled() {
411 1 : // the tests are running single threaded, or we got lucky and no other tests subscriber
412 1 : // was got to register their per-CALLSITE::META interest between `set_default` and
413 1 : // creation of the span, thus the filter got to apply and registered interest of Never,
414 1 : // so the span was never created.
415 1 : //
416 1 : // as the span is disabled, no keys were recorded to it, leading check_fields_present0
417 1 : // to find an error.
418 1 :
419 1 : let missing = check_fields_present0(extractors).unwrap_err();
420 1 : assert_missing(missing, vec![extractors[0]]);
421 1 : } else {
422 : // when the span is enabled, it is because some other test is running at the same time,
423 : // and that tests registry has filters which are interested in our above span.
424 : //
425 : // because the span is now enabled, all keys will be found for it. the
426 : // tracing_error::SpanTrace does not consider layer filters during the span hierarchy
427 : // walk (SpanTrace::with_spans), nor is the SpanTrace::status a reliable indicator in
428 : // this test-induced issue.
429 :
430 0 : let res = check_fields_present0(extractors);
431 0 : assert!(matches!(res, Ok(Summary::FoundEverything)), "{res:?}");
432 : }
433 1 : }
434 : }
|
