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's log feature should not cause code that would otherwise compile to break #1793

Closed
Noah-Kennedy opened this issue Dec 21, 2021 · 7 comments · Fixed by #2073
Closed
Labels
kind/bug Something isn't working

Comments

@Noah-Kennedy
Copy link

Currently, enabling the log feature in tracing can break code that would otherwise compile, which is a problem, as features are generally supposed to be additive. This leads to situations such as projects breaking when trying to use console, as Tonic enables the default features in tower, which enables this feature in tracing.

There has already been some discussion about this in the discord server.

Thread 1: https://discord.com/channels/500028886025895936/838895414455435335/905519088934211584
Thread 2: https://discord.com/channels/500028886025895936/838895414455435335/921838120788459561

@hawkw hawkw added the kind/bug Something isn't working label Dec 21, 2021
@Noah-Kennedy
Copy link
Author

Noah-Kennedy commented Apr 13, 2022

Bumping this, it's been long enough and it's a very easy problem to hit nowadays, especially with console-subscriber.

@hawkw
Copy link
Member

hawkw commented Apr 13, 2022

I thought this issue was fixed in #1823? Are you still seeing errors with an up-to-date tracing dependency?

@Noah-Kennedy
Copy link
Author

Noah-Kennedy commented Apr 13, 2022

Yes, I am sadly seeing this in v0.1.33

@hawkw
Copy link
Member

hawkw commented Apr 13, 2022

Can you share the error you're seeing? The issue fixed by #1823 is the only one I'm aware of, so I'd like to see if this is the same problem or a different one.

@Noah-Kennedy
Copy link
Author

@hawkw I'll get an mcre up shortly

Noah-Kennedy added a commit to Noah-Kennedy/tower that referenced this issue Apr 13, 2022
Unfortunately, tracing/log is a non-additive feature (tokio-rs/tracing#1793), so enabling it is a bit radioactive.
davidpdrsn pushed a commit to tower-rs/tower that referenced this issue Apr 14, 2022
Unfortunately, tracing/log is a non-additive feature (tokio-rs/tracing#1793), so enabling it is a bit radioactive.
@Noah-Kennedy
Copy link
Author

@hawkw I have an MCRE here: https://github.com/Noah-Kennedy/another-tracing-mcre

In a nutshell:

#[tokio::main(flavor = "current_thread")]
async fn main() {
    tracing_subscriber::fmt().init();
    tokio::spawn(do_request()).await.unwrap();
}

async fn do_request() {
    let response = reqwest::get("https://google.com").await.unwrap();
    tracing::info!("{}", response.text().await.unwrap());
}

This fails with tracing/log enabled because the future returned by do_request is no longer Send, but works without that feature. I suspect that this would work with any await held in that position. I shall attempt to minify further.

@Noah-Kennedy
Copy link
Author

Noah-Kennedy commented Apr 14, 2022

Got it working without reqwest:

#[tokio::main(flavor = "current_thread")]
async fn main() {
    tokio::spawn(do_request()).await.unwrap();
}

async fn do_request() {
    tracing::info!("{}", std::future::ready("test").await);
}

The tokio::spawn is basically just there to assert that the resulting future is Send.

hawkw added a commit that referenced this issue Apr 14, 2022
These pass without the `log` feature enabled, but fail when `log` is
enabled. Thanks @Noah-Kennedy for the original MCRE!
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
kind/bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants