short backtraces do not always work on Windows without debug info #87481

ehuss · 2021-07-26T14:05:59Z

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.

The text was updated successfully, but these errors were encountered:

mati865 · 2021-07-27T17:23:57Z

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 · 2021-07-27T17:31:51Z

It looks like there are two issues at play here:

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.)
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.

…ktraces_windows_optimized, r=dtolnay [backtraces]: look for the `begin` symbol only after seeing `end` On `x86_64-pc-windows-msvc`, we often get backtraces which look like this: ``` 10: 0x7ff77e0e9be5 - std::panicking::rust_panic_with_hook 11: 0x7ff77e0e11b4 - std::sys_common::backtrace::__rust_begin_short_backtrace::h5769736bdb11136c 12: 0x7ff77e0e116f - std::sys_common::backtrace::__rust_end_short_backtrace::h61c7ecb1b55338ae 13: 0x7ff77e0f89dd - std::panicking::begin_panic::h8e60ef9f82a41805 14: 0x7ff77e0e108c - d 15: 0x7ff77e0e1069 - c 16: 0x7ff77e0e1059 - b 17: 0x7ff77e0e1049 - a 18: 0x7ff77e0e1039 - core::ptr::drop_in_place<std::rt::lang_start<()>::{{closure}}>::h1bfcd14d5e15ba81 19: 0x7ff77e0e1186 - std::sys_common::backtrace::__rust_begin_short_backtrace::h5769736bdb11136c 20: 0x7ff77e0e100c - std::rt::lang_start::{{closure}}::ha054184bbf9921e3 ``` Notice that `__rust_begin_short_backtrace` appears on frame 11 before `__rust_end_short_backtrace` on frame 12. This is because in typical release binaries without debug symbols, dbghelp.dll, which we use to walk and symbolize the stack, does not know where CGU internal functions start or end and so the closure invoked by `__rust_end_short_backtrace` is incorrectly described as `__rust_begin_short_backtrace` because it happens to be near that symbol. While that can obviously change, this has been happening quite consistently since rust-lang#75048. Since this is a very small change to the std and the change makes sense by itself, I think this is worth doing. This doesn't completely resolve the situation for release binaries on Windows, since without debug symbols, the stack printed can still show incorrect symbol names (this is why the test uses `#[no_mangle]`) but it does slightly improve the situation in that you see the same backtrace you would see with `RUST_BACKTRACE=full` or in a debugger (without the uninteresting bits at the top and bottom). Fixes part of rust-lang#87481

10332: minor: Allow overwriting RUST_BACKTRACE for the server manually r=jonas-schievink a=Veykril Trying to figure out why we aren't getting backtraces for windows builds from CI, this let's one set the backtraces to `FULL` Might be cc rust-lang/rust#87481 bors r+ Co-authored-by: Lukas Wirth <[email protected]>

This has been causing failures in CI here and in rust-lang#90408. A comment there (rust-lang#90408 (comment)) suggested blessing the output; this commit does that manually.

ehuss added the C-bug Category: This is a bug. label Jul 26, 2021

jyn514 added A-runtime Area: std's runtime and "pre-main" init for handling backtraces, unwinds, stack overflows T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. O-windows Operating system: Windows labels Jul 26, 2021

wesleywiser self-assigned this Jul 27, 2021

wesleywiser added O-windows-msvc Toolchain: MSVC, Operating system: Windows and removed O-windows Operating system: Windows labels Jul 27, 2021

wesleywiser mentioned this issue Jul 29, 2021

[backtraces]: look for the begin symbol only after seeing end #87602

Merged

Veykril mentioned this issue Sep 24, 2021

minor: Allow overwriting RUST_BACKTRACE for the server manually rust-lang/rust-analyzer#10332

Merged

pierwill mentioned this issue Dec 6, 2021

Include rustc version in rustc_span::StableCrateId #89836

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

short backtraces do not always work on Windows without debug info #87481

short backtraces do not always work on Windows without debug info #87481

ehuss commented Jul 26, 2021

mati865 commented Jul 27, 2021

wesleywiser commented Jul 27, 2021 •

edited

Loading

short backtraces do not always work on Windows without debug info #87481

short backtraces do not always work on Windows without debug info #87481

Comments

ehuss commented Jul 26, 2021

Basic main

rustc treat-err-as-bug

Larger example

Expected behavior

Meta

mati865 commented Jul 27, 2021

wesleywiser commented Jul 27, 2021 • edited Loading

wesleywiser commented Jul 27, 2021 •

edited

Loading