Docs say that #[instrument] uses Value trait, but experiment disagree

[safinaskar]

Bug Report

Version

├── tracing v0.1.40
│   ├── tracing-attributes v0.1.27 (proc-macro)
│   └── tracing-core v0.1.32
└── tracing-subscriber v0.3.17
    ├── tracing-core v0.1.32 (*)
    ├── tracing-log v0.1.3
    │   └── tracing-core v0.1.32 (*)
    └── tracing-serde v0.1.3
        └── tracing-core v0.1.32 (*)

Platform

Linux comp 5.10.0-0.deb9.24-amd64 #1 SMP Debian 5.10.179-5~deb9u1 (2023-09-01) x86_64 GNU/Linux

Crates

tracing, tracing_subscriber

Description

Consider this code:

#[tracing::instrument]
fn f(x: String) {
}

fn main() {
        use tracing_subscriber::layer::SubscriberExt;
        use tracing_subscriber::util::SubscriberInitExt;
        use tracing_subscriber::fmt::format::FmtSpan;
        use tracing::info;
        tracing_subscriber::Registry::default()
            .with(tracing_subscriber::fmt::layer()
                .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
                .json()
            )
            .init();
    f("a".to_string());
}

Docs say this ( https://docs.rs/tracing/latest/tracing/attr.instrument.html ):

Arguments that are tracing primitive types implementing the Value trait will be recorded as fields of that type. Types which do not implement Value will be recorded using [std::fmt::Debug]

(Small note: link "Value trait" is broken. And std::fmt::Debug has extra square brackets.)

My interpretation of quote above is so: first Value will be tried, then Debug. It is not fully clear what means "primitive types" here. But the text says "tracing primitive types", not just "primitive types", so my interpretation is so: docs mean not Rust's primitive types (i. e. https://doc.rust-lang.org/nightly/std/#primitives ), but some tracing's notion of primitive types. And link goes to list of Value implementors, which include String. So I conclude that meaning is so: "first try Value, then Debug".

In code above we use String, which implements Value, so Value implementation should be used. Thus output should contain "x":"a". But here is actual output:

{"timestamp":"2023-10-25T14:19:41.358407Z","level":"INFO","fields":{"message":"new"},"target":"trac","span":{"x":"\"a\"","name":"f"},"spans":[]}
{"timestamp":"2023-10-25T14:19:41.358467Z","level":"INFO","fields":{"message":"close","time.busy":"3.92µs","time.idle":"58.7µs"},"target":"trac","span":{"x":"\"a\"","name":"f"},"spans":[]}

We see "x":"\"a\"" here instead of correct (according to docs) "x":"a". So either docs, either implementation should be fixed.

Moreover, https://docs.rs/tracing/latest/tracing/index.html says this:

A function annotated with #[instrument] will create and enter a span with that function’s name every time the function is called, with arguments to that function will be recorded as fields using fmt::Debug.

So, this text implies that Debug always will be used. This contradicts to docs from https://docs.rs/tracing/latest/tracing/attr.instrument.html . Surprisingly, this doesn't match reality, too! If I pass &str instead of String, then I see "x":"a"! I. e. Value or Display implementation used, not Debug. So, two documentation pieces contradict each other, and neither depicts reality correctly!

[kaffarell]

Note: the broken link in the docs and the extra square brackets are fixed here: #2780, turned out to be a small error when backporting changes.

The problem is (I think at least) that Value is implemented for String, but is missing in the RecordType::TYPES_FOR_VALUE array, which is used when parsing the function body. I just tried it on a minimal example and it seems to work. I will submit a PR and we'll see if this is the right approach to fixing this.
Thanks for submitting this issue!

Edit: #2781 will fix this behavior, but we still need to fix the docs.

[safinaskar]

the extra square brackets

While researching tracing ecosystem, I found a lot of similar typos. Here are some of them:

• https://docs.rs/tracing/0.1.40/tracing/attr.instrument.html (in addition to already mentioned std::fmt::Debug problem, this page contains similarly broken mentions of Result::Ok, std::fmt::Debug [yes, another mention!], std::fmt::Display, Result::Ok [again], Result::Err)
• https://docs.rs/tracing/0.1.40/tracing/trait.Subscriber.html#impl-dyn+Subscriber+%2B+Sync : [Subscriber]
• https://docs.rs/tracing-forest/0.1.6/tracing_forest/struct.ForestLayer.html#impl-Layer%3CS%3E-for-ForestLayer%3CP,+T%3E : [Subscriber]
• https://docs.rs/tracing-serde/0.1.3/tracing_serde/#unstable-features : [Visit::record_value]
• https://docs.rs/tracing-subscriber/0.3.17/tracing_subscriber/fmt/fn.fmt.html : [SubscriberBuilder::default()]
• https://docs.rs/tracing-subscriber/0.3.17/tracing_subscriber/fmt/format/index.html#functions : "[event formatter]" two times
• https://docs.rs/tracing-subscriber/0.3.17/tracing_subscriber/fmt/index.html#functions : "[event formatter]"
• https://docs.rs/tracing-tree/0.2.5/tracing_tree/time/trait.FormatTime.html : "[LocalDateTime]" two times

So, something goes wrong here. It seems we need to do some automatic search-and-replace

[safinaskar]

https://docs.rs/tracing/latest/tracing/index.html still says that Debug is always used. Please, reopen this bug

[kaffarell]

Oof, I missed that, thanks for the heads up!
Do you think this will fit?

A function annotated with #[instrument] will create and enter a span with that function’s name every time the function is called, with arguments to that function recorded as fields using the Value trait or fmt::Debug.

The docs here: https://docs.rs/tracing/latest/tracing/attr.instrument.html explain this behavior more in depth, so I don't think its necessary to write another sentence here.
@davidbarsky @safinaskar

[safinaskar]

I would say so:

with arguments to that function recorded as fields using the Value trait or, if it is not implemented, fmt::Debug

But your variant is okay, too

[kaffarell]

Added it to the PR!