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.

Sign up for GitHub

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

Jump to bottom

Backtraces shouldn't show stack frames generated by the implementation of async-await #74779

Closed
Michael-F-Bryan opened this issue Jul 26, 2020 · 7 comments
Closed

Backtraces shouldn't show stack frames generated by the implementation of async-await #74779

Michael-F-Bryan opened this issue Jul 26, 2020 · 7 comments
Labels
A-async-await Area: Async & Await A-runtime Area: std's runtime and "pre-main" init for handling backtraces, unwinds, stack overflows AsyncAwait-Triaged Async-await issues that have been triaged during a working group meeting. C-enhancement Category: An issue proposing an enhancement or a PR with one.

Comments

@Michael-F-Bryan
Copy link

Description

To reduce unnecessary noise while debugging, calls to the poll() method automatically generated by async-await's syntactic sugar should be hidden when generating a backtrace with RUST_BACKTRACE=1.

Actual Behaviour

As an example, this is a backtrace generated from a bot I've been playing around with:

Backtrace with 49 stack frames, of which 12 are calls to core::future::from_generator::GenFuture<T>::poll()`. 
Error: webdriver returned error: Dismissed user prompt dialog: undefined

Stack backtrace:
   0: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/anyhow-1.0.32/src/backtrace.rs:26
   1: bot::client::Client::goto_direct::{{closure}}
             at ./src/client.rs:66
   2: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
   3: bot::client::Client::goto::{{closure}}
             at ./src/client.rs:83
   4: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
   5: bot::trading::send_trades::{{closure}}::{{closure}}
             at ./src/trading.rs:33
   6: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
   7: <tracing_futures::Instrumented<T> as core::future::future::Future>::poll
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-futures-0.2.4/src/lib.rs:258
   8: bot::trading::send_trades::{{closure}}
             at ./src/trading.rs:28
   9: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  10: bot::schedule::execute_action::{{closure}}
             at ./src/schedule.rs:98
  11: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  12: bot::schedule::Scheduler::step::{{closure}}::{{closure}}::{{closure}}
             at ./src/schedule.rs:55
  13: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  14: bot::schedule::Scheduler::step::{{closure}}::{{closure}}
             at ./src/schedule.rs:42
  15: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  16: <tracing_futures::Instrumented<T> as core::future::future::Future>::poll
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-futures-0.2.4/src/lib.rs:258
  17: bot::schedule::Scheduler::step::{{closure}}
             at ./src/schedule.rs:42
  18: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  19: trading_bot::run::{{closure}}::{{closure}}::{{closure}}
             at src/bin/trading-bot.rs:38
  20: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  21: bot::utils::run_with_geckodriver::{{closure}}
             at ./src/utils.rs:32
  22: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  23: trading_bot::run::{{closure}}
             at src/bin/trading-bot.rs:31
  24: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  25: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/future.rs:119
  26: trading_bot::main::{{closure}}::{{closure}}
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/macros/select.rs:390
  27: <tokio::future::poll_fn::PollFn<F> as core::future::future::Future>::poll
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/future/poll_fn.rs:36
  28: trading_bot::main::{{closure}}
             at src/bin/trading-bot.rs:20
  29: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  30: tokio::runtime::basic_scheduler::BasicScheduler<P>::block_on::{{closure}}::{{closure}}
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/basic_scheduler.rs:131
  31: tokio::coop::with_budget::{{closure}}
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/coop.rs:127
  32: std::thread::local::LocalKey<T>::try_with
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:263
  33: std::thread::local::LocalKey<T>::with
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:239
  34: tokio::coop::with_budget
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/coop.rs:120
      tokio::coop::budget
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/coop.rs:96
      tokio::runtime::basic_scheduler::BasicScheduler<P>::block_on::{{closure}}
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/basic_scheduler.rs:131
  35: tokio::runtime::basic_scheduler::enter::{{closure}}
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/basic_scheduler.rs:213
  36: tokio::macros::scoped_tls::ScopedKey<T>::set
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/macros/scoped_tls.rs:63
  37: tokio::runtime::basic_scheduler::enter
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/basic_scheduler.rs:213
  38: tokio::runtime::basic_scheduler::BasicScheduler<P>::block_on
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/basic_scheduler.rs:123
  39: tokio::runtime::Runtime::block_on::{{closure}}
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/mod.rs:444
  40: tokio::runtime::context::enter
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/context.rs:72
  41: tokio::runtime::handle::Handle::enter
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/handle.rs:76
  42: tokio::runtime::Runtime::block_on
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/mod.rs:441
  43: trading_bot::main
             at src/bin/trading-bot.rs:11
  44: std::rt::lang_start::{{closure}}
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/rt.rs:67
  45: std::rt::lang_start_internal::{{closure}}
             at src/libstd/rt.rs:52
      std::panicking::try::do_call
             at src/libstd/panicking.rs:348
      std::panicking::try
             at src/libstd/panicking.rs:325
      std::panic::catch_unwind
             at src/libstd/panic.rs:394
      std::rt::lang_start_internal
             at src/libstd/rt.rs:51
  46: std::rt::lang_start
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/rt.rs:67
  47: main
  48: __libc_start_main
  49: _start
RUST_BACKTRACE=full cargo run --bin trading-bot  46.96s user 1.97s system 1% cpu 1:14:13.20 total

Ignoring the initial tokio setup code (frame 25 and later), every second frame in the backtrace contains the exact same text:

  20: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/michael/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78

Expected Behaviour

Frames containing core::future::from_generator::GenFuture<T>::poll() should be ignored because they are not relevant (and indeed, not even accessible) to the developer while debugging.

Compare the previous backtrace a version that removes the GenFuture::poll() stack frames:

Stack backtrace:
   0: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/anyhow-1.0.32/src/backtrace.rs:26
   1: bot::client::Client::goto_direct::{{closure}}
             at ./src/client.rs:66
   3: bot::client::Client::goto::{{closure}}
             at ./src/client.rs:83
   5: bot::trading::send_trades::{{closure}}::{{closure}}
             at ./src/trading.rs:33
   7: <tracing_futures::Instrumented<T> as core::future::future::Future>::poll
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-futures-0.2.4/src/lib.rs:258
   8: bot::trading::send_trades::{{closure}}
             at ./src/trading.rs:28
  10: bot::schedule::execute_action::{{closure}}
             at ./src/schedule.rs:98
  12: bot::schedule::Scheduler::step::{{closure}}::{{closure}}::{{closure}}
             at ./src/schedule.rs:55
  14: bot::schedule::Scheduler::step::{{closure}}::{{closure}}
             at ./src/schedule.rs:42
  16: <tracing_futures::Instrumented<T> as core::future::future::Future>::poll
             at /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-futures-0.2.4/src/lib.rs:258
  17: bot::schedule::Scheduler::step::{{closure}}
             at ./src/schedule.rs:42
  19: trading_bot::run::{{closure}}::{{closure}}::{{closure}}
             at src/bin/trading-bot.rs:38
  21: bot::utils::run_with_geckodriver::{{closure}}
             at ./src/utils.rs:32
  23: trading_bot::run::{{closure}}
             at src/bin/trading-bot.rs:31

(tokio and std frames elided)

Because the GenFuture adapter is unique to async-await it should be relatively safe to add it to the list of functions ignored when printing a backtrace.

Prior Art

As mentioned in #68336 (comment), trying to simplify backtraces is something that's had a lot of work in the past:

I would say this is a duplicate of #58554. There is a long history of filtering irrelevant frames, see #38165 (implemented filtering), #25621, #60852 removed the (broken) filtering when switching to the backtrace crate.

This might overlap with #68336 in that a rustc-internal attribute could be used when generating a backtrace to know what frames can be skipped. That issue mentions #[track_caller], but I'd probably create a #[rustc_backtrace_skip] attribute just for this.
@camelid camelid added A-async-await Area: Async & Await A-runtime Area: std's runtime and "pre-main" init for handling backtraces, unwinds, stack overflows C-enhancement Category: An issue proposing an enhancement or a PR with one. labels Oct 20, 2020
@tmandry
Copy link
Member

tmandry commented Nov 10, 2020

Possible duplicate of #65978.

@tmandry tmandry added the AsyncAwait-Triaged Async-await issues that have been triaged during a working group meeting. label Nov 10, 2020
@tmandry
Copy link
Member

tmandry commented Nov 10, 2020 •
edited
Loading

Something like #[rustc_backtrace_skip] could possibly be implemented with a DWARF annotation which is noticed during symbolization, but I'm not sure if one exists for this purpose.

@Michael-F-Bryan
Copy link
Author

@tmandry I wouldn't say this is a direct duplicate, more a related issue around how async-await gets desugared. From what I can tell #65978 is about useless symbols being added to the binary, whereas this issue is just about them being visible in a backtrace.

@Fishrock123
Copy link
Contributor

As someone who writes a lot of async rust (using async-std), this would be super handy.

Some of my team members are also less experienced Rust programmers and it;s hard to expect them to know how to filter through this.

I know it's out of scope of this, but related, a similar functionality in debuggers would often be super handy.

@daagaak
Copy link

daagaak commented Apr 13, 2021

As another side-effect, this makes the output of cargo bloat almost useless on an async binary:

File  .text    Size          Crate                                                                                                   Name
0.1%   5.9%  4.8KiB           core  <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::hbd1752d4c361ba61
0.1%   5.4%  4.4KiB           core  <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h05a946c21ab31fc7
0.1%   4.2%  3.4KiB           core                           <core::pin::Pin<P> as core::future::future::Future>::poll::hfba30f8ce2047a18
0.1%   3.0%  2.5KiB           core  <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h7dfb71c4afb99822
...

@Swatinem
Copy link
Contributor

This should be fixed by #104321 which gets rid of the GenFuture shim.

@tmandry
Copy link
Member

tmandry commented Dec 9, 2022

I don't have a reproducer handy but can confirm the PR looks like it fixes this. Please reopen if not!

@tmandry tmandry closed this as completed Dec 9, 2022
This was referenced Jan 16, 2023
Closed
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
A-async-await Area: Async & Await A-runtime Area: std's runtime and "pre-main" init for handling backtraces, unwinds, stack overflows AsyncAwait-Triaged Async-await issues that have been triaged during a working group meeting. C-enhancement Category: An issue proposing an enhancement or a PR with one.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@Swatinem @Fishrock123 @tmandry @daagaak @Michael-F-Bryan @camelid