search

godotengine / godot

Godot Engine – Multi-platform 2D and 3D game engine
https://godotengine.org
MIT License
91.59k stars 21.27k forks source link

`ResourceLoader.load_threaded_get_status(SCENE, PROGRESS)` always returns 0 (THREAD_LOAD_INVALID_RESOURCE) #95470

Closed maktoobgar closed 3 months ago

maktoobgar commented 3 months ago

Tested versions

System information

Ubuntu 22.04.4 LTS - Godot v4.3.rc3

Issue description

I have an addon called Scene Manager and I got an issue about this which made me come here and report the problem after identifying the problem.

In one sentence: ResourceLoader.load_threaded_get_status doesn't seem to work right at all.

Simply define a scene and request to load it with ResourceLoader.load_threaded_request and then ask for how it is doing with ResourceLoader.load_threaded_get_status and it always returns 0 which means THREAD_LOAD_INVALID_RESOURCE but actually when used ResourceLoader.load_threaded_get after you see the THREAD_LOAD_INVALID_RESOURCE, it actually returns the scene just fine but ResourceLoader.load_threaded_get_status said that the scene is not valid which means that it isn't working properly as expected.

Note: This was working completely fine in previous versions of godot4. Note: Loading normally is fine but loading with ResourceLoading doesn't seem to work at all.

Steps to reproduce

Simply pass a scene address into this function and watch the results:

func load_scene_interactive(_load_scene: String, use_sub_threads = false) -> void:
    ResourceLoader.load_threaded_request(_load_scene, "", use_sub_threads, ResourceLoader.CACHE_MODE_IGNORE)
    var _percent = []
    print("status: ", ResourceLoader.load_threaded_get_status(_load_scene, _percent))
    print("percent: ", _percent)
    print("actual scene: ", ResourceLoader.load_threaded_get(_load_scene))
    print("status: ",ResourceLoader.load_threaded_get_status(_load_scene, _percent))
    print("percent: ", _percent)

You will see this output:

status: 0
percent: [0]
actual scene: <PackedScene#-9223371992663587553>
status: 0
percent: [0]

Which means ResourceLoader.load_threaded_get_status is not working properly at all but actually ResourceLoader.load_threaded_get works just fine although is was said by ResourceLoader.load_threaded_get_status that the scene is not valid and it will not load properly.

What was expected:

status: 1
percent: [0]
actual scene: <PackedScene#-9223371992663587553>
status: 3
percent: [1]

Minimal reproduction project (MRP)

load_threaded_get_status.zip

akien-mga commented 3 months ago

Testing on Fedora 40.

I can reproduce the 0 status in 4.3.rc3, but not the 1/3 statuses of the "what was expected" in 4.2.2.stable. Could you clarify how you tested previous versions?

In 4.2.2.stable, I get:

status: 1
percent: [0]
actual scene: <PackedScene#-9223372003333897050>
status: 0
percent: [0]

I get the same result with 4.3.beta1.

Then 4.3.beta2 gives:

status: 1
percent: [0]
ERROR: Invalid Task ID
   at: wait_for_task_completion (core/object/worker_thread_pool.cpp:363)
actual scene: <PackedScene#-9223372002310486718>
status: 0
percent: [0]

4.3.beta3 exhibits the behavior described here and still reproducible as of 4.3.rc3:

status: 0
percent: [0]
actual scene: <PackedScene#-9223372003904322285>
status: 0
percent: [0]

And finally the latest master branch at a7a124a57d643103c882a781dfe1f3772363ecc7... segfaults :'(

ERROR: FATAL: Method/function failed.
   at: load_threaded_get_status (./core/io/resource_loader.cpp:586)

Thread 1 "godot-git" received signal SIGILL, Illegal instruction.
0x000000000a90d819 in ResourceLoader::load_threaded_get_status (p_path=..., r_progress=0x7fffffff0b3c) at ./core/io/resource_loader.cpp:586
586                             CRASH_NOW();

(gdb) bt
#0  0x000000000a90d819 in ResourceLoader::load_threaded_get_status (p_path=..., r_progress=0x7fffffff0b3c) at ./core/io/resource_loader.cpp:586
#1  0x000000000a7020ce in core_bind::ResourceLoader::load_threaded_get_status (this=0xb7c2c50, p_path=..., r_progress=...) at ./core/core_bind.cpp:58
#2  0x000000000a7d5cbf in call_with_variant_args_ret_helper<__UnexistingClass, core_bind::ResourceLoader::ThreadLoadStatus, String const&, Array, 0ul, 1ul> (p_instance=0xb7c2c50, 
    p_method=(core_bind::ResourceLoader::ThreadLoadStatus (__UnexistingClass::*)(__UnexistingClass * const, const String &, Array)) 0xa70209e <core_bind::ResourceLoader::load_threaded_get_status(String const&, Array)>, p_args=0x7fffffff0c20, r_ret=..., r_error=...) at ./core/variant/binder_common.h:756
#3  0x000000000a7c717f in call_with_variant_args_ret_dv<__UnexistingClass, core_bind::ResourceLoader::ThreadLoadStatus, String const&, Array> (p_instance=0xb7c2c50, 
    p_method=(core_bind::ResourceLoader::ThreadLoadStatus (__UnexistingClass::*)(__UnexistingClass * const, const String &, Array)) 0xa70209e <core_bind::ResourceLoader::load_threaded_get_status(String const&, Array)>, p_args=0x7fffffff0da8, p_argcount=2, r_ret=..., r_error=..., default_values=...) at ./core/variant/binder_common.h:535
#4  0x000000000a7ba262 in MethodBindTR<core_bind::ResourceLoader::ThreadLoadStatus, String const&, Array>::call (this=0xb7c34b0, p_object=0xb7c2c50, p_args=0x7fffffff0da8, p_arg_count=2, r_error=...)
    at ./core/object/method_bind.h:524
#5  0x00000000068eefed in GDScriptFunction::call (this=0xdad5260, p_instance=0xdad83f0, p_args=0x7fffffff50c0, p_argcount=1, r_err=..., p_state=0x0) at ./modules/gdscript/gdscript_vm.cpp:1874
#6  0x000000000683f134 in GDScriptInstance::callp (this=0xdad83f0, p_method=..., p_args=0x7fffffff50c0, p_argcount=1, r_error=...) at ./modules/gdscript/gdscript.cpp:2032
#7  0x000000000ad8c91f in Object::callp (this=0xdad0320, p_method=..., p_args=0x7fffffff50c0, p_argcount=1, r_error=...) at ./core/object/object.cpp:786
#8  0x000000000aa676b8 in Variant::callp (this=0x7fffffff5060, p_method=..., p_args=0x7fffffff50c0, p_argcount=1, r_ret=..., r_error=...) at ./core/variant/variant_call.cpp:1211
#9  0x00000000068ee28d in GDScriptFunction::call (this=0xdad90c0, p_instance=0xdad83f0, p_args=0x0, p_argcount=0, r_err=..., p_state=0x0) at ./modules/gdscript/gdscript_vm.cpp:1780
#10 0x000000000683f134 in GDScriptInstance::callp (this=0xdad83f0, p_method=..., p_args=0x0, p_argcount=0, r_error=...) at ./modules/gdscript/gdscript.cpp:2032
#11 0x000000000ad8c91f in Object::callp (this=0xdad0320, p_method=..., p_args=0x0, p_argcount=0, r_error=...) at ./core/object/object.cpp:786
#12 0x000000000aa52f41 in Callable::callp (this=0x7fffffff93b0, p_arguments=0x0, p_argcount=0, r_return_value=..., r_call_error=...) at ./core/variant/callable.cpp:69
#13 0x000000000ad8eac1 in Object::emit_signalp (this=0xdad6f80, p_name=..., p_args=0x0, p_argcount=0) at ./core/object/object.cpp:1187
#14 0x00000000088923a6 in Node::emit_signalp (this=0xdad6f80, p_name=..., p_args=0x0, p_argcount=0) at ./scene/main/node.cpp:3895
#15 0x000000000643f4cb in Object::emit_signal<>(StringName const&) (this=0xdad6f80, p_name=...) at ./core/object/object.h:936
#16 0x00000000089eb026 in BaseButton::on_action_event (this=0xdad6f80, p_event=...) at ./scene/gui/base_button.cpp:185
#17 0x00000000089ea8ff in BaseButton::gui_input (this=0xdad6f80, p_event=...) at ./scene/gui/base_button.cpp:68
#18 0x0000000008a441e5 in Control::_call_gui_input (this=0xdad6f80, p_event=...) at ./scene/gui/control.cpp:1830
#19 0x00000000088aea0b in Viewport::_gui_call_input (this=0xda43880, p_control=0xdad6f80, p_input=...) at ./scene/main/viewport.cpp:1567
#20 0x00000000088afc84 in Viewport::_gui_input_event (this=0xda43880, p_event=...) at ./scene/main/viewport.cpp:1836
#21 0x00000000088b7688 in Viewport::push_input (this=0xda43880, p_event=..., p_local_coords=false) at ./scene/main/viewport.cpp:3258
#22 0x00000000088dd2d5 in Window::_window_input (this=0xda43880, p_ev=...) at ./scene/main/window.cpp:1680
#23 0x00000000089e3f54 in call_with_variant_args_helper<Window, Ref<InputEvent> const&, 0ul> (p_instance=0xda43880, 
    p_method=(void (Window::*)(Window * const, const Ref<InputEvent> &)) 0x88dcd7a <Window::_window_input(Ref<InputEvent> const&)>, p_args=0x7fffffffc630, r_error=...) at ./core/variant/binder_common.h:304
#24 0x00000000089c657e in call_with_variant_args<Window, Ref<InputEvent> const&> (p_instance=0xda43880, 
    p_method=(void (Window::*)(Window * const, const Ref<InputEvent> &)) 0x88dcd7a <Window::_window_input(Ref<InputEvent> const&)>, p_args=0x7fffffffc630, p_argcount=1, r_error=...)
    at ./core/variant/binder_common.h:418
#25 0x00000000089a4f78 in CallableCustomMethodPointer<Window, Ref<InputEvent> const&>::call (this=0xd9a07e0, p_arguments=0x7fffffffc630, p_argcount=1, r_return_value=..., r_call_error=...)
    at ./core/object/callable_method_pointer.h:103
#26 0x000000000aa52c8d in Callable::callp (this=0x7fffffffc6d0, p_arguments=0x7fffffffc630, p_argcount=1, r_return_value=..., r_call_error=...) at ./core/variant/callable.cpp:57
#27 0x0000000005d163c9 in Callable::call<Ref<InputEvent> > (this=0x7fffffffc6d0) at ./core/variant/variant.h:875
#28 0x0000000005d01d1b in DisplayServerX11::_dispatch_input_event (this=0xbd93ae0, p_event=...) at platform/linuxbsd/x11/display_server_x11.cpp:4063
#29 0x0000000005d01aa5 in DisplayServerX11::_dispatch_input_events (p_event=...) at platform/linuxbsd/x11/display_server_x11.cpp:4039
#30 0x000000000a9ef057 in Input::_parse_input_event_impl (this=0xb5a88e0, p_event=..., p_is_emulated=false) at ./core/input/input.cpp:774
#31 0x000000000a9f03a0 in Input::flush_buffered_events (this=0xb5a88e0) at ./core/input/input.cpp:1055
#32 0x0000000005d06c86 in DisplayServerX11::process_events (this=0xbd93ae0) at platform/linuxbsd/x11/display_server_x11.cpp:5199
#33 0x0000000005cde1b6 in OS_LinuxBSD::run (this=0x7fffffffd090) at platform/linuxbsd/os_linuxbsd.cpp:958
#34 0x0000000005cd69f1 in main (argc=1, argv=0x7fffffffd6f8) at platform/linuxbsd/godot_linuxbsd.cpp:85
akien-mga commented 3 months ago

Nevermind the crash, it happens only in a DEV_ENABLED build due to this code:

                String local_path = _validate_local_path(p_path);
                if (!thread_load_tasks.has(local_path)) {
#ifdef DEV_ENABLED
                        CRASH_NOW();
#endif
                        // On non-dev, be defensive and at least avoid crashing (at this point at least).
                        return THREAD_LOAD_INVALID_RESOURCE;
                }

So it was trying to catch this kind of error case but it's only evident when running a dev build.

(For the record @RandomShaper I'm still of the opinion that well placed ERR_FAIL_COND_MSG(..., "Bug in ResourceLoader logic, please report.") would be more useful than dev-only asserts that are only useful if contributors end up triggering the edge case.)

In a non dev build, I get the same issue as in the OP in latest master:

status: 0
percent: [0]
actual scene: <PackedScene#-9223372005531712208>
status: 0
percent: [0]
akien-mga commented 3 months ago

I tested #94169 but it doesn't seem to address this issue.

maktoobgar commented 3 months ago

I can reproduce the 0 status in 4.3.rc3, but not the 1/3 statuses of the "what was expected" in 4.2.2.stable. Could you clarify how you tested previous versions?

You are right, sorry I just made a mistake, I got those logs from other situations which... doesn't matter actually.

The state you are seeing is right and in a normal behavior, the status: 3 and percent: [1] is accessible right before you retrieve your scene from ResourceLoader.load_threaded_get, after that you get your scene, you should see status: 0 and percent: [0]. I provide another test here and write how it should act:

load_threaded_get_status_2.zip

Expected logs:

*** load started ***

stating values:
status: 1
percent: [0]
=========================
*** In _process ***
status: 3
percent: [1]
actual scene: <PackedScene#-9223372005481380632>
*** load finished ***

=========================
status: 0
percent: [0]

Received Logs:

*** load started ***

stating values:
status: 0
percent: [0]
=========================
*** In _process ***
status: 0
percent: [0]
*** In _process ***
status: 0
percent: [0]
*** In _process ***
status: 0
percent: [0]
.
.
.

It goes into a loop because it never actually sees the status = 3 and so it never loads the scene.

akien-mga commented 3 months ago

Thanks, I can reproduce these results with the new MRP. I'll bisect so we can pinpoint when the regression happened exactly.

akien-mga commented 3 months ago

Bisected to 884d1da938bc679d537b322b4d02b53a6e334e59 / #93540.

BlueCube3310 commented 3 months ago

This seems to be the correct behavior since the cache mode is set to ignore, which means it doesn't get registered by the task map. Before the aforementioned commit the task would be incorrectly registered on the task map, so it looks like a compatibility issue.