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

Michael-F-Bryan commented 4 years ago

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:: 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: 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: 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: 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: 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: 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: 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: 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: 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: 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: 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: 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: 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: 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: 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: 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: 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

::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::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::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

::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::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

::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 https://github.com/rust-lang/rust/issues/68336#issuecomment-575916019, 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.

tmandry commented 3 years ago

Possible duplicate of #65978.

tmandry commented 3 years ago

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 commented 3 years ago

@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 commented 3 years ago

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 commented 3 years ago

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 commented 1 year ago

This should be fixed by https://github.com/rust-lang/rust/pull/104321 which gets rid of the GenFuture shim.

tmandry commented 1 year ago

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

rust-lang / rust