search

godot-rust / gdext

Rust bindings for Godot 4
https://mastodon.gamedev.place/@GodotRust
Mozilla Public License 2.0
3.09k stars 196 forks source link

Compatibility with color-backtrace in 0.1.3 #828

Closed QuadnucYard closed 1 month ago

QuadnucYard commented 3 months ago

I just run this code:

color_backtrace::install();
panic!("Just panic");

It will print unexpected panic information after normal information.

It seems alright in 0.1.1 with the output below, despite an issue with unwind:

(Output from color_backtrace omitted)
19: ZN6embree13TaskScheduler12startThreadsEv
    at <unknown source file>
20: ZN6embree13TaskScheduler12startThreadsEv
    at <unknown source file>
21: BaseThreadInitThunk
    at <unknown source file>
22: RtlUserThreadStart
    at <unknown source file>
The application panicked (crashed).
Message:  panic in a function that cannot unwind
Location: library\core\src\panicking.rs:221
......
21: ZN6embree13TaskScheduler12startThreadsEv
    at <unknown source file>
22: ZN6embree13TaskScheduler12startThreadsEv
    at <unknown source file>
23: BaseThreadInitThunk
    at <unknown source file>
24: RtlUserThreadStart
    at <unknown source file>
thread caused non-unwinding panic. aborting.

But on more unexpected stack backtrace from panic (no panic info available) occurs in 0.1.2 and 0.1.3 as below

The application panicked (crashed).
Message:  Just panic
(Output from color_backtrace omitted)
24: ZN6embree13TaskScheduler12startThreadsEv
    at <unknown source file>
25: ZN6embree13TaskScheduler12startThreadsEv
    at <unknown source file>
26: BaseThreadInitThunk
    at <unknown source file>
27: RtlUserThreadStart
    at <unknown source file>
thread '<unnamed>' panicked at E:\Program\rust\.cargo\registry\src\rsproxy.cn-0dccff568467c15b\godot-core-0.1.3\src\private.rs:361:39:
no panic info available
stack backtrace:
   0:     0x7fff82fbf82d - std::backtrace_rs::backtrace::dbghelp64::trace
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\..\..\backtrace\src\backtrace\dbghelp64.rs:91
   1:     0x7fff82fbf82d - std::backtrace_rs::backtrace::trace_unsynchronized
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66
   2:     0x7fff82fbf82d - std::sys::backtrace::_print_fmt
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\sys\backtrace.rs:68
   3:     0x7fff82fbf82d - std::sys::backtrace::impl$0::print::impl$0::fmt
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\sys\backtrace.rs:41
   4:     0x7fff82fd3ca9 - core::fmt::rt::Argument::fmt
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\fmt\rt.rs:173   
   5:     0x7fff82fd3ca9 - core::fmt::write
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\fmt\mod.rs:1182 
   6:     0x7fff82fbdb21 - std::io::Write::write_fmt<std::sys::pal::windows::stdio::Stderr>
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\io\mod.rs:1827   
   7:     0x7fff82fc1537 - std::panicking::default_hook::closure$1
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\panicking.rs:269 
   8:     0x7fff82fc1129 - std::panicking::default_hook
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\panicking.rs:296 
   9:     0x7fff82fc1cab - alloc::boxed::impl$50::call
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\alloc\src\boxed.rs:2163  
  10:     0x7fff82fc1cab - std::panicking::rust_panic_with_hook
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\panicking.rs:808 
  11:     0x7fff82fc1ab6 - std::panicking::begin_panic_handler::closure$0
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\panicking.rs:674 
  12:     0x7fff82fbff1f - std::sys::backtrace::__rust_end_short_backtrace<std::panicking::begin_panic_handler::closure_env$0,never$>
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\sys\backtrace.rs:172
  13:     0x7fff82fc1696 - std::panicking::begin_panic_handler
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\panicking.rs:665 
  14:     0x7fff82fde474 - core::panicking::panic_fmt
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\panicking.rs:74 
  15:     0x7fff82fde43c - core::panicking::panic_display
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\panicking.rs:264  16:     0x7fff82fde43c - core::option::expect_failed
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\option.rs:2030  
  17:     0x7fff8270f36b - godot_core::private::handle_panic_with_print<godot_core::private::handle_ptrcall_panic::closure_env$0<my_project::scene_tree::impl$13::__virtual_call::virtual_fn::closure_env$0,tuple$<> >,my_project::scene_tree::impl$13::__virtual_call::virtual_fn::c
                               at E:\Program\rust\.cargo\registry\src\rsproxy.cn-0dccff568467c15b\godot-core-0.1.3\src\private.rs:361
  18:     0x7fff826a13b1 - godot_core::private::handle_ptrcall_panic<my_project::scene_tree::impl$13::__virtual_call::virtual_fn::closure_env$0,tuple$<> >
                               at E:\Program\rust\.cargo\registry\src\rsproxy.cn-0dccff568467c15b\godot-core-0.1.3\src\private.rs:295
  19:     0x7fff8274e067 - my_project::scene_tree::impl$13::__virtual_call::virtual_fn
                               at E:\Project\my-project\rust\crates\my-project\src\scene_tree.rs:42
  20:     0x7ff6a468fff7 - ZN6embree13TaskScheduler12startThreadsEv
  21:     0x7ff6a28f75cd - <unknown>
  22:     0x7ff6a6f2da73 - ZN6embree13TaskScheduler12startThreadsEv
  23:     0x7ff6a28712ee - <unknown>
  24:     0x7ff6a28713e6 - <unknown>
  25:     0x7fffde727374 - BaseThreadInitThunk
  26:     0x7fffde95cc91 - RtlUserThreadStart
thread '<unnamed>' panicked at library\core\src\panicking.rs:221:5:
panic in a function that cannot unwind
stack backtrace:
   0:     0x7fff82fbf82d - std::backtrace_rs::backtrace::dbghelp64::trace
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\..\..\backtrace\src\backtrace\dbghelp64.rs:91
   1:     0x7fff82fbf82d - std::backtrace_rs::backtrace::trace_unsynchronized
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66
   2:     0x7fff82fbf82d - std::sys::backtrace::_print_fmt
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\sys\backtrace.rs:68
   3:     0x7fff82fbf82d - std::sys::backtrace::impl$0::print::impl$0::fmt
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\sys\backtrace.rs:41
   4:     0x7fff82fd3ca9 - core::fmt::rt::Argument::fmt
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\fmt\rt.rs:173   
   5:     0x7fff82fd3ca9 - core::fmt::write
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\fmt\mod.rs:1182 
   6:     0x7fff82fbdb21 - std::io::Write::write_fmt<std::sys::pal::windows::stdio::Stderr>
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\io\mod.rs:1827   
   7:     0x7fff82fc1537 - std::panicking::default_hook::closure$1
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\panicking.rs:269 
   8:     0x7fff82fc1129 - std::panicking::default_hook
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\panicking.rs:296 
   9:     0x7fff82fc1cab - alloc::boxed::impl$50::call
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\alloc\src\boxed.rs:2163
  10:     0x7fff82fc1cab - std::panicking::rust_panic_with_hook
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\panicking.rs:808 
  11:     0x7fff82fc1a7f - std::panicking::begin_panic_handler::closure$0
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\panicking.rs:667 
  12:     0x7fff82fbff1f - std::sys::backtrace::__rust_end_short_backtrace<std::panicking::begin_panic_handler::closure_env$0,never$>
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\sys\backtrace.rs:172
  13:     0x7fff82fc1696 - std::panicking::begin_panic_handler
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\std\src\panicking.rs:665 
  14:     0x7fff82fde4bd - core::panicking::panic_nounwind_fmt::runtime
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\panicking.rs:112  15:     0x7fff82fde4bd - core::panicking::panic_nounwind_fmt
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\panicking.rs:122  16:     0x7fff82fde563 - core::panicking::panic_nounwind
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\panicking.rs:221  17:     0x7fff82fde6bb - core::panicking::panic_cannot_unwind
                               at /rustc/7120fdac7a6e55a5e4b606256042890b36067052/library\core\src\panicking.rs:309  18:     0x7fff8274e096 - my_project::scene_tree::impl$13::__virtual_call::virtual_fn
                               at E:\Project\my-project\rust\crates\my-project\src\scene_tree.rs:42
  19:     0x7fffb4dd1060 - <unknown>
  20:     0x7fffb4dd4d38 - is_exception_typeof
  21:     0x7fffde9b1c96 - RtlCaptureContext2
  22:     0x7fff8274e067 - my_project::scene_tree::impl$13::__virtual_call::virtual_fn
                               at E:\Project\my-project\rust\crates\my-project\src\scene_tree.rs:42
  23:     0x7ff6a468fff7 - ZN6embree13TaskScheduler12startThreadsEv
  24:     0x7ff6a28f75cd - <unknown>
  25:     0x7ff6a6f2da73 - ZN6embree13TaskScheduler12startThreadsEv
  26:     0x7ff6a28712ee - <unknown>
  27:     0x7ff6a28713e6 - <unknown>
  28:     0x7fffde727374 - BaseThreadInitThunk
  29:     0x7fffde95cc91 - RtlUserThreadStart
thread caused non-unwinding panic. aborting.

If I do not use color_backtrace, only a simple piece of information is given (v0.1.3). And no backtrace is printed.

ERROR: godot-rust function call failed: ......
    Reason: [panic]  Just panic
   at: godot_core::private::report_call_error (E:\Program\rust\.cargo\registry\src\rsproxy.cn-0dccff568467c15b\godot-core-0.1.3\src\private.rs:313)

Rust version: rustc 1.82.0-nightly (7120fdac7 2024-07-25). color-backtrace=0.6.1 Run with RUST_BACKTRACE=full.

So is this a bug, or does it require additional setting up panic handling? Thank you for your response!

Bromeon commented 3 months ago

Thanks for reporting!

According to your stacktrace, it happens in this line: https://github.com/godot-rust/gdext/blob/15bc053d67b526aa79abd882219a292579631215/godot-core/src/private.rs#L361-L361

So the PanicInfo that's usually provided in a panic hook seems to be None (absent). I don't know how color_backtrace interferes with the panic system, here you'd need to help me to see what we need to consider.

Worst case we could just print "no panic info" instead of .expect(), but it would be nice to go to the bottom of this :thinking:

QuadnucYard commented 3 months ago

Besides, my previous tests triggered a panic in the initialize of SceneTree. If the panic occurs elsewhere (during process), only ERROR: ... with the panic information will be printed out (no backtrace), even if with color-backtrace installed.

Such panic cannot be caught by the debugger either, which is terrible for debugging.

QuadnucYard commented 3 months ago

It seems that color-backtrace just set a new panic hook but not take the previous one, so it is the only panic handler. It employs backtrace library to collect backtrace frames, which should do nothing with panic.

https://github.com/godot-rust/gdext/blob/15bc053d67b526aa79abd882219a292579631215/godot-core/src/private.rs#L333

This hook is taken when runing process, so no backtrace is printed. But why initialize appears differently?

https://github.com/godot-rust/gdext/blob/15bc053d67b526aa79abd882219a292579631215/godot-core/src/private.rs#L344

I didn't see this eprintln take effect. So the new hook doesn't work in initialize?

QuadnucYard commented 3 months ago

I hope to get a pretty backtrace (from color-backtrace, printed to stdout) during debugging. It needn't to be printed to godot debugger, considering:

But when released, I just need to collect plain backtrace as crash logs.

I take the following code from gdnative. It somehow works well in 0.1.1 (or earlier?), and I can see the crash from godot logs.

fn init_panic_hook() {
    let old_hook = std::panic::take_hook();
    std::panic::set_hook(Box::new(move |panic_info| {
        let loc_string;
        if let Some(location) = panic_info.location() {
            loc_string = format!("file '{}' at line {}", location.file(), location.line());
        } else {
            loc_string = "unknown location".to_owned()
        }

        let error_message;
        if let Some(s) = panic_info.payload().downcast_ref::<&str>() {
            error_message = format!("[RUST] {loc_string}: panic occurred: {s:?}");
        } else if let Some(s) = panic_info.payload().downcast_ref::<String>() {
            error_message = format!("[RUST] {loc_string}: panic occurred: {s:?}");
        } else {
            error_message = format!("[RUST] {loc_string}: unknown panic occurred");
        }
        godot_error!("{}", error_message);

        if let Ok(str) = format_backtrace_string() {
            godot_print!("{str}");
        }

        (*(old_hook.as_ref()))(panic_info);
    }));
}

fn format_backtrace_string() -> Result<String, std::io::Error> {
    use backtrace::Backtrace;
    use color_backtrace::{termcolor::NoColor, BacktracePrinter};

    let mut out = NoColor::new(vec![]);
    BacktracePrinter::new().print_trace(&Backtrace::new(), &mut out)?;
    Ok(String::from_utf8(out.into_inner()).unwrap())
}
Bromeon commented 3 months ago

Besides, my previous tests triggered a panic in the initialize of SceneTree. If the panic occurs elsewhere (during process), only ERROR: ... with the panic information will be printed out (no backtrace), even if with color-backtrace installed.

Such panic cannot be caught by the debugger either, which is terrible for debugging.

This probably falls under https://github.com/godot-rust/gdext/issues/411. Fully agree that we should look for ways to trigger the debugger.

It seems that color-backtrace just set a new panic hook but not take the previous one, so it is the only panic handler. It employs backtrace library to collect backtrace frames, which should do nothing with panic.

Hm, independently of this issue in gdext, do you think that's something worth reporting to color-backtrace?

This hook is taken when runing process, so no backtrace is printed. But why initialize appears differently?

Good question, do you think this should be unified somehow?

I take the following code from gdnative. It somehow works well in 0.1.1 (or earlier?), and I can see the crash from godot logs.

The main takeaway here seems to be calling the previous hook, right?

Btw, you seem to have quite a concrete idea how to improve panic handling. Would you be interested in helping out with a pull request? :slightly_smiling_face:

QuadnucYard commented 3 months ago

@Bromeon I'm glad to offer some help, but sorry I don't have much experience with Rust (especially runtime) and I'm not familiar with foundations of gdext yet...

Bromeon commented 3 months ago

Let us know if we can help somehow. Our Discord community is also quite friendly in case you need some onboarding 🙂

If not, that's also fair, just keep in mind that I'm currently addressing many foundational parts for v0.2, and likely won't get around looking into very specific integrations (like color-backtrace or #832) for several months 😉

QuadnucYard commented 3 months ago

Oh, I further noticed that my color-backtrace is unexpectedly stripped sometime.

In a panic triggered by a custom callable (used to connect to a pressed signal), my panic handle is gone. Only a large number of bare stack frames (but no [ERROR]) are printed, as if I haven't set a panic hook.

So the only [ERROR] output I saw before may be because there is only that panic handle left.

Bromeon commented 1 month ago

@QuadnucYard note that in the meantime, we disabled panic hooks in Release mode (https://github.com/godot-rust/gdext/pull/889). So it might be that Release mode already has the issue solved.

Other than that, do you plan to investigate this? I don't see any concrete actionables on gdext side, as it's not even clear whether it's color-backtrace or gdext misbehaving. If not, I would probably close this.