Capture bind/bind_mut backtraces + print on borrow errors

Author: Bromeon

godot-core/src/private.rs

@@ -17,15 +17,17 @@ pub use sys::out;
 
 #[cfg(feature = "trace")]
 pub use crate::meta::trace;
+#[cfg(debug_assertions)]
+use std::cell::RefCell;
 
 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;
 use sys::Global;
+
 // ----------------------------------------------------------------------------------------------------------------------------------------------
 // Global variables
 
@@ -249,6 +251,41 @@ pub fn format_panic_message(panic_info: &std::panic::PanicHookInfo) -> String {
     }
 }
 
+// Macro instead of function, to avoid 1 extra frame in backtrace.
+#[cfg(debug_assertions)]
+#[macro_export]
+macro_rules! format_backtrace {
+    ($prefix:expr, $backtrace:expr) => {{
+        use std::backtrace::BacktraceStatus;
+
+        let backtrace = $backtrace;
+
+        match backtrace.status() {
+            BacktraceStatus::Captured => format!("\n[{}]\n{}\n", $prefix, backtrace),
+            BacktraceStatus::Disabled => {
+                "(backtrace disabled, run application with `RUST_BACKTRACE=1` environment variable)"
+                    .to_string()
+            }
+            BacktraceStatus::Unsupported => {
+                "(backtrace unsupported for current platform)".to_string()
+            }
+            _ => "(backtrace status unknown)".to_string(),
+        }
+    }};
+
+    ($prefix:expr) => {
+        $crate::format_backtrace!($prefix, std::backtrace::Backtrace::capture())
+    };
+}
+
+#[cfg(not(debug_assertions))]
+#[macro_export]
+macro_rules! format_backtrace {
+    ($prefix:expr $(, $backtrace:expr)? ) => {
+        String::new()
+    };
+}
+
 pub fn set_gdext_hook<F>(godot_print: F)
 where
     F: Fn() -> bool + Send + Sync + 'static,
@@ -261,9 +298,9 @@ where
         if godot_print() {
             godot_error!("{message}");
         }
-        eprintln!("{message}");
-        #[cfg(debug_assertions)]
-        eprintln!("{}", std::backtrace::Backtrace::capture());
+
+        let backtrace = format_backtrace!("panic backtrace");
+        eprintln!("{message}{backtrace}");
         let _ignored_result = std::io::stderr().flush();
     }));
 }
@@ -322,6 +359,7 @@ thread_local! {
 pub fn get_gdext_panic_context() -> Option<String> {
     #[cfg(debug_assertions)]
     return ERROR_CONTEXT_STACK.with(|cell| cell.borrow().get_last());
+
     #[cfg(not(debug_assertions))]
     None
 }
@@ -337,13 +375,18 @@ where
     E: Fn() -> String,
     F: FnOnce() -> R + std::panic::UnwindSafe,
 {
+    #[cfg(not(debug_assertions))]
+    let _ = error_context; // Unused in Release.
+
     #[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

godot-core/src/storage/mod.rs

@@ -18,17 +18,23 @@ use std::any::type_name;
 // ----------------------------------------------------------------------------------------------------------------------------------------------
 // Shared code for submodules
 
-fn bind_failed<T>(err: Box<dyn std::error::Error>) -> ! {
+fn bind_failed<T>(err: Box<dyn std::error::Error>, tracker: &DebugBorrowTracker) -> ! {
     let ty = type_name::<T>();
+
+    eprint!("{tracker}");
+
     panic!(
         "Gd<T>::bind() failed, already bound; T = {ty}.\n  \
         Make sure to use `self.base_mut()` or `self.base()` instead of `self.to_gd()` when possible.\n  \
         Details: {err}."
     )
 }
 
-fn bind_mut_failed<T>(err: Box<dyn std::error::Error>) -> ! {
+fn bind_mut_failed<T>(err: Box<dyn std::error::Error>, tracker: &DebugBorrowTracker) -> ! {
     let ty = type_name::<T>();
+
+    eprint!("{tracker}");
+
     panic!(
         "Gd<T>::bind_mut() failed, already bound; T = {ty}.\n  \
         Make sure to use `self.base_mut()` instead of `self.to_gd()` when possible.\n  \
@@ -37,9 +43,9 @@ fn bind_mut_failed<T>(err: Box<dyn std::error::Error>) -> ! {
 }
 
 fn bug_inaccessible<T>(err: Box<dyn std::error::Error>) -> ! {
-    // We should never hit this, except maybe in extreme cases like having more than
-    // `usize::MAX` borrows.
+    // We should never hit this, except maybe in extreme cases like having more than `usize::MAX` borrows.
     let ty = type_name::<T>();
+
     panic!(
         "`base_mut()` failed for type T = {ty}.\n  \
         This is most likely a bug, please report it.\n  \
@@ -79,3 +85,100 @@ fn log_drop<T: StorageRefCounted>(storage: &T) {
         base = storage.base(),
     );
 }
+
+// ----------------------------------------------------------------------------------------------------------------------------------------------
+// Tracking borrows in Debug mode
+
+#[cfg(debug_assertions)]
+use borrow_info::DebugBorrowTracker;
+
+#[cfg(not(debug_assertions))]
+use borrow_info_noop::DebugBorrowTracker;
+
+#[cfg(debug_assertions)]
+mod borrow_info {
+    use std::backtrace::Backtrace;
+    use std::fmt;
+    use std::sync::Mutex;
+
+    struct TrackedBorrow {
+        backtrace: Backtrace,
+        is_mut: bool,
+    }
+
+    /// Informational-only info about ongoing borrows.
+    pub(super) struct DebugBorrowTracker {
+        // Currently just tracks the last borrow. Could technically track 1 mut or N ref borrows, but would need destructor integration.
+        // Also never clears it when a guard drops, assuming that once a borrow fails, there must be at least one previous borrow conflicting.
+        // Is also not yet integrated with "inaccessible" borrows (reborrow through base_mut).
+        last_borrow: Mutex<Option<TrackedBorrow>>,
+    }
+
+    impl DebugBorrowTracker {
+        pub fn new() -> Self {
+            Self {
+                last_borrow: Mutex::new(None),
+            }
+        }
+
+        // Currently considers RUST_BACKTRACE due to performance reasons; force_capture() can be quite slow.
+        // User is expected to set the env var during debug sessions.
+
+        #[track_caller]
+        pub fn track_ref_borrow(&self) {
+            let mut guard = self.last_borrow.lock().unwrap();
+            *guard = Some(TrackedBorrow {
+                backtrace: Backtrace::capture(),
+                is_mut: false,
+            });
+        }
+
+        #[track_caller]
+        pub fn track_mut_borrow(&self) {
+            let mut guard = self.last_borrow.lock().unwrap();
+            *guard = Some(TrackedBorrow {
+                backtrace: Backtrace::capture(),
+                is_mut: true,
+            });
+        }
+    }
+
+    impl fmt::Display for DebugBorrowTracker {
+        fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+            let guard = self.last_borrow.lock().unwrap();
+            if let Some(borrow) = &*guard {
+                let mutability = if borrow.is_mut { "bind_mut" } else { "bind" };
+
+                let prefix = format!("backtrace of previous `{mutability}` borrow");
+                let backtrace = crate::format_backtrace!(prefix, &borrow.backtrace);
+
+                writeln!(f, "{backtrace}")
+            } else {
+                writeln!(f, "no previous borrows tracked.")
+            }
+        }
+    }
+}
+
+#[cfg(not(debug_assertions))]
+mod borrow_info_noop {
+    use std::fmt;
+
+    pub(super) struct DebugBorrowTracker;
+
+    impl DebugBorrowTracker {
+        pub fn new() -> Self {
+            Self
+        }
+
+        pub fn track_ref_borrow(&self) {}
+
+        pub fn track_mut_borrow(&self) {}
+    }
+
+    impl fmt::Display for DebugBorrowTracker {
+        fn fmt(&self, _: &mut fmt::Formatter<'_>) -> fmt::Result {
+            Ok(())
+        }
+    }
+}

godot-core/src/storage/multi_threaded.rs

@@ -14,7 +14,7 @@ use godot_cell::panicking::{GdCell, InaccessibleGuard, MutGuard, RefGuard};
 use godot_cell::blocking::{GdCell, InaccessibleGuard, MutGuard, RefGuard};
 
 use crate::obj::{Base, GodotClass};
-use crate::storage::{AtomicLifecycle, Lifecycle, Storage, StorageRefCounted};
+use crate::storage::{AtomicLifecycle, DebugBorrowTracker, Lifecycle, Storage, StorageRefCounted};
 
 pub struct InstanceStorage<T: GodotClass> {
     user_instance: GdCell<T>,
@@ -23,6 +23,9 @@ pub struct InstanceStorage<T: GodotClass> {
     // Declared after `user_instance`, is dropped last
     pub(super) lifecycle: AtomicLifecycle,
     godot_ref_count: AtomicU32,
+
+    // No-op in Release mode.
+    borrow_tracker: DebugBorrowTracker,
 }
 
 // SAFETY:
@@ -47,6 +50,7 @@ unsafe impl<T: GodotClass> Storage for InstanceStorage<T> {
             base,
             lifecycle: AtomicLifecycle::new(Lifecycle::Alive),
             godot_ref_count: AtomicU32::new(1),
+            borrow_tracker: DebugBorrowTracker::new(),
         }
     }
 
@@ -58,16 +62,27 @@ unsafe impl<T: GodotClass> Storage for InstanceStorage<T> {
         &self.base
     }
 
+    // Multi-threaded binds are currently blocking. However, if they still report an error, we follow the single-threaded behavior
+    // of capturing the backtrace. This may be changed as the threading model (#18) evolves.
+
     fn get(&self) -> RefGuard<'_, T> {
-        self.user_instance
+        let guard = self
+            .user_instance
             .borrow()
-            .unwrap_or_else(|e| super::bind_failed::<T>(e))
+            .unwrap_or_else(|e| super::bind_failed::<T>(e, &self.borrow_tracker));
+
+        self.borrow_tracker.track_ref_borrow();
+        guard
     }
 
     fn get_mut(&self) -> MutGuard<'_, T> {
-        self.user_instance
+        let guard = self
+            .user_instance
             .borrow_mut()
-            .unwrap_or_else(|e| super::bind_mut_failed::<T>(e))
+            .unwrap_or_else(|e| super::bind_mut_failed::<T>(e, &self.borrow_tracker));
+
+        self.borrow_tracker.track_mut_borrow();
+        guard
     }
 
     fn get_inaccessible<'a: 'b, 'b>(

godot-core/src/storage/single_threaded.rs

@@ -14,8 +14,7 @@ use godot_cell::panicking::{GdCell, InaccessibleGuard, MutGuard, RefGuard};
 use godot_cell::blocking::{GdCell, InaccessibleGuard, MutGuard, RefGuard};
 
 use crate::obj::{Base, GodotClass};
-use crate::storage::borrow_info::DebugBorrowTracker;
-use crate::storage::{Lifecycle, Storage, StorageRefCounted};
+use crate::storage::{DebugBorrowTracker, Lifecycle, Storage, StorageRefCounted};
 
 pub struct InstanceStorage<T: GodotClass> {
     user_instance: GdCell<T>,
@@ -24,6 +23,9 @@ pub struct InstanceStorage<T: GodotClass> {
     // Declared after `user_instance`, is dropped last
     pub(super) lifecycle: cell::Cell<Lifecycle>,
     godot_ref_count: cell::Cell<u32>,
+
+    // No-op in Release mode.
+    borrow_tracker: DebugBorrowTracker,
 }
 
 // SAFETY:
@@ -48,6 +50,7 @@ unsafe impl<T: GodotClass> Storage for InstanceStorage<T> {
             base,
             lifecycle: cell::Cell::new(Lifecycle::Alive),
             godot_ref_count: cell::Cell::new(1),
+            borrow_tracker: DebugBorrowTracker::new(),
         }
     }
 
@@ -60,15 +63,23 @@ unsafe impl<T: GodotClass> Storage for InstanceStorage<T> {
     }
 
     fn get(&self) -> RefGuard<'_, T> {
-        self.user_instance
+        let guard = self
+            .user_instance
             .borrow()
-            .unwrap_or_else(|e| super::bind_failed::<T>(e))
+            .unwrap_or_else(|e| super::bind_failed::<T>(e, &self.borrow_tracker));
+
+        self.borrow_tracker.track_ref_borrow();
+        guard
     }
 
     fn get_mut(&self) -> MutGuard<'_, T> {
-        self.user_instance
+        let guard = self
+            .user_instance
             .borrow_mut()
-            .unwrap_or_else(|e| super::bind_mut_failed::<T>(e))
+            .unwrap_or_else(|e| super::bind_mut_failed::<T>(e, &self.borrow_tracker));
+
+        self.borrow_tracker.track_mut_borrow();
+        guard
     }
 
     fn get_inaccessible<'stor: 'inst, 'inst>(