tracing

tracing copied to clipboard

Motivation

See https://github.com/tokio-rs/tracing/issues/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

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 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: https://github.com/tokio-rs/tracing/blob/fd8740f3a5c512a40eb3e4afe2a312ffcb7f669d/tracing-subscriber/src/filter/env/mod.rs#L628-L645

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.

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 :)

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.

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.

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

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