tracing: fix macros "use of moved value" with log #1823

Skepfyr · 2022-01-09T00:40:58Z

Disclaimer: I'm not totally happy with this, it feels messy. However, I think the idea's sound, I need some input on how to best fit this into tracing.

Motivation

Fixes: #196, #1739

Previously, the field token trees would be substituted into the log macro invocation and the ValueSet, potentially meaning they are executed more than once.

Solution

This changes the event macro (and all the upstream macros like info!), so that it only uses each field once when the log feature is enabled. It does this by generating the log using the ValueSet meaning the token trees are only substituted once.

I'd like to add a test for this but rust-lang/cargo#2911 makes it a bit tricky to enable the log feature in the tests. There is a workaround but I'm not sure it works if dependents aren't using the new feature resolver.

This changes the event macro (and all the upstream macros like info!), so that it only uses each field once when the log feature is enabled. Previously, the `field` token trees would be substituted into the log macro invocation and the `ValueSet`, potentially meaning they are executed more than once. This change generates the log using the `ValueSet` meaning the token trees are only substituted once. Fixes: tokio-rs#196, tokio-rs#1739

Fixes the span macro to only substitute the field expressions once when the log feature is enabled. This stops enabling the log feature causing "use of moved value" errors and other odd behaviour. # Please enter the commit message for your changes. Lines starting # with '#' will be ignored, and an empty message aborts the commit. # # On branch macros-with-log # Your branch is up to date with 'origin/macros-with-log'. # # Changes to be committed: # modified: ../tracing/src/macros.rs # # Changes not staged for commit: # modified: Cargo.toml # # Untracked files: # examples/log-move.rs #

hawkw

Thanks for working on this! I think this approach seems basically correct. I commented on some potential issues I think we'll want to address, though. In particular, it would be good to ensure that this solution doesn't introduce a performance regression for disabled spans and events when log is not being used, so we should compare the benchmarks before and after this change.

In particular, we probably care about the benchmarks for globally-disabled spans (no_subscriber.rs):

tracing/tracing/benches/no_subscriber.rs

Lines 9 to 18 in 84bbbea

    
           group.bench_function("span", |b| { 
        
               b.iter(|| { 
        
                   black_box(tracing::span!(Level::TRACE, "span")); 
        
               }) 
        
           }); 
        
           group.bench_function("event", |b| { 
        
               b.iter(|| { 
        
                   tracing::event!(Level::TRACE, "hello"); 
        
               }) 
        
           });

and the filtering benchmarks in tracing-subscriber:
https://github.com/tokio-rs/tracing/blob/master/tracing-subscriber/benches/filter.rs

Regarding the question about testing,

I'd like to add a test for this but rust-lang/cargo#2911 makes it a bit tricky to enable the log feature in the tests. There is a workaround but I'm not sure it works if dependents aren't using the new feature resolver.

Currently, the way we test the log feature is by defining a separate crate that depends on tracing with the log feature flag enabled: https://github.com/tokio-rs/tracing/tree/master/tracing/test-log-support. That crate is not part of the main workspace, so it doesn't globally enable the feature flag, but CI includes a separate step that runs the tests defined in the test-log-support crate. You can add new tests for log-specific code in that crate.

tracing/src/macros.rs

hawkw · 2022-01-10T18:41:42Z

tracing/src/macros.rs

+            level: $lvl,
+            fields: $($fields)*
+        };
+        (|value_set: $crate::field::ValueSet| {


hmm...previous attempts to move ValueSet construction into a closure has caused some severe breakage in crates using tracing, because the closure borrows entire structs or tuples when their fields are referenced in the value set (see #987). So, I'm a bit concerned about this. However, we did add some tests to prevent regressions with this issue in the future (

tracing/tracing/tests/macros.rs

Lines 870 to 896 in 84bbbea

#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]

#[test]

fn borrow_val_events() {

// Reproduces https://github.com/tokio-rs/tracing/issues/954

let mut foo = (String::new(), String::new());

let zero = &mut foo.0;

trace!(one = ?foo.1);

debug!(one = ?foo.1);

info!(one = ?foo.1);

warn!(one = ?foo.1);

error!(one = ?foo.1);

zero.push_str("hello world");

}

#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]

#[test]

fn borrow_val_spans() {

// Reproduces https://github.com/tokio-rs/tracing/issues/954

let mut foo = (String::new(), String::new());

let zero = &mut foo.0;

let _span = trace_span!("span", one = ?foo.1);

let _span = debug_span!("span", one = ?foo.1);

let _span = info_span!("span", one = ?foo.1);

let _span = warn_span!("span", one = ?foo.1);

let _span = error_span!("span", one = ?foo.1);

zero.push_str("hello world");

}

), so if they pass, this is probably okay.

I'm not entirely sure if I get why the closure is necessary here, though. Is there a reason we can't just place the valueset in a let binding, instead?

It appears to be passing, which slightly surprises me because I can't see what's changed, I'll dig into this more to work out why, just in case the test is missing something. (oooh, it might be because value_set is constructed outside the closure)
I need to add some comments about this but the reason for the immediately invoked closures is to extend the lifetime of the temporaries created by valueset.
This doesn't compile because the string's are dropped before we get to baz.

let x = &[&String::from("foo"), &String::from("bar")]; baz(x);

This however does compile:

(|x| { baz(x); })(&[&String::from("foo"), &String::from("bar")]);

tracing/src/macros.rs

tracing-core/src/field.rs

tracing/src/macros.rs

This reverts commit bc81ef5. The issue with the event macro does not apply to the span macro.

hawkw

Overall, this looks pretty good to me! I left some minor suggestions, most of which aren't hard blockers.

It would be really nice to add tests that we no longer have compilation issues when log is enabled. We should add those in the test-log-support crate. Those tests don't even need to make any assertions or anything (although they could, if you like) --- they can just have some code that reproduces the compiler error, and make sure that it actually compiles.

Thanks!

hawkw · 2022-01-12T17:47:00Z

tracing/src/macros.rs

+            (|value_set: $crate::field::ValueSet| {
+                $crate::__tracing_log!(
+                    target: $target,
+                    $lvl,
+                    &value_set
+                );
+                let meta = CALLSITE.metadata();
+                // event with explicit parent
+                $crate::Event::child_of(
+                    $parent,
+                    meta,
+                    &value_set
+                );
+            })($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));


is there a reason we still need the closure in the event! macros, but we don't in the span! macros? I haven't actually tried it yet, but it seems like we should be able to just write this and get exactly the same behavior:

Suggested change

(|value_set: $crate::field::ValueSet| {

$crate::__tracing_log!(

target: $target,

$lvl,

&value_set

);

let meta = CALLSITE.metadata();

// event with explicit parent

$crate::Event::child_of(

$parent,

meta,

&value_set

);

})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));

let value_set = ($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*);

$crate::__tracing_log!(

target: $target,

$lvl,

&value_set

);

let meta = CALLSITE.metadata();

// event with explicit parent

$crate::Event::child_of(

$parent,

meta,

&value_set

);

This doesn't work for the reasons mentioned elsewhere, however I can replace the closures with function calls which may be preferable (it also appears to improve perf, see benchmarking comment). However, those functions do look a bit weird:

#[inline] pub fn log_and_dispatcht(target: &str, callsite: &MacroCallsite, value_set: ValueSet) { let meta = callsite.metadata(); // event with contextual parent $crate::Event::dispatch( meta, &value_set ); $crate::__tracing_log!( target: target, $lvl, &value_set ); }

and similarly a log_and_event, I imagine both would go in the __macro_support module.

hawkw · 2022-01-12T17:48:08Z

tracing/src/macros.rs

+            (|value_set: $crate::field::ValueSet| {
+                let meta = CALLSITE.metadata();
+                // event with contextual parent
+                $crate::Event::dispatch(
+                    meta,
+                    &value_set
+                );
+                $crate::__tracing_log!(
+                    target: $target,
+                    $lvl,
+                    &value_set
+                );
+            })($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));


similarly, it seems like the closure should be able to be replaced by a let-binding?

hawkw · 2022-01-12T17:49:01Z

tracing/src/lib.rs

+    /// Breaking changes to this module may occur in small-numbered versions
+    /// without warning.
+    #[derive(Debug)]
+    pub struct LogValueSet<'a>(pub &'a ValueSet<'a>);


i have a slight preference for giving this a new constructor, rather than a pub field, so that we can add new fields to it while still supporting earlier versions of the macros. however, i doubt this is an issue in practice, so it may not really matter...

tracing/src/lib.rs

hawkw · 2022-01-12T17:56:52Z

tracing/src/lib.rs

+            let res = if self.is_first {
+                self.is_first = false;
+                if field.name() == "message" {
+                    write!(self.f, "{:?}", value)
+                } else {
+                    write!(self.f, "{}={:?}", field.name(), value)
+                }
+            } else {
+                write!(self.f, " {}={:?}", field.name(), value)
+            };


nit, take it or leave it: this might look slightly nicer as a match?

Suggested change

let res = if self.is_first {

self.is_first = false;

if field.name() == "message" {

write!(self.f, "{:?}", value)

} else {

write!(self.f, "{}={:?}", field.name(), value)

}

} else {

write!(self.f, " {}={:?}", field.name(), value)

};

let res = match field.name() {

"message" if self.is_first() => write!(self.f, "{:?}", value),

"message" => write!(self.f, " {:?}", value),

name if self.is_first => write!(self.f, "{}={:?}", name, value),

name => write!(self.f, " {}={:?}", name, value,

};

self.is_first = false;

though, up to you

I prefer the explicit something is only weird about the first one of the if. However, your snippet does produce a different output to mine, in the case of message not being the first field. Mine would produce:

foo=bar message=Hi! baz=quux

whereas yours would produce:

foo=bar Hi! baz=quux

Is that behaviour ok, or should I change it to be in line with yours?

in practice, the valueset! macro will always re-order the message field to come first, so it doesn't really matter whether we handle it differently if it isn't the first field. i don't have a strong opinion about this code, so it's fine to leave it the way you had it if you prefer.

tracing-core/src/field.rs

Skepfyr · 2022-01-17T23:32:26Z

@hawkw I have attempted to benchmark this change as you requested, however I got very mixed (but reliable) results that I don't really know how to interpret (this is all with the log feature off):

no_subscriber/event & mixed/disabled_by_level got 100% slower
no_subscriber_field/span, static/baseline_single_threaded & static/disabled_level_one got 15% slower
no_subscriber_field/event, static/single_threaded, static/enabled_one, static/enabled_many, static/disabled_level_many got 15% faster.

With log-always enabled no_subscriber/event gets 50% slower, I didn't check the filter benches.

I can't work out what's causing this, a test program that just does tracing::event!(Level::TRACE, "hello"); does not get slower, and then generated code looks almost identical. I suspect that this change is just messing about with the optimizer. Note that the global_subscriber benchmark sees no changes (I believe they're just swamped out by the subscriber).

Replacing the closures with functions does mitigate the issue somewhat but doesn't fix the issue entirely (no_subscriber/event +25% instead of +100%).

hawkw · 2022-01-19T19:34:43Z

@hawkw I have attempted to benchmark this change as you requested, however I got very mixed (but reliable) results that I don't really know how to interpret (this is all with the log feature off):

no_subscriber/event & mixed/disabled_by_level got 100% slower no_subscriber_field/span, static/baseline_single_threaded & static/disabled_level_one got 15% slower no_subscriber_field/event, static/single_threaded, static/enabled_one, static/enabled_many, static/disabled_level_many got 15% faster.

With log-always enabled no_subscriber/event gets 50% slower, I didn't check the filter benches.

I can't work out what's causing this, a test program that just does tracing::event!(Level::TRACE, "hello"); does not get slower, and then generated code looks almost identical. I suspect that this change is just messing about with the optimizer. Note that the global_subscriber benchmark sees no changes (I believe they're just swamped out by the subscriber).

Replacing the closures with functions does mitigate the issue somewhat but doesn't fix the issue entirely (no_subscriber/event +25% instead of +100%).

Thanks for running the benchmarks, I appreciate that!

The results you're getting are mostly in line with my expectations; the expected impacts of this change are all in the case where the span or event is disabled (such as the no_subscriber benchmarks) rather than in the case where the span or event is enabled (the global_subscriber benchmarks).

A 100% slowdown in the disabled span benchmarks is...quite bad. I think we need to figure out how to fix this issue without having such a significant performance impact on code that doesn't even enable the log feature.

Replacing the closures with functions seems like a good start, so let's do that. I'll look closer at your change and see if anything else sticks out.

hawkw · 2022-01-19T19:35:54Z

tracing/test-log-support/tests/log_move_arg.rs

+#[derive(Debug)]
+struct Foo;
+#[derive(Debug)]
+struct Bar(Foo);


very minor style nit: can we put a newline between these:

Suggested change

#[derive(Debug)]

struct Foo;

#[derive(Debug)]

struct Bar(Foo);

#[derive(Debug)]

struct Foo;

#[derive(Debug)]

struct Bar(Foo);

hawkw · 2022-01-19T19:39:53Z

tracing/src/lib.rs

+            let res = if self.is_first {
+                self.is_first = false;
+                if field.name() == "message" {
+                    write!(self.f, "{:?}", value)
+                } else {
+                    write!(self.f, "{}={:?}", field.name(), value)
+                }
+            } else {
+                write!(self.f, " {}={:?}", field.name(), value)
+            };


in practice, the valueset! macro will always re-order the message field to come first, so it doesn't really matter whether we handle it differently if it isn't the first field. i don't have a strong opinion about this code, so it's fine to leave it the way you had it if you prefer.

hawkw · 2022-01-19T19:40:44Z

tracing/src/macros.rs

-                    file!(),
-                    ":",
-                    line!()
-                ),
-                kind: $crate::metadata::Kind::EVENT,
-                target: $target,
-                level: $lvl,
-                fields: $($fields)*
-            };
+        let enabled = $crate::level_enabled!($lvl) && {
            let interest = CALLSITE.interest();
-            if !interest.is_never() && CALLSITE.is_enabled(interest)  {
+            !interest.is_never() && CALLSITE.is_enabled(interest)
+        };
+        if enabled {


i wonder if we could improve the benchmark performance for disabled spans by going back to having a separate if statement for level_enabled! and checking if the callsite is enabled? it might be worth trying that and re-running the benchmarks?

I had a go at this, but it didn't make any difference, and the way it is now is more readable to me.

interesting, thanks for trying it anyway!

Skepfyr · 2022-01-23T17:18:51Z

I've attempted to improve the benchmarks but nothing is really working, and it's mostly just trying to get things exactly right for the optimizer, which feels fragile. For example, that closure -> function transformation may be a pessimisation as it forces some of the macro inputs to be evaluated early.

Additionally I'm not sure it's worth trying to optimize those benchmarks that have got 2x slower as they're both ~400ps, all the one's that have got quicker are in the tens of picoseconds. I'm not sure why anything's got quicker with this change.

One benchmark I've run that seems more interesting to me is subscriber event with a logger enabled (the logger string is thrown into a black_box rather than printed to stdout). In master that takes ~77ns on my machine and with this change it gets 20% slower to 93ns. I'm not too surprised by this as it has to got through the record machinery, but I think it's worth knowing. I've added a nop logger to the global_subscriber benchmark so that it's possible to test this in the future.

hawkw · 2022-01-28T20:19:29Z

Hmm, I ran the benchmarks on my machine, and I only saw about a 10% difference in the no_subscriber/event benchmark (227.38 ps on master to 284.98 ps on this branch). I'm significantly less concerned about that than a 100% slowdown. I do think that doubling the time to skip a disabled event is worth worrying about, though --- even though it's only measured in picoseconds, I don't think it's great for every disabled event in a program to suddenly cost twice as much. The 10% difference is much less concerning.

I think I'm fine with moving forward with this PR more or less as it is currently, without worrying too much more about this.

tracing-core/src/field.rs

Skepfyr · 2022-01-29T12:15:42Z

Hmm, I ran the benchmarks on my machine, and I only saw about a 10% difference in the no_subscriber/event benchmark (227.38 ps on master to 284.98 ps on this branch)

Huh curious, and thanks for the fix! What needs to be done now to get this to land?

hawkw

I believe this should be ready to merge! Thanks again @Skepfyr for all your hard work on this!

## Motivation Fixes: #196, #1739 Previously, the `field` token trees would be substituted into the log macro invocation and the `ValueSet`, potentially meaning they are executed more than once. ## Solution This changes the `event!` macro (and all the upstream macros like `info!`), so that it only uses each field once when the log feature is enabled. It does this by generating the log using the `ValueSet` meaning the token trees are only substituted once.

@xd009642

# 0.1.22 (February 3, 2022) This release adds *experimental* support for recording structured field values using the [`valuable`] crate. See [this blog post][post] for details on `valuable`. Note that `valuable` support currently requires `--cfg tracing_unstable`. See the documentation for details. ### Added - **field**: Experimental support for recording field values using the [`valuable`] crate ([#1608], [#1888], [#1887]) - **field**: Added `ValueSet::record` method ([#1823]) - **subscriber**: `Default` impl for `NoSubscriber` ([#1785]) - **metadata**: New `Kind::HINT` to support the `enabled!` macro in `tracing` ([#1883], [#1891]) ### Fixed - Fixed a number of documentation issues ([#1665], [#1692], [#1737]) Thanks to @xd009642, @Skepfyr, @guswynn, @Folyd, and @mbergkvist for contributing to this release!

@xd009642

# 0.1.22 (February 3, 2022) This release adds *experimental* support for recording structured field values using the [`valuable`] crate. See [this blog post][post] for details on `valuable`. Note that `valuable` support currently requires `--cfg tracing_unstable`. See the documentation for details. ### Added - **field**: Experimental support for recording field values using the [`valuable`] crate ([#1608], [#1888], [#1887]) - **field**: Added `ValueSet::record` method ([#1823]) - **subscriber**: `Default` impl for `NoSubscriber` ([#1785]) - **metadata**: New `Kind::HINT` to support the `enabled!` macro in `tracing` ([#1883], [#1891]) ### Fixed - Fixed a number of documentation issues ([#1665], [#1692], [#1737]) Thanks to @xd009642, @Skepfyr, @guswynn, @Folyd, and @mbergkvist for contributing to this release! [`valuable`]: https://crates.io/crates/valuable [post]: https://tokio.rs/blog/2021-05-valuable [#1608]: #1608 [#1888]: #1888 [#1887]: #1887 [#1823]: #1823 [#1785]: #1785 [#1883]: #1883 [#1891]: #1891 [#1665]: #1665 [#1692]: #1692 [#1737]: #1737

@vlad-scherbina

# 0.1.30 (February 3rd, 2021) This release adds *experimental* support for recording structured field values using the [`valuable`] crate. See [this blog post][post] for details on `valuable`. Note that `valuable` support currently requires `--cfg tracing_unstable`. See the documentation for details. This release also adds a new `enabled!` macro for testing if a span or event would be enabled. ### Added - **field**: Experimental support for recording field values using the [`valuable`] crate ([#1608], [#1888], [#1887]) - `enabled!` macro for testing if a span or event is enabled ([#1882]) ### Changed - `tracing-core`: updated to [0.1.22][core-0.1.22] - `tracing-attributes`: updated to [0.1.19][attributes-0.1.19] ### Fixed - **log**: Fixed "use of moved value" compiler error when the "log" feature is enabled ([#1823]) - Fixed macro hygiene issues when used in a crate that defines its own `concat!` macro ([#1842]) - A very large number of documentation fixes and improvements. Thanks to @@vlad-scherbina, @Skepfyr, @Swatinem, @guswynn, @teohhanhui, @xd009642, @tobz, @d-e-s-o@0b01, and @nickelc for contributing to this release! [`valuable`]: https://crates.io/crates/valuable [post]: https://tokio.rs/blog/2021-05-valuable [core-0.1.22]: https://github.com/tokio-rs/tracing/releases/tag/tracing-core-0.1.22 [attributes-0.1.19]: https://github.com/tokio-rs/tracing/releases/tag/tracing-attributes-0.1.19 [#1608]: #1608 [#1888]: #1888 [#1887]: #1887 [#1882]: #1882 [#1823]: #1823 [#1842]: #1842

@vlad-scherbina

# 0.1.30 (February 3rd, 2021) This release adds *experimental* support for recording structured field values using the [`valuable`] crate. See [this blog post][post] for details on `valuable`. Note that `valuable` support currently requires `--cfg tracing_unstable`. See the documentation for details. This release also adds a new `enabled!` macro for testing if a span or event would be enabled. ### Added - **field**: Experimental support for recording field values using the [`valuable`] crate ([#1608], [#1888], [#1887]) - `enabled!` macro for testing if a span or event is enabled ([#1882]) ### Changed - `tracing-core`: updated to [0.1.22][core-0.1.22] - `tracing-attributes`: updated to [0.1.19][attributes-0.1.19] ### Fixed - **log**: Fixed "use of moved value" compiler error when the "log" feature is enabled ([#1823]) - Fixed macro hygiene issues when used in a crate that defines its own `concat!` macro ([#1842]) - A very large number of documentation fixes and improvements. Thanks to @@vlad-scherbina, @Skepfyr, @Swatinem, @guswynn, @teohhanhui, @xd009642, @tobz, @d-e-s-o@0b01, and @nickelc for contributing to this release! [`valuable`]: https://crates.io/crates/valuable [post]: https://tokio.rs/blog/2021-05-valuable [core-0.1.22]: https://github.com/tokio-rs/tracing/releases/tag/tracing-core-0.1.22 [attributes-0.1.19]: https://github.com/tokio-rs/tracing/releases/tag/tracing-attributes-0.1.19 [#1608]: #1608 [#1888]: #1888 [#1887]: #1887 [#1882]: #1882 [#1823]: #1823 [#1842]: #1842

## Motivation Fixes: tokio-rs#196, tokio-rs#1739 Previously, the `field` token trees would be substituted into the log macro invocation and the `ValueSet`, potentially meaning they are executed more than once. ## Solution This changes the `event!` macro (and all the upstream macros like `info!`), so that it only uses each field once when the log feature is enabled. It does this by generating the log using the `ValueSet` meaning the token trees are only substituted once.

@xd009642

# 0.1.22 (February 3, 2022) This release adds *experimental* support for recording structured field values using the [`valuable`] crate. See [this blog post][post] for details on `valuable`. Note that `valuable` support currently requires `--cfg tracing_unstable`. See the documentation for details. ### Added - **field**: Experimental support for recording field values using the [`valuable`] crate ([tokio-rs#1608], [tokio-rs#1888], [tokio-rs#1887]) - **field**: Added `ValueSet::record` method ([tokio-rs#1823]) - **subscriber**: `Default` impl for `NoSubscriber` ([tokio-rs#1785]) - **metadata**: New `Kind::HINT` to support the `enabled!` macro in `tracing` ([tokio-rs#1883], [tokio-rs#1891]) ### Fixed - Fixed a number of documentation issues ([tokio-rs#1665], [tokio-rs#1692], [tokio-rs#1737]) Thanks to @xd009642, @Skepfyr, @guswynn, @Folyd, and @mbergkvist for contributing to this release! [`valuable`]: https://crates.io/crates/valuable [post]: https://tokio.rs/blog/2021-05-valuable [tokio-rs#1608]: tokio-rs#1608 [tokio-rs#1888]: tokio-rs#1888 [tokio-rs#1887]: tokio-rs#1887 [tokio-rs#1823]: tokio-rs#1823 [tokio-rs#1785]: tokio-rs#1785 [tokio-rs#1883]: tokio-rs#1883 [tokio-rs#1891]: tokio-rs#1891 [tokio-rs#1665]: tokio-rs#1665 [tokio-rs#1692]: tokio-rs#1692 [tokio-rs#1737]: tokio-rs#1737

@vlad-scherbina

# 0.1.30 (February 3rd, 2021) This release adds *experimental* support for recording structured field values using the [`valuable`] crate. See [this blog post][post] for details on `valuable`. Note that `valuable` support currently requires `--cfg tracing_unstable`. See the documentation for details. This release also adds a new `enabled!` macro for testing if a span or event would be enabled. ### Added - **field**: Experimental support for recording field values using the [`valuable`] crate ([tokio-rs#1608], [tokio-rs#1888], [tokio-rs#1887]) - `enabled!` macro for testing if a span or event is enabled ([tokio-rs#1882]) ### Changed - `tracing-core`: updated to [0.1.22][core-0.1.22] - `tracing-attributes`: updated to [0.1.19][attributes-0.1.19] ### Fixed - **log**: Fixed "use of moved value" compiler error when the "log" feature is enabled ([tokio-rs#1823]) - Fixed macro hygiene issues when used in a crate that defines its own `concat!` macro ([tokio-rs#1842]) - A very large number of documentation fixes and improvements. Thanks to @@vlad-scherbina, @Skepfyr, @Swatinem, @guswynn, @teohhanhui, @xd009642, @tobz, @d-e-s-o@0b01, and @nickelc for contributing to this release! [`valuable`]: https://crates.io/crates/valuable [post]: https://tokio.rs/blog/2021-05-valuable [core-0.1.22]: https://github.com/tokio-rs/tracing/releases/tag/tracing-core-0.1.22 [attributes-0.1.19]: https://github.com/tokio-rs/tracing/releases/tag/tracing-attributes-0.1.19 [tokio-rs#1608]: tokio-rs#1608 [tokio-rs#1888]: tokio-rs#1888 [tokio-rs#1887]: tokio-rs#1887 [tokio-rs#1882]: tokio-rs#1882 [tokio-rs#1823]: tokio-rs#1823 [tokio-rs#1842]: tokio-rs#1842

Skepfyr requested review from carllerche, davidbarsky, hawkw and a team as code owners January 9, 2022 00:40

hawkw requested changes Jan 10, 2022

View reviewed changes

Skepfyr commented Jan 10, 2022

View reviewed changes

tracing/src/macros.rs Outdated Show resolved Hide resolved

Skepfyr added 4 commits January 11, 2022 19:15

tracing: revert fix span macros with log feature

0ad95a9

This reverts commit bc81ef5. The issue with the event macro does not apply to the span macro.

tracing: Move LogValueSet into __macro_support

68b56d0

tracing: Replace std with core in LogVisitor

c20567a

tracing: generate valueset only when needed

50fd7f2

hawkw reviewed Jan 12, 2022

View reviewed changes

Skepfyr added 2 commits January 17, 2022 23:59

tracing: move some macro support behind log feature

b4c6208

tracing: add log_move_arg tests and fix log format

ce02eda

Merge branch 'master' into macros-with-log

a691c5b

hawkw reviewed Jan 19, 2022

View reviewed changes

tracing: Add nop logger to global subcriber bench

a4e8d26

hawkw reviewed Jan 28, 2022

View reviewed changes

tracing-core/src/field.rs Outdated Show resolved Hide resolved

Update tracing-core/src/field.rs

0c1ab2b

hawkw approved these changes Jan 29, 2022

View reviewed changes

hawkw enabled auto-merge (squash) January 29, 2022 19:34

Merge branch 'master' into macros-with-log

794040e

hawkw merged commit 8bbd5d6 into tokio-rs:master Jan 29, 2022

Skepfyr deleted the macros-with-log branch January 30, 2022 00:04

hawkw mentioned this pull request Feb 4, 2022

core: prepare to release v0.1.22 #1897

Merged

hawkw mentioned this pull request Feb 4, 2022

tracing: prepare to release 0.1.30 #1899

Merged

teohhanhui mentioned this pull request Feb 9, 2022

Fix macro hygiene for concat! calls #1842

Merged

hawkw mentioned this pull request Apr 13, 2022

Tracing's log feature should not cause code that would otherwise compile to break #1793

Closed

davidbarsky mentioned this pull request Sep 26, 2023

chore: backport roughly a year's worth of changes #2728

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tracing: fix macros "use of moved value" with log #1823

tracing: fix macros "use of moved value" with log #1823

Skepfyr commented Jan 9, 2022 •

edited

Loading

hawkw left a comment

hawkw Jan 10, 2022

Skepfyr Jan 10, 2022

hawkw left a comment

hawkw Jan 12, 2022

Skepfyr Jan 17, 2022

hawkw Jan 12, 2022

hawkw Jan 12, 2022

hawkw Jan 12, 2022

Skepfyr Jan 17, 2022

hawkw Jan 19, 2022

Skepfyr commented Jan 17, 2022

hawkw commented Jan 19, 2022

hawkw Jan 19, 2022

hawkw Jan 19, 2022

hawkw Jan 19, 2022

Skepfyr Jan 22, 2022

hawkw Jan 28, 2022

Skepfyr commented Jan 23, 2022 •

edited

Loading

hawkw commented Jan 28, 2022

Skepfyr commented Jan 29, 2022

hawkw left a comment

	group.bench_function("span", \|b\| {
	b.iter(\|\| {
	black_box(tracing::span!(Level::TRACE, "span"));
	})
	});
	group.bench_function("event", \|b\| {
	b.iter(\|\| {
	tracing::event!(Level::TRACE, "hello");
	})
	});

	#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
	#[test]
	fn borrow_val_events() {
	// Reproduces https://github.com/tokio-rs/tracing/issues/954
	let mut foo = (String::new(), String::new());
	let zero = &mut foo.0;
	trace!(one = ?foo.1);
	debug!(one = ?foo.1);
	info!(one = ?foo.1);
	warn!(one = ?foo.1);
	error!(one = ?foo.1);
	zero.push_str("hello world");
	}

	#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
	#[test]
	fn borrow_val_spans() {
	// Reproduces https://github.com/tokio-rs/tracing/issues/954
	let mut foo = (String::new(), String::new());
	let zero = &mut foo.0;
	let _span = trace_span!("span", one = ?foo.1);
	let _span = debug_span!("span", one = ?foo.1);
	let _span = info_span!("span", one = ?foo.1);
	let _span = warn_span!("span", one = ?foo.1);
	let _span = error_span!("span", one = ?foo.1);
	zero.push_str("hello world");
	}

tracing: fix macros "use of moved value" with log #1823

tracing: fix macros "use of moved value" with log #1823

Conversation

Skepfyr commented Jan 9, 2022 • edited Loading

Motivation

Solution

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Skepfyr commented Jan 17, 2022

hawkw commented Jan 19, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Skepfyr commented Jan 23, 2022 • edited Loading

hawkw commented Jan 28, 2022

Skepfyr commented Jan 29, 2022

hawkw left a comment

Choose a reason for hiding this comment

Skepfyr commented Jan 9, 2022 •

edited

Loading

Skepfyr commented Jan 23, 2022 •

edited

Loading