improve RUST_BACKTRACE panic output

[vvuk]

Currently RUST_BACKTRACE output includes a lot of noise, making it hard to see the actual issue. For example:

stack backtrace:
   1:     0x7f69d5ba46da - std::sys::imp::backtrace::tracing::imp::write::he3d1bfbdbf113480
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:42

   2:     0x7f69d5baae2f - std::panicking::default_hook::{{closure}}::h575f1b40d2e88f07
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:247
   3:     0x7f69d5ba90c6 - std::panicking::default_hook::h3d5dccce8125d0cf
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:263
   4:     0x7f69d5ba9777 - std::panicking::rust_panic_with_hook::h00b81bb3dcbd51f2
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:451
   5:     0x7f69d5ba9604 - std::panicking::begin_panic::ha6a0d553db9869ff
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:413
   6:     0x7f69d5ba9529 - std::panicking::begin_panic_fmt::h24d113aee3ee4081
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:397
   7:     0x7f69d5ba94b7 - rust_begin_unwind
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:373
   8:     0x7f69d5be55fd - core::panicking::panic_fmt::he441b2ea2036b98a
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libcore/panicking.rs:69
   9:     0x7f69d5ab93ea - core::result::unwrap_failed::h9123c8d5ed329cea
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libcore/macros.rs:29
  10:     0x7f69d5a7a485 - <core::result::Result<T, E>>::unwrap::had74dea202030e74
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libcore/result.rs:737
  11:     0x7f69d5b635bf - ipc_channel::platform::test::try_recv_large_delayed::{{closure}}::{{closure}}::h2e33a5fda2c9d793
                        at /home/vladimir/proj/ipc-channel/src/platform/test.rs:719
  12:     0x7f69d5b0472a - <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once::h67930f1a73be51d8
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/panic.rs:295
  13:     0x7f69d5a5f087 - std::panicking::try::do_call::h8e541b07456941e1
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:356
  14:     0x7f69d5bb290a - __rust_maybe_catch_panic
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libpanic_unwind/lib.rs:97
  15:     0x7f69d5a5b6d6 - std::panicking::try::h385588122564e243
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:332
  16:     0x7f69d5a4e70e - std::panic::catch_unwind::h7e92894a4b479185
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/panic.rs:351
  17:     0x7f69d5b52940 - std::thread::Builder::spawn::{{closure}}::h6c1a6bd520337fe4
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/thread/mod.rs:287
  18:     0x7f69d5ac32be - <F as alloc::boxed::FnBox<A>>::call_box::h606bb70e048e1567
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/liballoc/boxed.rs:595
  19:     0x7f69d5ba87c4 - std::sys::imp::thread::Thread::new::thread_start::h990fb082eb5abe34
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/liballoc/boxed.rs:605
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/sys_common/thread.rs:21
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../src/libstd/sys/unix/thread.rs:84
  20:     0x7f69d51d8183 - start_thread
  21:     0x7f69d4cda37c - clone
  22:                0x0 - <unknown>

The only actually relevant items start at 9 and go on down, up until 12 or so. Out of 45 lines, only 8 are actually useful! The ones after 12 are just noise and don't hurt much, but the ones at the top make it far more difficult to read. Combine this with the long filenames as a result of standard library pathnames, and RUST_BACKTRACE output is super noisy. Instead, we could do a few things...

(1) Save the rust source location as part of the libstd build and strip it from all output filenames. This would be "/buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/obj/../" and would significantly improve the output:

stack backtrace:
   1:     0x7f69d5ba46da - std::sys::imp::backtrace::tracing::imp::write::he3d1bfbdbf113480
                        at libstd/sys/unix/backtrace/tracing/gcc_s.rs:42
   2:     0x7f69d5baae2f - std::panicking::default_hook::{{closure}}::h575f1b40d2e88f07
                        at libstd/panicking.rs:247
   3:     0x7f69d5ba90c6 - std::panicking::default_hook::h3d5dccce8125d0cf
                        at libstd/panicking.rs:263
   4:     0x7f69d5ba9777 - std::panicking::rust_panic_with_hook::h00b81bb3dcbd51f2
                        at libstd/panicking.rs:451
   5:     0x7f69d5ba9604 - std::panicking::begin_panic::ha6a0d553db9869ff
                        at libstd/panicking.rs:413
   6:     0x7f69d5ba9529 - std::panicking::begin_panic_fmt::h24d113aee3ee4081
                        at libstd/panicking.rs:397
   7:     0x7f69d5ba94b7 - rust_begin_unwind
                        at libstd/panicking.rs:373
   8:     0x7f69d5be55fd - core::panicking::panic_fmt::he441b2ea2036b98a
                        at libcore/panicking.rs:69
   9:     0x7f69d5ab93ea - core::result::unwrap_failed::h9123c8d5ed329cea
                        at libcore/macros.rs:29
  10:     0x7f69d5a7a485 - <core::result::Result<T, E>>::unwrap::had74dea202030e74
                        at libcore/result.rs:737
  11:     0x7f69d5b635bf - ipc_channel::platform::test::try_recv_large_delayed::{{closure}}::{{closure}}::h2e33a5fda2c9d793
                        at /home/vladimir/proj/ipc-channel/src/platform/test.rs:719
  12:     0x7f69d5b0472a - <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once::h67930f1a73be51d8
                        at libstd/panic.rs:295
  13:     0x7f69d5a5f087 - std::panicking::try::do_call::h8e541b07456941e1
                        at libstd/panicking.rs:356
  14:     0x7f69d5bb290a - __rust_maybe_catch_panic
                        at libpanic_unwind/lib.rs:97
  15:     0x7f69d5a5b6d6 - std::panicking::try::h385588122564e243
                        at libstd/panicking.rs:332
  16:     0x7f69d5a4e70e - std::panic::catch_unwind::h7e92894a4b479185
                        at libstd/panic.rs:351
  17:     0x7f69d5b52940 - std::thread::Builder::spawn::{{closure}}::h6c1a6bd520337fe4
                        at libstd/thread/mod.rs:287
  18:     0x7f69d5ac32be - <F as alloc::boxed::FnBox<A>>::call_box::h606bb70e048e1567
                        at liballoc/boxed.rs:595
  19:     0x7f69d5ba87c4 - std::sys::imp::thread::Thread::new::thread_start::h990fb082eb5abe34
                        at liballoc/boxed.rs:605
                        at libstd/sys_common/thread.rs:21
                        at libstd/sys/unix/thread.rs:84
  20:     0x7f69d51d8183 - start_thread
  21:     0x7f69d4cda37c - clone
  22:                0x0 - <unknown>

(2) But the forced (accidental?) alignment makes it hard to scan down the list of functions, so now that we shortened things, we can push the file/line number further right making it much easier to visually scan to find the parts that we care about:

   1:     0x7f69d5ba46da - std::sys::imp::backtrace::tracing::imp::write::he3d1bfbdbf113480
                                at libstd/sys/unix/backtrace/tracing/gcc_s.rs:42
   2:     0x7f69d5baae2f - std::panicking::default_hook::{{closure}}::h575f1b40d2e88f07
                                at libstd/panicking.rs:247
   3:     0x7f69d5ba90c6 - std::panicking::default_hook::h3d5dccce8125d0cf
                                at libstd/panicking.rs:263
   4:     0x7f69d5ba9777 - std::panicking::rust_panic_with_hook::h00b81bb3dcbd51f2
                                at libstd/panicking.rs:451
   5:     0x7f69d5ba9604 - std::panicking::begin_panic::ha6a0d553db9869ff
                                at libstd/panicking.rs:413
   6:     0x7f69d5ba9529 - std::panicking::begin_panic_fmt::h24d113aee3ee4081
                                at libstd/panicking.rs:397
   7:     0x7f69d5ba94b7 - rust_begin_unwind
                                at libstd/panicking.rs:373
   8:     0x7f69d5be55fd - core::panicking::panic_fmt::he441b2ea2036b98a
                                at libcore/panicking.rs:69
   9:     0x7f69d5ab93ea - core::result::unwrap_failed::h9123c8d5ed329cea
                                at libcore/macros.rs:29
  10:     0x7f69d5a7a485 - <core::result::Result<T, E>>::unwrap::had74dea202030e74
                                at libcore/result.rs:737
  11:     0x7f69d5b635bf - ipc_channel::platform::test::try_recv_large_delayed::{{closure}}::{{closure}}::h2e33a5fda2c9d793
                                at /home/vladimir/proj/ipc-channel/src/platform/test.rs:719
  12:     0x7f69d5b0472a - <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once::h67930f1a73be51d8
                                at libstd/panic.rs:295
...

(3) Let's decide to give ourselves 120 columns to work with, and put the file/line on the same line if possible:

   1:     0x7f69d5ba46da - std::sys::imp::backtrace::tracing::imp::write::he3d1bfbdbf113480
                                at libstd/sys/unix/backtrace/tracing/gcc_s.rs:42
   2:     0x7f69d5baae2f - std::panicking::default_hook::{{closure}}::h575f1b40d2e88f07 at libstd/panicking.rs:247
   3:     0x7f69d5ba90c6 - std::panicking::default_hook::h3d5dccce8125d0cf at libstd/panicking.rs:263
   4:     0x7f69d5ba9777 - std::panicking::rust_panic_with_hook::h00b81bb3dcbd51f2 at libstd/panicking.rs:451
   5:     0x7f69d5ba9604 - std::panicking::begin_panic::ha6a0d553db9869ff at libstd/panicking.rs:413
   6:     0x7f69d5ba9529 - std::panicking::begin_panic_fmt::h24d113aee3ee4081 at libstd/panicking.rs:397
   7:     0x7f69d5ba94b7 - rust_begin_unwind at libstd/panicking.rs:373
   8:     0x7f69d5be55fd - core::panicking::panic_fmt::he441b2ea2036b98a at libcore/panicking.rs:69
   9:     0x7f69d5ab93ea - core::result::unwrap_failed::h9123c8d5ed329cea at libcore/macros.rs:29
  10:     0x7f69d5a7a485 - <core::result::Result<T, E>>::unwrap::had74dea202030e74 at libcore/result.rs:737
  11:     0x7f69d5b635bf - ipc_channel::platform::test::try_recv_large_delayed::{{closure}}::{{closure}}::h2e33a5fda2c9d793
                                at /home/vladimir/proj/ipc-channel/src/platform/test.rs:719
  12:     0x7f69d5b0472a - <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once::h67930f1a73be51d8
                                at libstd/panic.rs:295

(4) Much better, but frames 1-8 are still totally worthless. We know that calls to panic!() are going to go through either panicking::panic or panicking::panic_fmt. So, when doing a backtrace, let's skip all frames until we see one of those frames:

{ skipping 8 frames... }
   9:     0x7f69d5ab93ea - core::result::unwrap_failed::h9123c8d5ed329cea at libcore/macros.rs:29
  10:     0x7f69d5a7a485 - <core::result::Result<T, E>>::unwrap::had74dea202030e74 at libcore/result.rs:737
  11:     0x7f69d5b635bf - ipc_channel::platform::test::try_recv_large_delayed::{{closure}}::{{closure}}::h2e33a5fda2c9d793
                                at /home/vladimir/proj/ipc-channel/src/platform/test.rs:719
  12:     0x7f69d5b0472a - <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once::h67930f1a73be51d8
                                at libstd/panic.rs:295
  13:     0x7f69d5a5f087 - std::panicking::try::do_call::h8e541b07456941e1 at libstd/panicking.rs:356
  14:     0x7f69d5bb290a - __rust_maybe_catch_panic at libpanic_unwind/lib.rs:97
  15:     0x7f69d5a5b6d6 - std::panicking::try::h385588122564e243 at libstd/panicking.rs:332
  16:     0x7f69d5a4e70e - std::panic::catch_unwind::h7e92894a4b479185 at libstd/panic.rs:351
  17:     0x7f69d5b52940 - std::thread::Builder::spawn::{{closure}}::h6c1a6bd520337fe4 at libstd/thread/mod.rs:287
  18:     0x7f69d5ac32be - <F as alloc::boxed::FnBox<A>>::call_box::h606bb70e048e1567 at liballoc/boxed.rs:595
  19:     0x7f69d5ba87c4 - std::sys::imp::thread::Thread::new::thread_start::h990fb082eb5abe34
                                at liballoc/boxed.rs:605
                                at libstd/sys_common/thread.rs:21
                                at libstd/sys/unix/thread.rs:84
  20:     0x7f69d51d8183 - start_thread
  21:     0x7f69d4cda37c - clone
  22:                0x0 - <unknown>

Finally, we could disable all the output optimizations via RUST_BACKTRACE=2 or similar, so that if there are any tools that want a consistent format to deal with, they can still get it.

I'm happy to hack on this if there's interest.

[alexcrichton]

These all sound like amazing suggestions to me, especially printing everything on RUST_BACKTRACE=2 but keeping it quiet by default.

If you need any help getting up and running with this just let me know!

[Yamakaky]

Maybe RUST_BACKTRACE=full to see all the frames.
Other idea: shorten /home/vladimir/proj/ipc-channel. Maybe by checking pwd?
Also, when you use cargo, you don't really care what is the absolute path of the dependencies, you just want it's name + filename.
Finally, most of the time you don't care about the function address. Maybe RUST_BACKTRACE=short?

[vvuk]

full sounds good. I've been busy with servo stuff, but I'm going to work on this over the holidays. I'm motivated every time I get a backtrace :)

[Yamakaky]

Also, with RUST_BACKTRACE=short, it could remove the ::h990fb082eb5abe34 part.
In fact, I think short could be the default, and full would keep all.

[Yamakaky]

I'm working on this issue! Any idea how I could get the buildroot?

[binarycrusader]

I ran into this today, but have additional suggestions. For testing purposes, it would be incredibly helpful if there was a RUST_BACKTRACE=$cfg, where in my case it would be RUST_BACKTRACE=test and if the default stacktrace was a little more informative.

Here's why I'd like to see that; I was working on a unit test today that called a helper function in a test module that panics if certain conditions are not met.

Here's the project structure:

src/
  lib.rs
tests/
   action.rs
   utils/
     mod.rs

Here's the failure I encountered when running "cargo test":

$ cargo test
    Finished debug [unoptimized + debuginfo] target(s) in 0.0 secs
     Running target/debug/action-80d4ecacee9f9bcc

running 4 tests
test license ... ok
test errors ... FAILED
test parser ... ok
test tostr ... ok

failures:

---- errors stdout ----
	thread 'errors' panicked at 'Action not invalid: depend type=require', /builds/rsdev/tests/utils/mod.rs:105
note: Run with `RUST_BACKTRACE=1` for a backtrace.
...

This wasn't as helpful as I hoped by default, since I expected it to show me at the very least which function called the function that panicked.

So, I dutifully tried setting RUST_BACKTRACE=1 as suggested:

$ RUST_BACKTRACE=1 cargo test
    Finished debug [unoptimized + debuginfo] target(s) in 0.0 secs
     Running target/debug/action-80d4ecacee9f9bcc

running 4 tests
test license ... ok
test parser ... ok
test tostr ... ok
test errors ... FAILED

failures:

---- errors stdout ----
	thread 'errors' panicked at 'Action not invalid: depend type=require', /builds/rsdev/tests/utils/mod.rs:105
stack backtrace:
   1:     0x560d0dbebb5a - std::sys::imp::backtrace::tracing::imp::write::h917062bce4ff48c3
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:42
   2:     0x560d0dbf066f - std::panicking::default_hook::{{closure}}::h0bacac31b5ed1870
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:247
   3:     0x560d0dbee8a5 - std::panicking::default_hook::h5897799da33ece67
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:257
   4:     0x560d0dbeefb7 - std::panicking::rust_panic_with_hook::h109e116a3a861224
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:451
   5:     0x560d0dbeee44 - std::panicking::begin_panic::hbb38be1379e09df0
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:413
   6:     0x560d0dbeed69 - std::panicking::begin_panic_fmt::h26713cea9bce3ab0
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:397

This wasn't as helpful as I hoped by defa
   7:     0x560d0db4550b - action::utils::assert_invalid::h8e7640be05700633
                        at /builds/rsdev/tests/utils/mod.rs:105
   8:     0x560d0db4cb86 - action::errors::h54693ccbd5897fb6
                        at /builds/rsdev/tests/action.rs:389
   9:     0x560d0db5c3fe - <F as test::FnBox<T>>::call_box::he8581d59e8028413
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libtest/lib.rs:1265
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libtest/lib.rs:141
  10:     0x560d0dbf814a - __rust_maybe_catch_panic
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libpanic_unwind/lib.rs:97
  11:     0x560d0db514ef - std::panicking::try::do_call::h636b19c00d03e824
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:332
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panic.rs:351
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libtest/lib.rs:1210
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panic.rs:295
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:356
  12:     0x560d0dbf814a - __rust_maybe_catch_panic
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libpanic_unwind/lib.rs:97
  13:     0x560d0db57812 - <F as alloc::boxed::FnBox<A>>::call_box::h15256864a2eaf226
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:332
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panic.rs:351
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/thread/mod.rs:287
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/liballoc/boxed.rs:595
  14:     0x560d0dbee014 - std::sys::imp::thread::Thread::new::thread_start::ha102a6120fc52763
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/liballoc/boxed.rs:605
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/sys_common/thread.rs:21
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/sys/unix/thread.rs:84
  15:     0x7fa3b5c126b9 - start_thread
  16:     0x7fa3b573282c - clone
  17:                0x0 - <unknown>

As @vvuk noted, there's a lot of noise here and it isn't until entry 7 that we actually see the output I care about or expect. In addition, in the context of "cargo test", or specifically, in the context of #[test], I only care about entry 8 as well -- everything after that is outside of the unit test and so is probably completely irrelevant to the problem I'm debugging. So if there was a way to to have RUST_BACKTRACE elide the initial frames up to the one that contains the panic!, and then all of the frames after #[test] that would help significantly.

If we apply @vvuk's suggestions and my own, the output becomes substantially more readable:

$ RUST_BACKTRACE=test cargo test
    Finished debug [unoptimized + debuginfo] target(s) in 0.0 secs
     Running target/debug/action-80d4ecacee9f9bcc

running 4 tests
test license ... ok
test parser ... ok
test tostr ... ok
test errors ... FAILED

failures:

---- errors stdout ----
	thread 'errors' panicked at 'Action not invalid: depend type=require', /builds/rsdev/tests/utils/mod.rs:105
stack backtrace:
   1:     0x560d0db4550b - action::utils::assert_invalid::h8e7640be05700633
                        at /builds/rsdev/tests/utils/mod.rs:105
   2:     0x560d0db4cb86 - action::errors::h54693ccbd5897fb6
                        at /builds/rsdev/tests/action.rs:389

Now the error from the test is clear and concise, and I only have to read the information I care about when testing.

Update: To be clear, I'm relatively new to rust, so I have no idea if my crazy idea of specifying a cfg works, or if you even know that a given frame is from some function marked with #[test].

[codyps]

It seems like the "bad file paths" could be fixed with #38322 (remapping paths in debug info), and updating the release builders to use some short, sensible path.