RUST_BACKTRACE=1 panic output still includes functions called by panic!

[programmerjake]

RUST_BACKTRACE=1 panic output still includes the functions called by the panic! macro. This was previously reported in #37783 but, in the merged fix, only the functions before main were removed. This makes it harder to determine which function the panic occurred in.

In filter_frames, skipped_before is always 0.

[kornelski]

Backtraces printed by panic still contain frames that are internal details, and are not relevant to the panic. This lowers signal to noise ratio of the backtrace and makes it hard to notice where the actual panic is.

fn main() {
    panic!()
}

Prints 24 frames, and only 1 of them is in user code.

stack backtrace:
   0: backtrace::backtrace::`libunwind`::trace
             at /cargo/registry/src/github.aaakk.us.kg-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/github.aaakk.us.kg-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at src/libstd/sys_common/backtrace.rs:84
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at src/libstd/sys_common/backtrace.rs:61
   4: core::fmt::write
             at src/libcore/fmt/mod.rs:1025
   5: std::io::Write::write_fmt
             at src/libstd/io/mod.rs:1426
   6: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:65
   7: std::sys_common::backtrace::print
             at src/libstd/sys_common/backtrace.rs:50
   8: std::panicking::default_hook::{{closure}}
             at src/libstd/panicking.rs:193
   9: std::panicking::default_hook
             at src/libstd/panicking.rs:210
  10: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:471
  11: std::panicking::begin_panic
             at /rustc/f3e1a954d2ead4e2fc197c7da7d71e6c61bad196/src/libstd/panicking.rs:404
  12: playground::main
             at src/main.rs:2
  13: std::rt::lang_start::{{closure}}
             at /rustc/f3e1a954d2ead4e2fc197c7da7d71e6c61bad196/src/libstd/rt.rs:67
  14: std::rt::lang_start_internal::{{closure}}
             at src/libstd/rt.rs:52
  15: std::panicking::try::do_call
             at src/libstd/panicking.rs:292
  16: __rust_maybe_catch_panic
             at src/libpanic_unwind/lib.rs:78
  17: std::panicking::try
             at src/libstd/panicking.rs:270
  18: std::panic::catch_unwind
             at src/libstd/panic.rs:394
  19: std::rt::lang_start_internal
             at src/libstd/rt.rs:51
  20: std::rt::lang_start
             at /rustc/f3e1a954d2ead4e2fc197c7da7d71e6c61bad196/src/libstd/rt.rs:67
  21: main
  22: __libc_start_main
  23: _start

I'd expect the backtrace to at least omit the first 12 frames (0 to 11) after begin_panic, because from user perspective the panic didn't happen in write_fmt or libunwind. It's merely panic's particular implementation exposed as a side effect. Having to skip over 12 frames, with rather noisy function and path names, is a bit much.

[programmerjake]

One idea is to find the first occurrence of std::panicking::begin_panic in the backtrace and to remove up to that frame.

We'd have to be careful to show all frames if begin_panic is somehow not found.

Also, we'd have to make sure that we show S::fmt in:

use std::fmt;

struct S;

impl fmt::Display for S {
    fn fmt(&self, _f: &mut fmt::Formatter) -> fmt::Result {
        panic!("panic2")
    }
}

fn main() {
    panic!("panic1: {}", S)
}

(Playground)

[s97712]

I using std::panic::set_hook capure and filter errors

[sinesc]

I using std::panic::set_hook capure and filter errors

Could you maybe post your hook here or in a gist? I'm getting SIGILL for just trying the example in the docs and I'm about to tear my eyes out if I have to see more spam dumps.

panic::set_hook(Box::new(|panic_info| {
    println!("panic occurred: {:?}", panic_info.payload().downcast_ref::<&str>().unwrap());
}));

> thread panicked while processing panic. aborting.   
> Illegal instruction (core dumped)

[s97712]

I using std::panic::set_hook capure and filter errors

Could you maybe post your hook here or in a gist? I'm getting SIGILL for just trying the example in the docs and I'm about to tear my eyes out if I have to see more spam dumps.

panic::set_hook(Box::new(|panic_info| {
    println!("panic occurred: {:?}", panic_info.payload().downcast_ref::<&str>().unwrap());
}));

> thread panicked while processing panic. aborting.   
> Illegal instruction (core dumped)

You should not call unwrap on the set_hook callback

[HactarCE]

I'm new to the rustc codebase, but it seems like something akin to this could work:

let skipped_before = frames.iter().position(|frame|
    unimplemented!("somehow determine whether `frame` is a call to `begin_panic`")
).map(|i|
    // Exclude the call to `begin_panic()` as well.
    i + 1
).unwrap_or(0);

This should still include the S::fmt call in @programmerjake's example.

[ehuss]

@HactarCE Have you tried the latest beta? RUST_BACKTRACE=1 has been significantly shortened (via #75048). I believe this issue may be resolved.

[HactarCE]

@ehuss Thank you, I just switched to nightly and now everything before begin_panic is excluded. :) Should this issue be closed?

[ehuss]

I'm going to close this as fixed. A backtrace from main now looks like this:

thread 'main' panicked at 'explicit panic', src/main.rs:2:5
stack backtrace:
   0: std::panicking::begin_panic
             at /home/eric/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:505:12
   1: z25::main
             at ./src/main.rs:2:5
   2: core::ops::function::FnOnce::call_once
             at /home/eric/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5