Backtracing pretty print regression?

[steveklabnik]

I was investigating some backtracing stuff, and I noticed that backtraces look like this:

stack backtrace:
   0: backtrace::backtrace::trace_unsynchronized
             at C:\Users\VssAdministrator\.cargo\registry\src\github.jparrowsec.cn-1ecc6299db9ec823\backtrace-0.3.37\src\backtrace\mod.rs:66
   1: std::sys_common::backtrace::_print_fmt
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\sys_common\backtrace.rs:77
   2: std::sys_common::backtrace::_print::{{impl}}::fmt
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\sys_common\backtrace.rs:61
   3: core::fmt::write
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libcore\fmt\mod.rs:1030

Now, they used to look like the mingw target:

   0: backtrace::backtrace::dbghelp::trace
             at C:\Users\VssAdministrator\.cargo\registry\src\github.jparrowsec.cn-1ecc6299db9ec823\backtrace-0.3.29\src\backtrace/dbghelp.rs:90
   1: backtrace::backtrace::trace_unsynchronized
             at C:\Users\VssAdministrator\.cargo\registry\src\github.jparrowsec.cn-1ecc6299db9ec823\backtrace-0.3.29\src\backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print
             at src\libstd\sys_common/backtrace.rs:47
   3: std::sys_common::backtrace::print
             at src\libstd\sys_common/backtrace.rs:36

Note the lines from std; they're not showing the full path. There are still details wrong (using both \ and / for example) but I think this is a regression in pretty-printing? It's also not clear to me why the backtrace crate's full path is in there, but libstd is the nicer format.

[sfackler]

cc @alexcrichton @cramertj I'd guess fallout from #64152?

[alexcrichton]

@steveklabnik can you detail what you're doing, what targets you're using, and what rustc versions were involved? I wasn' able to easily reproduce on mingw stable/beta/nightly and msvc has the same behavior going back to at least 1.35.0

[steveklabnik]

~\tmp> cargo new panictest
     Created binary (application) `panictest` package
~\tmp> cd panictest
~\tmp\panictest [master +3 ~0 -0 !]> $env:RUST_BACKTRACE=1
~\tmp\panictest [master +3 ~0 -0 !]> code .\src\main.rs
~\tmp\panictest [master +3 ~0 -0 !]> cat .\src\main.rs
fn main() {
    panic!("Hello, world!");
}
~\tmp\panictest [master +3 ~0 -0 !]> rustc --version
rustc 1.37.0 (eae3437df 2019-08-13)
~\tmp\panictest [master +3 ~0 -0 !]> cargo run
   Compiling panictest v0.1.0 (C:\Users\steve\tmp\panictest)
    Finished dev [unoptimized + debuginfo] target(s) in 0.73s
     Running `target\debug\panictest.exe`
thread 'main' panicked at 'Hello, world!', src\main.rs:2:5
stack backtrace:
   0: backtrace::backtrace::trace_unsynchronized
             at C:\Users\VssAdministrator\.cargo\registry\src\github.jparrowsec.cn-1ecc6299db9ec823\backtrace-0.3.29\src\backtrace\mod.rs:66
   1: std::sys_common::backtrace::_print
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libstd\sys_common\backtrace.rs:47
   2: std::sys_common::backtrace::print
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libstd\sys_common\backtrace.rs:36
   3: std::panicking::default_hook::{{closure}}
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libstd\panicking.rs:200
   4: std::panicking::default_hook
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libstd\panicking.rs:214
   5: std::panicking::rust_panic_with_hook
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libstd\panicking.rs:477
   6: std::panicking::begin_panic<str*>
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\src\libstd\panicking.rs:411
   7: panictest::main
             at .\src\main.rs:2
   8: std::rt::lang_start::{{closure}}<()>
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\src\libstd\rt.rs:64
   9: std::rt::lang_start_internal::{{closure}}
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libstd\rt.rs:49
  10: std::panicking::try::do_call<closure,i32>
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libstd\panicking.rs:296
  11: panic_unwind::__rust_maybe_catch_panic
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libpanic_unwind\lib.rs:82
  12: std::panicking::try
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libstd\panicking.rs:275
  13: std::panic::catch_unwind
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libstd\panic.rs:394
  14: std::rt::lang_start_internal
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\/src\libstd\rt.rs:48
  15: std::rt::lang_start<()>
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\src\libstd\rt.rs:64
  16: main
  17: invoke_main
             at d:\agent\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:78
  18: __scrt_common_main_seh
             at d:\agent\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288
  19: BaseThreadInitThunk
  20: RtlUserThreadStart
error: process didn't exit successfully: `target\debug\panictest.exe` (exit code: 101)
~\tmp\panictest [master +4 ~0 -0 !]> rustc +nightly --version
rustc 1.39.0-nightly (96d07e0ac 2019-09-15)
~\tmp\panictest [master +4 ~0 -0 !]> cargo +nightly run
   Compiling panictest v0.1.0 (C:\Users\steve\tmp\panictest)
    Finished dev [unoptimized + debuginfo] target(s) in 0.53s
     Running `target\debug\panictest.exe`
thread 'main' panicked at 'Hello, world!', src\main.rs:2:5
stack backtrace:
   0: backtrace::backtrace::trace_unsynchronized
             at C:\Users\VssAdministrator\.cargo\registry\src\github.jparrowsec.cn-1ecc6299db9ec823\backtrace-0.3.37\src\backtrace\mod.rs:66
   1: std::sys_common::backtrace::_print_fmt
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\sys_common\backtrace.rs:77
   2: std::sys_common::backtrace::_print::{{impl}}::fmt
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\sys_common\backtrace.rs:61
   3: core::fmt::write
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libcore\fmt\mod.rs:1030
   4: std::io::Write::write_fmt<std::sys::windows::stdio::Stderr>
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\io\mod.rs:1412
   5: std::sys_common::backtrace::_print
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\sys_common\backtrace.rs:65
   6: std::sys_common::backtrace::print
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\sys_common\backtrace.rs:50
   7: std::panicking::default_hook::{{closure}}
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\panicking.rs:200
   8: std::panicking::default_hook
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\panicking.rs:214
   9: std::panicking::rust_panic_with_hook
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\panicking.rs:477
  10: std::panicking::begin_panic<str*>
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\src\libstd\panicking.rs:411
  11: panictest::main
             at .\src\main.rs:2
  12: std::rt::lang_start::{{closure}}<()>
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\src\libstd\rt.rs:64
  13: std::rt::lang_start_internal::{{closure}}
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\rt.rs:49
  14: std::panicking::try::do_call<closure-0,i32>
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\panicking.rs:296
  15: panic_unwind::__rust_maybe_catch_panic
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libpanic_unwind\lib.rs:80
  16: std::panicking::try
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\panicking.rs:275
  17: std::panic::catch_unwind
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\panic.rs:394
  18: std::rt::lang_start_internal
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\/src\libstd\rt.rs:48
  19: std::rt::lang_start<()>
             at /rustc/96d07e0ac9f0c56b95a2561c6cedac0b23a5d2a3\src\libstd\rt.rs:64
  20: main
  21: invoke_main
             at d:\agent\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:78
  22: __scrt_common_main_seh
             at d:\agent\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288
  23: BaseThreadInitThunk
  24: RtlUserThreadStart
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
error: process didn't exit successfully: `target\debug\panictest.exe` (exit code: 101)
~\tmp\panictest [master +4 ~0 -0 !]> rustc +stable-x86_64-pc-windows-gnu --version
rustc 1.37.0 (eae3437df 2019-08-13)
~\tmp\panictest [master +4 ~0 -0 !]> cargo +stable-x86_64-pc-windows-gnu run
   Compiling panictest v0.1.0 (C:\Users\steve\tmp\panictest)
    Finished dev [unoptimized + debuginfo] target(s) in 0.74s
     Running `target\debug\panictest.exe`
thread 'main' panicked at 'Hello, world!', src\main.rs:2:5
stack backtrace:
   0: backtrace::backtrace::dbghelp::trace
             at C:\Users\VssAdministrator\.cargo\registry\src\github.jparrowsec.cn-1ecc6299db9ec823\backtrace-0.3.29\src\backtrace/dbghelp.rs:90
   1: backtrace::backtrace::trace_unsynchronized
             at C:\Users\VssAdministrator\.cargo\registry\src\github.jparrowsec.cn-1ecc6299db9ec823\backtrace-0.3.29\src\backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print
             at src\libstd\sys_common/backtrace.rs:47
   3: std::sys_common::backtrace::print
             at src\libstd\sys_common/backtrace.rs:36
   4: std::panicking::default_hook::{{closure}}
             at src\libstd/panicking.rs:200
   5: std::panicking::default_hook
             at src\libstd/panicking.rs:214
   6: std::panicking::rust_panic_with_hook
             at src\libstd/panicking.rs:477
   7: std::panicking::begin_panic
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\src\libstd/panicking.rs:411
   8: panictest::main
             at src/main.rs:2
   9: std::rt::lang_start::{{closure}}
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\src\libstd/rt.rs:64
  10: std::rt::lang_start_internal::{{closure}}
             at src\libstd/rt.rs:49
  11: std::panicking::try::do_call
             at src\libstd/panicking.rs:296
  12: __rust_maybe_catch_panic
             at src\libpanic_unwind/lib.rs:82
  13: std::panicking::try
             at src\libstd/panicking.rs:275
  14: std::panic::catch_unwind
             at src\libstd/panic.rs:394
  15: std::rt::lang_start_internal
             at src\libstd/rt.rs:48
  16: std::rt::lang_start
             at /rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b\src\libstd/rt.rs:64
  17: main
  18: _tmainCRTStartup
  19: mainCRTStartup
  20: unit_addrs_search
  21: unit_addrs_search
error: process didn't exit successfully: `target\debug\panictest.exe` (exit code: 101)

[steveklabnik]

msvc has the same behavior going back to at least 1.35.0

It is, in theory, possible that I'm forgetting and MSVC has always had not-pretty backtraces. I don't look at backtraces that often, and it's possible that I'm mis-remembering.

[alexcrichton]

Hm I may be a bit confused, but it looks like nightly/stable in your snippet have basically the same output? I think stable and nightly are MSVC toolchains, so this looks like it's basically a difference between the MSVC and the MinGW toolchains? Have you seen differences over time within each toolchain?

[steveklabnik]

it looks like nightly/stable in your snippet have basically the same output?

Yes.

I think stable and nightly are MSVC toolchains,

Yes, sorry for not being more clear about that; I forgot you need -vV to get this in the output. My bad!

so this looks like it's basically a difference between the MSVC and the MinGW toolchains?

This is mostly true; if you look at MinGW, you'll see that some lines like 7: std::panicking::begin_panic have the weird path in front, even though most don't.

Have you seen differences over time within each toolchain?

I never use the GNU toolchain, and only installed it to triage another ticket. So I don't have a great feel for the splits here.

[pnkfelix]

Visiting for wg-debugging triage.

We think that the behavior described for MSVC actually matches that of Linux.

One potentially confusing thing here is the handling of the /rustc/<hash> path. @bjorn3 reminded us that for locally-codegened things (i.e. inlined or generic items) it should be mapped over to the locally installed rust-src component's path, if present.

I'm not sure if that might explain some of the discrepancies that @steveklabnik was observing...

[pnkfelix]

At this point, wg-debugging doesn't think there is any action to take here, as we have matching behavior between the Tier-1 platforms we looked at.

Closing (but feel free to reopen if you can spell out a bit more how the current behavior is not matching expectations set elsewhere)

one last thing:

One potentially confusing thing here is the handling of the /rustc/<hash> path. @bjorn3 reminded us that for locally-codegened things (i.e. inlined or generic items) it should be mapped over to the locally installed rust-src component's path, if present.

after further investigation, the expected remapping here doesn't seem to be happening. Maybe that is the root of the complaint here, but we should file that as a separate bug.

You can see discussion here