Skip to content
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.

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

Filter leak when using WithSubscriber #902

Closed
jeromegn opened this issue Aug 8, 2020 · 4 comments
Closed

Filter leak when using WithSubscriber #902

jeromegn opened this issue Aug 8, 2020 · 4 comments
Labels
crate/core Related to the `tracing-core` crate kind/bug Something isn't working

Comments

@jeromegn
Copy link
Contributor

jeromegn commented Aug 8, 2020

Bug Report

Version

├── tracing v0.1.18 (*)
├── tracing-core v0.1.13 (*)
├── tracing-futures v0.2.4
│   └── tracing v0.1.18 (*)
├── tracing-log v0.1.1
│   └── tracing-core v0.1.13 (*)
├── tracing-subscriber v0.2.10
│   ├── tracing-core v0.1.13 (*)
│   ├── tracing-log v0.1.1 (*)
│   └── tracing-serde v0.1.1
│       └── tracing-core v0.1.13 (*)

Platform

Linux 5.7.12-arch1-1

Crates

tracing-subscriber (probably)

Description

When using the WithSubscriber trait, the filter appears to leak to the global subscriber. At least when not setting any filter.

I'm using a global subscriber with an EnvFilter. If I use something like:

my_future.with_subscriber(tracing_subscriber::Registry::default())

then once my future completes, my global subscriber has "changed" (I think) and no longer filter events or spans according to the original setting. In my use case I was setting the level to "info" and I started getting events and spans with traces up to the "trace" level.

@hawkw
Copy link
Member

hawkw commented Aug 8, 2020

I think I know what's up here. When a Dispatch is created, we call the callsite::register_dispatch function, which adds the Dispatch to the registry, and registers every callsite with it:

callsite::register_dispatch(&me);

This stores cached filter evaluations from all current subscribers in the per-callsite cache.

However, when a Dispatch is dropped, these cached filters remain in the callsite cache until the next time it is invalidated, either by creating a new Dispatch or by manually calling rebuild_interest_cache. This results in the dropped dispatcher's filters persisting.

I think we ought to change this so that whenever the last clone of a Dispatch is dropped, it re-invalidates the interest cache. I think the easiest way to do this might be changing the Arc<dyn Subscriber + Send + Sync> to a newtype of some kind, and having a Drop impl for that type that calls rebuild_interest_cache.

@hawkw hawkw added crate/core Related to the `tracing-core` crate kind/bug Something isn't working labels Aug 8, 2020
@hawkw
Copy link
Member

hawkw commented Aug 8, 2020

@jeromegn the fix I described above should be fairly straightforward to implement, if you're interested in getting another tracing-core commit under your belt. :) Otherwise, I'm happy to do it.

@jeromegn
Copy link
Contributor Author

jeromegn commented Aug 8, 2020

I can give it a shot! Will probably ask for help on Discord though :)

hawkw added a commit that referenced this issue Aug 13, 2020
…bers (#927)

## Motivation

Currently, when multiple subscribers are in use, the way that `Interest`
values are combined results in surprising behavior. 

If _any_ subscriber returns `Interest::always` for a callsite, that
interest currently takes priority over any other `Interest`s. This means
that if two threads have separate subscribers, one of which enables a
callsite `always`, and the other `never`, _both_ subscribers will always
record that callsite, without the option to disable it. This is not
quite right. Instead, we should check whether the current subscriber
will enable that callsite in this case.

This issue is described in #902. 

## Solution

This branch changes the rules for combining `Interest`s so that `always`
is only returned if _both_ `Interest`s are `always`. If only _one_ is
`always`, the combined interest is now `sometimes`, instead. This means
that when multiple subscribers exist, `enabled` will always be called on
the _current_ subscriber, except when _all_ subscribers have indicated
that they are `always` or `never` interested in a callsite.

I've added tests that reproduce the issues with leaky filters.

Fixing this revealed an additional issue where `tracing-subscriber`'s
`EnvFilter` assumes that `enabled` is only called for events, and never
for spans, because it always returns either `always` or `never` from
`register_callsite` for spans. Therefore, the dynamic span matching
directives that might enable a span were never checked in `enabled`.
However, under the new interest-combining rules, `enabled` *may* still
be called even if a subscriber returns an `always` or `never` interest,
if *another* subscriber exists that returned an incompatible interest.
This PR fixes that, as well.

Depends on #919 

This was previously approved by @yaahc as PR #920, but I 
accidentally merged it into #919 _after_ that branch merged, rather
than into master (my bad!).

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@jeromegn
Copy link
Contributor Author

Confirmed fixed by 2a5da8d

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
crate/core Related to the `tracing-core` crate kind/bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants