Weird behavior of `tracing::instrument` macro when `tracing/log` feature is enabled

Bug Report

Version

├── tracing v0.1.37
│   ├── tracing-attributes v0.1.26 (proc-macro)
│   └── tracing-core v0.1.31
└── tracing-subscriber v0.3.18
    ├── tracing-core v0.1.31 (*)
    └── tracing-log v0.2.0
        └── tracing-core v0.1.31 (*)

Platform

Linux esquivalience 6.6.3-zen1-1-zen #1 ZEN SMP PREEMPT_DYNAMIC Wed, 29 Nov 2023 00:40:39 +0000 x86_64 GNU/Linux

Crates

tracing-attributes, tracing

Description

Here's a crate, it has a [feature] section containing log = ["tracing/log"]

use std::sync::atomic::{AtomicU8, Ordering};

use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};

static COUNT: AtomicU8 = AtomicU8::new(0);

macro_rules! gen {
    () => {{
        COUNT.fetch_add(1, Ordering::AcqRel) + 1
    }};
}

#[tracing::instrument(fields(field = gen!()))]
async fn func() {
    tracing::info!("test");
}

#[tokio::main]
async fn main() {
    tracing_subscriber::registry().with(fmt::layer()).init();

    func().await;
}

I am calling the gen! macro to generate a value for the field field.

$ cargo r -q
2023-12-07T15:32:31.393186Z  INFO func{field=1}: thing: test
$ cargo r -qF 'log'
2023-12-07T15:32:34.215495Z  INFO func{field=1}: thing: test

I only see field=1. This example may look a bit weird, as everything is working as expected, but now I change a code a bit:

use std::sync::atomic::{AtomicU8, Ordering};

use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};

struct U; // new
trait T {} // new

static COUNT: AtomicU8 = AtomicU8::new(0);

macro_rules! gen {
    () => {{
        impl T for U {} // new
        COUNT.fetch_add(1, Ordering::AcqRel) + 1
    }};
}

#[tracing::instrument(fields(field = gen!()))]
async fn func() {
    tracing::info!("test");
}

#[tokio::main]
async fn main() {
    tracing_subscriber::registry().with(fmt::layer()).init();

    func().await;
}

The gen! macro now implements a trait for a struct, this results in that the macro can only be called once, as multiple implementations of the same trait are forbidden.

Now, we've seen that the macro in the previous example was called only once by the instrument macro, with both tracing/log feature and without it, so why would the output change? Let's try:

$ cargo r -q
2023-12-07T15:33:28.652057Z  INFO func{field=1}: thing: test
$ cargo r -qF 'log'
error[E0119]: conflicting implementations of trait `T` for type `U`
  --> src/main.rs:13:9
   |
13 |         impl T for U {}
   |         ^^^^^^^^^^^^
   |         |
   |         first implementation here
   |         conflicting implementation for `U`
...
18 | #[tracing::instrument(fields(field = gen!()))]
   |                                      ------ in this macro invocation
   |
   = note: this error originates in the macro `gen` (in Nightly builds, run with -Z macro-backtrace for more info)

It's now obvious that gen! is called multiple times, but only when tracing/log feature is enabled.

Here's a list of problems:

Is it possible to refactor tracing::instrument so that it caches the values for the field and doesn't evaluate them multiple times?
Why the code with impl failed to compile, when first example showed us that gen! is actually called only once?
I used cargo-expand, and it does indeed show me that with tracing/log, the gen! is evaluated two times, but first example works regardless.

I call this "Schrödinger's macro" in my head

tokio-rs / tracing