Open yaahc opened 3 years ago
where as the builtin backtrace printer for the default provided panic hook has no such issues
Hm can you clarify what the default here is? Do you mean that libstd's own backtrace printing prints a full backtrace but this crate doesn't print a backtrace at all? (when the two are "called" from the same context).
I think that panic=abort vs panic=unwind can affect codegen and it may be affecting unwind tables as well. I'm not 100% certain about that though, and it wouldn't explain the difference in this crate vs libstd.
A bit of a long shot, but would it be possible to get some source code I could poke around?
Hm scratch that
RUST_BACKTRACE=1 CARGO_PROFILE_DEV_PANIC=abort cargo run --example backtrace
in this repository on macOS prints nothing for this crate itself, but libstd prints a backtrace for the panic! I'm perplexed and something weird is going on here, I'll get back to you after investigating!
@alexcrichton some background I know that the default panic hook from std
provides custom backtrace formatting machinery so that it can avoid needing to allocate, so my guess is that this implementation somehow works with panic = abort
but the ones in backtrace::Backtrace
and std::backtrace::Backtrace
do not. This came up recently in the Backtrace
stabilization issue: https://github.com/rust-lang/rust/issues/71706#issuecomment-713403545.
And yea, here's my simple example program
fn main() {
frame1();
}
fn frame1() {
frame2();
}
fn frame2() {
std::env::set_var("RUST_BACKTRACE", "full");
let backtrace = backtrace::Backtrace::new();
eprintln!("Backtrace:\n{:?}", backtrace);
panic!("foo");
}
And the output I get in panic = unwind
Backtrace:
0: backtrace::frame2
at examples/backtrace.rs:11:20
1: backtrace::frame1
at examples/backtrace.rs:6:4
2: backtrace::main
at examples/backtrace.rs:2:4
3: std::rt::lang_start::{{closure}}
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/rt.rs:67:33
4: std::rt::lang_start_internal::{{closure}}
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/rt.rs:52:12
std::panicking::try::do_call
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/panicking.rs:305:39
5: __rust_maybe_catch_panic
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libpanic_unwind/lib.rs:86:7
6: std::panicking::try
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/panicking.rs:281:12
std::panic::catch_unwind
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/panic.rs:394:13
std::rt::lang_start_internal
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/rt.rs:51:24
7: std::rt::lang_start
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/rt.rs:67:4
8: main
9: __libc_start_main
10: _start
thread 'main' panicked at 'foo', examples/backtrace.rs:13:5
stack backtrace:
0: 0x55cbd32bfc64 - backtrace::backtrace::libunwind::trace::h90669f559fb267f0
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
1: 0x55cbd32bfc64 - backtrace::backtrace::trace_unsynchronized::hffde4e353d8f2f9a
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
2: 0x55cbd32bfc64 - std::sys_common::backtrace::_print_fmt::heaf44068b7eaaa6a
at src/libstd/sys_common/backtrace.rs:77
3: 0x55cbd32bfc64 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h88671019cf081de2
at src/libstd/sys_common/backtrace.rs:59
4: 0x55cbd32d73fc - core::fmt::write::h4e6a29ee6319c9fd
at src/libcore/fmt/mod.rs:1052
5: 0x55cbd32be197 - std::io::Write::write_fmt::hf06b1c86d898d7d6
at src/libstd/io/mod.rs:1426
6: 0x55cbd32c1d15 - std::sys_common::backtrace::_print::h404ff5f2b50cae09
at src/libstd/sys_common/backtrace.rs:62
7: 0x55cbd32c1d15 - std::sys_common::backtrace::print::hcc4377f1f882322e
at src/libstd/sys_common/backtrace.rs:49
8: 0x55cbd32c1d15 - std::panicking::default_hook::{{closure}}::hc172eff6f35b7f39
at src/libstd/panicking.rs:204
9: 0x55cbd32c1a01 - std::panicking::default_hook::h7a68887d113f8029
at src/libstd/panicking.rs:224
10: 0x55cbd32c231a - std::panicking::rust_panic_with_hook::hb7ad5693188bdb00
at src/libstd/panicking.rs:472
11: 0x55cbd31db41b - std::panicking::begin_panic::h5b22d6d0d2936270
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/panicking.rs:399
12: 0x55cbd31da55b - backtrace::frame2::h0466262d13bbea09
at examples/backtrace.rs:13
13: 0x55cbd31da456 - backtrace::frame1::h32238f8b98516416
at examples/backtrace.rs:6
14: 0x55cbd31da446 - backtrace::main::h9ada77cd6bbdcc61
at examples/backtrace.rs:2
15: 0x55cbd31da6f0 - std::rt::lang_start::{{closure}}::haed21695f16ce364
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/rt.rs:67
16: 0x55cbd32c1de3 - std::rt::lang_start_internal::{{closure}}::hb26e39676675046f
at src/libstd/rt.rs:52
17: 0x55cbd32c1de3 - std::panicking::try::do_call::he4701ab6e48d80c0
at src/libstd/panicking.rs:305
18: 0x55cbd32c3fe7 - __rust_maybe_catch_panic
at src/libpanic_unwind/lib.rs:86
19: 0x55cbd32c27c0 - std::panicking::try::hd3de25f3cb7024b8
at src/libstd/panicking.rs:281
20: 0x55cbd32c27c0 - std::panic::catch_unwind::h86c02743a24e3d92
at src/libstd/panic.rs:394
21: 0x55cbd32c27c0 - std::rt::lang_start_internal::h9cf8802361ad86c2
at src/libstd/rt.rs:51
22: 0x55cbd31da6c9 - std::rt::lang_start::h527b728873cea05d
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/rt.rs:67
23: 0x55cbd31da59a - main
24: 0x7f7d210980b3 - __libc_start_main
25: 0x55cbd31da17e - _start
26: 0x0 - <unknown>
vs panic = abort
Backtrace:
0: backtrace::frame2
at examples/backtrace.rs:11:20
1: backtrace::frame1
at examples/backtrace.rs:6:4
2: backtrace::main
at examples/backtrace.rs:2:4
3: std::rt::lang_start::{{closure}}
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/rt.rs:67:33
thread 'main' panicked at 'foo', examples/backtrace.rs:13:5
stack backtrace:
0: 0x56514d8b2d44 - backtrace::backtrace::libunwind::trace::h90669f559fb267f0
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
1: 0x56514d8b2d44 - backtrace::backtrace::trace_unsynchronized::hffde4e353d8f2f9a
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
2: 0x56514d8b2d44 - std::sys_common::backtrace::_print_fmt::heaf44068b7eaaa6a
at src/libstd/sys_common/backtrace.rs:77
3: 0x56514d8b2d44 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h88671019cf081de2
at src/libstd/sys_common/backtrace.rs:59
4: 0x56514d8c9e1c - core::fmt::write::h4e6a29ee6319c9fd
at src/libcore/fmt/mod.rs:1052
5: 0x56514d8b1277 - std::io::Write::write_fmt::hf06b1c86d898d7d6
at src/libstd/io/mod.rs:1426
6: 0x56514d8b4da5 - std::sys_common::backtrace::_print::h404ff5f2b50cae09
at src/libstd/sys_common/backtrace.rs:62
7: 0x56514d8b4da5 - std::sys_common::backtrace::print::hcc4377f1f882322e
at src/libstd/sys_common/backtrace.rs:49
8: 0x56514d8b4da5 - std::panicking::default_hook::{{closure}}::hc172eff6f35b7f39
at src/libstd/panicking.rs:204
9: 0x56514d8b4a91 - std::panicking::default_hook::h7a68887d113f8029
at src/libstd/panicking.rs:224
10: 0x56514d8b53aa - std::panicking::rust_panic_with_hook::hb7ad5693188bdb00
at src/libstd/panicking.rs:472
11: 0x56514d7d63cb - std::panicking::begin_panic::h3e3ab4e410875c09
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/panicking.rs:399
12: 0x56514d7d54c7 - backtrace::frame2::hfd96dced912a452c
at examples/backtrace.rs:13
13: 0x56514d7d53d6 - backtrace::frame1::h5d7c5587ebab67dc
at examples/backtrace.rs:6
14: 0x56514d7d53c6 - backtrace::main::h1f6e5223b7ef4de0
at examples/backtrace.rs:2
15: 0x56514d7d5570 - std::rt::lang_start::{{closure}}::h1a8399b1346eb913
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libstd/rt.rs:67
Aborted (core dumped)
Some quick investigation (heading out now, will dig in more later), is that this is related to how the library that generates the backtrace is itself compiled.
In your code, for example, the backtrace
crate is compiled with -Cpanic=abort
but the standard library is compiled with -Cpanic=unwind
(because that's how we ship it). If you run via:
RUST_BACKTRACE=1 CARGO_PROFILE_DEV_PANIC=abort cargo +nightly run -Z build-std=std,panic_abort --target x86_64-apple-darwin
(substituting the right target) I think that you'll see that libstd can't generate a backtrace either (or at least that's what I get locally). This makes me think that if the request to unwind comes from code compiled with -Cpanic=abort
it doesn't unwind, but if the request to unwind comes from -Cpanic=unwind
code then it works.
It looks though like you're getting different output than I am for effectively the same example. You're on Linux, right?
It looks though like you're getting different output than I am for effectively the same example. You're on Linux, right?
yea, but this is using stable and I'm not setting that CARGO_PROFILE_DEV_PANIC=abort
flag, I was using the cargo.toml profile section to set it.
edit: I see you were using stable before too...
(substituting the right target) I think that you'll see that libstd can't generate a backtrace either (or at least that's what I get locally). This makes me think that if the request to unwind comes from code compiled with
-Cpanic=abort
it doesn't unwind, but if the request to unwind comes from-Cpanic=unwind
code then it works.
Just some clarification so I can keep up. "request to unwind", is the backtrace capture requesting an unwind? What does requesting an unwind mean? Is it actually unwinding?
Oh sorry so to clarify CARGO_PROFILE_DEV_PANIC=abort
is just an alternate way of settting the profile in Cargo.toml
, they do the same thing. It's just easier to gist snippets using CLI stuff instead of gisting files as well.
Using your example program from above this is what I get:
cargo +stable run
- 2 backtracesCARGO_PROFILE_DEV_PANIC=abort cargo +stable run
- truncated backtracesCARGO_PROFILE_DEV_PANIC=abort cargo +nightly run --target x86_64-apple-darwin -Zbuild-std=std,panic_abort
- no backtracesAnd then running Cargo inside of the backtrace-rs
repository iteslf:
cargo +stable run --example backtrace
- has a backtraceCARGO_PROFILE_DEV_PANIC=abort cargo +stable run --example backtrace
- no backtraceAlso to clarify, when I say "request unwind" I mean the function which called _Unwind_Backtrace
itself.
In general though I think that there may be room for another rustc flag here. Unwinding on ELF and Mach-O (Unix) platforms primarily goes through DWARF-based unwinding. This varies a bit per platform, but if the unwinding tables aren't present in an executable then the unwinder doesn't know what to do. I think it can sort of get through some functions above by matching standard prologues/epilogues, but honestly I'm not entirely sure why partial backtraces are present sometimes.
In any case with -Cpanic=abort
I believe rustc does not generate the uwtable
attribute on LLVM functions (unlike how it does so in the -Cpanic=unwind
case). That means, I think, that with -Cpanic=abort
there is no unwind table information and the unwinder is left to do whatever it can to try to unwind, but it can often fail and not give 100% accurate results.
To answer the original question of this issue, there is no original intention for how panic=abort
is supposed to interact with this crate. It seems it doesn't work super well today given how the unwinders we rely on rely on unwind tables and they're not present in panic=abort. That may mean we'll want a rustc flag -Cgenerate-unwind-tables
for panic=abort binaries that still want backtraces for unwinds and such.
I think I'm still missing a bit on why the backtraces at least partially work, but I think otherwise this is basically the state of things.
Oh okay, that makes a lot of sense, and a -Cgenerate-unwind-tables
sounds very helpful. If you want / need any help implementing the feature I can contribute to this as part of my job.
Oh I'm happy to provide advice/help/review, but unfortunately I don't have time to implement this myself. Feel free to take it on if you'd like!
Could we always have the unwind tables, but just omit the landingpads when using -Cpanic=abort
? (Maybe gating it on -Cdebuginfo
?)
Oh I'm happy to provide advice/help/review, but unfortunately I don't have time to implement this myself. Feel free to take it on if you'd like!
totally understandable. And yea, if you could write up some instructions on where to start and what the steps would be that would help a lot, and I'll be able to start on this right away.
Sure yeah! It looks like there's a custom-target-spec option called requires_uwtable
which presumably forcibly generates unwind tables for a target. I think we'll want to basically promote that to a CLI codegen flag as well (probably something like -Cunwind-tables={true,false}
. My recommendation would be to add a method to Session
called generate_unwind_tables()
which respects the CLI flag if given, and otherwise falls back to the target-specific configuration.
@rustbot modify labels +easy +good-first-issue +project-error-handling
Error: This repository is not enabled to use triagebot.
Add a triagebot.toml
in the root of the master branch to enable it.
Please let @rust-lang/release
know if you're having trouble with this bot.
This option exists! -C force-unwind-tables
This option exists!
-C force-unwind-tables
oh my goddd tylerrrrr :heart:
Oh wow, thanks @tmandry for pointing that out! I completely forgot that existed... I think that this issue may be mostly done in that case? Although it may be good to perhaps document that in the crate somewhere?
Just wanted to go ahead and confirm that this worked for me, after enabling force-unwind-tables
+ panic = abort I now get this as the backtrace
Backtrace:
0: panic::frame2
at src/main.rs:11:21
1: panic::frame1
at src/main.rs:6:5
2: panic::main
at src/main.rs:2:5
3: core::ops::function::FnOnce::call_once
at /home/jlusby/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5
4: std::sys_common::backtrace::__rust_begin_short_backtrace
at /home/jlusby/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:125:18
5: std::rt::lang_start::{{closure}}
at /home/jlusby/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:66:18
6: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once
at /rustc/a2f8f6281817d430e20726128b739d3c6708561c/library/core/src/ops/function.rs:259:13
std::panicking::try::do_call
at /rustc/a2f8f6281817d430e20726128b739d3c6708561c/library/std/src/panicking.rs:379:40
std::panicking::try
at /rustc/a2f8f6281817d430e20726128b739d3c6708561c/library/std/src/panicking.rs:343:19
std::panic::catch_unwind
at /rustc/a2f8f6281817d430e20726128b739d3c6708561c/library/std/src/panic.rs:396:14
std::rt::lang_start_internal
at /rustc/a2f8f6281817d430e20726128b739d3c6708561c/library/std/src/rt.rs:51:25
7: std::rt::lang_start
at /home/jlusby/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:65:5
8: main
9: __libc_start_main
10: _start
instead of the original
Backtrace:
0: panic::frame2
at src/main.rs:11:21
1: panic::frame1
at src/main.rs:6:5
2: panic::main
at src/main.rs:2:5
3: core::ops::function::FnOnce::call_once
at /home/jlusby/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5
I've tried to add some documentation for this in https://github.com/rust-lang/backtrace-rs/pull/407
I've tried to add some documentation for this in #407
awesome, I was thinking we might also want to add a note about force-unwind-tables
to various pages of panic = abort related documentation. A cursory google search shows these as possible targets:
Seems reasonable to me!
Hello, this flag does not seem to work in release mode. The unwind table is there by default in debug but never in release even with the force unwind tables flag set to yes:
Cargo.toml
[profile.dev]
panic = "abort"
lto = true
debug = 2
debug-assertions = true
[profile.release]
panic = "abort"
lto = true
debug = 2
debug-assertions = true
.cargo/config
[build]
target = "x86_64-pc-windows-msvc"
rustflags = [
"-C", "panic=abort",
"-C", "force-unwind-tables=yes",
# Pre Link Args
"-Z", "pre-link-arg=/NOLOGO",
"-Z", "pre-link-arg=/NXCOMPAT",
"-Z", "pre-link-arg=/NODEFAULTLIB",
"-Z", "pre-link-arg=/SUBSYSTEM:NATIVE",
"-Z", "pre-link-arg=/DRIVER",
"-Z", "pre-link-arg=/DYNAMICBASE",
"-Z", "pre-link-arg=/MANIFEST:NO",
# Post Link Args
"-C", "link-arg=/OPT:REF,ICF",
"-C", "link-arg=/ENTRY:driver_entry",
"-C", "link-arg=/MERGE:.edata=.rdata",
"-C", "link-arg=/MERGE:.rustc=.data",
"-C", "link-arg=/INTEGRITYCHECK"
]
Running `rustc --crate-name RSTrace --edition=2018 src/lib.rs --error-format=json --json=diagnostic-rendered-ansi --crate-type cdylib --emit=dep-info,link -C opt-level=3 -C panic=abort -C lto -C debuginfo=2 -C debug-assertions=on -C overflow-checks=off -C metadata=0783d6da86fe062c --out-dir C:\Users\steve\source\repos\RSTrace\target\x86_64-pc-windows-msvc\release\deps --target x86_64-pc-windows-msvc -L dependency=C:\Users\steve\source\repos\RSTrace\target\x86_64-pc-windows-msvc\release\deps -L dependency=C:\Users\steve\source\repos\RSTrace\target\release\deps --extern ntapi=C:\Users\steve\source\repos\RSTrace\target\x86_64-pc-windows-msvc\release\deps\libntapi-7f7dba2dc6ae5f22.rlib --extern utf16_lit=C:\Users\steve\source\repos\RSTrace\target\release\deps\utf16_lit-bbee57a78fade9e8.dll --extern wasmi=C:\Users\steve\source\repos\RSTrace\target\x86_64-pc-windows-msvc\release\deps\libwasmi-aabf18157cf6d5d2.rlib --extern winapi=C:\Users\steve\source\repos\RSTrace\target\x86_64-pc-windows-msvc\release\deps\libwinapi-0eb57b396aba78ff.rlib -C panic=abort -C force-unwind-tables=yes -Z pre-link-arg=/NOLOGO -Z pre-link-arg=/NXCOMPAT -Z pre-link-arg=/NODEFAULTLIB -Z pre-link-arg=/SUBSYSTEM:NATIVE -Z pre-link-arg=/DRIVER -Z pre-link-arg=/DYNAMICBASE -Z pre-link-arg=/MANIFEST:NO -C link-arg=/OPT:REF,ICF -C link-arg=/ENTRY:driver_entry -C link-arg=/MERGE:.edata=.rdata -C link-arg=/MERGE:.rustc=.data -C link-arg=/INTEGRITYCHECK -L "native=C:\Program Files (x86)\Windows Kits\10\lib\10.0.19041.0\km\x64"`
Then inspecting my binary there is not RUNTIME_FUNCTION entry, which would be expected if the unwind table was generated. This unwind table is strictly necessary for the binary interface i'm interacting with, are there any other techniques to force this table to generate, i only need an entry for one function in particular?
force-unwind-tables
any way to put this in like... Cargo.toml or .cargo/config.toml?
You can put it in the rustflags
field of .cargo/config.toml
.
for anybody following along
[build]
rustflags = ["-C", "force-unwind-tables"]
In our project at work we've been seeing issues with backtrace's not capturing the full context of the application state when we panic, where as the builtin backtrace printer for the default provided panic hook has no such issues.
https://github.com/ZcashFoundation/zebra/issues/1471 shows an example of a backtrace that gets cut off, it only shows the frames pushed onto the stack after calling
expect
, but doesn't include any of our application code's frames otherwise, where as the metadata of the issue captured the location the panic was created from via#[track_caller]
just fine.I'm not convinced I understand what is going on here, or whether this is a bug or expected behaviour, disabling
panic = abort
fixes the issue though, at least in the playground.