subscriber: cap per-layer-filter callsite interest at sometimes#3572
Open
arturhoo wants to merge 1 commit into
Open
subscriber: cap per-layer-filter callsite interest at sometimes#3572arturhoo wants to merge 1 commit into
sometimes#3572arturhoo wants to merge 1 commit into
Conversation
0841dc9 to
ab86a91
Compare
`Filtered<L, F>` carries each filter's per-call decision from `Layer::enabled` to `Layer::on_new_span`/`on_event` via the thread-local `FilterState` bitmap. When a callsite caches `Interest::always`, the macros skip `enabled()` entirely, so `on_new_span` reads whatever the previous `enabled()` call (for unrelated metadata, e.g. `LogTracer`'s `dispatch.enabled()` for a `log::log_enabled!` query) left there, and the span is silently dropped from every per-layer-filtered layer. Cap the per-layer-filter interest sum at `sometimes` in `Registry::register_callsite` so `enabled()` runs on every dispatch and `FilterState` is always fresh. Rejected callsites still cache as `never`. The four `*_interests_are_cached` tests are updated for the new invariant; a new `stale_filter_state` test reproduces the bug. This fixes the bare-`enabled()` trigger but not the re-entrancy triggers (tokio-rs#2448, tokio-rs#2704), which need `FilterState` to be a stack. Fixes: tokio-rs#2519 Refs: tokio-rs#3516, tokio-rs#2448, tokio-rs#2704
ab86a91 to
0b1f4ca
Compare
This file contains hidden or 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
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
Filtered<L, F>carries each filter's per-call decision fromLayer::enabledtoLayer::on_new_span/on_eventvia the thread-localFilterStatebitmap. That side-channel assumesenabled()runs immediately beforeon_new_span/on_eventfor the same metadata. When a callsite cachesInterest::always, thetracingmacros skipenabled()entirely — soon_new_spanreads whatever the previousenabled()call (for unrelated metadata) wrote, and the span is silently dropped from every per-layer-filtered layer.The common production trigger is
log::log_enabled!viatracing-log'sLogTracer, which callsdispatch.enabled()with per-call dynamic metadata that bypasses callsite caching. Any crate that does this between two#[instrument]ed calls — sqlx'sQueryLoggerdoes after every query — leaves stale disabled bits inFilterState, and the nextInterest::alwaysspan never reaches the OTel/fmt/etc. layer it was meant for.Fixes: #2519
Refs: #3516, #2448, #2704
Solution
Registry::register_callsitenow caps the per-layer-filter interest sum atInterest::sometimes. Callsites that every per-layer filter accepts getsometimesinstead ofalways, soenabled()runs on every dispatch andFilterStateis always fresh whendid_enablereads it. Callsites any filter rejects are unaffected (neverif all reject,sometimesif mixed — same as before).Trade-off. This removes the
Interest::alwaysfast-path for callsites every per-layer filter accepts. Those callsites now pay oneFilter::enabled()call per dispatch instead of zero — for the common filters (LevelFilter,Targets,EnvFilterwith static directives) that's a level compare plus a target prefix match, plus one thread-local write inFiltered::enabled. Stacks without per-layer filters are entirely unaffected. The four*_interests_are_cachedtests are updated to reflect the new invariant: rejected callsites still cache asnever; accepted callsites are re-evaluated per dispatch.Users are already paying a comparable cost via the "add a no-op layer" workaround (transact-rs/sqlx#3751), which makes rejected callsites
sometimesinstead. This PR is cheaper for the typical case where rejected callsites outnumber accepted ones, and it doesn't depend on a follow-up event being dispatched to reset the bits.Scope. This fixes the bare-
enabled()trigger of #3516 —LogTracer, theenabled!/event_enabled!macros, or any directdispatch.enabled()that isn't followed by a dispatch. It does not fix the re-entrancy triggers (#2448, #2704), where a layer'son_eventemits its own event and the inner pass'senabled()clobbersFilterStatebits the outer pass hasn't consumed yet. That case hasenabled()called fresh; the staleness is from nesting, not skipping, and fixing it needsFilterStateto be a stack (or the API rework #3516 discusses). This PR doesn't attempt that — it makes the existing mechanism sound for the non-re-entrant case at the cost of the fast-path, and leaves the deeper fix for #3516.Testing. New
tests/layer_filters/stale_filter_state.rsreproduces #2519: two per-layer-filtered layers, a span both accept (cachedalwaysbefore this PR), then a baredispatch.enabled()both reject, then a second span both accept. Before this PR the second span never reached either layer'son_new_span; with it, both spans do.