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

tracing macros awaiting Future is not Send with feature 'log' #1487

Closed
b-zee opened this issue Aug 3, 2021 · 2 comments · Fixed by #2073
Closed

tracing macros awaiting Future is not Send with feature 'log' #1487

b-zee opened this issue Aug 3, 2021 · 2 comments · Fixed by #2073
Labels
crate/log Related to the `tracing-log` crate crate/tracing Related to the `tracing` crate kind/bug Something isn't working

Comments

@b-zee
Copy link

b-zee commented Aug 3, 2021

Bug Report

Version

$ cargo tree | grep tracing
└── tracing v0.1.26
    ├── tracing-attributes v0.1.15 (proc-macro)
    └── tracing-core v0.1.18

Description

Consider the following example, where a debug event is created from a Future that is awaited.

// src/main.rs
fn main() {
    tokio::spawn(async {
        tracing::debug!("{:?}", async { 5 }.await);
    });
}

This works like it should, except with the log feature.

# Cargo.toml
tracing = { version = "0.1.26", features = [ "log" ] }

Result:

error: future cannot be sent between threads safely
   --> src/main.rs:2:5
    |
2   |     tokio::spawn(async {
    |     ^^^^^^^^^^^^ future created by async block is not `Send`
    | 
   ::: ~/.local/share/cargo/registry/src/git.luolix.top-1ecc6299db9ec823/tokio-1.9.0/src/task/spawn.rs:127:21
    |
127 |         T: Future + Send + 'static,
    |                     ---- required by this bound in `tokio::spawn`
    |
    = help: within `[ArgumentV1<'_>]`, the trait `Sync` is not implemented for `core::fmt::Opaque`
note: future is not `Send` as this value is used across an await
   --> src/main.rs:3:33
    |
3   |         tracing::debug!("{:?}", async { 5 }.await);
    |         ------------------------^^^^^^^^^^^^^^^^^--
    |         |                       |
    |         |                       await occurs here, with `log::Record::builder()` maybe used later
    |         `log::Record::builder()` is later dropped here
    |         has type `RecordBuilder<'_>` which is not `Send`
help: consider moving this into a `let` binding to create a shorter lived borrow
   --> src/main.rs:3:9
    |
3   |         tracing::debug!("{:?}", async { 5 }.await);
    |         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    = note: this error originates in the macro `$crate::__tracing_log` (in Nightly builds, run with -Z macro-backtrace for more info)

error: aborting due to previous error

error: could not compile `project`
@hawkw
Copy link
Member

hawkw commented Aug 3, 2021

As a workaround, consider something like:

let x = async { 5 }.await;
tracing::debug!("{:?}", x);

which should work regardless of whether or not the log feature is enabled.

I'm not sure if this is something we can easily fix in tracing (it may require changing something in the log crate), but I'll take a look.

@hawkw hawkw added crate/log Related to the `tracing-log` crate crate/tracing Related to the `tracing` crate kind/bug Something isn't working labels Aug 3, 2021
joshuef pushed a commit to maidsafe/temp_safe_network that referenced this issue Aug 9, 2021
The tracing crate has a bug when the log feature is enabled. This log
feature is enabled by deep dependencies of self_update. See the issue on
tracing repo here: tokio-rs/tracing#1487

This fix means the API can be used in a Send-context again.
@jplatte
Copy link
Member

jplatte commented Sep 21, 2021

Just stumbled upon this (see reference above), rustc was super unhelpful in pinning down what caused the issue (I even thought I had a fix temporarily when I tried to fix this in an entirely different way). Would be very nice if this was just fixed.

hawkw added a commit that referenced this issue Apr 14, 2022
)

## Motivation

Currently, enabling the `log` feature can cause a compilation error when
using `tracing` macros in async functions or blocks. This is because,
when the `log` feature is enabled, the `tracing` macros will construct a
`log::Record`, which is not `Send`, causing the async fn/block future to
become `!Send`. This can break compilation when the future is `Send`
without the `log` feature enabled. This is really not great, as it makes
the feature no longer purely additive.

## Solution

This branch fixes the issue by moving the `log::Record` construction
behind a function call. Because the `log::Record` is now only
constructed inside of a function, the `log::Record` is now never a local
variable within the async block, so it no longer affects the future's
auto traits. 

It's kind of a shame that the compiler can't otherwise determine that
the `log::Record` can never be held across an await point, but sticking
it in a separate function makes this obvious to the compiler. Also, as a
side benefit, this may reduce the size of macro-generated code when the
`log` feature is enabled a bit, which could improve performance
marginally in some cases.

I added two tests ensuring that `async fn` and `async` block futures are
`Send` when containing `tracing` macro calls. Previously, on `master`,
these failed when the `log` feature is enabled. After this change, the
tests now pass. Thanks to @Noah-Kennedy for the original MCRE these
tests were based on!

Finally, while I was here, I took advantage of the opportunity to clean
up the log integration code a bit. Now that the `log::Record`
construction is behind a function call in `__macro_support`, the
`LogValueSet` type, which is used to wrap a `ValueSet` and implement
`fmt::Display` to add it to the textual message of `log::Record`, no
longer needs to be exposed to the macros, so it can be made properly
private, rather than `#[doc(hidden)] pub`. Also, I noticed that the
`span` module implemented its own versions of `LogValueSet` (`FmtAttrs`
and `FmtValues`), which were essentially duplicating the same behavior
for logging span fields. I removed these and changed this code to use
the `LogValueSet` type instead (which will format string `message`
fields slightly nicer as well).

Fixes #1793
Fixes #1487

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this issue Apr 14, 2022
)

## Motivation

Currently, enabling the `log` feature can cause a compilation error when
using `tracing` macros in async functions or blocks. This is because,
when the `log` feature is enabled, the `tracing` macros will construct a
`log::Record`, which is not `Send`, causing the async fn/block future to
become `!Send`. This can break compilation when the future is `Send`
without the `log` feature enabled. This is really not great, as it makes
the feature no longer purely additive.

## Solution

This branch fixes the issue by moving the `log::Record` construction
behind a function call. Because the `log::Record` is now only
constructed inside of a function, the `log::Record` is now never a local
variable within the async block, so it no longer affects the future's
auto traits.

It's kind of a shame that the compiler can't otherwise determine that
the `log::Record` can never be held across an await point, but sticking
it in a separate function makes this obvious to the compiler. Also, as a
side benefit, this may reduce the size of macro-generated code when the
`log` feature is enabled a bit, which could improve performance
marginally in some cases.

I added two tests ensuring that `async fn` and `async` block futures are
`Send` when containing `tracing` macro calls. Previously, on `master`,
these failed when the `log` feature is enabled. After this change, the
tests now pass. Thanks to @Noah-Kennedy for the original MCRE these
tests were based on!

Finally, while I was here, I took advantage of the opportunity to clean
up the log integration code a bit. Now that the `log::Record`
construction is behind a function call in `__macro_support`, the
`LogValueSet` type, which is used to wrap a `ValueSet` and implement
`fmt::Display` to add it to the textual message of `log::Record`, no
longer needs to be exposed to the macros, so it can be made properly
private, rather than `#[doc(hidden)] pub`. Also, I noticed that the
`span` module implemented its own versions of `LogValueSet` (`FmtAttrs`
and `FmtValues`), which were essentially duplicating the same behavior
for logging span fields. I removed these and changed this code to use
the `LogValueSet` type instead (which will format string `message`
fields slightly nicer as well).

Fixes #1793
Fixes #1487

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this issue Apr 14, 2022
)

## Motivation

Currently, enabling the `log` feature can cause a compilation error when
using `tracing` macros in async functions or blocks. This is because,
when the `log` feature is enabled, the `tracing` macros will construct a
`log::Record`, which is not `Send`, causing the async fn/block future to
become `!Send`. This can break compilation when the future is `Send`
without the `log` feature enabled. This is really not great, as it makes
the feature no longer purely additive.

## Solution

This branch fixes the issue by moving the `log::Record` construction
behind a function call. Because the `log::Record` is now only
constructed inside of a function, the `log::Record` is now never a local
variable within the async block, so it no longer affects the future's
auto traits.

It's kind of a shame that the compiler can't otherwise determine that
the `log::Record` can never be held across an await point, but sticking
it in a separate function makes this obvious to the compiler. Also, as a
side benefit, this may reduce the size of macro-generated code when the
`log` feature is enabled a bit, which could improve performance
marginally in some cases.

I added two tests ensuring that `async fn` and `async` block futures are
`Send` when containing `tracing` macro calls. Previously, on `master`,
these failed when the `log` feature is enabled. After this change, the
tests now pass. Thanks to @Noah-Kennedy for the original MCRE these
tests were based on!

Finally, while I was here, I took advantage of the opportunity to clean
up the log integration code a bit. Now that the `log::Record`
construction is behind a function call in `__macro_support`, the
`LogValueSet` type, which is used to wrap a `ValueSet` and implement
`fmt::Display` to add it to the textual message of `log::Record`, no
longer needs to be exposed to the macros, so it can be made properly
private, rather than `#[doc(hidden)] pub`. Also, I noticed that the
`span` module implemented its own versions of `LogValueSet` (`FmtAttrs`
and `FmtValues`), which were essentially duplicating the same behavior
for logging span fields. I removed these and changed this code to use
the `LogValueSet` type instead (which will format string `message`
fields slightly nicer as well).

Fixes #1793
Fixes #1487

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
kaffarell pushed a commit to kaffarell/tracing that referenced this issue May 22, 2024
…kio-rs#2073)

## Motivation

Currently, enabling the `log` feature can cause a compilation error when
using `tracing` macros in async functions or blocks. This is because,
when the `log` feature is enabled, the `tracing` macros will construct a
`log::Record`, which is not `Send`, causing the async fn/block future to
become `!Send`. This can break compilation when the future is `Send`
without the `log` feature enabled. This is really not great, as it makes
the feature no longer purely additive.

## Solution

This branch fixes the issue by moving the `log::Record` construction
behind a function call. Because the `log::Record` is now only
constructed inside of a function, the `log::Record` is now never a local
variable within the async block, so it no longer affects the future's
auto traits.

It's kind of a shame that the compiler can't otherwise determine that
the `log::Record` can never be held across an await point, but sticking
it in a separate function makes this obvious to the compiler. Also, as a
side benefit, this may reduce the size of macro-generated code when the
`log` feature is enabled a bit, which could improve performance
marginally in some cases.

I added two tests ensuring that `async fn` and `async` block futures are
`Send` when containing `tracing` macro calls. Previously, on `master`,
these failed when the `log` feature is enabled. After this change, the
tests now pass. Thanks to @Noah-Kennedy for the original MCRE these
tests were based on!

Finally, while I was here, I took advantage of the opportunity to clean
up the log integration code a bit. Now that the `log::Record`
construction is behind a function call in `__macro_support`, the
`LogValueSet` type, which is used to wrap a `ValueSet` and implement
`fmt::Display` to add it to the textual message of `log::Record`, no
longer needs to be exposed to the macros, so it can be made properly
private, rather than `#[doc(hidden)] pub`. Also, I noticed that the
`span` module implemented its own versions of `LogValueSet` (`FmtAttrs`
and `FmtValues`), which were essentially duplicating the same behavior
for logging span fields. I removed these and changed this code to use
the `LogValueSet` type instead (which will format string `message`
fields slightly nicer as well).

Fixes tokio-rs#1793
Fixes tokio-rs#1487

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
crate/log Related to the `tracing-log` crate crate/tracing Related to the `tracing` crate kind/bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants