short backtraces do not always work on Windows without debug info

[ehuss]

Ever since #75048, RUST_BACKTRACE=1 does not show a backtrace in some situations when compiling with x86_64-pc-windows-msvc. Some examples:

Basic main

fn main() {
    panic!("test");
}

RUST_BACKTRACE=1 cargo run --release

On windows shows:

thread 'main' panicked at 'test', src\main.rs:2:5
stack backtrace:
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

On other platforms, this shows:

thread 'main' panicked at 'test', src/main.rs:2:5
stack backtrace:
   0: std::panicking::begin_panic
   1: foo::main
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

Hm, OK, maybe there's just something weird about main on Windows, let's panic from some function:

fn main() {
    abc();
}

#[inline(never)]
fn abc() {
    panic!("test");
}

Exact same results. I wonder what RUST_BACKTRACE=full shows:

thread 'main' panicked at 'foo', src\main.rs:7:5
stack backtrace:
   0:     0x7ff732d4681e - std::backtrace_rs::backtrace::dbghelp::trace
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\..\..\backtrace\src\backtrace\dbghelp.rs:98
   1:     0x7ff732d4681e - std::backtrace_rs::backtrace::trace_unsynchronized
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66
   2:     0x7ff732d4681e - std::sys_common::backtrace::_print_fmt
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\sys_common\backtrace.rs:67
   3:     0x7ff732d4681e - std::sys_common::backtrace::_print::{{impl}}::fmt
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\sys_common\backtrace.rs:46
   4:     0x7ff732d5390c - core::fmt::write
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\core\src\fmt\mod.rs:1094
   5:     0x7ff732d44dd8 - std::io::Write::write_fmt<std::sys::windows::stdio::Stderr>
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\io\mod.rs:1584
   6:     0x7ff732d48ea2 - std::sys_common::backtrace::_print
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\sys_common\backtrace.rs:49
   7:     0x7ff732d48ea2 - std::sys_common::backtrace::print
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\sys_common\backtrace.rs:36
   8:     0x7ff732d48ea2 - std::panicking::default_hook::{{closure}}
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panicking.rs:208
   9:     0x7ff732d48983 - std::panicking::default_hook
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panicking.rs:225
  10:     0x7ff732d49543 - std::panicking::rust_panic_with_hook
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panicking.rs:591
  11:     0x7ff732d41124 - std::sys_common::backtrace::__rust_begin_short_backtrace::he53d89a2ce3594a8
  12:     0x7ff732d410df - std::sys_common::backtrace::__rust_end_short_backtrace::h5e068a7cabcc7307
  13:     0x7ff732d579fd - std::panicking::begin_panic::h790bdae65623f4e6
  14:     0x7ff732d4115c - std::sys_common::backtrace::__rust_begin_short_backtrace::he53d89a2ce3594a8
  15:     0x7ff732d41139 - std::sys_common::backtrace::__rust_begin_short_backtrace::he53d89a2ce3594a8
  16:     0x7ff732d410f6 - std::sys_common::backtrace::__rust_begin_short_backtrace::he53d89a2ce3594a8
  17:     0x7ff732d4100c - std::rt::lang_start::{{closure}}::h27aee23826ad69ca
  18:     0x7ff732d496e7 - core::ops::function::impls::{{impl}}::call_once
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\library\core\src\ops\function.rs:280
  19:     0x7ff732d496e7 - std::panicking::try::do_call
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panicking.rs:379
  20:     0x7ff732d496e7 - std::panicking::try
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panicking.rs:343
  21:     0x7ff732d496e7 - std::panic::catch_unwind
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panic.rs:431
  22:     0x7ff732d496e7 - std::rt::lang_start_internal
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\rt.rs:34
  23:     0x7ff732d41187 - main
  24:     0x7ff732d56f08 - invoke_main
                               at d:\A01\_work\6\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:78
  25:     0x7ff732d56f08 - __scrt_common_main_seh
                               at d:\A01\_work\6\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288
  26:     0x7ffdb4837034 - BaseThreadInitThunk
  27:     0x7ffdb4c82651 - RtlUserThreadStart

There's a lot of weird __rust_begin_short_backtrace frames in there, and no sign of my abc function. Running with debuginfo:

CARGO_PROFILE_RELEASE_DEBUG=1 RUST_BACKTRACE=1 cargo run --release

thread 'main' panicked at 'foo', src\main.rs:7:5
stack backtrace:
   0:     0x7ff6b37067fe - std::backtrace_rs::backtrace::dbghelp::trace
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\..\..\backtrace\src\backtrace\dbghelp.rs:98
   1:     0x7ff6b37067fe - std::backtrace_rs::backtrace::trace_unsynchronized
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66
   2:     0x7ff6b37067fe - std::sys_common::backtrace::_print_fmt
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\sys_common\backtrace.rs:67
   3:     0x7ff6b37067fe - std::sys_common::backtrace::_print::{{impl}}::fmt
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\sys_common\backtrace.rs:46
   4:     0x7ff6b37138ec - core::fmt::write
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\core\src\fmt\mod.rs:1094
   5:     0x7ff6b3704db8 - std::io::Write::write_fmt<std::sys::windows::stdio::Stderr>
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\io\mod.rs:1584
   6:     0x7ff6b3708e82 - std::sys_common::backtrace::_print
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\sys_common\backtrace.rs:49
   7:     0x7ff6b3708e82 - std::sys_common::backtrace::print
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\sys_common\backtrace.rs:36
   8:     0x7ff6b3708e82 - std::panicking::default_hook::{{closure}}
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panicking.rs:208
   9:     0x7ff6b3708963 - std::panicking::default_hook
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panicking.rs:225
  10:     0x7ff6b3709523 - std::panicking::rust_panic_with_hook
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panicking.rs:591
  11:     0x7ff6b3701094 - std::panicking::begin_panic::{{closure}}<str>
                               at C:\Users\eric\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\panicking.rs:520
  12:     0x7ff6b370104f - std::sys_common::backtrace::__rust_end_short_backtrace<closure-0,!>
                               at C:\Users\eric\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\sys_common\backtrace.rs:
141
  13:     0x7ff6b37179dd - std::panicking::begin_panic<str>
                               at C:\Users\eric\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\panicking.rs:519
  14:     0x7ff6b37010dc - z2::abc
                               at D:\Temp\z2\src\main.rs:7
  15:     0x7ff6b37010b9 - z2::main
                               at D:\Temp\z2\src\main.rs:2
  16:     0x7ff6b3701066 - core::ops::function::FnOnce::call_once
                               at C:\Users\eric\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\core\src\ops\function.rs:227
  17:     0x7ff6b3701066 - std::sys_common::backtrace::__rust_begin_short_backtrace<fn(),tuple<>>
                               at C:\Users\eric\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\sys_common\backtrace.rs:
125
  18:     0x7ff6b370100c - std::rt::lang_start::{{closure}}<tuple<>>
                               at C:\Users\eric\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\rt.rs:49
  19:     0x7ff6b37096c7 - core::ops::function::impls::{{impl}}::call_once
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\library\core\src\ops\function.rs:280
  20:     0x7ff6b37096c7 - std::panicking::try::do_call
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panicking.rs:379
  21:     0x7ff6b37096c7 - std::panicking::try
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panicking.rs:343
  22:     0x7ff6b37096c7 - std::panic::catch_unwind
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\panic.rs:431
  23:     0x7ff6b37096c7 - std::rt::lang_start_internal
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b\/library\std\src\rt.rs:34
  24:     0x7ff6b3701107 - main
  25:     0x7ff6b3716ee8 - invoke_main
                               at d:\A01\_work\6\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:78
  26:     0x7ff6b3716ee8 - __scrt_common_main_seh
                               at d:\A01\_work\6\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288
  27:     0x7ffdb4837034 - BaseThreadInitThunk
  28:     0x7ffdb4c82651 - RtlUserThreadStart

Well at least with debuginfo the frames look much more reasonable.

rustc treat-err-as-bug

Trying to get a backtrace from rustc:

// Some bogus code to trigger a compiler error.
abc

RUSTFLAGS="-Ztreat-err-as-bug" RUST_BACKTRACE=1 cargo build

results in:

thread 'rustc' panicked at 'aborting due to `-Z treat-err-as-bug=1`', compiler\rustc_errors\src\lib.rs:1038:27
stack backtrace:
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

Hmm, no frames at all. Here's what full looks like:

thread 'rustc' panicked at 'aborting due to `-Z treat-err-as-bug=1`', compiler\rustc_errors\src\lib.rs:1038:27
stack backtrace:
   0:     0x7ffd571c73cf - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h6ba2a9241bb86732
   1:     0x7ffd571eff7a - core::fmt::write::ha9fdc24e2055a123
   2:     0x7ffd571ba948 - <std::io::IoSlice as core::fmt::Debug>::fmt::h2f7de836a9fea840
   3:     0x7ffd571cb106 - std::panicking::take_hook::h880a3a97a8692ac2
   4:     0x7ffd571cabe9 - std::panicking::take_hook::h880a3a97a8692ac2
   5:     0x7ffd193546d5 - <sha2::sha512::Sha512Trunc224 as std::io::Write>::flush::hee6b95fd494feb4c
   6:     0x7ffd571cba00 - std::panicking::rust_panic_with_hook::hf71bb7c83433b29f
   7:     0x7ffd1d5adc04 - <rustc_errors::lock::acquire_global_lock::Guard as core::ops::drop::Drop>::drop::h4f8f15aa7cec4dfd
   8:     0x7ffd1d5adb9f - <rustc_errors::lock::acquire_global_lock::Guard as core::ops::drop::Drop>::drop::h4f8f15aa7cec4dfd
   9:     0x7ffd1d86afbd - rustc_query_system::query::job::report_cycle::h6ad95b2abe0c2755
  10:     0x7ffd1d5e2d97 - rustc_errors::HandlerInner::emit_diagnostic::heb8a31dc5e552518
  11:     0x7ffd1d5a6d9d - rustc_errors::diagnostic_builder::DiagnosticBuilder::emit::he0557bac758754fe
  12:     0x7ffd1948b8c5 - rustc_interface::queries::Queries::parse::h62446bebd0215358
  13:     0x7ffd193a9fe1 - <rustc_middle::ty::SymbolName as core::fmt::Debug>::fmt::h1888c009faa2f58c
  14:     0x7ffd1937234d - rustc_driver::pretty::print_after_hir_lowering::h982e6ec8534626ef
  15:     0x7ffd193ac7e9 - <rustc_middle::ty::SymbolName as core::fmt::Debug>::fmt::h1888c009faa2f58c
  16:     0x7ffd1937c9ba - <rustc_middle::ty::SymbolName as core::fmt::Debug>::fmt::h1888c009faa2f58c
  17:     0x7ffd19372f5f - rustc_driver::pretty::print_after_hir_lowering::h982e6ec8534626ef
  18:     0x7ffd193d0f9d - <rustc_driver::args::Error as core::fmt::Debug>::fmt::hac2312e292f84c23
  19:     0x7ffd571d92dc - std::sys::windows::thread::Thread::new::hd7a080f67ca1d43d
  20:     0x7ffdb4837034 - BaseThreadInitThunk
  21:     0x7ffdb4c82651 - RtlUserThreadStart

Notice the complete absence of __rust_begin_short_backtrace.

Larger example

What's strange is that it works sometimes. I figured I'd try a larger example. I put a panic inside cargo itself, and got this:

thread 'main' panicked at 'test', src/cargo\ops\cargo_compile.rs:861:5
stack backtrace:
   0: std::panicking::begin_panic
   1: cargo::ops::cargo_compile::create_bcx
   2: cargo::ops::cargo_compile::compile_ws
   3: cargo::ops::cargo_compile::compile
   4: cargo::commands::check::exec
   5: cargo::cli::main
   6: cargo::commands::owner::exec

Well that's weird! The short backtrace seems to work fine there.

Expected behavior

In general, I would expect it to work like it does on other platforms.

Meta

The short backtraces start with nightly-2020-08-09. In versions prior to that, RUST_BACKTRACE=1 just shows the full backtrace (with all the "noisy" frames). Tested up to nightly-2021-07-26.

[mati865]

Works fine with windows-gnu:

$ RUST_BACKTRACE=1 cargo r
   Compiling panic v0.1.0 (D:\tmp\panic)
    Finished dev [unoptimized + debuginfo] target(s) in 0.66s
     Running `target\debug\panic.exe`
thread 'main' panicked at 'Hello, world!', src\main.rs:2:5
stack backtrace:
   0: std::panicking::begin_panic
             at /rustc/08095fc1f875c89e507f17cf6c6a780c8ffa4c01\library\std\src/panicking.rs:541:12
   1: panic::main
             at .\src/main.rs:2:5
   2: core::ops::function::FnOnce::call_once
             at /rustc/08095fc1f875c89e507f17cf6c6a780c8ffa4c01\library\core\src\ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
error: process didn't exit successfully: `target\debug\panic.exe` (exit code: 101)

$ RUST_BACKTRACE=1 cargo r --release
   Compiling panic v0.1.0 (D:\tmp\panic)
    Finished release [optimized] target(s) in 0.44s
     Running `target\release\panic.exe`
thread 'main' panicked at 'Hello, world!', src\main.rs:2:5
stack backtrace:
   0: std::panicking::begin_panic
   1: panic::main
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
error: process didn't exit successfully: `target\release\panic.exe` (exit code: 101)

$ rustc -vV
rustc 1.56.0-nightly (08095fc1f 2021-07-26)
binary: rustc
commit-hash: 08095fc1f875c89e507f17cf6c6a780c8ffa4c01
commit-date: 2021-07-26
host: x86_64-pc-windows-gnu
release: 1.56.0-nightly
LLVM version: 12.0.1

[wesleywiser]

It looks like there are two issues at play here:

1. Rust (on the windows-msvc target) uses dbghelp.dll to walk and symbolize the stack but Windows doesn't know how to demangle Rust symbols so if there isn't any debug info (pdb files), it can't understand the symbol names. That's why enabling debug info causes the functions to appear. (I see slightly different behavior on my PC where the missing frames are instead included but shown as "__ImageBase" instead of their true function names. Perhaps the behavior in some part of the backtrace machinery on either the Rust or Windows side has changed recently.)

2. In optimized code, __rust_end_short_backtrace ends up calling __rust_begin_short_backtrace . Based on the disassembly, I'm guessing this is a result of some kind of code-sharing optimization LLVM performed since it calls into the middle of that function. However, this messes up the short backtrace formatting machinery which expects to see the begin symbol last and stops walking the stack at that point before it gets to the interesting part! That part should be easy to fix so I will try to get that fixed today or tomorrow.