Skip to content
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.

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

Intuition footgun: only_key is ignored when not assigned a value in #[instrument(fields(only_key))] #2933

Open
Veetaha opened this issue Apr 8, 2024 · 1 comment

Comments

@Veetaha
Copy link
Contributor

Veetaha commented Apr 8, 2024

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) { }
@mladedav
Copy link
Contributor

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants