mgattozzi opened PR #3220 from mgattozzi/a-fix-that-spans-awaits
to main
:
[ ] This has been discussed in issue #..., or if not, please tell us why
here.
This was an issue that @pchickey stumbled on internally at work when testing
out some things and I was asked to take a look at it and figure out what was going on[X] A short description of what this does, why it is needed; if the
description becomes long, the matter should probably be discussed in an issue
first.Fixes incorrect behavior with spans generated by wiggle in asynchronous code.
[X] This PR contains test cases, if meaningful.
N/A but have confirmed in internal testing that this does indeed fix the issue and doesn't break
functionality, just changes the function signatures.[X] A reviewer from the core maintainer team has been assigned for this PR.
If you don't know who could review this, please indicate so. The list of
suggested reviewers on the right can help you.@pchickey asked for me to tag him for review when I put this PR up.
Commit Message Follows:
Up to this point when using wiggle to generate functions we could end up
with two types of functions an async or sync one with this proc macro#[allow(unreachable_code)] // deals with warnings in noreturn functions pub #asyncness fn #ident( ctx: &mut (impl #(#bounds)+*), memory: &dyn #rt::GuestMemory, #(#abi_params),* ) -> Result<#abi_ret, #rt::Trap> { use std::convert::TryFrom as _; let _span = #rt::tracing::span!( #rt::tracing::Level::TRACE, "wiggle abi", module = #mod_name, function = #func_name ); let _enter = _span.enter(); #body }
Now this might seem fine, we just create a span and enter it and run the
body code and we get async versions as well. However, this is where the
source of our problem lies. The impetus for this fix was seeing multiple
request IDs output in the logs for a single function call of a generated
function. Something was clearly happening that shouldn't have been. If
we take a look at the tracing docs here we can see why the above code
will not work in asynchronous code.https://docs.rs/tracing/0.1.26/tracing/span/struct.Span.html#in-asynchronous-code
Warning: in asynchronous code that uses async/await syntax,
Span::enter should be used very carefully or avoided entirely.
Holding the drop guard returned by Span::enter across .await points
will result in incorrect traces.The above documentation provides some more information, but what could
happen is that the#body
itself could contain code that would await
and mess up the tracing that occurred and causing output that would be
completely nonsensical. The code itself should work fine in the
synchronous case though and in cases where await was not called again
inside the body as the future would poll to completion as if it was a
synchronous function.The solution then is to use the newer
Instrument
trait which can make
sure that the span will be entered on every poll of the future. In order
to make sure that we have the same behavior as before we generate
synchronous functions and the ones that were async instead return a
future that uses the instrument trait. This way we can guarantee that
the span is created in synchronous code before being passed into a
future. This does change the function signature, but the functionality
itself is exactly as before and so we should see no actual difference in
how it's used by others. We also just to be safe call the synchronous
version's body within_scope
now as per the docs recommendation even
though it's more intended for calling sync code inside async functions.
Functionally it's the same as before with the call to enter. We also
bump the version of tracing uses so that wiggle can reexport tracing
with the instrument changes.
mgattozzi edited PR #3220 from mgattozzi/a-fix-that-spans-awaits
to main
:
[x] This has been discussed in issue #..., or if not, please tell us why
here.
This was an issue that @pchickey stumbled on internally at work when testing
out some things and I was asked to take a look at it and figure out what was going on[X] A short description of what this does, why it is needed; if the
description becomes long, the matter should probably be discussed in an issue
first.Fixes incorrect behavior with spans generated by wiggle in asynchronous code.
[X] This PR contains test cases, if meaningful.
N/A but have confirmed in internal testing that this does indeed fix the issue and doesn't break
functionality, just changes the function signatures.[X] A reviewer from the core maintainer team has been assigned for this PR.
If you don't know who could review this, please indicate so. The list of
suggested reviewers on the right can help you.@pchickey asked for me to tag him for review when I put this PR up.
Commit Message Follows:
Up to this point when using wiggle to generate functions we could end up
with two types of functions an async or sync one with this proc macro#[allow(unreachable_code)] // deals with warnings in noreturn functions pub #asyncness fn #ident( ctx: &mut (impl #(#bounds)+*), memory: &dyn #rt::GuestMemory, #(#abi_params),* ) -> Result<#abi_ret, #rt::Trap> { use std::convert::TryFrom as _; let _span = #rt::tracing::span!( #rt::tracing::Level::TRACE, "wiggle abi", module = #mod_name, function = #func_name ); let _enter = _span.enter(); #body }
Now this might seem fine, we just create a span and enter it and run the
body code and we get async versions as well. However, this is where the
source of our problem lies. The impetus for this fix was seeing multiple
request IDs output in the logs for a single function call of a generated
function. Something was clearly happening that shouldn't have been. If
we take a look at the tracing docs here we can see why the above code
will not work in asynchronous code.https://docs.rs/tracing/0.1.26/tracing/span/struct.Span.html#in-asynchronous-code
Warning: in asynchronous code that uses async/await syntax,
Span::enter should be used very carefully or avoided entirely.
Holding the drop guard returned by Span::enter across .await points
will result in incorrect traces.The above documentation provides some more information, but what could
happen is that the#body
itself could contain code that would await
and mess up the tracing that occurred and causing output that would be
completely nonsensical. The code itself should work fine in the
synchronous case though and in cases where await was not called again
inside the body as the future would poll to completion as if it was a
synchronous function.The solution then is to use the newer
Instrument
trait which can make
sure that the span will be entered on every poll of the future. In order
to make sure that we have the same behavior as before we generate
synchronous functions and the ones that were async instead return a
future that uses the instrument trait. This way we can guarantee that
the span is created in synchronous code before being passed into a
future. This does change the function signature, but the functionality
itself is exactly as before and so we should see no actual difference in
how it's used by others. We also just to be safe call the synchronous
version's body within_scope
now as per the docs recommendation even
though it's more intended for calling sync code inside async functions.
Functionally it's the same as before with the call to enter. We also
bump the version of tracing uses so that wiggle can reexport tracing
with the instrument changes.
alexcrichton submitted PR review.
alexcrichton submitted PR review.
alexcrichton created PR review comment:
Since this call is somewhat nontrivial could this call to
span!
get pulled out of the two branches of thisif
and something likelet _span = #mk_span;
be used in both macros?
alexcrichton created PR review comment:
I think the indentation may be a bit off here and below? (to match the indentation above)
mgattozzi submitted PR review.
mgattozzi created PR review comment:
Yeah! I can do that :+1:🏻
mgattozzi updated PR #3220 from mgattozzi/a-fix-that-spans-awaits
to main
.
mgattozzi submitted PR review.
mgattozzi created PR review comment:
Yeah cargo fmt can't really handle things inside macros. I think I got it fixed up in the most recent commit as well.
mgattozzi updated PR #3220 from mgattozzi/a-fix-that-spans-awaits
to main
.
alexcrichton submitted PR review.
alexcrichton merged PR #3220.
Last updated: Dec 23 2024 at 12:05 UTC