tracing
tracing copied to clipboard
Intuition footgun: `only_key` is ignored when not assigned a value in `#[instrument(fields(only_key))]`
If you don't assign a value to a key in #[instrument(fields(key))]
, then that key
entry is ignored.
I tried this code:
use tracing::{info, instrument};
fn main() {
tracing_subscriber::fmt::fmt()
.with_max_level(tracing::Level::DEBUG)
.init();
foo("buck");
}
#[instrument(fields(bucket))]
fn foo(bucket: &str) {
let _ = bucket;
info!("Fooing around");
}
Intuitive expectation
I expected #[instrument]
macro to add a field bucket
with the value of the bucket
parameter of the function. I know, this looks weird, but this is the kind of code that may appear when you are actively prototyping or refactoring a lot of code. It's also logical for a use case combined with skip_all
.
E.g. I often use the pattern #[instrument(skip_all, fields(...))]
to avoid logging everything and select a subset of parameters I'm interested in. With this pattern I just mention the bucket
key in fields and expect it to behave just like it would behave with a regular event!()
macro where it would produce a field with the value taken from the variable named the same available in the scope. The scope in this case includes the function parameters.
Unintuitive reality
Instead, this code compiles just fine, and when I run it no bucket
field is printed:
cargo run
Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.02s
Running `target/debug/sandbox-1`
2024-04-08T21:52:03.760950Z INFO foo: sandbox_1: Fooing around
Moreover, if you use a bogus name for the key like this, it is also totally ignored. You may have as much key-only entries in fields(...)
and all of them will be ignored
#[instrument(fields(chimicherrichanga, this_is_an_amre_doozy))]
fn foo(bucket: &str) {
let _ = bucket;
info!("Fooing around");
}
I admit, I've been using tracing
for years already, and I completely forgot about the "empty field" feature on spans documented for #[instrument]
here. I only found it once I started studying the code from the #[instrument]
macro expansion, even though I definitely read tracing docs years ago.
I've never used the "empty field" feature and I've never had a use case suitable for it. I wonder how popular this feature is in the wild though (I guess not very popular). I've just been following my intuition that tells me to just correlate fields(...)
syntax with event!(...)
syntax.
I think the main problem here is in the discrepancy of the syntax for defining these "empty fields" between #[instrument(fields(...))]
and event!(...)
macros:
-
#[instrument(fields(empty_field))]
-
info!(empty_field = tracing::field::Empty)
Why is this a footgun?
First of all, I expected a different behaviour for #[instrument(fields(..))]
that what I would expect is intuitive. Second, imagine, though, that the developer knows about this behaviour. Then just think about how easy it is to make such a mistake where you use the following syntax to skip all parameters and explicitly select a subset of parameters to include in the span:
// Uh oh, you forgot to put % or ? in front of `c` to include its display
// or debug value in the span. Now it's silently ignored
#[instrument(skip_all, fields(%a, %b, c))]
fn foo(self, a: &str, b: bool, c: u32, d: &str) { }
First of all, I agree this is an easy mistake to make so this sould be improved.
Second, the instrument macro should really be more similar to the span!
macro in usage. I think I've seen other proposed changes for 0.2 elsewhere like requiring a level, having skip_all
by default and maybe other changes, but I can't find any of that here (maybe I've seen it mentioned on discord instead?)
If there is no issue for this, I think it should be created and linked from the 0.2 tracing issue. As this would be a breaking change, I think that the instrument
and span
macros should be made more similar, but how is either going to end up looking is an open question.
On the topic of the empty fields, we do use the feature a fair amount, e.g. when we have a top level span and want it to have more information which is only parsed and recorded during its lifetime. I'm not sure from the top of my head if we create the spans with the instrument
macro, but we do use the feature.