importing `tracing-tracy` into godot-rust project prevents the gdextension from being read by Godot correctly

[bcolloran]

I decided to dig into some funny behavior I was seeing when I tried to get Tracy running with my project discord question

I wanted to make sure it wasn't just due to the complexity of my project, so I cooked up a minimal reproduction repo here: https://github.com/bcolloran/godot_rust_tracing_tracy_bug

It turns out that just adding a use tracing_tracy::TracyLayer; in lib.rs will prevent the gdextension from working, causing the following error to show up in the Godot console:
ERROR: core/extension/gdextension_library_loader.cpp:233 - GDExtension initialization function 'gdext_rust_init' returned an error.

I was surprised that just adding the use statement could cause an error, so I thought I'd file an issue. I think both godot-rust and tracing-tracy are doing some sophisticated low level magic behind the scenes, but I thought that it might be worth looking in to how these crates might be bumping into each other in case there is some kind of state leakage or unsafe ...something-something... that might causing unexpected issues that could turn up elsewhere as well.

I thought I'd file the issue over here, because the tracing-tracy lib is small enough that someone who understands the inner workings of godot-rust might be able to scan over it and notice what could be causing the conflict:
https://github.com/nagisa/rust_tracy_client/blob/main/tracing-tracy/src/lib.rs

But it could well be a problem in that code, so I'm happy to file an issue with that repo if that would be preferable.

Thanks!

[Bromeon]

Which Godot version and OS? I assume you use godot-rust master?

It turns out that just adding a use tracing_tracy::TracyLayer; in lib.rs will prevent the gdextension from working, causing the following error to show up in the Godot console:
ERROR: core/extension/gdextension_library_loader.cpp:233 - GDExtension initialization function 'gdext_rust_init' returned an error.

Could you invoke Godot from the command line, and print the entire command-line output (stdout + stderr) from start? Would be interesting to see if other errors are printed.

[brezhnevtusks]

Are you sure that use tracing_tracy::TracyLayer; alone breaks it for you? It seems to work fine with just that line. However, when on_level_init is uncommented as well, it does break, logging this:

thread '<unnamed>' panicked at /home/brezhnevtusks/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/godot-ffi-0.3.2/src/linux_reload_workaround.rs:95:10:
hot reloading should only be set once: true
stack backtrace:
   0:     0x7cf6972763f2 - std::backtrace_rs::backtrace::libunwind::trace::hc8093f7d5570c634
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9
   1:     0x7cf6972763f2 - std::backtrace_rs::backtrace::trace_unsynchronized::h4cd8dc3d0b404add
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14
   2:     0x7cf6972763f2 - std::sys::backtrace::_print_fmt::h7fb3bdf2478d699a
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/sys/backtrace.rs:66:9
   3:     0x7cf6972763f2 - <std::sys::backtrace::BacktraceLock::print::DisplayBacktrace as core::fmt::Display>::fmt::h5d4004938ff2c5de
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/sys/backtrace.rs:39:26
   4:     0x7cf697295993 - core::fmt::rt::Argument::fmt::h534fbc4e56905c62
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/core/src/fmt/rt.rs:173:76
   5:     0x7cf697295993 - core::fmt::write::he40d39caeedce22d
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/core/src/fmt/mod.rs:1465:25
   6:     0x7cf697273f93 - std::io::default_write_fmt::h9047e7f2ee0becf0
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/io/mod.rs:639:11
   7:     0x7cf697273f93 - std::io::Write::write_fmt::h6b481595dd1fc53f
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/io/mod.rs:1954:13
   8:     0x7cf697276242 - std::sys::backtrace::BacktraceLock::print::h6122e56851fd7e04
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/sys/backtrace.rs:42:9
   9:     0x7cf6972774c0 - std::panicking::default_hook::{{closure}}::h5da9a6ee005a6c0c
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/panicking.rs:300:27
  10:     0x7cf6972772c3 - std::panicking::default_hook::he77158b4319b132a
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/panicking.rs:327:9
  11:     0x7cf697277ed2 - std::panicking::rust_panic_with_hook::hbc48a4f07e431d11
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/panicking.rs:833:13
  12:     0x7cf697277c6a - std::panicking::begin_panic_handler::{{closure}}::hc7687229f89659e1
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/panicking.rs:706:13
  13:     0x7cf6972768f9 - std::sys::backtrace::__rust_end_short_backtrace::he778acc2814e945f
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/sys/backtrace.rs:168:18
  14:     0x7cf6972778fd - __rustc[23c8550fe4817b53]::rust_begin_unwind
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/std/src/panicking.rs:697:5
  15:     0x7cf697293570 - core::panicking::panic_fmt::h83f0c88dbe3c1f31
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/core/src/panicking.rs:75:14
  16:     0x7cf697293a06 - core::result::unwrap_failed::h52b0be9a4e22767d
                               at /rustc/f26e58023071e71636a3c72ac3a2bf89b1f76706/library/core/src/result.rs:1761:5
  17:     0x7cf6972393c8 - core::result::Result<T,E>::expect::h953166bab5008992
                               at /home/brezhnevtusks/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/result.rs:1119:23
  18:     0x7cf69723fedf - godot_ffi::linux_reload_workaround::enable_hot_reload::h4f882adfecebf212
                               at /home/brezhnevtusks/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/godot-ffi-0.3.2/src/linux_reload_workaround.rs:95:10
  19:     0x7cf69723fd76 - godot_ffi::linux_reload_workaround::default_set_hot_reload::h8ddde56868fc7e02
                               at /home/brezhnevtusks/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/godot-ffi-0.3.2/src/linux_reload_workaround.rs:26:9
  20:     0x7cf696fba6ac - godot_core::init::__gdext_load_library::{{closure}}::hdc6427535079d1da
                               at /home/brezhnevtusks/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/godot-core-0.3.2/src/init/mod.rs:34:9
  21:     0x7cf696fa7d89 - core::ops::function::FnOnce::call_once::h1abbeebdf81a2e81
                               at /home/brezhnevtusks/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:250:5
  22:     0x7cf696fb079c - std::panicking::catch_unwind::do_call::h0907511e3c672b9a
                               at /home/brezhnevtusks/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:589:40
  23:     0x7cf696fb159b - __rust_try
  24:     0x7cf696fb1478 - std::panicking::catch_unwind::h5f4cc91a320967a9
                               at /home/brezhnevtusks/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:552:19
  25:     0x7cf696fb1478 - std::panic::catch_unwind::hd9adc28cf33f7e4e
                               at /home/brezhnevtusks/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panic.rs:359:14
  26:     0x7cf696fba67b - godot_core::init::__gdext_load_library::h6e4935bfcaeef27c
                               at /home/brezhnevtusks/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/godot-core-0.3.2/src/init/mod.rs:82:22
  27:     0x7cf696fb3c08 - gdext_rust_init
                               at /home/brezhnevtusks/Repos/godot_rust_tracing_tracy_bug/rust/src/lib.rs:27:1
  28:          0x46d36ae - <unknown>
  29:          0x4ce2338 - <unknown>
  30:          0x47406df - <unknown>
  31:          0x4741508 - <unknown>
  32:          0x179868a - <unknown>
  33:          0x179a509 - <unknown>
  34:          0x4745048 - <unknown>
  35:          0x28ffdec - <unknown>
  36:          0x2941223 - <unknown>
  37:          0x2941849 - <unknown>
  38:           0x513b2d - <unknown>
  39:           0x41e7b2 - <unknown>
  40:     0x7cf6a0a2a1ca - __libc_start_call_main
                               at ./csu/../sysdeps/nptl/libc_start_call_main.h:58:16
  41:     0x7cf6a0a2a28b - __libc_start_main_impl
                               at ./csu/../csu/libc-start.c:360:3
  42:           0x44297a - <unknown>
  43:                0x0 - <unknown>

This is Godot 4.4.1, latest godot-rust master on Linux.

[bcolloran]

Which Godot version and OS? I assume you use godot-rust master?

Oops sorry @Bromeon , should have included my system info! This reproduction was run under Godot v4.4.1.stable.official [49a5bc7b6], and with godot = "0.3.2" .

Sys info from Godot is:
Godot v4.4.1.stable - Linux Mint 22.1 (Xia) on X11 - X11 display driver, Multi-window, 1 monitor - Vulkan (Forward+) - dedicated NVIDIA GeForce RTX 2060 (nvidia; 550.144.03) - AMD Ryzen 9 5900XT 16-Core Processor (32 threads)

Could you invoke Godot from the command line, and print the entire command-line output (stdout + stderr) from start? Would be interesting to see if other errors are printed.

Sure thing, here's that output. Procedure here was:

• uncomment the use tracing_tracy::TracyLayer; statement
• cargo build
• launch the godot editor from the terminal
  • One thing to note: ERROR: Error loading GDExtension configuration file: 'res://gamecode.gdextension'. comes up as soon as the editor's project selector opens, but before I select any project. gamecode.gdextension Is the name of the extension for my main project, and it works fine in the context of that project. Not sure why that's popping up here, but I think it's unrelated?
• select the test project that's using tracing_tracy
• at that point, I see the same error as @brezhnevtusks, from linux_reload_workaround.rs:95:10

~/Desktop$ ./Godot_v4.4.1-stable_linux.x86_64 
ERROR: Error loading GDExtension configuration file: 'res://gamecode.gdextension'.
   at: parse_gdextension_file (core/extension/gdextension_library_loader.cpp:275)
ERROR: GDExtension dynamic library not found: 'res://gamecode.gdextension'.
   at: open_library (core/extension/gdextension.cpp:701)
ERROR: Error loading extension: 'res://gamecode.gdextension'.
   at: load_extensions (core/extension/gdextension_manager.cpp:291)
Godot Engine v4.4.1.stable.official.49a5bc7b6 - https://godotengine.org
OpenGL API 3.3.0 NVIDIA 550.144.03 - Compatibility - Using Device: NVIDIA - NVIDIA GeForce RTX 2060

Editing project: /data/code_projects/godot/issue-tracy_with_godot_rust/godot

thread '<unnamed>' panicked at /home/bc/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/godot-ffi-0.3.2/src/linux_reload_workaround.rs:95:10:
hot reloading should only be set once: true
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
ERROR: GDExtension initialization function 'gdext_rust_init' returned an error.
   at: initialize (core/extension/gdextension_library_loader.cpp:233)
ERROR: Error loading extension: 'res://test.gdextension'.
   at: load_extensions (core/extension/gdextension_manager.cpp:291)
Godot Engine v4.4.1.stable.official.49a5bc7b6 - https://godotengine.org
Vulkan 1.3.277 - Forward+ - Using Device #0: NVIDIA - NVIDIA GeForce RTX 2060

bc@bc-mint-22-2024:~/Desktop$ 
thread '<unnamed>' panicked at /home/bc/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/godot-ffi-0.3.2/src/linux_reload_workaround.rs:95:10:
hot reloading should only be set once: true
ERROR: GDExtension initialization function 'gdext_rust_init' returned an error.
   at: initialize (core/extension/gdextension_library_loader.cpp:233)

thread '<unnamed>' panicked at /home/bc/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/godot-ffi-0.3.2/src/linux_reload_workaround.rs:95:10:
hot reloading should only be set once: true
ERROR: GDExtension initialization function 'gdext_rust_init' returned an error.
   at: initialize (core/extension/gdextension_library_loader.cpp:233)
ERROR: Cannot get class 'Tester'.
   at: _instantiate_internal (core/object/class_db.cpp:549)

@brezhnevtusks, re:

Are you sure that use tracing_tracy::TracyLayer; alone breaks it for you?

I just double checked to make sure I wasn't doing something stupid, and I can confirm that on my system I get the error with only that use statement, and the on_level_init code commented out.

[Bromeon]

It might be closely related to #1209 (comment), which also points to this stacktrace:

linux_reload_workaround.rs:95:10
hot reloading should only be set once: true

It's interesting though that you seem to encounter this without hot reload, just by starting the project regularly.

[bcolloran]

Edit bromeon: Rust codetags

I've updated my test repo, as of this commit I'm able to get compile the library and capture traces.

I'm no longer seeing errors when I load the project from scratch, but it's still not compatible with hot reloading.

ChatGPT told me:
"""
tracing-tracy relies on static C constructors in tracy-client-sys; those run as soon as the shared object is mapped into the process, before Godot calls gdext_rust_init. When Godot hot‑reloads the .so, the ctor runs again and double‑initialises global state → the start‑up code in Tracy panics, bubbling back as GDExtension initialization function 'gdext_rust_init' returned an error
"""
This is beyond my depth, but it got me to some partially working code, so I think maybe there is a grain of truth in there.

Based on that, I thought that perhaps wrapping the Tracy init stuff in a !Engine::singleton().is_editor_hint() check would prevent the double init during hot reload, but that didn't work:

fn on_level_init(level: InitLevel) {
    if level == InitLevel::Scene && !Engine::singleton().is_editor_hint() {
        godot_print!("MyExtension::on_level_init, with tracing enabled");
        // Make sure we only run the init block once per library load.
        static START: Once = Once::new();
        START.call_once(|| {
            // 1. Start Tracy manually (manual‑lifetime feature enabled).
            let client = Client::start();
            let _ = TRACY_CLIENT.set(client);

            // 2. Install the Tracy layer for all `tracing` spans.
            let _ = tracing_subscriber::registry()
                .with(TracyLayer::default())
                .try_init(); // avoids panics if already set
        });
    }
}

So not all the way there, but some progress!

[bcolloran]

I now have a working minimal recipe for using tracy in this demo project as of this commit: bcolloran/godot_rust_with_tracing_tracy@bbe3993

The pattern is just to gate the tracy init/deinit code within a profiling cfg flag, which seems fine to me -- the workflow would just be to use regular debug builds for working in the editor with hot reloading, and then spin a profiling build when you need to make measurements (which is the best practice anyway).

Still need to make sure this pattern works in my real project, but I see no reason it should not.

[bcolloran]

This pattern is confirmed working in my main project, so I'm happy to call this workaround good enough and to close this issue (of course feel free to reopen if you want to track this as part of #1221 )

Note for posterity: as of this discord message it's still not clear if the solution works on windows, though it seems likely that this has to do with details of reloading .so files on linux, as the file linux_reload_workaround.rs:95:10 is mentioned in the stack traces from above.