Skip to content

[tracing-subscriber][tracing] improve duplciate tracing situation a bit #3319

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 3 commits into
base: main
Choose a base branch
from
Open

[tracing-subscriber][tracing] improve duplciate tracing situation a bit #3319

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
969e82c
no longer use Deref for FormattedFields in tracing-subscriber to prep…
xMAC94x Jun 18, 2025
1fa67da
warn users of a bug in `tracing-subscriber` which is there for some t…
xMAC94x Jun 19, 2025
24f7012
fix a spelling mistake. change position to the end of the description…
xMAC94x Jun 19, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions tracing-subscriber/src/fmt/fmt_layer.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -797,6 +797,7 @@ impl<E: ?Sized> fmt::Display for FormattedFields<E> {
}
}

// TODO: Evaluate removing Deref in future versions, as its a powerful tool and barely useful (consumers can just call `.fields` directly)
impl<E: ?Sized> Deref for FormattedFields<E> {
type Target = String;
fn deref(&self) -> &Self::Target {
Expand Down Expand Up @@ -1631,8 +1632,7 @@ mod test {
.with_timer(MockTime)
.with_span_events(FmtSpan::ACTIVE);

let (reloadable_layer, reload_handle) =
crate::reload::Layer::new(inner_layer);
let (reloadable_layer, reload_handle) = crate::reload::Layer::new(inner_layer);
let reload = reloadable_layer.with_subscriber(Registry::default());

with_default(reload, || {
Expand Down
4 changes: 2 additions & 2 deletions tracing-subscriber/src/fmt/format/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -969,7 +969,7 @@ where

let ext = span.extensions();
if let Some(fields) = &ext.get::<FormattedFields<N>>() {
if !fields.is_empty() {
if !fields.fields.is_empty() {
write!(writer, "{}{}{}", bold.paint("{"), fields, bold.paint("}"))?;
}
}
Expand Down Expand Up @@ -1146,7 +1146,7 @@ where
{
let exts = span.extensions();
if let Some(fields) = exts.get::<FormattedFields<N>>() {
if !fields.is_empty() {
if !fields.fields.is_empty() {
write!(writer, " {}", dimmed.paint(&fields.fields))?;
}
}
Expand Down
4 changes: 2 additions & 2 deletions tracing-subscriber/src/fmt/format/pretty.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -324,7 +324,7 @@ where
let fields = &ext
.get::<FormattedFields<N>>()
.expect("Unable to find FormattedFields in extensions; this is a bug");
if !fields.is_empty() {
if !fields.fields.is_empty() {
write!(writer, " {} {}", dimmed.paint("with"), fields)?;
}
writer.write_char('\n')?;
Expand All @@ -346,7 +346,7 @@ impl<'writer> FormatFields<'writer> for Pretty {
current: &'writer mut FormattedFields<Self>,
fields: &span::Record<'_>,
) -> fmt::Result {
let empty = current.is_empty();
let empty = current.fields.is_empty();
let writer = current.as_writer();
let mut v = PrettyVisitor::new(writer, empty);
fields.record(&mut v);
Expand Down
5 changes: 5 additions & 0 deletions tracing/src/span.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1162,6 +1162,11 @@ impl Span {
/// span was created:
/// </pre>
///
/// <pre class="ignore" style="white-space:normal;font:inherit;">
/// <strong>Note</strong>: <a href="https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/struct.Subscriber.html"><code>FmtSubscriber</code></a> has a bug
/// where it duplicates span fiels because of its implementation. See details at: <a href="https://github.com/tokio-rs/tracing/issues/1372">Github</a>
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
/// where it duplicates span fiels because of its implementation. See details at: <a href="https://github.com/tokio-rs/tracing/issues/1372">Github</a>
/// where it duplicates span fields because of its implementation. See details at: <a href="https://github.com/tokio-rs/tracing/issues/1372">Github</a>

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

fixed

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is definitely not a good thing for this note, just beforee it is another note which ends with : because right after it was supposed to be an example illustrating what the note was about. So you might want to move this further down.

Also this bug happens specifically only when someone uses multiple fmt layers, right? I think that's pretty important to mention, the note sounds like this happens every time but most users will never encounter this.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more. 

//[dependencies]
//tracing-subscriber = "0.3"
//tracing = "0.1"


fn main() {
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::TRACE)
        .init();

    let span = tracing::info_span!("request", duplicate = tracing::field::Empty);

    span.record("duplicate", &100);
    span.record("duplicate", &200);
    span.record("duplicate", tracing::field::Empty);
    span.record("duplicate", &300);

    // produces:
    // 2025-06-19T10:45:31.070903Z  INFO request{duplicate=100 duplicate=200  duplicate=300}: bbbb: some event!
    //                                           ^ first duplicate
    //                                                         ^ second duplcate
    //                                                                      ^ an additional space by the empty field
    //                                                                        ^ expected value here

    let _guard = span.enter();

    tracing::info!("some event!");
}

Copy link
Author

@xMAC94x xMAC94x Jun 19, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is an other minimal example it can trigger the bug. no need for fancy layers.
It just appends... always to a simple String:
https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.19/tracing-subscriber/src/fmt/format/mod.rs#L246-L249

I moved the note to the bottom to not interfere with the :

Though in my code I also had multiple layers, because I think one will eventually need it when writing enterprise software.

/// </pre>
///
/// ```
/// use tracing::{trace_span, field};
///
Expand Down