Fix access to transient object data in Debug log

While C++ destructors are run, virtual functions on C++ Object will no
longer dispatch correctly. These are however relied upon for functionality
like casting, dynamic class query, etc.

Author: Bromeon

godot-core/src/classes/class_runtime.rs

@@ -22,13 +22,21 @@ pub(crate) fn debug_string<T: GodotClass>(
     ty: &str,
 ) -> std::fmt::Result {
     if let Some(id) = obj.instance_id_or_none() {
+        // Sample the reference count FIRST, before any other operations that might affect it.
+        // This avoids the +1 temporary reference from subsequent FFI calls during debug formatting.
+        let refcount = obj.maybe_refcount();
+
         let class: StringName = obj.dynamic_class_string();
 
         let mut builder = f.debug_struct(ty);
-        builder.field("id", &id).field("class", &class);
-        if let Some(refcount) = obj.maybe_refcount() {
+        builder
+            .field("id", &id.to_i64())
+            .field("class", &format_args!("{class}"));
+
+        if let Some(refcount) = refcount {
             builder.field("refc", &refcount);
         }
+
         builder.finish()
     } else {
         write!(f, "{ty} {{ freed obj }}")
@@ -46,8 +54,8 @@ pub(crate) fn debug_string_nullable<T: GodotClass>(
         // Unsafety introduced here to avoid creating a new Gd<T> (which can have all sorts of side effects, logs, refcounts etc.)
         // *and* pushing down all high-level Gd<T> functions to RawGd<T> as pure delegates.
 
-        // SAFETY: layout of Gd<T> is currently equivalent to RawGd<T>.
-        let obj: &Gd<T> = unsafe { std::mem::transmute::<&RawGd<T>, &Gd<T>>(obj) };
+        // SAFETY: checked non-null.
+        let obj = unsafe { obj.as_non_null() };
         debug_string(obj, f, ty)
     }
 }
@@ -59,16 +67,21 @@ pub(crate) fn debug_string_with_trait<T: GodotClass>(
     trt: &str,
 ) -> std::fmt::Result {
     if let Some(id) = obj.instance_id_or_none() {
+        // Sample the reference count FIRST, before any other operations that might affect it.
+        let refcount = obj.maybe_refcount();
+
         let class: StringName = obj.dynamic_class_string();
 
         let mut builder = f.debug_struct(ty);
         builder
-            .field("id", &id)
-            .field("class", &class)
-            .field("trait", &trt);
-        if let Some(refcount) = obj.maybe_refcount() {
+            .field("id", &id.to_i64())
+            .field("class", &format_args!("{class}"))
+            .field("trait", &format_args!("{trt}"));
+
+        if let Some(refcount) = refcount {
             builder.field("refc", &refcount);
         }
+
         builder.finish()
     } else {
         write!(f, "{ty} {{ freed obj }}")

godot-core/src/obj/base.rs

@@ -102,6 +102,12 @@ impl<T: GodotClass> Base<T> {
     pub fn obj_sys(&self) -> sys::GDExtensionObjectPtr {
         self.obj.obj_sys()
     }
+
+    // Internal use only, do not make public.
+    #[cfg(feature = "debug-log")]
+    pub(crate) fn debug_instance_id(&self) -> crate::obj::InstanceId {
+        self.obj.instance_id()
+    }
 }
 
 impl<T: GodotClass> Debug for Base<T> {

godot-core/src/obj/gd.rs

@@ -305,12 +305,18 @@ impl<T: GodotClass> Gd<T> {
     /// Returns the reference count, if the dynamic object inherits `RefCounted`; and `None` otherwise.
     pub(crate) fn maybe_refcount(&self) -> Option<usize> {
         // Fast check if ref-counted without downcast.
-        self.instance_id_unchecked().is_ref_counted().then(|| {
+        self.instance_id().is_ref_counted().then(|| {
             let rc = self.raw.with_ref_counted(|refc| refc.get_reference_count());
             rc as usize
         })
     }
 
+    #[cfg(feature = "trace")] // itest only.
+    #[doc(hidden)]
+    pub fn test_refcount(&self) -> Option<usize> {
+        self.maybe_refcount()
+    }
+
     /// **Upcast:** convert into a smart pointer to a base class. Always succeeds.
     ///
     /// Moves out of this value. If you want to create _another_ smart pointer instance,

godot-core/src/obj/raw_gd.rs

@@ -18,7 +18,7 @@ use crate::meta::{
 use crate::obj::bounds::{Declarer, DynMemory as _};
 use crate::obj::casts::CastSuccess;
 use crate::obj::rtti::ObjectRtti;
-use crate::obj::{bounds, Bounds, GdDerefTarget, GdMut, GdRef, GodotClass, InstanceId};
+use crate::obj::{bounds, Bounds, Gd, GdDerefTarget, GdMut, GdRef, GodotClass, InstanceId};
 use crate::storage::{InstanceCache, InstanceStorage, Storage};
 use crate::{classes, out};
 
@@ -147,10 +147,15 @@ impl<T: GodotClass> RawGd<T> {
     ///
     /// On success, you'll get a `CastSuccess<T, U>` instance, which holds a weak `RawGd<U>`. You can only extract that one by trading
     /// a strong `RawGd<T>` for it, to maintain the balance.
+    ///
+    /// This function is unreliable when invoked _during_ destruction (e.g. C++ `~RefCounted()` destructor). This can occur when debug-logging
+    /// instances during cleanups. `Object::object_cast_to()` is a virtual function, but virtual dispatch during destructor doesn't work in C++.
     pub(super) fn ffi_cast<U>(&self) -> Result<CastSuccess<T, U>, ()>
     where
         U: GodotClass,
     {
+        //eprintln!("ffi_cast: {} (dyn {}) -> {}", T::class_name(), self.as_non_null().dynamic_class_string(), U::class_name());
+
         // `self` may be null when we convert a null-variant into a `Option<Gd<T>>`, since we use `ffi_cast`
         // in the `ffi_from_variant` conversion function to ensure type-correctness. So the chain would be as follows:
         // - Variant::nil()
@@ -183,24 +188,57 @@ impl<T: GodotClass> RawGd<T> {
         Ok(CastSuccess::from_weak(weak))
     }
 
+    /// Executes a function, assuming that `self` inherits `RefCounted`.
+    ///
+    /// This function is unreliable when invoked _during_ destruction (e.g. C++ `~RefCounted()` destructor). This can occur when debug-logging
+    /// instances during cleanups. `Object::object_cast_to()` is a virtual function, but virtual dispatch during destructor doesn't work in C++.
+    ///
+    /// # Panics
+    /// If `self` does not inherit `RefCounted` or is null.
     pub(crate) fn with_ref_counted<R>(&self, apply: impl Fn(&mut classes::RefCounted) -> R) -> R {
         // Note: this previously called Declarer::scoped_mut() - however, no need to go through bind() for changes in base RefCounted.
         // Any accesses to user objects (e.g. destruction if refc=0) would bind anyway.
+        //
+        // Might change implementation as follows -- but last time caused UB; investigate.
+        // pub(crate) unsafe fn as_ref_counted_unchecked(&mut self) -> &mut classes::RefCounted {
+        //     self.as_target_mut()
+        // }
+
+        let mut ref_counted = match self.ffi_cast::<classes::RefCounted>() {
+            Ok(cast_success) => cast_success,
+            Err(()) if self.is_null() => {
+                panic!("RawGd::with_ref_counted(): expected to inherit RefCounted, encountered null pointer");
+            }
+            Err(()) => {
+                // SAFETY: this branch implies non-null.
+                let gd_ref = unsafe { self.as_non_null() };
+                let class = gd_ref.dynamic_class_string();
+
+                // One way how this may panic is when invoked during destruction of a RefCounted object. The C++ `Object::object_cast_to()`
+                // function is virtual but cannot be dynamically dispatched in a C++ destructor.
+                panic!("RawGd::with_ref_counted(): expected to inherit RefCounted, but encountered {class}");
+            }
+        };
 
-        let mut cast_obj = self
-            .ffi_cast::<classes::RefCounted>()
-            .expect("object expected to inherit RefCounted");
+        let return_val = apply(ref_counted.as_dest_mut().as_target_mut());
 
-        // Using as_dest_mut() ensures that there is no refcount increment happening, i.e. any apply() function happens on *current* object.
-        // Apart from performance considerations, this is relevant when examining RefCounted::get_reference_count() -- otherwise we have an
-        // Observer effect, where reading the RefCounted object changes its reference count -- e.g. in Debug impl.
-        apply(cast_obj.as_dest_mut().as_target_mut())
+        // CastSuccess is forgotten when dropped, so no ownership transfer.
+        return_val
     }
 
-    // TODO replace the above with this -- last time caused UB; investigate.
-    // pub(crate) unsafe fn as_ref_counted_unchecked(&mut self) -> &mut classes::RefCounted {
-    //     self.as_target_mut()
-    // }
+    /// Enables outer `Gd` APIs or bypasses additional null checks, in cases where `RawGd` is guaranteed non-null.
+    ///
+    /// # Safety
+    /// `self` must not be null.
+    pub(crate) unsafe fn as_non_null(&self) -> &Gd<T> {
+        debug_assert!(
+            !self.is_null(),
+            "RawGd::as_non_null() called on null pointer; this is UB"
+        );
+
+        // SAFETY: layout of Gd<T> is currently equivalent to RawGd<T>.
+        unsafe { std::mem::transmute::<&RawGd<T>, &Gd<T>>(self) }
+    }
 
     pub(crate) fn as_object_ref(&self) -> &classes::Object {
         // SAFETY: Object is always a valid upcast target.

godot-core/src/storage/instance_storage.rs

@@ -15,8 +15,9 @@ use godot_cell::panicking::{InaccessibleGuard, MutGuard, RefGuard};
 #[cfg(feature = "experimental-threads")]
 use godot_cell::blocking::{InaccessibleGuard, MutGuard, RefGuard};
 
+use crate::godot_error;
 use crate::obj::{Base, Gd, GodotClass, Inherits};
-use crate::{godot_error, out};
+use crate::storage::log_pre_drop;
 
 #[derive(Copy, Clone, Debug)]
 pub enum Lifecycle {
@@ -134,20 +135,12 @@ pub unsafe trait Storage {
     }
 
     fn mark_destroyed_by_godot(&self) {
-        out!(
-            "    Storage::mark_destroyed_by_godot", // -- {:?}",
-                                                    //self.user_instance
-        );
         self.set_lifecycle(Lifecycle::Destroying);
-        out!(
-            "    mark;  self={:?}, val={:?}, obj={:?}",
-            self as *const _,
-            self.get_lifecycle(),
-            self.base(),
-        );
+
+        log_pre_drop(self);
     }
 
-    #[inline(always)]
+    /*#[inline(always)]
     fn destroyed_by_godot(&self) -> bool {
         out!(
             "    is_d;  self={:?}, val={:?}, obj={:?}",
@@ -156,11 +149,12 @@ pub unsafe trait Storage {
             self.base(),
         );
         matches!(self.get_lifecycle(), Lifecycle::Destroying)
-    }
+    }*/
 }
 
 /// An internal trait for keeping track of reference counts for a storage.
 pub(crate) trait StorageRefCounted: Storage {
+    #[allow(dead_code)] // used in `debug-log` feature. Don't micromanage.
     fn godot_ref_count(&self) -> u32;
 
     fn on_inc_ref(&self);

godot-core/src/storage/mod.rs

@@ -11,7 +11,6 @@ mod multi_threaded;
 #[cfg_attr(feature = "experimental-threads", allow(dead_code))]
 mod single_threaded;
 
-use godot_ffi::out;
 pub use instance_storage::*;
 use std::any::type_name;
 
@@ -53,37 +52,74 @@ fn bug_inaccessible<T>(err: Box<dyn std::error::Error>) -> ! {
     )
 }
 
-fn log_construct<T: GodotClass>(base: &Base<T::Base>) {
-    out!(
-        "    Storage::construct:             {base:?}  (T={ty})",
-        ty = type_name::<T>()
-    );
-}
+#[cfg(feature = "debug-log")]
+use log_active::*;
 
-fn log_inc_ref<T: StorageRefCounted>(storage: &T) {
-    out!(
-        "    Storage::on_inc_ref (rc={rc}):  {base:?}  (T={ty})",
-        rc = T::godot_ref_count(storage),
-        base = storage.base(),
-        ty = type_name::<T>(),
-    );
-}
+#[cfg(not(feature = "debug-log"))]
+use log_inactive::*;
+
+#[cfg(feature = "debug-log")]
+mod log_active {
+    use super::*;
+    use godot_ffi::out;
+
+    pub fn log_construct<T: GodotClass>(base: &Base<T::Base>) {
+        out!(
+            "    Storage::construct:             {base:?}  (T={ty})",
+            ty = type_name::<T>()
+        );
+    }
+
+    pub fn log_inc_ref<T: StorageRefCounted>(storage: &T) {
+        out!(
+            "    Storage::on_inc_ref (rc={rc}):  {base:?}  (T={ty})",
+            rc = T::godot_ref_count(storage),
+            base = storage.base(),
+            ty = type_name::<T>(),
+        );
+    }
 
-fn log_dec_ref<T: StorageRefCounted>(storage: &T) {
-    out!(
-        "  | Storage::on_dec_ref (rc={rc}):  {base:?}  (T={ty})",
-        rc = T::godot_ref_count(storage),
-        base = storage.base(),
-        ty = type_name::<T>(),
-    );
+    pub fn log_dec_ref<T: StorageRefCounted>(storage: &T) {
+        out!(
+            "  | Storage::on_dec_ref (rc={rc}):  {base:?}  (T={ty})",
+            rc = T::godot_ref_count(storage),
+            base = storage.base(),
+            ty = type_name::<T>(),
+        );
+    }
+
+    pub fn log_pre_drop<T: Storage + ?Sized>(storage: &T) {
+        // Do not Debug-fmt `self.base()` object here, as the C++ destructor may already be running. Debug::fmt fetches dynamic object information
+        // (class type, virtual object_cast_to(), ...), but virtual dispatch won't run in active C++ destructors, thus causing weird behavior.
+
+        out!(
+            "    Storage::mark_destroyed_by_godot:  {base_id} (lcy={lifecycle:?})",
+            base_id = storage.base().debug_instance_id(),
+            lifecycle = storage.get_lifecycle(),
+        );
+    }
+
+    pub fn log_drop<T: StorageRefCounted>(storage: &T) {
+        // Do not Debug-fmt `self.base()` object here, see above.
+
+        out!(
+            "    Storage::drop (rc={rc}):        {base_id}",
+            rc = storage.godot_ref_count(),
+            base_id = storage.base().debug_instance_id(),
+        );
+    }
 }
 
-fn log_drop<T: StorageRefCounted>(storage: &T) {
-    out!(
-        "    Storage::drop (rc={rc}):        {base:?}",
-        rc = storage.godot_ref_count(),
-        base = storage.base(),
-    );
+// out! macro still mentions arguments in all cfgs, so they must exist (and may or may not be optimized away).
+#[cfg(not(feature = "debug-log"))]
+mod log_inactive {
+    use super::*;
+
+    pub fn log_construct<T: GodotClass>(_base: &Base<T::Base>) {}
+    pub fn log_inc_ref<T: StorageRefCounted>(_storage: &T) {}
+    pub fn log_dec_ref<T: StorageRefCounted>(_storage: &T) {}
+    pub fn log_pre_drop<T: Storage + ?Sized>(_storage: &T) {}
+    pub fn log_drop<T: StorageRefCounted>(_storage: &T) {}
 }
 
 // ----------------------------------------------------------------------------------------------------------------------------------------------

itest/rust/src/object_tests/dyn_gd_test.rs

@@ -398,20 +398,28 @@ fn dyn_gd_error_unimplemented_trait() {
     let back = variant.try_to::<DynGd<RefCounted, dyn Health>>();
 
     let err = back.expect_err("DynGd::try_to() should have failed");
-    assert_eq!(
-        err.to_string(),
-        format!("none of the classes derived from `RefCounted` have been linked to trait `dyn Health` with #[godot_dyn]: {obj:?}")
-    );
+
+    let refc_id = obj.instance_id().to_i64();
+    let expected_debug = format!(
+            "none of the classes derived from `RefCounted` have been linked to trait `dyn Health` with #[godot_dyn]: \
+         Gd {{ id: {refc_id}, class: RefCounted, refc: 3 }}")
+    ;
+    // was: {obj:?}
+    assert_eq!(err.to_string(), expected_debug);
 
     let node = foreign::NodeHealth::new_alloc();
     let variant = node.to_variant();
     let back = variant.try_to::<DynGd<foreign::NodeHealth, dyn InstanceIdProvider<Id = f32>>>();
 
     let err = back.expect_err("DynGd::try_to() should have failed");
-    assert_eq!(
-        err.to_string(),
-        format!("none of the classes derived from `NodeHealth` have been linked to trait `dyn InstanceIdProvider<Id = f32>` with #[godot_dyn]: {node:?}")
+
+    // NodeHealth is manually managed (inherits Node), so no refcount in debug output.
+    let node_id = node.instance_id().to_i64();
+    let expected_debug =        format!(
+            "none of the classes derived from `NodeHealth` have been linked to trait `dyn InstanceIdProvider<Id = f32>` with #[godot_dyn]: \
+         Gd {{ id: {node_id}, class: NodeHealth }}"
     );
+    assert_eq!(err.to_string(), expected_debug);
 
     node.free();
 }