diff --git a/godot-core/src/init/mod.rs b/godot-core/src/init/mod.rs index 49aeeaeb0..99b060e23 100644 --- a/godot-core/src/init/mod.rs +++ b/godot-core/src/init/mod.rs @@ -49,6 +49,17 @@ pub unsafe fn __gdext_load_library( sys::initialize(get_proc_address, library, config); } + // With experimental-features enabled, we can always print panics to godot_print! + #[cfg(feature = "experimental-threads")] + crate::private::set_gdext_hook(|| true); + + // Without experimental-features enabled, we can only print panics with godot_print! if the panic occurs on the main (Godot) thread. + #[cfg(not(feature = "experimental-threads"))] + { + let main_thread = std::thread::current().id(); + crate::private::set_gdext_hook(move || std::thread::current().id() == main_thread); + } + // Currently no way to express failure; could be exposed to E if necessary. // No early exit, unclear if Godot still requires output parameters to be set. let success = true; @@ -68,8 +79,11 @@ pub unsafe fn __gdext_load_library( success as u8 }; - let ctx = || "error when loading GDExtension library"; - let is_success = crate::private::handle_panic(ctx, init_code); + // Use std::panic::catch_unwind instead of handle_panic: handle_panic uses TLS, which + // calls `thread_atexit` on linux, which sets the hot reloading flag on linux. + // Using std::panic::catch_unwind avoids this, although we lose out on context information + // for debugging. + let is_success = std::panic::catch_unwind(init_code); is_success.unwrap_or(0) } diff --git a/godot-core/src/lib.rs b/godot-core/src/lib.rs index 133121610..d7ff530fc 100644 --- a/godot-core/src/lib.rs +++ b/godot-core/src/lib.rs @@ -34,6 +34,7 @@ pub mod task {} pub mod tools; mod storage; +pub use crate::private::{get_gdext_panic_context, set_gdext_hook}; pub use godot_ffi as sys; // ---------------------------------------------------------------------------------------------------------------------------------------------- diff --git a/godot-core/src/private.rs b/godot-core/src/private.rs index c321ce256..9f6d6ef37 100644 --- a/godot-core/src/private.rs +++ b/godot-core/src/private.rs @@ -22,9 +22,9 @@ use crate::global::godot_error; use crate::meta::error::CallError; use crate::meta::CallContext; use crate::sys; +use std::cell::RefCell; +use std::io::Write; use std::sync::atomic; -#[cfg(debug_assertions)] -use std::sync::{Arc, Mutex}; use sys::Global; // ---------------------------------------------------------------------------------------------------------------------------------------------- // Global variables @@ -179,11 +179,6 @@ pub unsafe fn has_virtual_script_method( sys::interface_fn!(object_has_script_method)(sys::to_const_ptr(object_ptr), method_sname) != 0 } -pub fn flush_stdout() { - use std::io::Write; - std::io::stdout().flush().expect("flush stdout"); -} - /// Ensure `T` is an editor plugin. pub const fn is_editor_plugin>() {} @@ -220,15 +215,7 @@ pub fn is_class_runtime(is_tool: bool) -> bool { // ---------------------------------------------------------------------------------------------------------------------------------------------- // Panic handling -#[cfg(debug_assertions)] -#[derive(Debug)] -struct GodotPanicInfo { - line: u32, - file: String, - //backtrace: Backtrace, // for future use -} - -pub fn extract_panic_message(err: Box) -> String { +pub fn extract_panic_message(err: &(dyn Send + std::any::Any)) -> String { if let Some(s) = err.downcast_ref::<&'static str>() { s.to_string() } else if let Some(s) = err.downcast_ref::() { @@ -238,18 +225,49 @@ pub fn extract_panic_message(err: Box) -> String { } } -fn format_panic_message(msg: String) -> String { +pub fn format_panic_message(panic_info: &std::panic::PanicHookInfo) -> String { + let mut msg = extract_panic_message(panic_info.payload()); + + if let Some(context) = get_gdext_panic_context() { + msg = format!("{msg}\nContext: {context}"); + } + + let prefix = if let Some(location) = panic_info.location() { + format!("panic {}:{}", location.file(), location.line()) + } else { + "panic".to_string() + }; + // If the message contains newlines, print all of the lines after a line break, and indent them. let lbegin = "\n "; let indented = msg.replace('\n', lbegin); if indented.len() != msg.len() { - format!("[panic]{lbegin}{indented}") + format!("[{prefix}]{lbegin}{indented}") } else { - format!("[panic] {msg}") + format!("[{prefix}] {msg}") } } +pub fn set_gdext_hook(godot_print: F) +where + F: Fn() -> bool + Send + Sync + 'static, +{ + std::panic::set_hook(Box::new(move |panic_info| { + // Flush, to make sure previous Rust output (e.g. test announcement, or debug prints during app) have been printed. + let _ignored_result = std::io::stdout().flush(); + + let message = format_panic_message(panic_info); + if godot_print() { + godot_error!("{message}"); + } + eprintln!("{message}"); + #[cfg(debug_assertions)] + eprintln!("{}", std::backtrace::Backtrace::capture()); + let _ignored_result = std::io::stderr().flush(); + })); +} + pub fn set_error_print_level(level: u8) -> u8 { assert!(level <= 2); ERROR_PRINT_LEVEL.swap(level, atomic::Ordering::Relaxed) @@ -260,19 +278,75 @@ pub(crate) fn has_error_print_level(level: u8) -> bool { ERROR_PRINT_LEVEL.load(atomic::Ordering::Relaxed) >= level } +/// Internal type used to store context information for debug purposes. Debug context is stored on the thread-local +/// ERROR_CONTEXT_STACK, which can later be used to retrieve the current context in the event of a panic. This value +/// probably shouldn't be used directly; use ['get_gdext_panic_context()'](get_gdext_panic_context) instead. +#[cfg(debug_assertions)] +struct ScopedFunctionStack { + functions: Vec<*const dyn Fn() -> String>, +} + +#[cfg(debug_assertions)] +impl ScopedFunctionStack { + /// # Safety + /// Function must be removed (using [`pop_function()`](Self::pop_function)) before lifetime is invalidated. + unsafe fn push_function(&mut self, function: &dyn Fn() -> String) { + let function = std::ptr::from_ref(function); + #[allow(clippy::unnecessary_cast)] + let function = function as *const (dyn Fn() -> String + 'static); + self.functions.push(function); + } + + fn pop_function(&mut self) { + self.functions.pop().expect("function stack is empty!"); + } + + fn get_last(&self) -> Option { + self.functions.last().cloned().map(|pointer| { + // SAFETY: + // Invariants provided by push_function assert that any and all functions held by ScopedFunctionStack + // are removed before they are invalidated; functions must always be valid. + unsafe { (*pointer)() } + }) + } +} + +#[cfg(debug_assertions)] +thread_local! { + static ERROR_CONTEXT_STACK: RefCell = const { + RefCell::new(ScopedFunctionStack { functions: Vec::new() }) + } +} + +// Value may return `None`, even from panic hook, if called from a non-Godot thread. +pub fn get_gdext_panic_context() -> Option { + #[cfg(debug_assertions)] + return ERROR_CONTEXT_STACK.with(|cell| cell.borrow().get_last()); + #[cfg(not(debug_assertions))] + None +} + /// Executes `code`. If a panic is thrown, it is caught and an error message is printed to Godot. /// /// Returns `Err(message)` if a panic occurred, and `Ok(result)` with the result of `code` otherwise. /// /// In contrast to [`handle_varcall_panic`] and [`handle_ptrcall_panic`], this function is not intended for use in `try_` functions, /// where the error is propagated as a `CallError` in a global variable. -pub fn handle_panic(error_context: E, code: F) -> Result +pub fn handle_panic(error_context: E, code: F) -> Result where - E: FnOnce() -> S, + E: Fn() -> String, F: FnOnce() -> R + std::panic::UnwindSafe, - S: std::fmt::Display, { - handle_panic_with_print(error_context, code, has_error_print_level(1)) + #[cfg(debug_assertions)] + ERROR_CONTEXT_STACK.with(|cell| unsafe { + // SAFETY: &error_context is valid for lifetime of function, and is removed from LAST_ERROR_CONTEXT before end of function. + cell.borrow_mut().push_function(&error_context) + }); + let result = + std::panic::catch_unwind(code).map_err(|payload| extract_panic_message(payload.as_ref())); + #[cfg(debug_assertions)] + ERROR_CONTEXT_STACK.with(|cell| cell.borrow_mut().pop_function()); + result } // TODO(bromeon): make call_ctx lazy-evaluated (like error_ctx) everywhere; @@ -285,7 +359,7 @@ pub fn handle_varcall_panic( F: FnOnce() -> Result + std::panic::UnwindSafe, { let outcome: Result, String> = - handle_panic_with_print(|| call_ctx, code, false); + handle_panic(|| format!("{call_ctx}"), code); let call_error = match outcome { // All good. @@ -314,7 +388,7 @@ pub fn handle_ptrcall_panic(call_ctx: &CallContext, code: F) where F: FnOnce() -> R + std::panic::UnwindSafe, { - let outcome: Result = handle_panic_with_print(|| call_ctx, code, false); + let outcome: Result = handle_panic(|| format!("{call_ctx}"), code); let call_error = match outcome { // All good. @@ -343,91 +417,6 @@ fn report_call_error(call_error: CallError, track_globally: bool) -> i32 { } } -fn handle_panic_with_print(error_context: E, code: F, print: bool) -> Result -where - E: FnOnce() -> S, - F: FnOnce() -> R + std::panic::UnwindSafe, - S: std::fmt::Display, -{ - #[cfg(debug_assertions)] - let info: Arc>> = Arc::new(Mutex::new(None)); - - // Back up previous hook, set new one. - #[cfg(debug_assertions)] - let prev_hook = { - let info = info.clone(); - let prev_hook = std::panic::take_hook(); - - std::panic::set_hook(Box::new(move |panic_info| { - if let Some(location) = panic_info.location() { - *info.lock().unwrap() = Some(GodotPanicInfo { - file: location.file().to_string(), - line: location.line(), - //backtrace: Backtrace::capture(), - }); - } else { - eprintln!("panic occurred, but can't get location information"); - } - })); - - prev_hook - }; - - // Run code that should panic, restore hook. - let panic = std::panic::catch_unwind(code); - - // Restore the previous panic hook if in Debug mode. - #[cfg(debug_assertions)] - std::panic::set_hook(prev_hook); - - match panic { - Ok(result) => Ok(result), - Err(err) => { - // Flush, to make sure previous Rust output (e.g. test announcement, or debug prints during app) have been printed - // TODO write custom panic handler and move this there, before panic backtrace printing. - flush_stdout(); - - // Handle panic info only in Debug mode. - #[cfg(debug_assertions)] - { - let msg = extract_panic_message(err); - let mut msg = format_panic_message(msg); - - // Try to add location information. - if let Ok(guard) = info.lock() { - if let Some(info) = guard.as_ref() { - msg = format!("{}\n at {}:{}", msg, info.file, info.line); - } - } - - if print { - godot_error!( - "Rust function panicked: {}\n Context: {}", - msg, - error_context() - ); - //eprintln!("Backtrace:\n{}", info.backtrace); - } - - Err(msg) - } - - #[cfg(not(debug_assertions))] - { - let _ = error_context; // Unused warning. - let msg = extract_panic_message(err); - let msg = format_panic_message(msg); - - if print { - godot_error!("{msg}"); - } - - Err(msg) - } - } - } -} - // ---------------------------------------------------------------------------------------------------------------------------------------------- #[cfg(test)] diff --git a/godot-core/src/task/async_runtime.rs b/godot-core/src/task/async_runtime.rs index 5f683bcfd..17c1e73f5 100644 --- a/godot-core/src/task/async_runtime.rs +++ b/godot-core/src/task/async_runtime.rs @@ -403,7 +403,7 @@ fn poll_future(godot_waker: Arc) { return; }; - let error_context = || "Godot async task failed"; + let error_context = || "Godot async task failed".to_string(); // If Future::poll() panics, the future is immediately dropped and cannot be accessed again, // thus any state that may not have been unwind-safe cannot be observed later. diff --git a/godot-macros/src/class/data_models/func.rs b/godot-macros/src/class/data_models/func.rs index 70e971f7e..36df39b0c 100644 --- a/godot-macros/src/class/data_models/func.rs +++ b/godot-macros/src/class/data_models/func.rs @@ -485,7 +485,7 @@ fn make_ptrcall_fn(call_ctx: &TokenStream, wrapped_method: &TokenStream) -> Toke ) { let call_ctx = #call_ctx; let _success = ::godot::private::handle_panic( - || &call_ctx, + || format!("{call_ctx}"), || #invocation ); diff --git a/itest/rust/src/builtin_tests/containers/callable_test.rs b/itest/rust/src/builtin_tests/containers/callable_test.rs index 27e6cb1ea..74a881b0e 100644 --- a/itest/rust/src/builtin_tests/containers/callable_test.rs +++ b/itest/rust/src/builtin_tests/containers/callable_test.rs @@ -382,7 +382,7 @@ impl CallableRefcountTest { #[cfg(since_api = "4.2")] pub mod custom_callable { use super::*; - use crate::framework::{assert_eq_self, quick_thread, ThreadCrosser}; + use crate::framework::{assert_eq_self, quick_thread, suppress_panic_log, ThreadCrosser}; use godot::builtin::{Dictionary, RustCallable}; use godot::prelude::Signal; use godot::sys; @@ -596,7 +596,9 @@ pub mod custom_callable { let received = Arc::new(AtomicU32::new(0)); let received_callable = received.clone(); let callable = Callable::from_local_fn("test", move |_args| { - panic!("TEST: {}", received_callable.fetch_add(1, Ordering::SeqCst)) + suppress_panic_log(|| { + panic!("TEST: {}", received_callable.fetch_add(1, Ordering::SeqCst)) + }) }); assert_eq!(Variant::nil(), callable.callv(&varray![])); diff --git a/itest/rust/src/framework/mod.rs b/itest/rust/src/framework/mod.rs index d581c9ecf..37a9682c2 100644 --- a/itest/rust/src/framework/mod.rs +++ b/itest/rust/src/framework/mod.rs @@ -9,6 +9,7 @@ use godot::classes::{Engine, Node, Os}; use godot::obj::Gd; use godot::sys; use std::collections::HashSet; +use std::panic; mod bencher; mod runner; @@ -171,21 +172,30 @@ pub fn passes_filter(filters: &[String], test_name: &str) -> bool { // ---------------------------------------------------------------------------------------------------------------------------------------------- // Toolbox for tests -pub fn expect_panic(context: &str, code: impl FnOnce()) { - use std::panic; - - // Exchange panic hook, to disable printing during expected panics. Also disable gdext's panic printing. +/// Swaps panic hooks, to disable printing during expected panics. Also disables gdext's panic printing. +pub fn suppress_panic_log(callback: impl FnOnce() -> R) -> R { + // DISABLE following lines to *temporarily* debug panics. + // Note that they currently print "itest `{}` failed", even if the test doesn't fail (which isn't usually relevant in suppressed mode). let prev_hook = panic::take_hook(); - panic::set_hook(Box::new(|_panic_info| {})); + panic::set_hook(Box::new( + |_panic_info| { /* suppress panic hook; do nothing */ }, + )); + + // Keep following lines. let prev_print_level = godot::private::set_error_print_level(0); + let res = callback(); + godot::private::set_error_print_level(prev_print_level); + + // DISABLE following line to *temporarily* debug panics. + panic::set_hook(prev_hook); + res +} + +pub fn expect_panic(context: &str, code: impl FnOnce()) { // Generally, types should be unwind safe, and this helps ergonomics in testing (especially around &mut in expect_panic closures). let code = panic::AssertUnwindSafe(code); - - // Run code that should panic, restore hook + gdext panic printing. - let panic = panic::catch_unwind(code); - panic::set_hook(prev_hook); - godot::private::set_error_print_level(prev_print_level); + let panic = suppress_panic_log(move || panic::catch_unwind(code)); assert!( panic.is_err(), diff --git a/itest/rust/src/framework/runner.rs b/itest/rust/src/framework/runner.rs index 097969b64..50c9f7188 100644 --- a/itest/rust/src/framework/runner.rs +++ b/itest/rust/src/framework/runner.rs @@ -310,7 +310,7 @@ impl IntegrationTests { // could not be caught, causing UB at the Godot FFI boundary (in practice, this will be a defined Godot crash with // stack trace though). godot_error!("GDScript test panicked"); - godot::private::extract_panic_message(e); + godot::private::extract_panic_message(&e); TestOutcome::Failed } }; @@ -444,8 +444,11 @@ fn run_rust_test(test: &RustTestCase, ctx: &TestContext) -> TestOutcome { return TestOutcome::Skipped; } - // Explicit type to prevent tests from returning a value + // This will appear in all panics, but those inside expect_panic() are suppressed. + // So the "itest failed" message will only appear for unexpected panics, where tests indeed fail. let err_context = || format!("itest `{}` failed", test.name); + + // Explicit type to prevent tests from returning a value. let success: Result<(), _> = godot::private::handle_panic(err_context, || (test.function)(ctx)); TestOutcome::from_bool(success.is_ok()) @@ -523,7 +526,8 @@ fn print_test_pre(test_case: &str, test_file: &str, last_file: Option<&str>, flu if flush { // Flush in GDScript, because its own print may come sooner than Rust prints otherwise. // (Strictly speaking, this can also happen from Rust, when Godot prints something. So far, it didn't though...) - godot::private::flush_stdout(); + use std::io::Write; + std::io::stdout().flush().expect("flush stdout"); } } diff --git a/itest/rust/src/object_tests/dynamic_call_test.rs b/itest/rust/src/object_tests/dynamic_call_test.rs index 6f3c80b4f..20388997c 100644 --- a/itest/rust/src/object_tests/dynamic_call_test.rs +++ b/itest/rust/src/object_tests/dynamic_call_test.rs @@ -11,6 +11,7 @@ use godot::meta::error::CallError; use godot::meta::{FromGodot, ToGodot}; use godot::obj::{InstanceId, NewAlloc}; use std::error::Error; +use std::sync::{Arc, Mutex}; use crate::framework::{expect_panic, itest, runs_release}; use crate::object_tests::object_test::ObjPayload; @@ -139,8 +140,19 @@ fn dynamic_call_parameter_mismatch() { obj.free(); } +// There seems to be a weird bug where running *only* this test with #[itest(focus)] causes panic, which then causes a +// follow-up failure of Gd::bind_mut(), preventing benchmarks from being run. Doesn't happen with #[itest], when running all. #[itest] fn dynamic_call_with_panic() { + let panic_message = Arc::new(Mutex::new(None)); + let panic_message_clone = panic_message.clone(); + + std::panic::set_hook(Box::new(move |panic_info| { + let error_message = godot::private::format_panic_message(panic_info); + *panic_message_clone.lock().unwrap() = + Some((error_message, godot::private::get_gdext_panic_context())); + })); + let mut obj = ObjPayload::new_alloc(); let result = obj.try_call("do_panic", &[]); @@ -149,28 +161,39 @@ fn dynamic_call_with_panic() { assert_eq!(call_error.class_name(), Some("Object")); assert_eq!(call_error.method_name(), "call"); - let appendix = if cfg!(debug_assertions) { - let mut path = "itest/rust/src/object_tests/object_test.rs".to_string(); + let expected_error_message = "godot-rust function call failed: Object::call(&\"do_panic\")\ + \n Source: ObjPayload::do_panic()\ + \n Reason: do_panic exploded" + .to_string(); + + assert_eq!(call_error.to_string(), expected_error_message); - if cfg!(target_os = "windows") { - path = path.replace('/', "\\") - } + let (panic_message, error_context) = panic_message + .lock() + .unwrap() + .clone() + .expect("panic message/context absent"); - // Obtain line number dynamically, avoids tedious maintenance on code reorganization. - let line = ObjPayload::get_panic_line(); + let mut path = "itest/rust/src/object_tests/object_test.rs".to_string(); + if cfg!(target_os = "windows") { + path = path.replace('/', "\\") + } - format!("\n at {path}:{line}") + // Obtain line number dynamically -- avoids tedious maintenance on code reorganization. + let line = ObjPayload::get_panic_line(); + let context = error_context + .map(|context| format!("\n Context: {context}")) + .unwrap_or_default(); + + // In Debug, there is a context -> message is multi-line -> '\n' is inserted after [panic ...]. + // In Release, simpler message -> single line -> no '\n'. + let expected_panic_message = if cfg!(debug_assertions) { + format!("[panic {path}:{line}]\n do_panic exploded{context}") } else { - String::new() + format!("[panic {path}:{line}] do_panic exploded") }; - let expected_error_message = format!( - "godot-rust function call failed: Object::call(&\"do_panic\")\ - \n Source: ObjPayload::do_panic()\ - \n Reason: [panic] do_panic exploded{appendix}" - ); - - assert_eq!(call_error.to_string(), expected_error_message); + assert_eq!(panic_message, expected_panic_message); obj.free(); }