## Summary
Adds a new example (`per-layer-filter.rs`) demonstrating per-layer filtering
with `tracing-subscriber`, a common real-world pattern that isn't covered
by existing examples.
### What the example shows
- Using `Registry` with multiple `fmt::Layer`s, each with its own filter
- **stdout layer**: pretty-printed output at DEBUG level and above
- **file layer**: JSON-formatted output at WARN level and above using `filter::Targets`
- Printing the log file contents at the end to show that only WARN+ events were captured
### Motivation
Per-layer filtering is one of the most powerful features of `tracing-subscriber`,
but the existing examples only cover global `EnvFilter` usage. This pattern
(e.g., verbose console output for development + structured file logging for
production) comes up frequently in discussions and issues.
## Motivation
After spending quite a bit of time to figure out why we hit the assert
that a span is being closed after it has been closed, I felt like it might
be a good idea to just be a bit more explicit about this in the error
message.
## Solution
Changed the assert message to points to the documentation of
`EnteredSpan::enter` After the changes in #3463, the documentation
now suggests adding `EnteredSpan` and `Entered` to the
`clippy::await_holding_invalid_type` configuration to catch cases
where objects of these types are held over await points.
Co-authored-by: Hayden Stainsby <hds@caffeineconcepts.com>
## Motivation
Holding a span entered guard across `.await`
points can lead to incorrect behavior.
## Solution
Adds documentation recommending the `clippy::await_holding_invalid_type`
lint configuration to help users detect when `Entered`
or `EnteredSpan` guards are held across `.await`
points.
Fixes: #3408
The macro expands to a trialing if statement that is used as an implicit return value
for the function. That works, but for users who set `implicit_return = "deny"` then
this results in triggering clippy.
## Motivation
See https://github.com/rust-lang/rust-clippy/issues/16676
Minimum reproducible example:
**Cargo.toml:**
```
[package]
name = "clippy-implicit-return-instrument-repro"
edition = "2024"
[dependencies]
tracing = { version = "0.1.44", features = ["attributes"] }
[lints.clippy]
implicit_return = "deny"
```
**src/lib.rs:**
```rust
#[tracing::instrument]
pub async fn run() {
}
```
If you then run `cargo clippy` you get this result:
```
error: missing `return` statement
--> src/lib.rs:1:1
|
1 | #[tracing::instrument]
| ^^^^^^^^^^^^^^^^^^^^^^
|
= help: for further information visit https://rust-lang.github.io/rust-clippy/rust-1.94.0/index.html#implicit_return
= note: requested on the command line with `-D clippy::implicit-return`
= note: this error originates in the attribute macro `tracing::instrument` (in Nightly builds, run with -Z macro-backtrace for more info)
```
## Solution
`#[allow(clippy::implicit_return)]` on the trailing return so it doesn't trigger clippy.
## Motivation
`EnvFilter` maintains two `RwLock`-protected `HashMap`s (`by_id` and `by_cs`)
for tracking per-span field-level match state. These are only populated when
`has_dynamics` is `true` — i.e., when the filter includes span-name or
field-level directives like `my_crate[span_name]=debug`.
However, the span lifecycle callbacks (`on_new_span`, `on_enter`, `on_exit`,
`on_close`, `on_record`) unconditionally acquire the `by_id` read lock (or write
lock for `on_close`) on every invocation, even when `has_dynamics` is `false`
and the maps are guaranteed empty.
For the common case of pure `target=level` directives (e.g.
`RUST_LOG=info,hyper=warn`), these locks are acquired and released on every span
enter/exit/close/record with no effect.
## Problem
Under high concurrency this causes measurable lock contention. A GDB backtrace
captured from a Tokio-based HTTP server (80+ async workers, 3 `EnvFilter`
instances as per-layer filters) during a load test showed ~25 threads contending
on `RwLock::read` inside `EnvFilter::on_enter`, `on_exit`, and
`cares_about_span`, with threads blocked in `read_contended` by `on_close`'s
write lock:
``` #0 std::sys::sync::rwlock::futex::RwLock::read_contended #1 RwLock::read
(self=0x55e0c7694178) #2 RwLock<HashMap<SpanId, MatchSet<SpanMatch>>>::read #3
EnvFilter::on_enter at filter/env/mod.rs:585 ```
## Solution
Add an early `if !self.has_dynamics { return; }` guard to each of the five span
lifecycle methods. When dynamic directives are present, the existing code path
runs unchanged. When they're absent (the common case), the lock is never
touched.
## Motivation
On filesystems where `std::fs::Metadata::created`
is unsupported, `RollingFileAppender` falls back
to parsing the creation date from the log filename.
However, `PrimitiveDateTime::parse` fails with
`InsufficientInformation` for daily and weekly
rotations because the filename lacks time
components.
## Solution
Replace the direct `time::PrimitiveDateTime::parse`
call with a `time::parsing::Parsed`-based approach
that defaults missing hour to midnight (00:00:00),
allowing date-only filenames to be parsed
successfully.
Fixes: #3470
## Motivation
From the issue (#3270):
> It has always been a bit annoying to find the latest log file in a large
> directory instead of just jumping to a "latest log" symlink. And as @clia
> mentioned in #1979, it's also useful to be able to tail -F the symlink for
> peace of mind.
## Solution
I've added a `RollingFileAppender` builder method to create a symbolic link to
the latest log file. The method takes as input the desired name of the symlink,
and the link is updated whenever the appender rotates log files.
I've also written an integration test for this.
## Dependencies
This introduces a dependency on [`symlink`](https://crates.io/crates/symlink)
for cross-platform symbolic link management. `symlink` itself has zero
dependencies and hasn't changed in years. That being said, it's understandable
if you're hesitant to introduce a new dependency. The other most compelling
options are:
- Recreate the functionality of `symlink` within tracing-appender to avoid the
dep altogether
- Create a Cargo feature for this and make `symlink` an optional dependency
- If you'd like to go down this route, how far would you like to go?
`[cfg(...)]` gate all over the place?
Fixes: #3270
## Motivation
From the issue (#3270):
> It has always been a bit annoying to find the latest log file in a large
> directory instead of just jumping to a "latest log" symlink. And as @clia
> mentioned in #1979, it's also useful to be able to tail -F the symlink for
> peace of mind.
## Solution
I've added a `RollingFileAppender` builder method to create a symbolic link to
the latest log file. The method takes as input the desired name of the symlink,
and the link is updated whenever the appender rotates log files.
I've also written an integration test for this.
## Dependencies
This introduces a dependency on [`symlink`](https://crates.io/crates/symlink)
for cross-platform symbolic link management. `symlink` itself has zero
dependencies and hasn't changed in years. That being said, it's understandable
if you're hesitant to introduce a new dependency. The other most compelling
options are:
- Recreate the functionality of `symlink` within tracing-appender to avoid the
dep altogether
- Create a Cargo feature for this and make `symlink` an optional dependency
- If you'd like to go down this route, how far would you like to go?
`[cfg(...)]` gate all over the place?
Fixes: #3270
## Motivation
This was missing, so `on_register_dispatch` would not be callen when wrapping
a layer in `Option` or a `Vec`.
## Solution
Implements `on_register_dispatch` on both generic types.
## Motivation
The changes made in #3368 to sanitize ANSI control characters to avoid
terminal injection attacks also break colored output and other control
characters that users may legitimately wish to use. There is no mechanism
to disable this sanitization.
## Solution
Add `with_ansi_sanitization` method to allow turning off the sanitization
of ansi output. Sanitizing output remains the default behavior.
Fixes: #3369
## Motivation
This seems to be a result of the new `valueset!` optimisations combined
with this new `record_all!` feature. In fact, the `record_all!` feature never
worked with a set of fields differnt to all a span's fields in the correct order.
The following code panics
```rust
#[test]
fn tracing_bug() {
let span = tracing::info_span!("example", foo=1, bar=2);
tracing::record_all!(span, foo=3);
}
```
## Solution
This is horrible. We rename `valueset!` to `valueset_all!`, then
we re-introduce the original `valueset!` with some notable changes.
The new `valueset!` doesn't use fields from the fieldset iterator, it
instead uses `FieldSet::field(...)` to find the correct field. If the field
isn't found, we set a fallback field that will be ignored (callsites are
not equal).
Fixes#3431
## Motivation
The change merged in #3382 caused a breaking change when released. This
is because users of the tracing macros depend on being able to use a
bare `debug` or `display` function within the macro itself, for example:
```rust
tracing::info!(foo = debug(foo), bar = display(bar));
```
## Solution
This change reverts the breaking part of the original commit, which is
removing the import statement from the `valueset!` macro. However, it
leaves the change to use full module paths inside the macro. E.g.
`$crate::field::debug`. This is best practice, and so worth keeping.
This change also adds a nice warning comment above the import statement
to try and avoid another break happening in the future (because this
isn't the first time that this has happened). It also adds explicit
tests for the use of bare `debug` and `display` usage with the same end.
## Motivation
While investigating #3405, we found that some tests are not being run on
CI. Specifically the `tracing-subscriber` tests that depend on
non-default features.
## Solution
This change adds 2 new `run` commands to the `test-features-stable` CI
job, one with `nextest` and another for the doc tests.
There is also 1 more `run` command to run the `tracing-mock` tests with
all features (which is just `tracing-subscriber` right now, but safer to
set all).
## Motivation
In order to add a regression test, #3379 added support to `tracing-mock`
to expect calls to `on_register_dispatch` for both mock subscribers and
mock layers. A negative integration test for the layer case was included
in #3415. However, there are no negative doctests for this (and as per
my own suggestion, there's no negative test for the subscriber method
either as I wasn't sure it was possible).
## Solution
After a bit of thought, I realised that we could include a negative test
for the `MockSubscriber`. This change adds that test as a doctest, since
we have those in almost all of our documentation and also includes the
already written negative test for the `MockLayer` to a doctest.
## Motivation
The `Layered` implementation of `Subscriber` does not implement and propagate the `on_register_dispatch` callback. This means that combined layers will never have their `on_register_dispatch` methods called.
## Solution
Implement the missing `on_register_dispatch` method.
---------
Co-authored-by: Hayden Stainsby <hds@caffeineconcepts.com>
## Motivation
When `max_files` set to zero,
[rolling.rs:695](c01d4fd9de/tracing-appender/src/rolling.rs (L695))
will cause integer underflow and panicking in debug build. In my
opinion the API should prevent this from happening as "zero" is a
valid `usize` value to pass in.
## Solution
Currently, in release builds, if `max_files` is set to zero, it
behaves just like `u64::MAX` on `x86_64` platforms. Therefore, I
decided to simply make `zero == None`, which should align with the
existing behavior but without the panicking. I believe this can be
considered as "non-breaking".
I'd like to get notifications on these explicitly and I'm doing a lot of
the reviews and maintenance these days, so I think it makes sense.
Also removed Zeki (@zekisherif) as GitHub is telling me that the account
doesn't exist any more.
## Motivation
Continuous profiling on a production workload shows that `Span::enter` is
a significant percent of the samples.
This is currently using `tracing-subscriber = "0.3.19"`.
Concrete numbers:
- 7.7% of samples were found within the stacktrace of a `Span::enter`.
- Of those samples, 22.8% were inside `clone_span`.
- Collectively, that's 1.8% of total CPU time spent in `clone_span` as a result of
`Span::enter`.
## Solution
Remove `clone_span` from `enter`, remove `try_close` from `exit`.
This was originally included to protect against misuse of the `tracing-core` API.
However, there has not been so much use of this low level API as was originally
anticipated, and it is not worth the performance hit.
## Motivation
Using with_subscriber will trigger a panic if the async block creates
a span & enters it on a different thread that will target the default
subscriber. I believe both the with_subscriber AND the enter off-thread
scenario are idiomatic. The reason for the crash is that the span.enter()
try's recording the span exit into the default subscriber which isn't
aware of it since it's registered by the scoped subscriber.
## Solution
From my understanding, it's sufficient for `Registry::exit` just to call
`self.try_close()` and do local bookkeeping:
- The attempt to use the thread dispatcher leads directly to the issues
observed in #3223, and
- I don't think it's correct to call `try_close` on the whole `Layer` stack
at this point anyway, a span being exited is not yet ready to close. All
that is needed is to decrement the reference count within the current
registry.
I've added a test which spawns a thread and enters (and exits, and drops)
a span created on a dispatcher not registered to that thread.
Before this patch, the test fails with the span never being closed
(because there is no thread dispatcher when the span is exited, and so a
reference is leaked in `Registry::exit`).
With this patch, the bookkeeping demonstrated in the test seems correct
to me.
Fixes: #3223
`ValueSet`s contain both a `FieldSet` reference and a slice of
(`&Field`, `Option<&dyn Value>`) pairs. In cases where `ValueSet`s are
generated via documented interfaces (specifically, `tracing::event!` and
other macros), the `Field` references are redundant, because the
`ValueSet` contains a value slot for every field (either a value or
`None`), in the correct order.
As a result, the code generated by the macros is terrible--it must
put a `Field` on the stack for each field--that's 32 bytes per field!
This is a lot of work for apparently no purpose at runtime, and it
can't be moved into a read-only data section since it's intermixed with
dynamic data.
Fix this by adding a variant of `ValueSet` that skips the `Field`
references, knowing that it represents the full set of fields. Keep
the old kind of `ValueSet`, too--it's still needed by `Span::record`,
by old versions of crates, and potentially by third-party crates using
undocumented methods such as `FieldSet::value_set`.
In some adhoc tests on x86_64 Linux, this reduces the code size as
follows:
* One-field event: 258 bytes to 189 bytes, 25% reduction.
* Five-field event: 638 bytes to 276 bytes, **57%** reduction.
* In a larger project with lots of events, ~5% reduction in .text section.
Due to an import of `::tracing::field::{display, debug, Value}`,
macro `valueset!` wasn't sanitary and would produce compile
errors when identifiers `debug` and `display` were used.
This change fixes the issue and makes the macro sanitary.
Fixes: #3381
## Motivation
Making sure the mentioned macro is sanitary and avoiding users
from encountering unexpected compile errors.
## Solution
Removed the import inside macro and used fully-qualified
paths for imported items.
The libsystemd code is documented to determine the syslog
identifier by using
https://man7.org/linux/man-pages/man3/program_invocation_short_name.3.html
(a glibc thing).
This code is parsing via looking at `/proc/self/exe`.
Often, these things are the same, but in my case they're not
because for unfortunate reasons I need to re-exec the current
binary in a tempfile.
It's actually simpler and more reliable for us anyways
to match what libsystemd is doing by looking at argv[0].
Signed-off-by: Colin Walters <walters@verbum.org>
## Motivation
Was reading the docs in the `format` module, and noticed a
couple of typos/missing links, etc.
## Solution
Did a quick pass and tried to fix the above. If I missed something or
the changes are not desired, just let me know!
## Motivation
We would like to apply some Rust 2024 idioms so that, in case of edition
migration, the workload is slightly reduced.
At the very least, this will allow experimentation with latest tracing crates
in `rustc`.
## Solution
Here is a list of applied idioms.
- `-Dwarnings`
- `-Wunused_lifetimes`
- `-Wrustc::internal`
- `-Wunreachable_pub`
- `-Wunused_crate_dependencies`
- `-Wrust_2018_idioms`
- `-Wunsafe_op_in_unsafe_fn`
- `-Wkeyword_idents_2024`
---------
Signed-off-by: Xiangfei Ding <dingxiangfei2009@protonmail.ch>
Co-authored-by: Hayden Stainsby <hds@caffeineconcepts.com>
## Motivation
The `#[instrument]` proc macro only allows setting field names as identifiers, which is not on par with other macros such as `span!` or `event!` that allow constant expressions. Using constants for example can ensure consistency across a project for the field names used.
This addresses #2969, which was already mentioned in this [comment here](https://github.com/tokio-rs/tracing/pull/2617#issuecomment-1718996094) on #2617 (note that "classic macros" mentioned there already work, there are tests attesting of it).
I also updated the doc block to mention field values can be any arbitrary expressions, which was implemented by #672 but never updated.
## Solution
I updated the instrument proc macro to allow constant expressions (const, const fn, literal str, ...) as field names, using the same syntax as #2617, **enclosed in curly braces**.
```rust
const CONST_FIELD_NAME: &str = "foo.bar";
#[instrument(fields({CONST_FIELD_NAME} = "quux"))]
fn fn_const_field_name() {}
```
The behavior around overriding function parameters needed to be
a bit different with const field names, where duplicate fields will
occur if the function parameter isn't explicitly skipped. This is
to avoid any runtime check and may be able to be improved in
future Rust versions.
---------
Co-authored-by: Hayden Stainsby <hds@caffeineconcepts.com>
