tracing: make the "log" feature honor log's max level
#870
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
In `tracing/macros.rs` `tracing_log!()` computes whether to log differently from the log crate. While the log crate checks for `lvl <= log::STATIC_MAX_LEVEL && lvl <= log::max_level()`, tracing instead checks for `lvl <= log::STATIC_MAX_LEVEL` and later the output of `logger.enabled()`. This causes differences in what is being logged including unexpected log output. Since most of our testing has been with `env_logger`, we missed this issue, since `env_logger` will also return `false` from its `enabled` method for any records below the max level. However, other loggers may not. Also, `enabled` is more expensive than checking the max level, so this should result in better filtering performance for `log` records emitted by tracing. Fixes #856 Signed-off-by: Eliza Weisman <eliza@buoyant.io>
davidbarsky
approved these changes
Jul 31, 2020
hawkw
added a commit
that referenced
this pull request
Jul 31, 2020
Fixed - Fixed a bug where `LevelFilter::OFF` (and thus also the `static_max_level_off` feature flag) would enable *all* traces, rather than *none* (#853) - **log**: Fixed `tracing` macros and `Span`s not checking `log::max_level` before emitting `log` records (#870) Changed - **macros**: Macros now check the global max level (`LevelFilter::current`) before the per-callsite cache when determining if a span or event is enabled. This significantly improves performance in some use cases (#853) - **macros**: Simplified the code generated by macro expansion significantly, which may improve compile times and/or `rustc` optimizatation of surrounding code (#869, #869) - **macros**: Macros now check the static max level before checking any runtime filtering, improving performance when a span or event is disabled by a `static_max_level_XXX` feature flag (#868) - `LevelFilter` is now a re-export of the `tracing_core::LevelFilter` type, it can now be used interchangably with the versions in `tracing-core` and `tracing-subscriber` (#853) - Significant performance improvements when comparing `LevelFilter`s and `Level`s (#853) - Updated the minimum `tracing-core` dependency to 0.1.12 (#853) Added - **macros**: Quoted string literals may now be used as field names, to allow fields whose names are not valid Rust identifiers (#790) - **docs**: Several documentation improvements (#850, #857, #841) - `LevelFilter::current()` function, which returns the highest level that any subscriber will enable (#853) - `Subscriber::max_level_hint` optional trait method, for setting the value returned by `LevelFilter::current()` (#853) Thanks to new contributors @cuviper, @ethanboxx, @ben0x539, @dignati, @colelawrence, and @rbtcollins for helping out with this release! Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw
added a commit
that referenced
this pull request
Jul 31, 2020
### Fixed - Fixed a bug where `LevelFilter::OFF` (and thus also the `static_max_level_off` feature flag) would enable *all* traces, rather than *none* (#853) - **log**: Fixed `tracing` macros and `Span`s not checking `log::max_level` before emitting `log` records (#870) ### Changed - **macros**: Macros now check the global max level (`LevelFilter::current`) before the per-callsite cache when determining if a span or event is enabled. This significantly improves performance in some use cases (#853) - **macros**: Simplified the code generated by macro expansion significantly, which may improve compile times and/or `rustc` optimizatation of surrounding code (#869, #869) - **macros**: Macros now check the static max level before checking any runtime filtering, improving performance when a span or event is disabled by a `static_max_level_XXX` feature flag (#868) - `LevelFilter` is now a re-export of the `tracing_core::LevelFilter` type, it can now be used interchangably with the versions in `tracing-core` and `tracing-subscriber` (#853) - Significant performance improvements when comparing `LevelFilter`s and `Level`s (#853) - Updated the minimum `tracing-core` dependency to 0.1.12 (#853) ### Added - **macros**: Quoted string literals may now be used as field names, to allow fields whose names are not valid Rust identifiers (#790) - **docs**: Several documentation improvements (#850, #857, #841) - `LevelFilter::current()` function, which returns the highest level that any subscriber will enable (#853) - `Subscriber::max_level_hint` optional trait method, for setting the value returned by `LevelFilter::current()` (#853) Thanks to new contributors @cuviper, @ethanboxx, @ben0x539, @dignati, @colelawrence, and @rbtcollins for helping out with this release! Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Motivation
In
tracing/macros.rstracing_log!()computes whether to logdifferently from the log crate.
While the log crate checks for
lvl <= log::STATIC_MAX_LEVEL && lvl <= log::max_level(), tracing instead checks forlvl <= log::STATIC_MAX_LEVELand later the output oflogger.enabled(). Thiscauses differences in what is being logged including unexpected log
output.
Since most of our testing has been with
env_logger, we missed thisissue, since
env_loggerwill also returnfalsefrom itsenabledmethod for any records below the max level. However, other loggers may
not. Also,
enabledis more expensive than checking the max level, sothis should result in better filtering performance for
logrecordsemitted by tracing.
Solution
This commit...fixes that.
Fixes #856
Signed-off-by: Eliza Weisman eliza@buoyant.io