Skip to content

subscriber: cap per-layer-filter callsite interest at sometimes#3572

Open
arturhoo wants to merge 1 commit into
tokio-rs:mainfrom
arturhoo:filter-state-reset-on-all-reject
Open

subscriber: cap per-layer-filter callsite interest at sometimes#3572
arturhoo wants to merge 1 commit into
tokio-rs:mainfrom
arturhoo:filter-state-reset-on-all-reject

Conversation

@arturhoo

@arturhoo arturhoo commented Jun 26, 2026

Copy link
Copy Markdown

Motivation

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. That side-channel assumes enabled() runs immediately before on_new_span/on_event for the same metadata. When a callsite caches Interest::always, the tracing macros skip enabled() entirely — so on_new_span reads whatever the previous enabled() 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! via tracing-log's LogTracer, which calls dispatch.enabled() with per-call dynamic metadata that bypasses callsite caching. Any crate that does this between two #[instrument]ed calls — sqlx's QueryLogger does after every query — leaves stale disabled bits in FilterState, and the next Interest::always span never reaches the OTel/fmt/etc. layer it was meant for.

Fixes: #2519
Refs: #3516, #2448, #2704

Solution

Registry::register_callsite now caps the per-layer-filter interest sum at Interest::sometimes. Callsites that every per-layer filter accepts get sometimes instead of always, so enabled() runs on every dispatch and FilterState is always fresh when did_enable reads it. Callsites any filter rejects are unaffected (never if all reject, sometimes if mixed — same as before).

Trade-off. This removes the Interest::always fast-path for callsites every per-layer filter accepts. Those callsites now pay one Filter::enabled() call per dispatch instead of zero — for the common filters (LevelFilter, Targets, EnvFilter with static directives) that's a level compare plus a target prefix match, plus one thread-local write in Filtered::enabled. Stacks without per-layer filters are entirely unaffected. The four *_interests_are_cached tests are updated to reflect the new invariant: rejected callsites still cache as never; 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 sometimes instead. 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 #3516LogTracer, the enabled!/event_enabled! macros, or any direct dispatch.enabled() that isn't followed by a dispatch. It does not fix the re-entrancy triggers (#2448, #2704), where a layer's on_event emits its own event and the inner pass's enabled() clobbers FilterState bits the outer pass hasn't consumed yet. That case has enabled() called fresh; the staleness is from nesting, not skipping, and fixing it needs FilterState to 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.rs reproduces #2519: two per-layer-filtered layers, a span both accept (cached always before this PR), then a bare dispatch.enabled() both reject, then a second span both accept. Before this PR the second span never reached either layer's on_new_span; with it, both spans do.

@arturhoo arturhoo requested review from a team, carllerche, davidbarsky, hawkw and yaahc as code owners June 26, 2026 21:49
@arturhoo arturhoo changed the base branch from master to main June 26, 2026 21:50
@arturhoo arturhoo requested a review from hds as a code owner June 26, 2026 21:50
@arturhoo arturhoo force-pushed the filter-state-reset-on-all-reject branch from 0841dc9 to ab86a91 Compare June 26, 2026 22:20
`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
@arturhoo arturhoo force-pushed the filter-state-reset-on-all-reject branch from ab86a91 to 0b1f4ca Compare June 26, 2026 22:31
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Querying "enabled" from the log crate makes tracing swallow the next event

1 participant