search

godotengine / godot

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

`EditorLog::add_message` error about message queue out of memory triggers infinite error spam and crash #84713

Closed akien-mga closed 11 months ago

akien-mga commented 1 year ago

Godot version

4.2.beta5 and 2b987d1c54b77a394d302a89118274538726bcf1

System information

Mageia 9 - Vulkan (Forward+) - dedicated AMD Radeon RX Vega M GL Graphics (RADV VEGAM) () - Intel(R) Core(TM) i7-8705G CPU @ 3.10GHz (8 Threads)

Issue description

When the editor spams an error message for one reason or another (as seen with the MRP from #84712 in 4.2.beta5 / 2b987d1c54b77a394d302a89118274538726bcf1), eventually the MessageQueue seems to run out of memory and starts spamming this error instead:

ERROR: Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.
   at: push_callablep (./core/object/message_queue.cpp:96)
ERROR: Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.
   at: push_callablep (./core/object/message_queue.cpp:96)

This gets spammed repeatedly until eventually it segfaults:

Thread 40 "godot-git" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fff7affd6c0 (LWP 250114)]
0x00007ffff7d38550 in __vfprintf_internal () from /lib64/libc.so.6

(gdb) bt
#0  0x00007ffff7d38550 in __vfprintf_internal () from /lib64/libc.so.6
#1  0x00007ffff7d3aaca in buffered_vfprintf () from /lib64/libc.so.6
#2  0x00000000097890da in StdLogger::logv (this=0xa5e8a00, p_format=0x422ee45 "%sERROR:%s %s\n", p_list=0x7fff7a8004c8, p_err=true) at ./core/io/logger.cpp:222
#3  0x0000000009788706 in Logger::logf_error (this=0xa5e8a00, p_format=0x422ee45 "%sERROR:%s %s\n") at ./core/io/logger.cpp:114
#4  0x000000000698fb16 in UnixTerminalLogger::log_error (this=0xa5e8a00, p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_code=0x7fff43303400 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_rationale=0x536c968 "", p_editor_notify=false, p_type=Logger::ERR_ERROR) at ./drivers/unix/os_unix.cpp:834
#5  0x000000000978928b in CompositeLogger::log_error (this=0xa5e8a40, p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_code=0x7fff43303400 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_rationale=0x536c968 "", p_editor_notify=false, p_type=Logger::ERR_ERROR) at ./core/io/logger.cpp:256
#6  0x00000000096a347c in OS::print_error (this=0x7fffffffcfa0, p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_code=0x7fff43303400 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_rationale=0x536c968 "", p_editor_notify=false, p_type=Logger::ERR_ERROR) at ./core/os/os.cpp:86
#7  0x0000000009c796c8 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_error=0x7fff43303400 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_message=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at core/error/error_macros.cpp:87
#8  0x0000000009c79652 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, p_error=..., p_editor_notify=false, p_type=ERR_HANDLER_ERROR)
    at core/error/error_macros.cpp:81
#9  0x0000000009bd704b in CallQueue::push_callablep (this=0xa90f8f0, p_callable=..., p_args=0x0, p_argcount=0, p_show_error=false) at ./core/object/message_queue.cpp:96
#10 0x00000000098ccd66 in Callable::call_deferredp (this=0x7fff7a8009d0, p_arguments=0x0, p_argcount=0) at ./core/variant/callable.cpp:40
#11 0x000000000651abe0 in Callable::call_deferred<>() const (this=0x7fff7a8009d0) at ./core/variant/callable.h:85
#12 0x0000000006eaf832 in EditorLog::_error_handler (p_self=0x141cd7e0, p_func=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_error=0x7fff43303560 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_errorexp=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at ./editor/editor_log.cpp:62
#13 0x0000000009c79764 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_error=0x7fff43303560 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_message=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at core/error/error_macros.cpp:97
#14 0x0000000009c79652 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, p_error=..., p_editor_notify=false, p_type=ERR_HANDLER_ERROR)
    at core/error/error_macros.cpp:81
--Type <RET> for more, q to quit, c to continue without paging--
#15 0x0000000009bd704b in CallQueue::push_callablep (this=0xa90f8f0, p_callable=..., p_args=0x0, p_argcount=0, p_show_error=false) at ./core/object/message_queue.cpp:96
#16 0x00000000098ccd66 in Callable::call_deferredp (this=0x7fff7a800d20, p_arguments=0x0, p_argcount=0) at ./core/variant/callable.cpp:40
#17 0x000000000651abe0 in Callable::call_deferred<>() const (this=0x7fff7a800d20) at ./core/variant/callable.h:85
#18 0x0000000006eaf832 in EditorLog::_error_handler (p_self=0x141cd7e0, p_func=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_error=0x7fff433015e0 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_errorexp=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at ./editor/editor_log.cpp:62
#19 0x0000000009c79764 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_error=0x7fff433015e0 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_message=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at core/error/error_macros.cpp:97
#20 0x0000000009c79652 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, p_error=..., p_editor_notify=false, p_type=ERR_HANDLER_ERROR)
    at core/error/error_macros.cpp:81
#21 0x0000000009bd704b in CallQueue::push_callablep (this=0xa90f8f0, p_callable=..., p_args=0x0, p_argcount=0, p_show_error=false) at ./core/object/message_queue.cpp:96
#22 0x00000000098ccd66 in Callable::call_deferredp (this=0x7fff7a801070, p_arguments=0x0, p_argcount=0) at ./core/variant/callable.cpp:40
#23 0x000000000651abe0 in Callable::call_deferred<>() const (this=0x7fff7a801070) at ./core/variant/callable.h:85
#24 0x0000000006eaf832 in EditorLog::_error_handler (p_self=0x141cd7e0, p_func=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_error=0x7fff43301740 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_errorexp=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at ./editor/editor_log.cpp:62
#25 0x0000000009c79764 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_error=0x7fff43301740 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_message=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at core/error/error_macros.cpp:97
#26 0x0000000009c79652 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, p_error=..., p_editor_notify=false, p_type=ERR_HANDLER_ERROR)
    at core/error/error_macros.cpp:81
#27 0x0000000009bd704b in CallQueue::push_callablep (this=0xa90f8f0, p_callable=..., p_args=0x0, p_argcount=0, p_show_error=false) at ./core/object/message_queue.cpp:96
#28 0x00000000098ccd66 in Callable::call_deferredp (this=0x7fff7a8013c0, p_arguments=0x0, p_argcount=0) at ./core/variant/callable.cpp:40
#29 0x000000000651abe0 in Callable::call_deferred<>() const (this=0x7fff7a8013c0) at ./core/variant/callable.h:85
#30 0x0000000006eaf832 in EditorLog::_error_handler (p_self=0x141cd7e0, p_func=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
    p_error=0x7fff432ff7c0 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", 
    p_errorexp=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at ./editor/editor_log.cpp:62
#31 0x0000000009c79764 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, 
--Type <RET> for more, q to quit, c to continue without paging--

[ a ton more looping frames ]

#59226 0x0000000006eaf832 in EditorLog::_error_handler (p_self=0x141cd7e0, p_func=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, p_error=0x7fff40eb73a0 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", p_errorexp=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at ./editor/editor_log.cpp:62
#59227 0x0000000009c79764 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, p_error=0x7fff40eb73a0 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", p_message=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at core/error/error_macros.cpp:97
#59228 0x0000000009c79652 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, p_error=..., p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at core/error/error_macros.cpp:81
#59229 0x0000000009bd704b in CallQueue::push_callablep (this=0xa90f8f0, p_callable=..., p_args=0x0, p_argcount=0, p_show_error=false) at ./core/object/message_queue.cpp:96
#59230 0x00000000098ccd66 in Callable::call_deferredp (this=0x7fff7affc030, p_arguments=0x0, p_argcount=0) at ./core/variant/callable.cpp:40
#59231 0x000000000651abe0 in Callable::call_deferred<>() const (this=0x7fff7affc030) at ./core/variant/callable.h:85
#59232 0x0000000006eaf832 in EditorLog::_error_handler (p_self=0x141cd7e0, p_func=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, p_error=0x7fff40eb61f0 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", p_errorexp=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at ./editor/editor_log.cpp:62
#59233 0x0000000009c79764 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, p_error=0x7fff40eb61f0 "Failed method: EditorLog::add_message. Message queue out of memory. Message queue out of memory. Try increasing 'memory/limits/message_queue/max_size_mb' in project settings.", p_message=0x536c968 "", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at core/error/error_macros.cpp:97
#59234 0x0000000009c79652 in _err_print_error (p_function=0x533edb8 "push_callablep", p_file=0x533ed98 "./core/object/message_queue.cpp", p_line=96, p_error=..., p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at core/error/error_macros.cpp:81
#59235 0x0000000009bd704b in CallQueue::push_callablep (this=0xa90f8f0, p_callable=..., p_args=0x0, p_argcount=0, p_show_error=false) at ./core/object/message_queue.cpp:96
#59236 0x00000000098ccd66 in Callable::call_deferredp (this=0x7fff7affc380, p_arguments=0x0, p_argcount=0) at ./core/variant/callable.cpp:40
#59237 0x000000000651abe0 in Callable::call_deferred<>() const (this=0x7fff7affc380) at ./core/variant/callable.h:85
#59238 0x0000000006eaf832 in EditorLog::_error_handler (p_self=0x141cd7e0, p_func=0x3af8364 "_mix_frames_vorbis", p_file=0x3af82f8 "modules/vorbis/audio_stream_ogg_vorbis.cpp", p_line=159, p_error=0x3af83b8 "Condition \"err != 0\" is true. Returning: 0", p_errorexp=0x7fff70025860 "Error during vorbis synthesis -135", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at ./editor/editor_log.cpp:62
#59239 0x0000000009c79764 in _err_print_error (p_function=0x3af8364 "_mix_frames_vorbis", p_file=0x3af82f8 "modules/vorbis/audio_stream_ogg_vorbis.cpp", p_line=159, p_error=0x3af83b8 "Condition \"err != 0\" is true. Returning: 0", p_message=0x7fff70025860 "Error during vorbis synthesis -135", p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at core/error/error_macros.cpp:97
#59240 0x0000000009c79871 in _err_print_error (p_function=0x3af8364 "_mix_frames_vorbis", p_file=0x3af82f8 "modules/vorbis/audio_stream_ogg_vorbis.cpp", p_line=159, p_error=0x3af83b8 "Condition \"err != 0\" is true. Returning: 0", p_message=..., p_editor_notify=false, p_type=ERR_HANDLER_ERROR) at core/error/error_macros.cpp:110
#59241 0x0000000005af84a5 in AudioStreamPlaybackOggVorbis::_mix_frames_vorbis (this=0x236b9900, p_buffer=0x236b9d58, p_frames=64) at modules/vorbis/audio_stream_ogg_vorbis.cpp:159
#59242 0x0000000005af7d99 in AudioStreamPlaybackOggVorbis::_mix_internal (this=0x236b9900, p_buffer=0x236b9b58, p_frames=128) at modules/vorbis/audio_stream_ogg_vorbis.cpp:63
#59243 0x0000000009239971 in AudioStreamPlaybackResampled::mix (this=0x236b9900, p_buffer=0x7fff70000cd0, p_rate_scale=1, p_frames=10209) at ./servers/audio/audio_stream.cpp:163
#59244 0x0000000006c9374b in AudioStreamPreviewGenerator::_preview_thread (p_preview=0x1c1ea9c8) at ./editor/audio_stream_preview.cpp:132
#59245 0x00000000096a73ae in Thread::callback (p_caller_id=28, p_settings=..., p_callback=0x6c93558 <AudioStreamPreviewGenerator::_preview_thread(void*)>, p_userdata=0x1c1ea9c8) at ./core/os/thread.cpp:61
#59246 0x00000000096ba0f9 in std::__invoke_impl<void, void (*)(unsigned long, Thread::Settings const&, void (*)(void*), void*), unsigned long, Thread::Settings, void (*)(void*), void*> (__f=@0x1f062ac8: 0x96a7320 <Thread::callback(unsigned long, Thread::Settings const&, void (*)(void*), void*)>) at /usr/include/c++/12/bits/invoke.h:61
#59247 0x00000000096b9fc2 in std::__invoke<void (*)(unsigned long, Thread::Settings const&, void (*)(void*), void*), unsigned long, Thread::Settings, void (*)(void*), void*> (__fn=@0x1f062ac8: 0x96a7320 <Thread::callback(unsigned long, Thread::Settings const&, void (*)(void*), void*)>) at /usr/include/c++/12/bits/invoke.h:96
#59248 0x00000000096b9e7d in std::thread::_Invoker<std::tuple<void (*)(unsigned long, Thread::Settings const&, void (*)(void*), void*), unsigned long, Thread::Settings, void (*)(void*), void*> >::_M_invoke<0ul, 1ul, 2ul, 3ul, 4ul> (this=0x1f062aa8) at /usr/include/c++/12/bits/std_thread.h:279
#59249 0x00000000096b8750 in std::thread::_Invoker<std::tuple<void (*)(unsigned long, Thread::Settings const&, void (*)(void*), void*), unsigned long, Thread::Settings, void (*)(void*), void*> >::operator() (this=0x1f062aa8) at /usr/include/c++/12/bits/std_thread.h:286
#59250 0x00000000096b7602 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)(unsigned long, Thread::Settings const&, void (*)(void*), void*), unsigned long, Thread::Settings, void (*)(void*), void*> > >::_M_run (this=0x1f062aa0) at /usr/include/c++/12/bits/std_thread.h:231
#59251 0x000000000a087b83 in std::execute_native_thread_routine (__p=0x1f062aa0) at ../../../../../libstdc++-v3/src/c++11/thread.cc:82
#59252 0x00007ffff7d668da in start_thread () from /lib64/libc.so.6
#59253 0x00007ffff7de248c in clone3 () from /lib64/libc.so.6

Steps to reproduce

Minimal reproduction project

ogg_error_spam.zip

lawnjelly commented 1 year ago

From rocket chat:

lawnjelly 3:57 PM For the MessageQueue filling up, like dark_sylinc says, there are 2 obvious options:

  • Fix the bug (done).
  • Don't repeat error messages.

I've tried the second, but that might mean that duplicate error messages on different frames get ignored, unless we de-duplicate on e.g. a per-frame basis. So while it would solve some problems it might create others, where we are missing multiple errors. But I'll maybe create a draft PR to discuss it.

On making the MessageQueue tolerant to filling up, I don't think that's easy, because once something is filling it, it can't process messages and the editor locks up. If you take away the limit, you just run out of memory and crash the OS.

But I'll have a think maybe there's some good alternative. I'm half asleep today so unlikely to come up with ideal solutions. 😁

Akien We have ERR_PRINT_ONCE which can be used for stuff that risks being spammy, it could be generalized... but indeed the problem is that sometimes you do want one message per occurrence of a bug.

lawnjelly Maybe we could build some AI so it de-duplicated on the same frame prior to sending. I have a feeling the toaster does some de-duplication but by then it's too late as it's gone through the MessageQueue. It would no doubt need a bit of balancing.

AThousandShips commented 11 months ago

Solved in https://github.com/godotengine/godot/pull/85397