Profanity: Profanity freezes when resizing the terminal

[mdosch]

Version 0.7.0dev.master.aa0f4979

Profanity freezes (frozen screen with blinking cursor in the top left corner in gnome-terminal; blank screen in xterm and urxvt).
Going back to 09b6fc9aaa99b73b2eb58e4d6ea1b6a56a07a189 fixes this.

(gdb) bt
#0  0x00007ffff6f17504 in __GI___libc_write (fd=2, buf=0x7fffffffb450, nbytes=116)
    at ../sysdeps/unix/sysv/linux/write.c:26
#1  0x00007ffff6ea83bd in _IO_new_file_write (f=0x7ffff6fe9680 <_IO_2_1_stderr_>, data=0x7fffffffb450, n=116)
    at fileops.c:1183
#2  0x00007ffff6ea775f in new_do_write (fp=fp@entry=0x7ffff6fe9680 <_IO_2_1_stderr_>, 
    data=data@entry=0x7fffffffb450 "\n(profanity:20803): GLib-CRITICAL **: 19:07:25.636: g_string_insert_len: assertion 'len == 0 || val != NULL' failed\n\377\177", to_do=to_do@entry=116) at libioP.h:839
#3  0x00007ffff6ea8aee in _IO_new_file_xsputn (n=116, data=<optimized out>, f=0x7ffff6fe9680 <_IO_2_1_stderr_>)
    at fileops.c:1262
#4  _IO_new_file_xsputn (f=0x7ffff6fe9680 <_IO_2_1_stderr_>, data=<optimized out>, n=116) at fileops.c:1204
#5  0x00007ffff6e7f932 in buffered_vfprintf (s=s@entry=0x7ffff6fe9680 <_IO_2_1_stderr_>, 
    format=format@entry=0x7ffff74c4b17 "%s\n", args=args@entry=0x7fffffffda10) at ../libio/libioP.h:839
#6  0x00007ffff6e7ceb2 in _IO_vfprintf_internal (s=s@entry=0x7ffff6fe9680 <_IO_2_1_stderr_>, 
    format=0x7ffff74c4b17 "%s\n", ap=ap@entry=0x7fffffffda10) at vfprintf.c:1296
#7  0x00007ffff6f35536 in ___fprintf_chk (fp=0x7ffff6fe9680 <_IO_2_1_stderr_>, flag=1, format=<optimized out>)
    at fprintf_chk.c:35
#8  0x00007ffff747101a in g_log_writer_standard_streams () from target:/lib/x86_64-linux-gnu/libglib-2.0.so.0
#9  0x00007ffff7471102 in g_log_writer_default () from target:/lib/x86_64-linux-gnu/libglib-2.0.so.0
#10 0x00007ffff746f4e7 in g_log_structured_array () from target:/lib/x86_64-linux-gnu/libglib-2.0.so.0
#11 0x00007ffff746f91d in g_log_default_handler () from target:/lib/x86_64-linux-gnu/libglib-2.0.so.0
#12 0x00007ffff746fb6f in g_logv () from target:/lib/x86_64-linux-gnu/libglib-2.0.so.0
#13 0x00007ffff746fd5f in g_log () from target:/lib/x86_64-linux-gnu/libglib-2.0.so.0
#14 0x00007ffff748b417 in g_string_insert_len () from target:/lib/x86_64-linux-gnu/libglib-2.0.so.0
#15 0x00005555555f886f in _theme_prep_fgnd (setting=0x555555637ad8 "main.text.history", lookup_str=0x55555c9e1080, 
    bold=0x7fffffffde7c) at src/config/theme.c:637
#16 0x00005555555f89de in theme_attrs (attrs=THEME_TEXT_HISTORY) at src/config/theme.c:680
#17 0x00005555555adbb8 in _win_print (window=0x555558001ad0, show_char=45 '-', pad_indent=0, time=0x5555586c6a00, 
    flags=0, theme_item=THEME_TEXT_HISTORY, from=0x5555586c2410 "", 
    message=0x5555586b4190 "jonas’: zugegeben, ich nutze pidgin auch nur für 1:1 chats und eine handvoll kleiner MUCs in die ich mit dem poezio-account nicht reinkann", receipt=0x0) at src/ui/window.c:1502
#18 0x00005555555ae3cc in win_redraw (window=0x555558001ad0) at src/ui/window.c:1643
#19 0x00005555555aa96b in win_resize (window=0x555558001ad0) at src/ui/window.c:661
#20 0x00005555555be6e9 in wins_resize_all () at src/ui/window_list.c:742
#21 0x00005555555aef26 in ui_resize () at src/ui/core.c:201
#22 0x00005555555aed55 in ui_update () at src/ui/core.c:146
#23 0x000055555558a196 in prof_run (log_level=0x55555563ca50 "INFO", account_name=0x0, config_file=0x0) at src/profanity.c:130
#24 0x0000555555615239 in main (argc=1, argv=0x7fffffffe168) at src/main.c:175

[pasis]

Haven't read the code yet, but as far as I remember, Profanity redirects stderr to its log file. And according to the backtrace, Profanity waits on blocking I/O to stderr. Maybe buffer for stderr is full before logging subsystem has a chance to read it? Anyway, I guess we need to set nonblocking mode for the file descriptor and check how glib will handle such a situation.

[jubalh]

@mdosch can you please test if this still happens if you add main.text.history=red to your theme file.

[jubalh]

Can't reproduce this with:

gnome-terminal --version
# GNOME Terminal 3.32.2 using VTE 0.56.3 +GNUTLS

But I added two more commits regarding this. Maybe you can check with https://github.com/profanity-im/profanity/commit/2c97a484180ebd607b7debf3507f9dc2fe12a9d0

[mdosch]

gnome-terminal --version
# GNOME Terminal 3.30.2 using VTE 0.54.2 +GNUTLS

With 2c97a484180ebd607b7debf3507f9dc2fe12a9d0 it works well again. Thanks!

[jubalh]

Good! I forgot to initialize main.text.history if it's not set by the theme.
I'll close this then :)

[pasis]

@jubalh, it looks to me that the issue with NULL pointer revealed a problem with stderr logging. Profanity shouldn't freeze on such errors. I would reopen this ticket and fix the problem in logging subsystem. @mdosch Do you have a setup to reproduce the freeze, so you can test a possible solution?

[mdosch]

I should be able to reproduce it by removing the initialisation of main.text.history and removing it from my theme file.

[jubalh]

@pasis ah yes, I wanted to comment about the issue discovered as a sideeffect today :)
Was a bit in a hurry yesterday.

Can you prepare a solution?

[pasis]

@mdosch , could you check branch https://github.com/profanity-im/profanity/tree/issue1186 ? You should see error messages from glib in ~/.local/share/profanity/logs/profanity.log instead of freezing.

[mdosch]

@pasis my log gets spammed with messages about the bad color name "orange_default" although it is not in my theme but doesn't freeze.

grep "prof: ERR: Color: bad color name orange_default" ~/.local/share/profanity/logs/profanity.log | wc -l
1920

grep orange_default ~/.config/profanity/themes/solarized-dark | wc -l      :(
0

[jubalh]

@mdosch are you sure these are not old entries?

[mdosch]

No, it's current:

12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default
12/09/2019 21:50:16: prof: ERR: Color: bad color name orange_default

[jubalh]

Did you grep through all the themes? For orange since default could be added if something is not set.

[mdosch]

He, that's what I did right now before reading your reply and I found the culprit. It seems I forgot to replace "orange" in one place: https://github.com/profanity-im/profanity/blob/master/themes/solarized-dark#L56

[jubalh]

So does it still freeze?

[mdosch]

No, neither with current master nor with pasis' branch issue1183. 😃

[pasis]

@mdosch, have you tried branch issue1186 (not issue1183)? I expected that you would have messages like this:

(profanity:20803): GLib-CRITICAL **: 19:07:25.636: g_string_insert_len: assertion 'len == 0 || val != NULL' failed

Could you check if you have other ERR logs besides ones you mentioned?

Also, could you do the following test:

1. checkout commit which has the problem (aa0f4979)
2. reproduce freezing
3. cherry-pick only commit 102ae630eb501e846e35ad54355e22d006c6d8ca which should fix the freeze
4. try to reproduce freezing in the same way

I want to be sure that my commit fixes the problem and this is not other commit in the branch or because branch issue1186 doesn't contain the affected commit.

[pasis]

As for the number of bad color name orange_default messages - this is unrelated. They are printed here:

src/config/color.c:405:        log_error("Color: bad color name %s", pair_name);

And the issue with freezing comes from redirecting stderr.

@jubalh , Maybe open a ticket to reduce number of the above logs?

[pasis]

Reopen this issue until the freeze is actually fixed.

[jubalh]

@jubalh , Maybe open a ticket to reduce number of the above logs?

So far it's printed whenever such a number is initialized/used. How would you limit it?

[pasis]

So far it's printed whenever such a number is initialized/used. How would you limit it?

I'm not familiar with the code, but it looks to me that we can check a color_pair once. When a theme is loaded we check every color, print error message if something is wrong and replace missed color with default. So we don't check colors the they are used, only when initialized.

[pasis]

What I wanted to say is that 1920 the same error messages is something wrong. But I can't say what exactly, because don't know what the code does.

[jubalh]

I'm not familiar with the code, but it looks to me that we can check a color_pair once. When a theme is loaded we check every color, print error message if something is wrong and replace missed color with default. So we don't check colors the they are used, only when initialized.

What we do is this:
theme_attrs() is used everywhere to get the attributes of a theme. For example wbkgd(statusbar_win, theme_attrs(THEME_STATUS_TEXT)); to get what THEME_STATUS_TEXT. Should look like.

In theme_attrs() we lookup the colour pair like this:

     result = color_pair_cache_get(lookup_str->str);                                                                                                                                       
     if (result < 0) {                                                                                                                                                                     
         log_error("Unable to load colour theme");                                                                                                                                         
         result = 0;                                                                                                                                                                       
     }

ncurses only allows 256 color pairs AFAIK, so we do this to see if we already intialized the pair of foreground-background color or not. In case of not we initialize it.

The colour names we use are the xterm names (https://jonasjacek.github.io/colors/)

So in color_pair_cache_get() we set the pairs based on the text red_blue we take the foreground color of red and the background color of blue. But if one of the names is not from the xterm name list then we logColor: bad color nameto the file. We return -1 to indicate an error and log also to the fileUnable to load colour theme`.

So instead of returning -1 and printing Unable to load colour theme in the calling function, we could also set it to a default value. And log Color: bad color name 'orange' using 'white' instead.

Do you like this better?

But we will also have to set it so that we don't try to look up the bad name again. Not sure where. Otherwise the message is still printed often.

In my opinion its not worth to find a perfect solution here, because the amount of time it takes and that it gives few benefit. If people see the error message (often) in their log they should just adjust their theme.

[mdosch]

• aa0f497
  
  
  
  • profanity freezes
  
  
  • nothing suspicious in the logs
  
  
• aa0f497 with cherrypicked 102ae63
  
  
  
  • profanity doesn't freeze
  
  
  • A lot of the following error
  
  

13/09/2019 13:34:24: stderr: ERR: 
13/09/2019 13:34:24: stderr: ERR: (profanity:19500): GLib-CRITICAL **: 13:34:24.062: g_string_insert_len: assertion 'len == 0 || val != NULL' failed
13/09/2019 13:34:24: stderr: ERR: 
13/09/2019 13:34:24: stderr: ERR: (profanity:19500): GLib-CRITICAL **: 13:34:24.062: g_string_insert_len: assertion 'len == 0 || val != NULL' failed
13/09/2019 13:34:24: stderr: ERR: 
13/09/2019 13:34:24: stderr: ERR: (profanity:19500): GLib-CRITICAL **: 13:34:24.062: g_string_insert_len: assertion 'len == 0 || val != NULL' failed
13/09/2019 13:34:24: stderr: ERR: 
13/09/2019 13:34:24: stderr: ERR: (profanity:19500): GLib-CRITICAL **: 13:34:24.062: g_string_insert_len: assertion 'len == 0 || val != NULL' failed
13/09/2019 13:34:24: stderr: ERR: 
13/09/2019 13:34:24: stderr: ERR: (profanity:19500): GLib-CRITICAL **: 13:34:24.062: g_string_insert_len: assertion 'len == 0 || val != NULL' failed

[pasis]

@mdosch thanks, this is what I expected, the number of the errors is another issue, at least it doesn't freeze now.

[jubalh]

Alright. So this issue got closed through the commit. I'm happy with it as it is.

@pasis if you feel like the numbers of errors logged should be reduced feel free to open a new issue. Personally I have several programs that operate like this and print multiple error messages due to one cause.