From 9cb351c323c307fac7334439e97770a4a0a9b1e0 Mon Sep 17 00:00:00 2001 From: Hayden Stainsby Date: Fri, 24 Oct 2025 15:46:31 +0200 Subject: [PATCH 1/3] TEMP (don't merge): add some usdt probes for testing Adding some [usdt] proboes to `tracing-subscriber` to try and debug an issue with filtering via the EnvFilter not working correctly. Probes have been added to the `FilterState` and `Filtered` structs. The application must call `tracing_subscriber::register_probes()` at some point before the interesting probes will be executed, otherwise they won't show up. [usdt]: https://docs.rs/usdt --- tracing-subscriber/Cargo.toml | 2 + .../src/filter/layer_filters/mod.rs | 159 ++++++++++++++---- tracing-subscriber/src/lib.rs | 20 +++ 3 files changed, 152 insertions(+), 29 deletions(-) diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index 8184e2117..391d9acf1 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -51,6 +51,8 @@ regex-automata = { optional = true, version = "0.4", default-features = false, f smallvec = { optional = true, version = "1.9.0" } once_cell = { optional = true, version = "1.13.0" } +usdt = "0.6" + # fmt tracing-log = { path = "../tracing-log", version = "0.2.0", optional = true, default-features = false, features = ["log-tracer", "std"] } nu-ansi-term = { version = "0.50.0", optional = true } diff --git a/tracing-subscriber/src/filter/layer_filters/mod.rs b/tracing-subscriber/src/filter/layer_filters/mod.rs index 238ec932d..b27bc1331 100644 --- a/tracing-subscriber/src/filter/layer_filters/mod.rs +++ b/tracing-subscriber/src/filter/layer_filters/mod.rs @@ -740,6 +740,19 @@ where fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { let interest = self.filter.callsite_enabled(metadata); + crate::usdt_provider::filtered__register__callsite!(|| { + ( + std::format!("{:?}", self.id()), + metadata as *const _ as u64, + std::string::String::from(metadata.target()), + std::format!( + "{}:{}", + metadata.file().unwrap_or(""), + metadata.line().unwrap_or(0) + ), + std::format!("{interest:?}"), + ) + }); // If the filter didn't disable the callsite, allow the inner layer to // register it — since `register_callsite` is also used for purposes @@ -765,37 +778,66 @@ where fn enabled(&self, metadata: &Metadata<'_>, cx: Context<'_, S>) -> bool { let cx = cx.with_filter(self.id()); - let enabled = self.filter.enabled(metadata, &cx); - FILTERING.with(|filtering| filtering.set(self.id(), enabled)); + let filter_enabled = self.filter.enabled(metadata, &cx); - if enabled { + let layer_enabled = if filter_enabled { // If the filter enabled this metadata, ask the wrapped layer if // _it_ wants it --- it might have a global filter. - self.layer.enabled(metadata, cx) + Some(self.layer.enabled(metadata, cx)) } else { - // Otherwise, return `true`. The _per-layer_ filter disabled this - // metadata, but returning `false` in `Layer::enabled` will - // short-circuit and globally disable the span or event. This is - // *not* what we want for per-layer filters, as other layers may - // still want this event. Returning `true` here means we'll continue - // asking the next layer in the stack. - // - // Once all per-layer filters have been evaluated, the `Registry` - // at the root of the stack will return `false` from its `enabled` - // method if *every* per-layer filter disabled this metadata. - // Otherwise, the individual per-layer filters will skip the next - // `new_span` or `on_event` call for their layer if *they* disabled - // the span or event, but it was not globally disabled. - true - } + None + }; + + crate::usdt_provider::filtered__enabled!(|| { + ( + std::format!("{:?}", self.id()), + metadata as *const _ as u64, + filter_enabled as u8, + layer_enabled.map(|b| b as i8).unwrap_or(-1), + ) + }); + FILTERING.with(|filtering| filtering.set(self.id(), filter_enabled)); + + // Otherwise, return `true`. The _per-layer_ filter disabled this + // metadata, but returning `false` in `Layer::enabled` will + // short-circuit and globally disable the span or event. This is + // *not* what we want for per-layer filters, as other layers may + // still want this event. Returning `true` here means we'll continue + // asking the next layer in the stack. + // + // Once all per-layer filters have been evaluated, the `Registry` + // at the root of the stack will return `false` from its `enabled` + // method if *every* per-layer filter disabled this metadata. + // Otherwise, the individual per-layer filters will skip the next + // `new_span` or `on_event` call for their layer if *they* disabled + // the span or event, but it was not globally disabled. + layer_enabled.unwrap_or(true) } fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, cx: Context<'_, S>) { + self.did_enable(|| { + crate::usdt_provider::filtered__on__new__span!(|| { + ( + std::format!("{:?}", self.id()), + attrs.metadata() as *const _ as u64, + id.into_u64(), + true as u8, + ) + }); let cx = cx.with_filter(self.id()); self.filter.on_new_span(attrs, id, cx.clone()); self.layer.on_new_span(attrs, id, cx); - }) + }); + + crate::usdt_provider::filtered__on__new__span!(|| { + ( + std::format!("{:?}", self.id()), + attrs.metadata() as *const _ as u64, + id.into_u64(), + false as u8, + ) + }); } #[doc(hidden)] @@ -820,42 +862,91 @@ where fn event_enabled(&self, event: &Event<'_>, cx: Context<'_, S>) -> bool { let cx = cx.with_filter(self.id()); - let enabled = FILTERING + let filter_enabled = FILTERING .with(|filtering| filtering.and(self.id(), || self.filter.event_enabled(event, &cx))); - if enabled { + + let layer_enabled = if filter_enabled { // If the filter enabled this event, ask the wrapped subscriber if // _it_ wants it --- it might have a global filter. - self.layer.event_enabled(event, cx) + Some(self.layer.event_enabled(event, cx)) } else { // Otherwise, return `true`. See the comment in `enabled` for why this // is necessary. - true - } + None + }; + crate::usdt_provider::filtered__on__event!(|| { + ( + std::format!("{:?}", self.id()), + event.metadata() as *const _ as u64, + filter_enabled as u8, + layer_enabled.map(|b| b as i8).unwrap_or(-1), + ) + }); + + layer_enabled.unwrap_or(true) } fn on_event(&self, event: &Event<'_>, cx: Context<'_, S>) { self.did_enable(|| { + crate::usdt_provider::filtered__on__event!(|| { + ( + std::format!("{:?}", self.id()), + event.metadata() as *const _ as u64, + true as u8, + ) + }); self.layer.on_event(event, cx.with_filter(self.id())); - }) + }); + crate::usdt_provider::filtered__on__event!(|| { + ( + std::format!("{:?}", self.id()), + event.metadata() as *const _ as u64, + false as u8, + ) + }); } fn on_enter(&self, id: &span::Id, cx: Context<'_, S>) { - if let Some(cx) = cx.if_enabled_for(id, self.id()) { + let maybe_cx = cx.if_enabled_for(id, self.id()); + crate::usdt_provider::filtered__on__enter!(|| { + ( + std::format!("{:?}", self.id()), + id.into_u64(), + maybe_cx.is_some() as u8, + ) + }); + if let Some(cx) = maybe_cx { self.filter.on_enter(id, cx.clone()); self.layer.on_enter(id, cx); } } fn on_exit(&self, id: &span::Id, cx: Context<'_, S>) { - if let Some(cx) = cx.if_enabled_for(id, self.id()) { + let maybe_cx = cx.if_enabled_for(id, self.id()); + crate::usdt_provider::filtered__on__exit!(|| { + ( + std::format!("{:?}", self.id()), + id.into_u64(), + maybe_cx.is_some() as u8, + ) + }); + if let Some(cx) = maybe_cx { self.filter.on_exit(id, cx.clone()); self.layer.on_exit(id, cx); } } fn on_close(&self, id: span::Id, cx: Context<'_, S>) { - if let Some(cx) = cx.if_enabled_for(&id, self.id()) { + let maybe_cx = cx.if_enabled_for(&id, self.id()); + crate::usdt_provider::filtered__on__exit!(|| { + ( + std::format!("{:?}", self.id()), + id.into_u64(), + maybe_cx.is_some() as u8, + ) + }); + if let Some(cx) = maybe_cx { self.filter.on_close(id.clone(), cx.clone()); self.layer.on_close(id, cx); } @@ -1120,10 +1211,12 @@ impl FilterState { ) } + crate::usdt_provider::filterstate__set!(|| (std::format!("{filter:?}"), enabled as u8)); self.enabled.set(self.enabled.get().set(filter, enabled)) } fn add_interest(&self, interest: Interest) { + crate::usdt_provider::filterstate__add__interest!(|| std::format!("{interest:?}")); let mut curr_interest = self.interest.borrow_mut(); #[cfg(debug_assertions)] @@ -1179,6 +1272,10 @@ impl FilterState { if map.is_enabled(filter) { // If the filter didn't disable the current span/event, run the // callback. + crate::usdt_provider::filterstate__did__enable!(|| ( + std::format!("{filter:?}"), + true as u8 + )); f(); } else { // Otherwise, if this filter _did_ disable the span or event @@ -1186,6 +1283,10 @@ impl FilterState { // `FilterState`. The bit has already been "consumed" by skipping // this callback, and we need to ensure that the `FilterMap` for // this thread is reset when the *next* `enabled` call occurs. + crate::usdt_provider::filterstate__did__enable!(|| ( + std::format!("{filter:?}"), + false as u8 + )); self.enabled.set(map.set(filter, true)); } #[cfg(debug_assertions)] diff --git a/tracing-subscriber/src/lib.rs b/tracing-subscriber/src/lib.rs index 619fd97b1..316630371 100644 --- a/tracing-subscriber/src/lib.rs +++ b/tracing-subscriber/src/lib.rs @@ -253,3 +253,23 @@ feature! { mod sealed { pub trait Sealed {} } + +pub use usdt::register_probes; + +#[usdt::provider(provider = "tracing_subscriber")] +mod usdt_provider { + fn filterstate__set(id: String, enabled: u8) {} + fn filterstate__did__enable(id: String, enabled: u8) {} + fn filterstate__add__interest(interest: String) {} + + fn filtered__register__callsite(id: String, callsite: u64, target: String, loc: String, filter_interest: String) {} + fn filtered__enabled(id: String, callsite: u64, filter_enabled: u8, layer_enabled: i8) {} + + fn filtered__event_enabled(id: String, callsite: u64, filter_enabled: u8, layer_enabled: i8) {} + fn filtered__on__event(id: String, callsite: u64, enabled: u8) {} + + fn filtered__on__new__span(id: String, callsite: u64, span_id: u64, enabled: u8) {} + fn filtered__on__enter(id: String, span_id: u64, enabled: u8) {} + fn filtered__on__exit(id: String, span_id: u64, enabled: u8) {} + fn filtered__on__close(id: String, span_id: u64, enabled: u8) {} +} From edb125e52c42b3f294aa353b6dd30845f70254ec Mon Sep 17 00:00:00 2001 From: Hayden Stainsby Date: Fri, 31 Oct 2025 16:07:00 +0100 Subject: [PATCH 2/3] changes from dingxiangfei2009/patch #2.diff https://gist.github.com/dingxiangfei2009/a8475a8e2c4ad05462b42fa219974fbe --- tracing-subscriber/src/filter/layer_filters/mod.rs | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/tracing-subscriber/src/filter/layer_filters/mod.rs b/tracing-subscriber/src/filter/layer_filters/mod.rs index b27bc1331..0bc9f8ebd 100644 --- a/tracing-subscriber/src/filter/layer_filters/mod.rs +++ b/tracing-subscriber/src/filter/layer_filters/mod.rs @@ -815,7 +815,6 @@ where } fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, cx: Context<'_, S>) { - self.did_enable(|| { crate::usdt_provider::filtered__on__new__span!(|| { ( @@ -865,7 +864,6 @@ where let filter_enabled = FILTERING .with(|filtering| filtering.and(self.id(), || self.filter.event_enabled(event, &cx))); - let layer_enabled = if filter_enabled { // If the filter enabled this event, ask the wrapped subscriber if // _it_ wants it --- it might have a global filter. @@ -875,7 +873,7 @@ where // is necessary. None }; - crate::usdt_provider::filtered__on__event!(|| { + crate::usdt_provider::filtered__event_enabled!(|| { ( std::format!("{:?}", self.id()), event.metadata() as *const _ as u64, @@ -1211,7 +1209,7 @@ impl FilterState { ) } - crate::usdt_provider::filterstate__set!(|| (std::format!("{filter:?}"), enabled as u8)); + crate::usdt_provider::filterstate__set!(|| (std::format!("{filter:?} set"), enabled as u8)); self.enabled.set(self.enabled.get().set(filter, enabled)) } @@ -1287,6 +1285,10 @@ impl FilterState { std::format!("{filter:?}"), false as u8 )); + crate::usdt_provider::filterstate__set!(|| ( + std::format!("{filter:?} did_ena"), + true as u8 + )); self.enabled.set(map.set(filter, true)); } #[cfg(debug_assertions)] @@ -1310,6 +1312,7 @@ impl FilterState { fn and(&self, filter: FilterId, f: impl FnOnce() -> bool) -> bool { let map = self.enabled.get(); let enabled = map.is_enabled(filter) && f(); + crate::usdt_provider::filterstate__set!(|| (std::format!("{filter:?} and"), enabled as u8)); self.enabled.set(map.set(filter, enabled)); enabled } From a43fae4044ffb27c8dc00448270bd997ba0b195b Mon Sep 17 00:00:00 2001 From: Hayden Stainsby Date: Fri, 31 Oct 2025 16:21:45 +0100 Subject: [PATCH 3/3] fix duplicate on-event probes --- tracing-subscriber/src/filter/layer_filters/mod.rs | 11 +++-------- 1 file changed, 3 insertions(+), 8 deletions(-) diff --git a/tracing-subscriber/src/filter/layer_filters/mod.rs b/tracing-subscriber/src/filter/layer_filters/mod.rs index 0bc9f8ebd..25aa4c454 100644 --- a/tracing-subscriber/src/filter/layer_filters/mod.rs +++ b/tracing-subscriber/src/filter/layer_filters/mod.rs @@ -886,21 +886,16 @@ where } fn on_event(&self, event: &Event<'_>, cx: Context<'_, S>) { + let mut enabled = false; self.did_enable(|| { - crate::usdt_provider::filtered__on__event!(|| { - ( - std::format!("{:?}", self.id()), - event.metadata() as *const _ as u64, - true as u8, - ) - }); + enabled = true; self.layer.on_event(event, cx.with_filter(self.id())); }); crate::usdt_provider::filtered__on__event!(|| { ( std::format!("{:?}", self.id()), event.metadata() as *const _ as u64, - false as u8, + enabled as u8, ) }); }