tracing::instrument args by autoref specialization

[CAD97]

Motivation

• Allow capturing Option<impl Value> by value (core: impl field::Value for Option<T> #1585 (review))
• Record destructured impl Value fields by Value
• Remove fragile by-name argument matching in tracing::instrument, which breaks with e.g. shadowing or qualified paths
• Make captured strings filter as bob not "bob", see implement stricter env filter parsing #1542 (comment) for some more context

Solution

Autoref specialization!

#[tracing::instrument]ed function arguments are now captured via __tracing_capture_value!, which uses autoref specialization on .__tracing_capture_value() to first capture Value types by-Value, and then capture Debug types by-Debug. It could also attempt to capture by-Display, but I opted to not do so to make a smaller deviation from the current behavior and avoid the potential loss of detail that Display entails.

The span! and event! macros are unchanged.

Demo

let no_quotes_filter = "[{name=bob}]";
let yes_quotes_filter = r#"[{name="bob"}]"#;

let no_quotes = tracing_subscriber::fmt()
    .pretty()
    .finish()
    .with(EnvFilter::try_from(no_quotes_filter).unwrap());
let yes_quotes = tracing_subscriber::fmt()
    .pretty()
    .finish()
    .with(EnvFilter::try_from(yes_quotes_filter).unwrap());

let run = || {
    let name = "bob";
    info_span!("span0",  name).in_scope(|| info!("by-value"));
    info_span!("span1", ?name).in_scope(|| info!("by-debug"));
    info_span!("span2", %name).in_scope(|| info!("by-display"));
    span3(name); // fn span3(name: &str) { info!("by-argument") }
};

println!(" {} ", no_quotes_filter);
println!("==============");
tracing::collect::with_default(no_quotes, run);
println!();

println!("{}", yes_quotes_filter);
println!("==============");
tracing::collect::with_default(yes_quotes, run);
println!();

master (0fa74b9)

 [{name=bob}] 
==============
  Oct 03 17:24:34.216  INFO tracing_test: by-value
    at src\main.rs:19
    in tracing_test::span0 with name: "bob"

  Oct 03 17:24:34.217  INFO tracing_test: by-display
    at src\main.rs:21
    in tracing_test::span2 with name: bob

  Oct 03 17:24:34.217  INFO tracing_test: by-instrumented-argument
    at src\main.rs:45
    in tracing_test::span3 with name: "bob"


[{name="bob"}]
==============
  Oct 03 17:24:34.218  INFO tracing_test: by-debug
    at src\main.rs:20
    in tracing_test::span1 with name: "bob"

this PR (3fb7366)

 [{name=bob}] 
==============
  Oct 03 17:25:37.757  INFO tracing_test: by-value
    at src\main.rs:19
    in tracing_test::span0 with name: "bob"

  Oct 03 17:25:37.758  INFO tracing_test: by-display
    at src\main.rs:21
    in tracing_test::span2 with name: bob

  Oct 03 17:25:37.759  INFO tracing_test: by-instrumented-argument
    at src\main.rs:45
    in tracing_test::span3 with name: "bob"


[{name="bob"}]
==============
  Oct 03 17:25:37.760  INFO tracing_test: by-debug
    at src\main.rs:20
    in tracing_test::span1 with name: "bob"

Uhh apparently when I did my testing in #1542 I didn't have #1378 🙃

Future

Once capturing by-Value means capturing by-Valuable, this change simultaneously becomes more desirable (more structured argument capture) and more behavior-changing (as more types will potentially capture by-Value).

[hawkw]

Sorry I haven't reviewed this yet --- I'd like to get the bug fixes for issues in the v0.1.17 release of tracing-attributes merged first and release a patch that fixes those issues before making additional changes, to minimize churn. Once there's a patch published for those bugs, I'd love to get this change into a new release!

[CAD97]

Rebased over the tracing-attributes split.

[CAD97]

tracing-attributes 0.1.18 has been published. Is there anything specific blocking this, or are we just waiting on person time?

[hawkw]

tracing-attributes 0.1.18 has been published. Is there anything specific blocking this, or are we just waiting on person time?

Sorry, it's on my list of things to do --- I was hoping to spend some time going through the backlog of tracing PRs this week, but I wasn't feeling well for a couple days...hopefully I'll get to it soon!

[CAD97]

Now that we have #1906, I guess I should look into capturing by-Valuable rather than by-Value.

[CAD97]

Alright, this now supports capturing by-valuable, with the autoref order of

Valuable > Value > Debug

(This can be adjusted if desired; it might make sense to swap Valuable and Value. If Valuable works out well, will it replace Value for 0.2.0?)

[hawkw]

thanks for the reminder that this branch exists, i had kind of forgotten about it (sorry!). i'm really excited about this change and i'd love to get it merged --- and once it lands, it would be really nice to use the autoref capture macro in the span! and event! macros as well, in a follow-up PR.

i did have a few questions about the change, and it would be nice to have some additional comments explaining some of the details about what's going on here. also, it could be nice to add some more tests for instrument ensuring that autoref capture behaves correctly --- in particular, it would be nice to have a (cfg-flagged) test that valuable capture works.

once those comments are addressed, i'll be very excited to merge this!

[CAD97]

One thing I just want to confirm is the way we want to handle it: the current order the conversions are tried is

• by Valuable, then
• by Value, then
• by Debug.

This is the least behavior-changing option, since primitives are currently opportunistically recognized to be captured by-Value and everything else is captured by-Debug. However, we could add by-Display capture into the lookup options (likely between Value and Debug). However, the risk is that this could lose (stringified) information from the logs, as many types provide more information in their Debug implementation than their Display implementation. Ultimately, the logs are a developer-focused output, so Debug seems the more appropriate default to use.

For event! or span!, though, if we use the same autoref specialization capture there, Display makes a stronger case for inclusion than #[tracing::instrument].

[hawkw]

One thing I just want to confirm is the way we want to handle it: the current order the conversions are tried is

* by `Valuable`, then

* by `Value`, then

* by `Debug`.

I think this approach makes sense. I think it's reasonable for Display to be opt-in only.

[hawkw]

okay, i think this seems ready to merge. thanks again for working on this!

[hawkw]

Oh, hmm. I just noticed something kind of unfortunate: releasing a new version of tracing-attributes that contains this change will break compatibility with older versions of tracing that don't contain the __tracing_capture_value! macro. Unfortunately, tracing depends on (and re-exports) tracing-attributes, rather than tracing-attributes depending on tracing, so there isn't any way for tracing-attributes to require a compatible version of tracing. This means that if users depend on tracing-attributes explicitly, and they update just the tracing-attributes version, without also updating tracing, their code will no longer compile.

I think there a couple of possible solutions here. One of them is to just release an 0.2 version of tracing-attributes and document that it requires tracing 0.1.36 or greater. This would prevent any tracing-attributes dependencies from being automatically updated to an incompatible version. A new tracing release could depend on tracing-attributes 0.2, as the attribute macro's behavior should still be compatible.

Alternatively, we could put the autoref specialization code in tracing-core rather than tracing. This would permit us to add a tracing-core dependency in tracing-attributes, with the minimum necessary version required to have the autoref specialization code. Although tracing-attributes itself would never actually use tracing-core, adding the dependency would ensure that user code always has the minimum necessary version in its dependency tree, without requiring a cyclical dependency on tracing. I think this ought to work, provided that the autoref code is placed in a module of tracing-core that's blanket-reexported by tracing¹ such as the field module. I'm not a huge fan of putting additional code in tracing-core that doesn't need to be in core, especially #[doc(hidden)] pub unstable APIs, but this would let us avoid a tracing-attributes version bump.

@CAD97, what do you think makes the most sense here?

Footnotes

1. Since the attribute macro should not generate code that uses tracing-core:: paths, as tracing-core will generally not be a direct dependency of user code. ↩

[CAD97]

The optimal solution per my understanding of the proc macro ecosystem is to go back in time and make all tracing dependencies on tracing-attributes an = exact version dependency, and document that tracing-attributes is an implementation detail of tracing not meant to be used directly.

In practice, proc macros are coupled rather tightly to their runtime crate. In a perfect future, the proc macro crate is distributed as part of the runtime package and not a separately versioned artifact.

For a comparison point, serde-derive will fail if used with an incompatible version of serde. This isn't an easy situation to get into (modern serde releases have an optional = dependency on serde-derive which is the recommended way to use the derives) but illustrates that this is a common pain point of proc macro crates.

There's also a possibility that the proc-macro->runtime dependency edge won't impact runtime version selection in the future. IIRC resolver = "2" might not split proc macro dependencies from runtime dependencies (can't check right now) when they show up in the [dependencies] table, but it has split runtime from the [build-dependencies] version resolution, so it's not an impossibility that resolver = "3" would additionally add a split between runtime and proc-macro = true's dependency tree (if it doesn't exist already — again, can't check right now).

So if we want to avoid the case where someone gets broken by upgrading [email protected] without upgrading [email protected], I think the solution would be

• bump to [email protected]
• tracing depends on = version of tracing-attributes
• [email protected] specifically says that using it not via the tracing reëxport is unsupported and will break
• decide if releasing tracing-attributes patch version in lockstep with tracing, or only bumping it with code changes, but still requiring a new version of tracing to use it

Personally I think the proc macro crate version bump isn't really required (unless maybe if there was a period of time where using the crate directly was the recommended usage pattern) because this is (unfortunately) a known limitation of the proc-macro/runtime split.

Now for a silly alternative solution: rename the macro __tracing_capture_value_requires_version_0_1_XX! 😝

[hawkw]

Personally I think the proc macro crate version bump isn't really required (unless maybe if there was a period of time where using the crate directly was the recommended usage pattern) because this is (unfortunately) a known limitation of the proc-macro/runtime split.

Yeah...that's fair; I'm also not sure if this is a big deal. I would be pretty surprised if anyone is explicitly depending on tracing-attributes rather than getting it from tracing: I can't think of any reason to do that, and we've certainly never told people to do it.

My concern was mostly about automated tools like Dependabot bumping just the tracing-attributes version in a lockfile, even when the crate itself only has an explicit dependency on tracing. But...the failure mode for that is just that the Dependabot PR wouldn't build, and you could just...not merge it. So, it seems like this could break those builds, but maybe won't actually cause serious problems, unless people are doing weird things with automated tools. I just tend to be cautious about these things, because of how widely-used tracing is...the number of times when a "nobody could possibly be broken by that in practice" change caused a problem for someone, somewhere, is greater than zero.

[CAD97]

FWIW, if your used version of tracing has an = dependency constraint on tracing-attributes, it's impossible to pull in an incorrect version of tracing-attributes (currently) due to cargo's one-per-major-version rule. So the only downside of bumping tracing-attributes to 0.2 and using an = depends clause is

• have to do a version bump
• can't publish a new version of tracing-attributes that will get used without a new tracing version

both of which seem trivial enough that just doing the version increment seems reasonable enough to me (unless I'm missing something, which is possible)

[CAD97]

This means that if users depend on tracing-attributes explicitly, and they update just the tracing-attributes version, without also updating tracing, their code will no longer compile.

FWIW it's worse than that, actually: since tracing depends on tracing-attributes=^0.1, it declares itself backwards-and-forwards-compatible with any version in 0.1.X.

Getting a broken version resolution would be as simple as cargo update -p tracing-attributes.