tracing
tracing copied to clipboard
Calling record() multiple times logs the field multiple times
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?
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.
+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");
}
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
?
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: https://github.com/tokio-rs/tracing/issues/2334#issuecomment-1270751200.