Skip to content

Clarify filter.not() w.r.t. event_enabled #2251

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
hawkw merged 5 commits into from
Jul 28, 2022
Merged

Clarify filter.not() w.r.t. event_enabled #2251

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
cdae874
Explain filter.not() w.r.t. event_enabled
CAD97 Jul 27, 2022
d7b1d4f
Tweak Filter::not wording further
CAD97 Jul 28, 2022
602d875
Apply nits
CAD97 Jul 28, 2022
193f25c
Merge branch 'master' into explain-filter-not
CAD97 Jul 28, 2022
cf3cacd
fix spelling of "pseudo"
hawkw Jul 28, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
55 changes: 50 additions & 5 deletions tracing-subscriber/src/filter/subscriber_filters/combinator.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -403,11 +403,56 @@ where
/// If the wrapped filter would enable a span or event, it will be disabled. If
/// it would disable a span or event, that span or event will be enabled.
///
/// This inverts the values returned by the [`enabled`] and [`callsite_enabled`]
/// methods on the wrapped filter; it does *not* invert [`event_enabled`], as
/// implementing that method is optional, and filters which do not implement
/// filtering on event field values will return `true` even for events that their
/// [`enabled`] method would disable.
/// The wrapped filter's [`callsite_enabled`] and [`enabled`] are inverted,
/// but [`event_enabled`] is ignored, as most filters always return `true`
/// from `event_enabled` and rely on `[callsite_]enabled` for filtering.
///
/// Essentially, where a normal filter is roughly
///
/// ```ignore (psuedo-code)
/// // for spans
/// match callsite_enabled() {
/// ALWAYS => on_span(),
/// SOMETIMES => if enabled() { on_span() },
/// NEVER => (),
/// }
/// // for events
/// match callsite_enabled() {
/// ALWAYS => on_event(),
/// SOMETIMES => if enabled() && event_enabled() { on_event() },
/// NEVER => (),
/// }
/// ```
///
/// an inverted filter is roughly
///
/// ```ignore (psuedo-code)
/// // for spans
/// match callsite_enabled() {
/// ALWAYS => (),
/// SOMETIMES => if !enabled() { on_span() },
/// NEVER => on_span(),
/// }
/// // for events
/// match callsite_enabled() {
/// ALWAYS => (),
/// SOMETIMES => if !enabled() { on_event() },
/// NEVER => on_event(),
/// }
/// ```
Copy link
Member

@hawkw hawkw Jul 27, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i'm not completely sure how i feel about the use of Rust-like pseudocode in the documentation; it seems like it could potentially create some confusion if people incorrectly interpret it actual code. do you think it would make sense to document this as a Markdown table or something, instead? i'm fine with this if it's really the best way to document this behavior, but i am mildly skeptical about it...

Copy link
Contributor Author

@CAD97 CAD97 Jul 28, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The thing which is easier explained with pseudocode is the short circuiting behavior. Also, just trying to reason about using a filter on top of a layer which reports global filtering is overloading my brain atm, so...

That said, here's an attempt at a table to communicate the same information plus a bit:

Normal

F::callsite_enabled F::enabled S::enabled F::event_enabled S::event_enabled lifecycle callbacks
ALWAYS ✗ ✗ ✗ ✗ ✓
NEVER ✗ ✗ ✗ ✗ ✗
SOMETIMES true ✓ ✗ ✗ ✓ (span)
SOMETIMES true ✓ true ✓ ✓ (event)
SOMETIMES true ✓ false ✗ ✗ (event)
SOMETIMES false ✗ ✗ ✗ ✗

Not

F::callsite_enabled F::enabled S::enabled F::event_enabled S::event_enabled lifecycle callbacks
ALWAYS ✗ ✗ ✗ ✗ ✗
NEVER ✗ ✗ ✗ ✗ ✓
SOMETIMES true ✗ ✗ ✗ ✗
SOMETIMES false ✓ ✗ ✗ ✓ (span)
SOMETIMES false ✓ ✗ ✓ ✓ (event)

Pure logical filter inverse without time travel

F::callsite_enabled F::enabled S::enabled F::event_enabled S::event_enabled lifecycle callbacks
ALWAYS ✗ ✗ ✗ ✗ ✗
NEVER ✗ ✗ ✗ ✗ ✓
SOMETIMES true ✗ ✗ ✗ ✗ (span)
SOMETIMES true ✓ true ✗ ✗ (event)
SOMETIMES true ✓ false ✓ ✓ (event)
SOMETIMES false ✓ ✗ ✗ ✓ (span)
SOMETIMES false ✓ ✗ ✓ ✓ (event)

I wish I could give a nice visual diff between the tables, but this'll have to do: diff Not to "logical":

 | `F::callsite_enabled` | `F::enabled` | `S::enabled` | `F::event_enabled` | `S::event_enabled` | lifecycle callbacks |
 | :-:                   | :-:          | :-:          | :-:                | :-:                | :-:                 |
 | `ALWAYS`              | ✗           | ✗           | ✗                 | ✗                 | ✗                  |
 | `NEVER`               | ✗           | ✗           | ✗                 | ✗                 | ✓                  |
-| `SOMETIMES`           | `true`       | ✗           | ✗                 | ✗                 | ✗                  |
+| `SOMETIMES`           | `true`       | ✗           | ✗                 | ✗                 | ✗ (span)           |
+| `SOMETIMES`           | `true`       | ✓           | `true`             | ✗                 | ✗ (event)          |
+| `SOMETIMES`           | `true`       | ✓           | `false`            | ✓                 | ✓ (event)          |
 | `SOMETIMES`           | `false`      | ✓           | ✗                 | ✗                 | ✓ (span)           |
 | `SOMETIMES`           | `false`      | ✓           | ✗                 | ✓                 | ✓ (event)          |

Copy link
Member

@hawkw hawkw Jul 28, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

hmm, yeah, that's...not great. i'm fine with the pseudocode instead, then.

Copy link
Contributor Author

@CAD97 CAD97 Jul 28, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(It's worth noting that the pseudocode doesn't contain the S::* information from the tables, so for a fair comparison drop those two columns. But yeah, communicating short circuiting in a table is hard.)

Copy link
Contributor Author

@CAD97 CAD97 Jul 28, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You mentioned thinking maybe we should've made event_enabled return Option<bool>; the "correct" behavior I think would've been for (a time machine and) enabled to also return Interest, then iff that returns a sometimes() calling span_enabled/event_enabled for a final determination.

So roughly

  • Cached once per callsite, callsite_enabled.
  • Each time span! is entered:
    • if callsite enabled always: Evaluate fields. Return active span.
    • if callsite enabled sometimes:
      • Check enabled.
      • if enabled always: Evaluate fields. Return active span.
      • if enabled sometimes:
        • Evaluate fields.
        • If span_enabled: Return active span.
    • Return disabled span.
  • Each time event! is entered:
    • if callsite enabled always: Evaluate fields. Emit event.
    • if callsite enabled sometimes:
      • Check enabled.
      • If enabled always: Evaluate fields. Emit event.
      • If enabled sometimes:
        • Evaluate fields.
        • If event_enabled: Emit event.

In terms of signatures,

  • Collect
    • register_callsite(&self, &Metadata) -> Interest
    • enabled(&self, &Metadata) -> Interest
    • span_enabled(&self, &Attributes) -> bool
    • event_enabled(&self, &Attributes) -> bool
  • Subscribe (but only local filtering)
    • register_callsite(&self, &Metadata) -> Interest
    • enabled(&self, &Metadata, &Context) -> Interest
    • span_enabled(&self, &Attributes, &Context) -> bool
    • event_enabled(&self, &Attributes, &Context) -> bool
  • Per-layer filtering is done by layering Subscribe in a tree fashion.

(I'd personally also say that the enabled functions not being called when !interest.is_sometimes() is purely an optimization and you are not allowed to rely on this being true. This isn't necessary, but it's imho easier to reason about for wrapping collectors/filters.)

(Yes, there's complexity in the system I'm not fully aware of that probably makes that too simple.)

///
/// A proper inversion would do `!(enabled() && event_enabled())` (or
/// equivalently `!enabled() || !event_enabled()`), but because of the
/// implicit `&&` relation between `enabled` and `event_enabled`, it is
/// difficult to short circuit and not call the wrapped `event_enabled`.
///
/// A combinator which remembers the result of `enabled` in order to call
/// `event_enabled` only when `enabled() == true` is possible, but requires
/// additional thread-local mutable state to support a very niche use case.
//
// Also, it'd mean the wrapped layer's `enabled()` always gets called and
// globally applied to events where it doesn't today, since we can't know
// what `event_enabled` will say until we have the event to call it with.
///
/// [`Filter`]: crate::subscribe::Filter
/// [`enabled`]: crate::subscribe::Filter::enabled
Expand Down
55 changes: 50 additions & 5 deletions tracing-subscriber/src/filter/subscriber_filters/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -299,11 +299,56 @@ pub trait FilterExt<S>: subscribe::Filter<S> {
/// Inverts `self`, returning a filter that enables spans and events only if
/// `self` would *not* enable them.
///
/// This inverts the values returned by the [`enabled`] and [`callsite_enabled`]
/// methods on the wrapped filter; it does *not* invert [`event_enabled`], as
/// implementing that method is optional, and filters which do not implement
/// filtering on event field values will return `true` even for events that their
/// [`enabled`] method would disable.
/// The wrapped filter's [`callsite_enabled`] and [`enabled`] are inverted,
/// but [`event_enabled`] is ignored, as most filters always return `true`
/// from `event_enabled` and rely on `[callsite_]enabled` for filtering.
///
/// Essentially, where a normal filter is roughly
///
/// ```ignore (psuedo-code)
/// // for spans
/// match callsite_enabled() {
/// ALWAYS => on_span(),
/// SOMETIMES => if enabled() { on_span() },
/// NEVER => (),
/// }
/// // for events
/// match callsite_enabled() {
/// ALWAYS => on_event(),
/// SOMETIMES => if enabled() && event_enabled() { on_event() },
/// NEVER => (),
/// }
/// ```
///
/// an inverted filter is roughly
///
/// ```ignore (psuedo-code)
/// // for spans
/// match callsite_enabled() {
/// ALWAYS => (),
/// SOMETIMES => if !enabled() { on_span() },
/// NEVER => on_span(),
/// }
/// // for events
/// match callsite_enabled() {
/// ALWAYS => (),
/// SOMETIMES => if !enabled() { on_event() },
/// NEVER => on_event(),
/// }
/// ```
///
/// A proper inversion would do `!(enabled() && event_enabled())` (or
/// equivalently `!enabled() || !event_enabled()`), but because of the
/// implicit `&&` relation between `enabled` and `event_enabled`, it is
/// difficult to short circuit and not call the wrapped `event_enabled`.
///
/// A combinator which remembers the result of `enabled` in order to call
/// `event_enabled` only when `enabled() == true` is possible, but requires
/// additional thread-local mutable state to support a very niche use case.
//
// Also, it'd mean the wrapped layer's `enabled()` always gets called and
// globally applied to events where it doesn't today, since we can't know
// what `event_enabled` will say until we have the event to call it with.
///
/// [`Filter`]: crate::subscribe::Filter
/// [`enabled`]: crate::subscribe::Filter::enabled
Expand Down