Calling record() multiple times logs the field multiple times

[kosta]

Bug Report

When calling Span::record multiple times, the the fmt subscriber logs the field multiple times. I don't think that this is the desired behaviour, but if it is, it should be more clear from the documentation.

Version

tracing-double-record v0.1.0 (/Users/kosta/code/toy/tracing-double-record)
├── tracing v0.1.34
│   ├── tracing-attributes v0.1.21 (proc-macro)
│   └── tracing-core v0.1.26
└── tracing-subscriber v0.3.11
    ├── tracing v0.1.34 (*)
    ├── tracing-core v0.1.26 (*)
    ├── tracing-log v0.1.3
    │   └── tracing-core v0.1.26 (*)
    └── tracing-serde v0.1.3
        └── tracing-core v0.1.26 (*)

Platform

Darwin hostname.localdomain 21.4.0 Darwin Kernel Version 21.4.0: Fri Mar 18 00:46:32 PDT 2022; root:xnu-8020.101.4~15/RELEASE_ARM64_T6000 arm64

Crates

tracing-subscriber I guess?

Description

This code:

use tracing::{field::Empty, info, span, Level};

fn main() {
    tracing_subscriber::fmt::init();

    info!("zero");
    let my_span = span!(Level::INFO, "my_span", foo = "foo", bar = Empty);
    let _entered = my_span.enter();
    info!("one");
    my_span.record("foo", &"bar");
    info!("two");
    my_span.record("foo", &"bar");
    info!("three");
    my_span.record("bar", &"bar");
    info!("four");
    my_span.record("bar", &"bar");
    info!("four");
}

outputs, when run with RUST_LOG=info cargo run

2022-05-12T13:11:36.146639Z  INFO tracing_double_record: zero
2022-05-12T13:11:36.146771Z  INFO my_span{foo="foo"}: tracing_double_record: one
2022-05-12T13:11:36.146802Z  INFO my_span{foo="foo" foo="bar"}: tracing_double_record: two
2022-05-12T13:11:36.146825Z  INFO my_span{foo="foo" foo="bar" foo="bar"}: tracing_double_record: three
2022-05-12T13:11:36.146845Z  INFO my_span{foo="foo" foo="bar" foo="bar" bar="bar"}: tracing_double_record: four
2022-05-12T13:11:36.146865Z  INFO my_span{foo="foo" foo="bar" foo="bar" bar="bar" bar="bar"}: tracing_double_record: four

I would expect that only the last recording of foo and bar are logged, respectively.

I ran into this because I Span::record()ed the extracted username in an axum middleware extractor, which seems to run twice: Once as a middleware and once as an extractor. Now the username exists in the span twice.

I have not found a way around this and from reading the source, I'm not sure whether this is currently possible without an architecture change?

[kosta]

Workaround for my specific issue: Don't re-use an axum middleware as an extractor; instead the middleware calls request.extensions_mut().insert(...).

I think the current behaviour is okay-ish (and hard to change due to the way it's designed). It should just be documented properly. If you agree, I can try to send an MR.

[mnpw]

+1, I'm facing this similar issue.

My use case is something like this:

fn run_loop() {
    // create a span
    let span = info_span!("my_span", my_field = field::Empty);
    let _guard = span.enter();
    
    loop {
        run_inner();
    }
}

fn run_inner() {
    // set current span's field
    let iteration_name = format!("iter-{}", rand::thread_rng());
    Span::current().record("my_field", iteration_name);
    
    // this prints field value multiple times 🙁
    error!("something went wrong");
}

[jeff-hiner]

I'm hitting this now myself. I've also noticed that setting the initial value to tracing::field::Empty and then trying to overwrite it with a value later adds empty blank spaces before printing the first value.

Is this a bug in fmt?

[davidbarsky]

I'm hitting this now myself. I've also noticed that setting the initial value to tracing::field::Empty and then trying to overwrite it with a value later adds empty blank spaces before printing the first value.

Is this a bug in fmt?

This is a behavior in fmt. I generally recommend the following approach: #2334 (comment).