drwhut
commented
1 year ago Sounds like something (probably an error) is being spammed in the logs - are you able to somehow post a snippet of the logs, or get it to occur again?
Open Saiv46 opened 1 year ago
drwhut
commented
1 year ago Sounds like something (probably an error) is being spammed in the logs - are you able to somehow post a snippet of the logs, or get it to occur again?
Saiv46
commented
1 year ago Sounds like something (probably an error) is being spammed in the logs - are you able to somehow post a snippet of the logs, or get it to occur again?
After some time I started game, then launched and focused on OBS Studio.
Start time: 17:43:39 End time: 18:02:30 (+18:51) File size: 43GB
Message that was spammed:
ERROR: Disconnecting nonexistent signal 'changed', slot: 6329:_mesh_changed.
at: _disconnect (core/object.cpp:1538) - Condition "!s->slot_map.has(target)" is true.Hmm... my suspicion is that this is a threading issue. godotengine/godot#60098 seems to be the likely culprit - godotengine/godot#58715 and godotengine/godot#34752 may also be related.
As for the logs being spammed, this has already been reported in godotengine/godot#45181, but we may need to implement a fix ourselves for the time being.
drwhut
commented
1 year ago I've been trying to reproduce the issue on the master branch (after v0.1.0-beta3), but to no avail. I've been leaving it on the main menu for upwards of 30 minutes, increasing and decreasing the number of pieces that fall in the background, trying debug vs release builds, and focusing on OBS - it just doesn't want to crash. I think I need help from others to figure out if there is a way to get this issue to consistently happen.
However, I've also had a deep-dive into the Godot source code to see where the problem may potentially lie. The error originates from trying to disconnect the Mesh.changed signal from what I'm guessing is a MeshInstance, which causes an infinite loop, which then causes the spam in the logs. Here's the beginning of Object._disconnect(), which contains the line that is erroring:
void Object::_disconnect(const StringName &p_signal, Object *p_to_object, const StringName &p_to_method, bool p_force) {
ERR_FAIL_NULL(p_to_object);
Signal *s = signal_map.getptr(p_signal);
if (!s) {
bool signal_is_valid = ClassDB::has_signal(get_class_name(), p_signal) ||
(!script.is_null() && Ref<Script>(script)->has_script_signal(p_signal));
ERR_FAIL_COND_MSG(signal_is_valid,
vformat("Attempt to disconnect a nonexistent connection to signal '%s' in %s, with target '%s' in %s.",
p_signal, to_string(), p_to_method, p_to_object->to_string()));
}
ERR_FAIL_COND_MSG(!s, vformat("Disconnecting nonexistent signal '%s' in %s.", p_signal, to_string()));
Signal::Target target(p_to_object->get_instance_id(), p_to_method);
// The line that is erroring:
ERR_FAIL_COND_MSG(!s->slot_map.has(target), "Disconnecting nonexistent signal '" + p_signal + "', slot: " + itos(target._id) + ":" + target.method + ".");From what I can see, there are two possible places that this signal is being disconnected:
When setting the mesh property in MeshInstance:
void MeshInstance::set_mesh(const Ref<Mesh> &p_mesh) {
if (mesh == p_mesh) {
return;
}
if (mesh.is_valid()) {
mesh->disconnect(CoreStringNames::get_singleton()->changed, this, SceneStringNames::get_singleton()->_mesh_changed);
}During the Object::~Object() destructor:
Object::~Object() {
// ...
if (_emitting) {
//@todo this may need to actually reach the debugger prioritarily somehow because it may crash before
ERR_PRINT("Object " + to_string() + " was freed or unreferenced while a signal is being emitted from it. Try connecting to the signal using 'CONNECT_DEFERRED' flag, or use queue_free() to free the object (if this object is a Node) to avoid this error and potential crashes.");
}
while ((S = signal_map.next(nullptr))) {
Signal *s = &signal_map[*S];
//brute force disconnect for performance
int slot_count = s->slot_map.size();
const VMap<Signal::Target, Signal::Slot>::Pair *slot_list = s->slot_map.get_array();
for (int i = 0; i < slot_count; i++) {
slot_list[i].value.conn.target->connections.erase(slot_list[i].value.cE);
}
signal_map.erase(*S);
}
//signals from nodes that connect to this node
while (connections.size()) {
Connection c = connections.front()->get();
c.source->_disconnect(c.signal, c.target, c.method, true);
}I think it's the second instance that is causing the error, since it's a destructor, it may be the engine constantly trying to destroy the object (and it can't because of the error in the disconnect method), plus in the game I've put in a bit of code that I think prevents the first option from ever becoming a problem in ResourceManager:
func free_object(object: Object) -> void:
# Lock the resource mutex here, just in case a resource used by the object
# is being created as it is being freed here.
_res_mutex.lock()
if object is Node:
# This is a workaround for a crash that sometimes happens when a
# MeshInstance tries to disconnect its mesh's _mesh_changed signal.
var node_stack = [object]
while not node_stack.empty():
var node: Node = node_stack.pop_back()
for child in node.get_children():
node_stack.push_back(child)
if node is MeshInstance:
node.mesh = null
object.queue_free()
else:
object.free()
_res_mutex.unlock()Whenever something like a piece is freed from memory, the game first goes through all of the child nodes and finds any MeshInstances - if it does, it then sets the mesh being displayed to null before queueing the node to be freed, all while the resource mutex is locked (so resources are confirmed to not be loading at the same time). Since both the Mesh and MeshInstance are still active, this should always ensure that the connections are still alive when set_mesh is called.
So my current working theory is that some threading issue or race condition is causing the signal map to become invalid before Object::_disconnect, which is called by Object::~Object, which then goes into an infinite loop since it's the destructor that is receiving the error.
If we are struggling to replicate the issue, one thing that we could try is to detect if this error happens in the destructor, and make sure the destructor is completed so the error is not spammed. Either that, or we wait for the fix to this issue upstream (which may take a while given the issue mentioned above has a milestone for 4.x). Ideally, the issue would be easily recreatable so we could find out the root cause of the issue, but since this issue occurs so rarely it seems, it may just be worth preventing the spamming of the logs themselves for the time being, since in my opinion the file becoming so large it fills the filesystem is much more of a problem than the game freezing.
Describe the bug Game keeps all logs, and sometimes produces huge one (in case of error).
To Reproduce Steps to reproduce the behavior:
Expected behavior Game should rotate logs or at least crash if something went wrong.
Environment
Version v0.1.0 Beta 1
Additional context Game can freeze when capturing its window using OBS Studio (latest).