Stream: git-wasmtime

Topic: wasmtime / PR #3220 Fix wiggle code generation for correc...

Wasmtime GitHub notifications bot (Aug 20 2021 at 14:50):

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 with in_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.

Wasmtime GitHub notifications bot (Aug 20 2021 at 14:50):

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 with in_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.

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:06):

alexcrichton submitted PR review.

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:06):

alexcrichton submitted PR review.

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:06):

alexcrichton created PR review comment:

Since this call is somewhat nontrivial could this call to span! get pulled out of the two branches of this if and something like let _span = #mk_span; be used in both macros?

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:06):

alexcrichton created PR review comment:

I think the indentation may be a bit off here and below? (to match the indentation above)

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:25):

mgattozzi submitted PR review.

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:25):

mgattozzi created PR review comment:

Yeah! I can do that :+1:🏻

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:30):

mgattozzi updated PR #3220 from mgattozzi/a-fix-that-spans-awaits to main.

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:31):

mgattozzi submitted PR review.

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:31):

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.

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:34):

mgattozzi updated PR #3220 from mgattozzi/a-fix-that-spans-awaits to main.

Wasmtime GitHub notifications bot (Aug 20 2021 at 15:45):

alexcrichton submitted PR review.

Wasmtime GitHub notifications bot (Aug 20 2021 at 16:20):

alexcrichton merged PR #3220.

Last updated: Oct 23 2024 at 20:03 UTC