The level event macros (e.g. `trace!`, `info!`) call into the `event!`
macro with the level set appropriately. However, these macros have
become complex, covering many different cases and reaching aroudn 250
lines of patterns.
As discovered in #3437, there were many cases where these level event
macros didn't correctly handle patterns which the `event!` macro does
handle.
This change simplifies the event macros to delegate more parsing to the
common `event!` macro patterns. Rather than matching all the possible
field patterns, the level event macros only match the directives (name,
target, and parent or some combination thereof). The remainder of the
macro invocation is matched as a token tree (`tt`) and passed as is to
the `event!` macro.
This reduces the patterns to only the 8 combinations of directives
(including no directives at all), reducing the previous 250 lines of
patterns for each macro down to around 25 lines instead.
Additionally, an unqualified use of `Some` in the `valueset` macro has
been fixed, as this affected all event macros (`event!` and all the
level event macros).
With these changes, the comprehensive checks introduced in #3437 now all
pass and so the job can be fully enabled to fail on CI.
There are a large number of combinations of field types which currently
are not matched by the level event macros (e.g. `info!`).
A recent example from #3407 is the following invocation that doesn't
compile:
```rust
info!(name: "order.received.ok", order.id = 123, "order received");
```
However, the corresponding `event!` macro does compile:
```rust
event!(name: "order.received.ok", Level::INFO, order.id = 123, "order received");
```
And other variants also compile:
```rust
// Without `name:` directive
info!(order.id = 123, "order received");
// With another field before the dotted one
info!(name: "order.received.ok", foo = true, order.id = 123, "order received");
```
Many such cases have been fixed in the past (#2983, #2883, #2879).
However, this has been a bit like wack-a-mole, where we keep finding
issues and then fixing those issues, adding extra tests for them and
then going on our way.
Since the complexity is often in combinations (as above, only when using
the `name:` directive together with a dotted field name on the first
field), it would be useful to have some extensive tests that attempt to
cover all possible combinations.
It turns out that there are **a lot** of combiantions.
This change adds an `xtask` that generates tests for event macros (span
macros are out of scope for this change) similar to the ones found in
`tracing/tests/macros.rs`. Which is to say, tests containing macros
which should compile, but don't need to run.
Owing to the large number of combinations, the tests are split into test
files by macro (e.g. `event!`, `info!`) and directive combination (e.g.
no directives, just `name:`, `name:` and `target:`). The tests are kept
in a separate crate outside the main workspace to avoid rust-analyzer
trying to parse the files - as they are quite large. Specifically, there
are 1220 macro invocations per test file.
For each macro, there are 9760 invocations generated (including all
combinatiosn of directives). When run against the current `tracing`
macros, this resulted in the following failure counts:
* `event!`: 705
* `info!`, `warn!`: 1683 (each)
* `trace!`, `debug!`, `error!`: 1652 (each)
The test files are generated (no need to check them in) and then
validated by `cargo check` on CI.
The CI job has not been made blocking because none of the errors have
been fixed yet!
## 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>
## Motivation
This PR fixes perf regression (binary size and instruction counts) existed
in tracing > 0.1.37 in case if `release_max_level_*` feature was not set,
but `max_level_*` was.
## Solution
Regression was introduced in #2553, where logic was unintentionally
changed: before pr, in case if `release_max_level_*` wasn't set, log
level from `max_level_*` was used, but after it was unconditionally set
to trace level.
See additional info in https://github.com/tokio-rs/tracing/pull/2553#issuecomment-3262310405
Due to a change in the error messages produced by rustc, one of the UI
tests for failing compilation of the `#[instrument]` attribute when
applied to async functions was failing.
This change updates the expected output so that the test passes.
Some lint failures and errors in core were also fixed.
Co-authored-by: Hayden Stainsby <hds@caffeineconcepts.com>
When using the linux-musl target for rust, the file creation time
cannot be retrieved, as the current version does not support it yet (
This will be fixed with [0]). In the meantime, we parse the datetime
from the filename and use that as a fallback.
Fixes: #2999
[0]: https://github.com/rust-lang/rust/pull/125692
The prune_old_logs function only gets called when we rollover the
appender. The problem is that at startup we create an initial log file
without rolling over, if e.g., the executable then exits before rolling
over for the first time, we never call prune_old_logs.
E.g.: If we have a tracing-appender that rolls over every minute and we
have a max_files parameter of 2. Running the program (which prints a
single log line and exits) every minute, will result in a new log file
everytime without deleting the old ones.
Fixes: #2937
Co-authored-by: Nick Fagerlund <nick@hashicorp.com>
Fixes a security vulnerability where ANSI escape sequences in user input
could be injected into terminal output, potentially allowing attackers to
manipulate terminal behavior through log messages and error displays.
The vulnerability occurred when user-controlled content was formatted using
Display (`{}`) instead of Debug (`{:?}`) formatting, allowing raw ANSI
sequences to pass through unescaped.
Changes:
- Add streaming ANSI escape wrapper to avoid string allocations
- Escape message content in default and pretty formatters
- Escape error Display content in all error formatting paths
- Add comprehensive integration tests for all formatter types
The fix specifically targets untrusted user input while preserving the
ability for applications to deliberately include formatting in trusted
contexts like thread names.
Security impact: Prevents terminal injection attacks such as title bar
manipulation, screen clearing, and other malicious terminal control
sequences that could be injected through log messages.
This is useful when using `EnvFilter` for multiple identical per-layer
filters, as well as with clap and similar libraries that have `Clone`
bounds.
We generally expect users to be cloning an `EnvFilter` before attaching it
to a subscriber, rather than cloning `EnvFilters` that are already
attached. Because of this, we reset all the accumulated dynamic state
when cloning. This means that some spans and callsites might be missed
when an already-attached `EnvFilter` is cloned, but the presence of the
dynamic state mean that detaching and attaching `EnvFilter`s to existing
subscribers (e.g. with `reload`) already doesn't work very well. This
isn't a new class of problem.
There was a previous implementation of this in #2398, that shared the
dynamic state between all cloned filters behind an `Arc`. I chose
not do go for that approach because it causes inconsistencies if the
cloned filters are attached to different subscribers.
Fixes: #2360
