Make logging filters work again by moving EnvFilter into its own layer #147613
Conversation
`tracing` at the time of writing has a feature (?) in its Filter implementation, so that filters like EnvFilter are consulted for status of a span or event and whether it is marked as interesting for logging. Combining a Filter with another layer through the `with_filter` combinator produces a filtered layer that enables an event unless it is statically determined that the event is uninteresting. However, if the filter is dynamic, because of filtering on span names or field values as an example, events are **always** enabled. There is an `event_enabled` predicate on `EnvFilter` implementation but it falls back to default and, thus, the dynamic filters are **unused**. This patch re-enables span- and field-based filters.
rustbot
added
S-waiting-on-review
|
rustbot has assigned @jdonszelmann. Use |
dingxiangfei2009
changed the title
|
The job Click to see the possible cause of the failure (guessed by this bot) |
rustbot
removed
the
S-waiting-on-review
rustbot
added
the
S-waiting-on-review
|
this seems useful, @bors r+ rollup |
bors
added
S-waiting-on-bors
|
Cc @Stypox -- I hope this doesn't break the Miri profiling logic. |
Rollup of 7 pull requests Successful merges: - #144266 (Supress swapping lhs and rhs in equality suggestion in extern macro ) - #147471 (Assert that non-extended temporaries and `super let` bindings have scopes) - #147533 (Renumber return local after state transform) - #147566 (rewrite outlives placeholder constraints to outlives static when handling opaque types) - #147613 (Make logging filters work again by moving EnvFilter into its own layer) - #147615 (reduce calls to attr.span() in old doc attr parsing) - #147636 (miri subtree update) r? `@ghost` `@rustbot` modify labels: rollup
Rollup merge of #147613 - dingxiangfei2009:investigate-log, r=jdonszelmann Make logging filters work again by moving EnvFilter into its own layer `tracing` at the time of writing has a feature (?) in its Filter implementation, so that filters like EnvFilter are consulted for status of a span or event and whether it is marked as interesting for logging. Combining a Filter with another layer through the `with_filter` combinator produces a filtered layer that enables an event unless it is statically determined that the event is uninteresting. However, if the filter is dynamic, because of filtering on span names or field values as an example, events are **always** enabled by design. There is an `event_enabled` predicate on `EnvFilter` implementation but it falls back to default and, thus, the dynamic filters are **unused**. Previously, `RUSTC_LOG=[]` or `RUSTC_LOG=[garbage]` enables all events, even when spans do not match. This patch re-enables span- and field-based filters. With `RUSTC_LOG=[garbage]` one should expect no events are enabled again. This will help with development greatly because we can meaningfully filter internal logs again.
Rollup of 7 pull requests Successful merges: - rust-lang/rust#144266 (Supress swapping lhs and rhs in equality suggestion in extern macro ) - rust-lang/rust#147471 (Assert that non-extended temporaries and `super let` bindings have scopes) - rust-lang/rust#147533 (Renumber return local after state transform) - rust-lang/rust#147566 (rewrite outlives placeholder constraints to outlives static when handling opaque types) - rust-lang/rust#147613 (Make logging filters work again by moving EnvFilter into its own layer) - rust-lang/rust#147615 (reduce calls to attr.span() in old doc attr parsing) - rust-lang/rust#147636 (miri subtree update) r? `@ghost` `@rustbot` modify labels: rollup
|
@RalfJung I just tested the tracing logic and this PR indeed seems to break it:
|
|
Hey @Stypox. Thanks for looking into this. How shall I reproduce the profiling problem in MIRI? I would like to try on my end, too. |
| .without_time() | ||
| .event_format(BacktraceFormatter { backtrace_target }); | ||
| let subscriber = subscriber.with(fmt_layer); | ||
| let subscriber = subscriber.with(layer).with(fmt_layer).with(filter); |
There was a problem hiding this comment.
This applies the filter to all layers. I think that's what breaks Miri, which is adding its own layer that needs to have a different filter.
|
@Stypox thanks for taking a look!
So are you saying that it is impossible to have two layers such that the first layer is dynamically filtered, but the 2nd layer always receives all events? That would be pretty bad... |
See "From the rustc codebase" here: https://github.com/rust-lang/miri/blob/master/doc/tracing.md#from-the-rustc-codebase After editing bootstrap and running the command you should get a .json file with some data in it (at least a few MB). If it's an empty JSON array, then something is off. |
Sadly that is the case. Now I know better! It appears that a proper fix should happen in |
RUSTC_LOG worked fine until we shuffled around the layers for Miri tracing... we should fix that regression. rustc is bigger than Miri.
That's awesome, thanks :) |
It turns out that the `event_enabled` is not yet implemented on `EnvFilter`. It has created issues that dynamic filters are effectively ignored, when this filter is composed with another layer through `with_filter` combinator. Related to rust-lang/rust#147613 Signed-off-by: Xiangfei Ding <[email protected]>
8 participants
tracingat the time of writing has a feature (?) in its Filter implementation, so that filters like EnvFilter are consulted for status of a span or event and whether it is marked as interesting for logging. Combining a Filter with another layer through thewith_filtercombinator produces a filtered layer that enables an event unless it is statically determined that the event is uninteresting. However, if the filter is dynamic, because of filtering on span names or field values as an example, events are always enabled by design. There is anevent_enabledpredicate onEnvFilterimplementation but it falls back to default and, thus, the dynamic filters are unused.Previously,
RUSTC_LOG=[]orRUSTC_LOG=[garbage]enables all events, even when spans do not match.This patch re-enables span- and field-based filters. With
RUSTC_LOG=[garbage]one should expect no events are enabled again. This will help with development greatly because we can meaningfully filter internal logs again.