Impl filter for EnvFilter

[tfreiberg-fastly]

Fixes #1868
Follow-up on #1973

Motivation

Filtering by span and field requires using EnvFilter. Per-layer filtering requires the Filter trait.

Solution

Implement the Filter trait for EnvFilter

[tfreiberg-fastly]

I'm not sure about this implementation (especially if callsite_enabled should be implemented the same way as register_callsite), but I thought maybe this PR could save some work.
I tested it locally, and it doesn't seem to work properly - I guess the Interest needs to be different for Filter than for Layer...?

[hawkw]

I tested it locally, and it doesn't seem to work properly - I guess the Interest needs to be different for Filter than for Layer...?

Can you share the way you've been testing this?

[hawkw]

At a glance, this seems correct. I'd like to figure out why it's not working for you in your tests.

Ideally, can we add integration tests for EnvFilter's Filter implementation? We can probably do that by copying these tests: https://github.com/tokio-rs/tracing/blob/v0.1.x/tracing-subscriber/tests/filter.rs and modifying the subscriber to use a mock Layer wrapped in Filtered, rather than using a mock Subscriber. The layer filter tests show how the mock layers are used:

tracing/tracing-subscriber/tests/layer_filters/main.rs

Lines 16 to 38 in f701166

	let (trace_layer, trace_handle) = layer::named("trace")
	.event(event::mock().at_level(Level::TRACE))
	.event(event::mock().at_level(Level::DEBUG))
	.event(event::mock().at_level(Level::INFO))
	.done()
	.run_with_handle();
	let (debug_layer, debug_handle) = layer::named("debug")
	.event(event::mock().at_level(Level::DEBUG))
	.event(event::mock().at_level(Level::INFO))
	.done()
	.run_with_handle();
	let (info_layer, info_handle) = layer::named("info")
	.event(event::mock().at_level(Level::INFO))
	.done()
	.run_with_handle();
	let _subscriber = tracing_subscriber::registry()
	.with(trace_layer.with_filter(LevelFilter::TRACE))
	.with(debug_layer.with_filter(LevelFilter::DEBUG))
	.with(info_layer.with_filter(LevelFilter::INFO))
	.set_default();

[hawkw]

It took me a minute to realize that these are not actually recursive because the context isn't passed through. Looks correct.

[tfreiberg-fastly]

yeah, I think I'd also be on board with writing all the delegating calls like EnvFilter::method(self, ...) for consistency

[tfreiberg-fastly]

The test is here: https://github.com/tfreiberg-fastly/tracing-envfilter-bug/blob/main/src/main.rs

cargo run with per-layer filtering:

2022-03-10T22:01:34.603414Z TRACE span1{field1="val1"}: target1: should be logged
2022-03-10T22:01:34.603456Z TRACE target2: should be ignored (wrong target, no field)
2022-03-10T22:01:34.603479Z TRACE span2{field2="val1"}: target2: should be ignored (correct field, but wrong target)

cargo run with global filter:

2022-03-10T22:01:29.120669Z TRACE span1{field1="val1"}: target1: should be logged

[hawkw]

The test is here: https://github.com/tfreiberg-fastly/tracing-envfilter-bug/blob/main/src/main.rs

This link is 404

[tfreiberg-fastly]

Oops, created as private by accident - public now

[tfreiberg-fastly]

I ported the tests to use EnvFilter as a Filter, and had to change the mock configuration for span_name_filter_is_dynamic a bit. The changes are in the last commit.

I had to add .in_scope(..) to the MockEvents which wasn't in the original test. I'm honestly more confused that those aren't necessary in the original test tbh.

Also, I'm confused that the first two events in "uncool_span" aren't in both "uncool_span" and "cool_span", is that correct?
This means with line 349 (configuring the first event triggered after "uncool_span" is entered while "cool_span" hasn't been exited yet) like this, the test succeeds:

.in_scope(vec![span::mock().named("uncool_span")])`

but like that it fails:

.in_scope(vec![span::mock().named("uncool_span"), span::mock().named("cool_span")])

)

[hawkw]

I had to add .in_scope(..) to the MockEvents which wasn't in the original test. I'm honestly more confused that those aren't necessary in the original test tbh.

I think that's just be a difference in behavior between the mock Subscriber and the mock Layer. It looks like the mock Layer always asserts that an event is in the expected scope:

tracing/tracing-subscriber/tests/support.rs

Lines 234 to 265 in c6c8097

	let expected_scope = expected.scope_mut();
	let mut i = 0;
	for (expected, actual) in expected_scope.iter_mut().zip(&mut current_scope) {
	println!(
	"[{}] event_scope[{}] actual={} ({:?}); expected={}",
	self.name,
	i,
	actual.name(),
	actual.id(),
	expected
	);
	self.check_span_ref(
	expected,
	&actual,
	format_args!("the {}th span in the event's scope to be", i),
	);
	i += 1;
	}
	let remaining_expected = &expected_scope[i..];
	assert!(
	remaining_expected.is_empty(),
	"\n[{}] did not observe all expected spans in event scope!\n[{}] missing: {:#?}",
	self.name,
	self.name,
	remaining_expected,
	);
	assert!(
	current_scope.next().is_none(),
	"\n[{}] did not expect all spans in the actual event scope!",
	self.name,
	);
	}

on the other hand, the test Subscriber implementation doesn't make assertions about the event's expected scope, only the immediate parent span:

tracing/tracing/tests/support/event.rs

Lines 86 to 118 in 5287e7d

	pub fn check(
	&mut self,
	event: &tracing::Event<'_>,
	get_parent_name: impl FnOnce() -> Option<String>,
	subscriber_name: &str,
	) {
	let meta = event.metadata();
	let name = meta.name();
	self.metadata
	.check(meta, format_args!("event \"{}\"", name), subscriber_name);
	assert!(
	meta.is_event(),
	"[{}] expected {}, but got {:?}",
	subscriber_name,
	self,
	event
	);
	if let Some(ref mut expected_fields) = self.fields {
	let mut checker = expected_fields.checker(name, subscriber_name);
	event.record(&mut checker);
	checker.finish();
	}
	if let Some(ref expected_parent) = self.parent {
	let actual_parent = get_parent_name();
	expected_parent.check_parent_name(
	actual_parent.as_deref(),
	event.parent().cloned(),
	event.metadata().name(),
	subscriber_name,
	)
	}
	}

We may want to change this behavior, but I think that, ideally, we would have a way to differentiate between "asserting that there are NO spans in scope" and "not caring about what spans are in scope" --- I believe some of the other per-layer filtering tests actually depend on an empty in_scope asserting that there are no spans in scope.

[tfreiberg-fastly]

Alright, that makes sense. I totally agree with your ideas about the different kinds of assertions.

I've added another test that currently fails - it seems to fail differently than this one, I am a bit confused about the situation tbh.

Alright I read through the "cares about metadata" code and phew, I didn't know that spans aren't recorded if the span target doesn't match the directive. I think I saw a discussion about that in discord once... eh, I guess I'll sleep on it and look at the test with fresh eyes tomorrow :)

[hawkw]

Thanks for adding the failing tests, I'll take a closer look at the code and see if I can figure out what's up!

[hawkw]

I've added another test that currently fails - it seems to fail differently than this one, I am a bit confused about the situation tbh.

...oh, the test is wrong. The directive stuff[cool_span]=debug means "enable the DEBUG level if inside a span with the target stuff and the name cool_span", but the test seems to expect the behavior to be "enable the DEBUG level for events with the target stuff if inside a span named cool_span, where the span can have any target". I'm pretty sure we'd see the exact same behavior if we were using EnvFilter as a global filter.

[tfreiberg-fastly]

yeah, that seriously confused me 😬 thanks for the explanation!
after fixing that, I found a real unexpected failure in the test (which passes when using a global filter), and it was specific enough for me to find the issue - Filtered's on_exit called the inner filters on_enter... Yeah so that is fixed now

[Veetaha]

@tfreiberg-fastly, @hawkw

Just FYI, I don't think it really requires any action, just taking this into account would be fine.
This update has broken our code.

TLDR: it turns out adding a new trait impl in tracing-subscriber for the preexisting type that also implements other trait that contains the method of the same name is a breaking change because it introduces symbol ambiguity.

Our code lives in a private repo, so I can provide you with only a snippet:

This code compiled fine for us with tracing-subscriber 0.3.9, but it doesn't compile with tracing-subscriber 0.3.10

    use tracing::*;
    use tracing_subscriber::Layer;
    
    // A quirk of tracing-subscriber is that `EnvFilter` is itself a `Layer` impl which filters
    // events that match the env filter.  Unfortunately these act as global filters, not filters
    // specific to each layer, so we have to use this `with_filter` combinator instead
    struct EnvFilterAsLayerFilter(tracing_subscriber::EnvFilter);
    impl<S: tracing::Subscriber> tracing_subscriber::layer::Filter<S> for EnvFilterAsLayerFilter {
        fn enabled(
            &self,
            meta: &Metadata<'_>,
            cx: &tracing_subscriber::layer::Context<'_, S>,
        ) -> bool {
            self.0.enabled(meta, cx.clone())
        }
    }

    let console_layer = tracing_subscriber::fmt::Layer::new()
        .json()
        .with_writer(std::io::stderr)
        .with_filter(EnvFilterAsLayerFilter(console_filter));

The compile error is the following one:

error[E0034]: multiple applicable items in scope
    --> /home/vvv/.cargo/registry/src/{redacted}/cheburashka-4.3.0/src/logging/mod.rs:1511:20
     |
1511 |             self.0.enabled(meta, cx.clone())
     |                    ^^^^^^^ multiple `enabled` found
     |
     = note: candidate #1 is defined in an impl of the trait `__tracing_subscriber_Layer` for the type `tracing_subscriber::EnvFilter`
     = note: candidate #2 is defined in an impl of the trait `tracing_subscriber::layer::Filter` for the type `tracing_subscriber::EnvFilter`
note: candidate #3 is defined in the trait `tracing::Subscriber`
    --> /home/vvv/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.24/src/subscriber.rs:172:5
     |
172  |     fn enabled(&self, metadata: &Metadata<'_>) -> bool;
     |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
help: disambiguate the associated function for candidate #1
     |
1511 |             __tracing_subscriber_Layer::enabled(&self.0, meta, cx.clone())
     |
help: disambiguate the associated function for candidate #2
     |
1511 |             tracing_subscriber::layer::Filter::enabled(&self.0, meta, cx.clone())
     |
help: disambiguate the associated function for candidate #3
     |
1511 |             tracing::Subscriber::enabled(self.0, meta, cx.clone())
     |

[tfreiberg-fastly]

Oh, sorry for that :/

In case you haven't already found that out: to keep using the same functionality with minimal changes, you can use both Layer::enabled as well as Filter::enabled - they use the exact same implementation.
(I'd use Filter::enabled because the suggested path looks nicer 🤷 )

Also, you don't have to use this wrapper anymore, .with_filter(console_filter) should work now.

Still, sorry to cause additional work.

[Veetaha]

Sure, I understand, that wasn't difficult to fix on our side, and the patch made the code cleaner anyway, thanks for the contribution though! =)

[hawkw]

@Veetaha hmm, the breaking change is certainly unfortunate, I hadn't considered that. Normally, we would consider yanking 0.3.10, publishing a new release with the accidentally breaking change removed, and saving this change for an 0.4. However, in this case, removing the Filter impl is also a breaking change, and removing it may break more code than the name collision does. So, I'm not totally sure what's best here. Sorry for the inconvenience, though!

[CAD97]

This falls under known allowed method resolution breakage.

(When the methods have the same content, it would be nice if they could actually be the same item, and not have a conflict...)

There is a way to manually prevent an ambiguity error, though: add an inherent impl.