Godot: Infinite loop in rich_text_label.cpp

[DrMoriarty]

Godot version:
Godot 3.2.2.beta1

OS/device including version:
MacOSX 10.14.6 (18G95)

Issue description:
Today all day I'm working on fixing pvrtc and twice my godot did hung up with this errors:

   At: scene/gui/rich_text_label.cpp:170.
ERROR: _process_line: Index line = 0 is out of bounds (l.offset_caches.size() = 0).
   At: scene/gui/rich_text_label.cpp:170.
ERROR: _process_line: Index line = 0 is out of bounds (l.offset_caches.size() = 0).
   At: scene/gui/rich_text_label.cpp:170.
ERROR: _process_line: Index line = 0 is out of bounds (l.offset_caches.size() = 0).
   At: scene/gui/rich_text_label.cpp:170.
ERROR: _process_line: Index line = 0 is out of bounds (l.offset_caches.size() = 0).

It repeats in infinite cycle and godot interface is frozen. I can not reproduce it when I want to. But two times it happened.

Steps to reproduce:

Minimal reproduction project:

[aaronfranke]

This code is weird. line is guaranteed to be 0 here, so the check whether line is between 0 and the size should be simplified to just a check for if the size is 0. I don't know why it would be 0, though.

[Eoin-ONeill-Yokai]

I haven't looked majorly into this, but I think that the caching system and this check might be what's returning garbage line size values as well. So I think this is possibly related to #18722. @DrMoriarty I haven't had a chance to reproduce this myself and can't find a way to reproduce it. If someone else can try getting a gdb trace on this, that'd be very useful.

For the record, as someone who has worked on this class within the last year (or two I suppose), the problem this class currently has is that the codeflow is hard to parse because of a combination of extensive macro-use and arguably too many vaguely named variables. It's kind of on my todo to go back to this class and clean it up to make it easier to work with, but I never really find the time.

line is guaranteed to be 0 here, so the check whether line is between 0 and the size should be simplified to just a check for if the size is 0.

@aaronfranke Indeed. I think there's a very high likelihood that these checks were actually intended for the macro define on line 216 and were but in the wrong place probably because the macro text is greyed out.

[HungryProton]

Not sure if it's related but this issue consistently happens since I tried adding multi-threading to my addon. I'll see if I can produce a minimal reproduction project but the code is so convoluted I'm having a hard time tracking down this issue.

[BattyBovine]

Just wanted to confirm that I'm now getting this same error, every single time I push a build to my Android phone for debugging, and it seems to have started as soon as I started using ResourceInteractiveLoader to switch scenes. Removing that part of the code doesn't seem to have stopped this issue from happening every time I run the debugger, but disabling "Small Deploy with Network FS" seems to work. This also seems to only affect Android as far as I can tell, and not when I run a debug build on Windows 10.

[lupoDharkael]

I'm working on a C++ module and I'm having the same experience as @HungryProton. I do procedural generation from a thread and this happens sometimes when I use print_line(). The reproduction rate seems arbitrary.

[lupoDharkael]

@Eoin-ONeill-Yokai I have a trace from commit 561438c5f67fcd2b4a3132d36b32333e4d8eb6c5

GDB bt

#0  0x00007ffff76ef4bf in write () from /lib64/libc.so.6
#1  0x00007ffff767f4cd in _IO_file_write@@GLIBC_2.2.5 () from /lib64/libc.so.6
#2  0x00007ffff767e826 in new_do_write () from /lib64/libc.so.6
#3  0x00007ffff767fbfe in __GI__IO_file_xsputn () from /lib64/libc.so.6
#4  0x00007ffff766b6b1 in buffered_vfprintf () from /lib64/libc.so.6
#5  0x00007ffff7668654 in __vfprintf_internal () from /lib64/libc.so.6
#6  0x0000000006e549cd in StdLogger::logv (this=0x77d6750, p_format=0x1b21d10 "%sERROR:%s %s\n", 
    p_list=0x7fffffffab70, p_err=true) at core/io/logger.cpp:230
#7  0x0000000006e53901 in Logger::logf_error (this=0x77d6750, p_format=0x1b21d10 "%sERROR:%s %s\n")
    at core/io/logger.cpp:100
#8  0x00000000048b0543 in UnixTerminalLogger::log_error (this=0x77d6750, 
    p_function=0x1b453da "_process_line", p_file=0x1b453e8 "scene/gui/rich_text_label.cpp", p_line=176, 
    p_code=0x3a4cb630 "Index line = 0 is out of bounds (l.offset_caches.size() = 0).", 
    p_rationale=0x1b8389b "", p_type=Logger::ERR_ERROR) at drivers/unix/os_unix.cpp:582
#9  0x0000000006e54c59 in CompositeLogger::log_error (this=0x77d6790, 
    p_function=0x1b453da "_process_line", p_file=0x1b453e8 "scene/gui/rich_text_label.cpp", p_line=176, 
    p_code=0x3a4cb630 "Index line = 0 is out of bounds (l.offset_caches.size() = 0).", 
    p_rationale=0x1b8389b "", p_type=Logger::ERR_ERROR) at core/io/logger.cpp:264
#10 0x0000000006cac54a in OS::print_error (this=0x7fffffffd5e8, p_function=0x1b453da "_process_line", 
    p_file=0x1b453e8 "scene/gui/rich_text_label.cpp", p_line=176, 
    p_code=0x3a4cb630 "Index line = 0 is out of bounds (l.offset_caches.size() = 0).", 
    p_rationale=0x1b8389b "", p_type=Logger::ERR_ERROR) at core/os/os.cpp:120
#11 0x0000000006ab6e57 in _err_print_error (p_function=0x1b453da "_process_line", 
    p_file=0x1b453e8 "scene/gui/rich_text_label.cpp", p_line=176, 
    p_error=0x3a4cb630 "Index line = 0 is out of bounds (l.offset_caches.size() = 0).", 
    p_message=0x1b8389b "", p_type=ERR_HANDLER_ERROR) at core/error_macros.cpp:81
#12 0x0000000006ab7513 in _err_print_index_error (p_function=0x1b453da "_process_line", 
    p_file=0x1b453e8 "scene/gui/rich_text_label.cpp", p_line=176, p_index=0, p_size=0, 
    p_index_str=0x1a8d3f2 "line", p_size_str=0x1a18d15 "l.offset_caches.size()", p_message=0x1b8389b "", 
    fatal=false) at core/error_macros.cpp:110
#13 0x0000000005977a06 in RichTextLabel::_process_line (this=0xe7d23d0, p_frame=0xe7d2a90, p_ofs=..., 
    y=@0x7fffffffc91c: 172, p_width=1333, p_line=470075, p_mode=RichTextLabel::PROCESS_DRAW, 
    p_base_font=..., p_base_color=..., p_font_color_shadow=..., p_shadow_as_outline=false, 
    shadow_ofs=..., p_click_pos=..., r_click_item=0x0, r_click_char=0x0, r_outside=0x0, 
    p_char_count=18487) at scene/gui/rich_text_label.cpp:176
#14 0x00000000059818fe in RichTextLabel::_notification (this=0xe7d23d0, p_what=30)
    at scene/gui/rich_text_label.cpp:1039
#15 0x000000000599626b in RichTextLabel::_notificationv (this=0xe7d23d0, p_notification=30, 
    p_reversed=false) at scene/gui/rich_text_label.h:39
#16 0x0000000006b45a4b in Object::notification (this=0xe7d23d0, p_notification=30, p_reversed=false)
    at core/object.cpp:914
#17 0x00000000056d24d8 in CanvasItem::_update_callback (this=0xe7d23d0) at scene/main/canvas_item.cpp:452
#18 0x00000000056e7764 in MethodBind0::call (this=0x8acf450, p_object=0xe7d23d0, p_args=0x0, 
    p_arg_count=0, r_error=...) at ./core/method_bind.gen.inc:147
#19 0x0000000006b48f6a in Object::call (this=0xe7d23d0, p_method=..., p_args=0x0, p_argcount=0, 
    r_error=...) at core/object.cpp:904
#20 0x0000000006a86323 in Callable::call (this=0x7fffe9e31020, p_arguments=0x0, p_argcount=0, 
    r_return_value=..., r_call_error=...) at core/callable.cpp:52
#21 0x0000000006b3d043 in MessageQueue::_call_function (this=0x78d1990, p_callable=..., 
    p_args=0x7fffe9e31038, p_argcount=0, p_show_error=false) at core/message_queue.cpp:253
#22 0x0000000006b3d392 in MessageQueue::flush (this=0x78d1990) at core/message_queue.cpp:303
#23 0x000000000575cba5 in SceneTree::idle (this=0x911c180, p_time=0.020833334)
    at scene/main/scene_tree.cpp:460
#24 0x00000000035535b5 in Main::iteration () at main/main.cpp:2190
#25 0x00000000035168e6 in OS_LinuxBSD::run (this=0x7fffffffd5e8) at platform/linuxbsd/os_linuxbsd.cpp:259
#26 0x0000000003514276 in main (argc=4, argv=0x7fffffffdac8) at platform/linuxbsd/godot_linuxbsd.cpp:56

[ebeem]

I am using threads, and it's causing this issue to me.

I don't understand why it works sometimes, shouldn't we always update GUI from the main thread?
as a workaround, instead of updating the control immediately (richtext to store console/terminal logs in my case), I am storing the list of strings I want to add to my log.

I am actually wondering how it works sometimes anyway, I don't think we can update the GUI from a thread other than the main, it seems like there's something that handles such situations in Godot?

before
```C#
private Node _console;
private Node Console
{
get
{
if (_console == null)
_console = GetNode("/root/Console");
return _console;
}
}
public void WriteLine(string text)
{
Console.Call("writeLine", text);
}

    public void Write(string text)
    {
        Console.Call("write", text);
    }

after

```C#
        private Node _console;
        private Queue<string> _logLines = new Queue<string>();
        private Queue<string> _logs = new Queue<string>();

        private Node Console
        {
            get
            {
                if (_console == null)
                    _console = GetNode("/root/Console");
                return _console;
            }
        }

        public void WriteLine(string text)
        {
            _logLines.Enqueue(text);
        }

        public void Write(string text)
        {
            _logs.Enqueue(text);
        }

        public override void _Process(float delta)
        {
            base._Process(delta);
            while(_logs.Count > 0)
                Console.Call("write", _logs.Dequeue());
            while(_logLines.Count > 0)
                Console.Call("writeLine", _logLines.Dequeue());
        }

[Rubonnek]

This just started happening to me quite often in 3.2 branch at commit 49b3750b3671e6c0c3edd0ca4d41df85593ff26f.

I'm not explicitly using threads in GDScript land -- only the intrinsic threads the engine itself uses, and the threaded LSP server.

Here's the backtrace I was able to catch:

#0  RichTextLabel::_process_line (this=0xe6a7810, p_frame=0xe6a7f90, p_ofs=..., y=@0x7fffffffcec4: 0, p_width=-8, p_line=0, p_mode=RichTextLabel::PROCESS_DRAW, p_base_font=..., p_base_color=..., p_font_color_shadow=..., p_shadow_as_outline=false, shadow_ofs=..., p_click_pos=..., r_click_item=0x0, r_click_char=0x0, r_outside=0x0, p_char_count=0) at scene/gui/rich_text_label.cpp:170
#1  0x000000000320a8c4 in RichTextLabel::_notification (this=0xe6a7810, p_what=30) at scene/gui/rich_text_label.cpp:1025
#2  0x0000000003230d1d in RichTextLabel::_notificationv (this=0xe6a7810, p_notification=30, p_reversed=false) at scene/gui/rich_text_label.h:39
#3  0x000000000512b898 in Object::notification (this=0xe6a7810, p_notification=30, p_reversed=false) at core/object.cpp:932
#4  0x00000000037e4a5e in CanvasItem::_update_callback (this=0xe6a7810) at scene/2d/canvas_item.cpp:459
#5  0x000000000058820a in MethodBind0::call (this=0xb370ed0, p_object=0xe6a7810, p_args=0x0, p_arg_count=0, r_error=...) at ./core/method_bind.gen.inc:59
#6  0x000000000512b62f in Object::call (this=0xe6a7810, p_method=..., p_args=0x0, p_argcount=0, r_error=...) at core/object.cpp:922
#7  0x0000000005114680 in MessageQueue::_call_function (this=0x9edfb40, p_target=0xe6a7810, p_func=..., p_args=0x7ffff692b5f0, p_argcount=0, p_show_error=false) at core/message_queue.cpp:250
#8  0x0000000005114aa7 in MessageQueue::flush (this=0x9edfb40) at core/message_queue.cpp:297
#9  0x0000000002f0f555 in SceneTree::iteration (this=0xb840020, p_time=0.0166666675) at scene/main/scene_tree.cpp:483
#10 0x00000000004ae8e8 in Main::iteration () at main/main.cpp:2084
#11 0x0000000000453b75 in OS_X11::run (this=0x7fffffffd7f0) at platform/x11/os_x11.cpp:3233
#12 0x00000000004387c7 in main (argc=2, argv=0x7fffffffe008) at platform/x11/godot_x11.cpp:56

[Eoin-ONeill-Yokai]

@Rubonnek Well, since there's currently a planned refactor (as seen in RichTextLabel issues tracker), I think that this would likely be addressed by that refactor.

Out of curiosity, do you happen to have a scene configuration where this is quickly reproducible?

[Rubonnek]

@Eoin-ONeill-Yokai Unfortunately I wasn't able to reproduce the issue consistently. It just happened to me five times in a row in the same project, but suddenly it stopped happening. I spent a couple of hours trying to reproduce it but to no avail.

[Rubonnek]

I can add that it always happened when one of my i3-wm windows was full screen, the project was running with a RichTextLabel node in it, and all three windows (i.e. the Editor, the running project, and my external text editor) were in the same workspace. My external editor connected to the LSP server covered the Editor as well as the project I was running, as I was debugging the code.