WIP: dynamic filters override static ones

[tfreiberg-fastly]

Motivation

See #1388.
Similar to how more specific static filters can disable things that more general filters would enable (e.g. foo=info,foo::bar=warn), it would be nice if dynamic filters could do something similar (although "more specific" is way harder to define here, but let's maybe try)

Solution

1. Always evaluate dynamic filters (not just when their max level is high enough to enable the metadata)
2. If none of the dynamic filters in scope (-> with matching span/fields, right?) enable the metadata, that means it was disabled

[tfreiberg-fastly]

The tests currently fail, and all those printlns in there are because the changed EnvFilter::enabled method is not actually called, and I have no idea why.

[hawkw]

The tests currently fail, and all those printlns in there are because the changed EnvFilter::enabled method is not actually called, and I have no idea why.

The reason EnvFilter::enabled would not be called is if register_callsite returns Interest::always or Interest::never for a span or event, indicating that enabled does not need to be called every time that span/event occurs. Currently, we always return a cacheable interest for all event callsites:

tracing/tracing-subscriber/src/filter/env/mod.rs

Lines 628 to 645 in fd8740f

	fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
	if self.has_dynamics && metadata.is_span() {
	// If this metadata describes a span, first, check if there is a
	// dynamic filter that should be constructed for it. If so, it
	// should always be enabled, since it influences filtering.
	if let Some(matcher) = self.dynamics.matcher(metadata) {
	let mut by_cs = try_lock!(self.by_cs.write(), else return self.base_interest());
	by_cs.insert(metadata.callsite(), matcher);
	return Interest::always();
	}
	}
	// Otherwise, check if any of our static filters enable this metadata.
	if self.statics.enabled(metadata) {
	Interest::always()
	} else {
	self.base_interest()
	}

You would need to change this behavior so that if an EnvFilter has dynamic filters, it will always return Interest::sometimes for any event whose level is below the highest level that any static or dynamic filter would ever enable --- since there's no way to determine statically if a given event might ever occur within a particular span. This, unfortunately, increases the overhead of using dynamic filters, but if we ensure that we still return cacheable interests when only static filters are in use, the performance impact would only occur with dynamic filters.

[tfreiberg-fastly]

ah! that makes a lot of sense, thanks for the help :)
yeah I'm not sure if this feature is a good idea, I'd leave that up to you. I wanted to explore it though :)

[tfreiberg-fastly]

Cool, it actually seems to work now (at least the tests do)

I tried using directives_for(metadata) here, but that doesn't seem to be possible:
cares_for compares the span name (my_span in the test) with the name of the event metadata (event tracing-subscriber/tests/env_filter/per_layer.rs:327 in the test), so it looks like we can't filter the dynamic directives at all here :/

I think it's still debatable whether this feature should exist and whether this is a good implementation.
This currently gives dynamic filters higher priority over static filters, which is not obviously wrong to me, but I definitely haven't thought through all the implications.
Also this should probably be documented somewhere.

[hawkw]

I tried using directives_for(metadata) here, but that doesn't seem to be possible:
cares_for compares the span name (my_span in the test) with the name of the event metadata (event tracing-subscriber/tests/env_filter/per_layer.rs:327 in the test), so it looks like we can't filter the dynamic directives at all here :/

I don't think we want to do that, a dynamic directive will effect any event within a span that matches the directive, so we can't filter the directives in that check. Instead, we just want to check if any dynamic directive would enable the event's level. So, what you've written is correct.

[tfreiberg-fastly]

yep, I think I kinda noticed that while I was trying to understand why it doesn't work 😅

[hawkw]

we can simplify this check; self.dynamics has a max_level field, so we can just check if the metadata's level is <= self.dynamics.max_level

[tfreiberg-fastly]

i don't think that does the same thing though?
we need to find at least one filter that would disable the metadata,
the max level being greater means that at least one filter can enable it, right?

[SomeoneToIgnore]

While the proposed simplifications is more appealing to me, I obeserve that both versions work for filters like

info,[{timeline=a6cfe8a1ca34765fd9a432d6193856b2}]=debug,[{timeline=a4273b74e519eb7f2d93b2c6245cd8ec}]=error

in my usecase.

[SomeoneToIgnore]

Hey @hawkw , @tfreiberg-fastly thank you for working on this feature, this is exactly what I've stumbled onto and would wish to have in the tracing-subscriber 0.3 version, if possible.

Can I help you somehow with the PR to make it happen?

[SomeoneToIgnore]

While the proposed simplifications is more appealing to me, I obeserve that both versions work for filters like

info,[{timeline=a6cfe8a1ca34765fd9a432d6193856b2}]=debug,[{timeline=a4273b74e519eb7f2d93b2c6245cd8ec}]=error

in my usecase.

[slinkydeveloper]

Hi all,
same here I would find this PR extremely helpful. Is there something I can do to help complete it?