Re: finally caught an error on crash

OK, I got a crash, but without the lock/unlock debugs, and I also  
realized I capture stdout and stderr to separate files, so the exact  
ordering is not clear.  I've fixed the first issue and will see if I  
get another one.  Am I better off just combining stdout and stderr in a  
single capture file?  I'll do that for now.  Minor point - using  
__func__ does print the function you are in, but not the line, and some  
functions have multiple debugs in them.  Not sure if I just need to add  
some distinct code to the output (as is in the output below).

 From stderr:  (There are more javascript warnings, I only show the  
last one, and that email is basically advertising sent by a company  
administering one of my 401K (retirement) accounts, and clearly not a  
Balsa problem.  I'm pretty sure I have seen the GLib-GOblect-CRITICAL  
message before, but can't tell what I was actually doing at the time.   
It seems more relevant now than it has in the past.

JavaScript warning:  
https://wl.lifecare.com/lifemart-portal-theme/js/jquery/jquery.min.js,  
line 2: Using //@ to indicate sourceMappingURL pragmas is deprecated.  
Use //# instead
JavaScript warning:  
moz-extension://828c46ee-cd14-4a62-b031-d0d6d0f1818b/lib/adblockplus.js,  
line 0: Successfully compiled asm.js code (total compilation time 0ms)
JavaScript error:  
moz-extension://828c46ee-cd14-4a62-b031-d0d6d0f1818b/lib/adblockplus.js,  
line 0: Error: frame.state is undefined
Compressing mail folders…
JavaScript warning:  
moz-extension://828c46ee-cd14-4a62-b031-d0d6d0f1818b/lib/adblockplus.js,  
line 0: Successfully compiled asm.js code (total compilation time 0ms)
JavaScript error:  
moz-extension://828c46ee-cd14-4a62-b031-d0d6d0f1818b/lib/adblockplus.js,  
line 0: Error: frame.state is undefined

(balsa:9232): GLib-GObject-CRITICAL **: 18:47:11.969: g_object_unref:  
assertion 'G_IS_OBJECT (object)' failed

(balsa:9232): GLib-GObject-CRITICAL **: 18:47:52.790: g_object_unref:  
assertion 'G_IS_OBJECT (object)' failed
**
mbox-mbox:ERROR:../balsa-git/libbalsa/mailbox_mbox.c:252:message_info_from_msgno:  
assertion failed: (msgno > 0 && msgno <= mbox->msgno_2_msg_info->len)

###!!! [Child][RunMessage] Error: Channel closing: too late to  
send/recv, messages will be lost


The following is the tail of stderr: (GMS is get_message_stream, msync  
is mailbox_mbox_sync with the digit being which call to  
message_info_from_msgno)

(balsa:9232): mbox-mbox-DEBUG: 19:02:40.096: lbm_mbox_save:     
Sentbox    saved 14 messages
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC1 Sentbox: msgno 1 of  
14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC1 Sentbox: msgno 2 of  
14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC2 mbox: Sentbox:  
msgno 2 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 2 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 3 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 4 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 5 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 6 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 7 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 8 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 9 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 10 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 11 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 12 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 13 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.903: MSYNC3 mbox: Sentbox:  
msgno 14 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:40.958: libbalsa_mailbox_mbox_sync  
Sentbox set size from tell 7928
(balsa:9232): mbox-mbox-DEBUG: 19:02:41.024: MSYNC5 mbox: Sentbox:  
msgno 2 of 14.
(balsa:9232): mbox-mbox-DEBUG: 19:02:41.024: MSYNC5 mbox: Sentbox:  
msgno 2 of 13.
(balsa:9232): mbox-mbox-DEBUG: 19:02:41.025: MSYNC5 mbox: Sentbox:  
msgno 2 of 12.
(balsa:9232): mbox-mbox-DEBUG: 19:02:41.025: MSYNC5 mbox: Sentbox:  
msgno 2 of 11.
(balsa:9232): mbox-mbox-DEBUG: 19:02:41.025: MSYNC5 mbox: Sentbox:  
msgno 2 of 10.
(balsa:9232): mbox-mbox-DEBUG: 19:02:41.025: MSYNC5 mbox: Sentbox:  
msgno 2 of 9.
(balsa:9232): mbox-mbox-DEBUG: 19:02:41.025: MSYNC5 mbox: Sentbox:  
msgno 2 of 8.
(balsa:9232): mbox-mbox-DEBUG: 19:02:41.025: MSYNC5 mbox: Sentbox:  
msgno 2 of 7.
(balsa:9232): mbox-mbox-DEBUG: 19:02:41.025: GMS: Sentbox: msgno 12 of  
7.
Bail out!  
mbox-mbox:ERROR:../balsa-git/libbalsa/mailbox_mbox.c:252:message_info_from_msgno:  
assertion failed: (msgno > 0 && msgno <= mbox->msgno_2_msg_info->len)

This humbly tells me that perhaps not all my crashes have actually be  
in the INBOX, although I don't suppose that matters much.  I think I  
had just been cleaning out the sentbox, and hit the crash on  
"Expunge."  I wouldn't be surprised if the message selected at the time  
was the 12th message before I deleted any, and would have been the 7th  
after.    However, when I now look at the Sentbox, there are only 4  
messages, but I thought I was something flash when it first opened,  
possibly it catching up at having crashed before updating the number of  
messages it thinks are in that mailbox.

Anyway - the msgno 12 of 7 does appear to show something happening out  
of order, or might it be that the number of the selected message is  
cached and not recalculated after deleting and expunging other messages  
in the mailbox?

Jack

On 2020.05.05 16:01, Albrecht Dreß wrote:
> Am 04.05.20 23:01 schrieb(en) Jack via balsa-list:
>> This continues to happen at a low, but still annoying frequency.   
>> The line number in the error is now 247, having been 249 for a  
>> while, presumably just due to other edits to that file.  As I can  
>> remember, it happens after either deleting message(s) from the  
>> inbox, and/or moving message(s) to different mailboxes, in case that  
>> points to any possibilities.
> 
> Hmmm, the error message (failed assertion msgno <=  
> mbox->msgno_2_msg_info->len) “smells” like a corrupted GPtrArray;  
> maybe caused by a race between two threads, when messages are moved  
> and/or deleted.  I'm not really familiar with the mailbox code  
> (Peter? Pawel? Are you?), so this is a wild guess, though.  The  
> failing function seems to be message_info_from_msgno() which is  
> called in several places; do you have a backtrace from a crash?
> 
>> Given the recent changes (in the cleanup-logging branch) I'm  
>> wondering if I might just for my own use add some additional debug  
>> statements, either in the function where the g-assert fails, or else  
>> before the calls to that function.
> 
> As running in gdb is not always feasible, this may actually be  
> helpful.  Just add g_debug() statements…
> 
>> Any quick pointers (or even just a pointer to an example line or  
>> two) would be helpful, and also advice on which debug domain to use  
>> (or even to set for current testing) or how  to go about adding a  
>> new domain.
> 
> If you use the new branch, the log domain is set to (line 50) to
> 
> #define G_LOG_DOMAIN "mbox-mbox"
> 
> so running balsa by calling
> 
> G_MESSAGES_DEBUG=mbox-mbox /path/to/balsa
> 
> would print /only/ messages from this domain.
> 
> It might also be helpful (given that my assumption of a race  
> condition is true) to add debug messages to libbalsa/mailbox.c,  
> namely in libbalsa_lock_mailbox() and libbalsa_unlock_mailbox() (and  
> probably more), like
> 
> g_debug("%s: mbox %s", __func__, libbalsa_mailbox_get_name(mailbox));
> 
> That file didn't have its own log domain – which is bad, I just  
> pushed a tiny change to the branch setting it to
> 
> #define G_LOG_DOMAIN "mailbox"
> 
> The above call should now read
> 
> G_MESSAGES_DEBUG="mailbox mbox-mbox" /path/to/balsa
> 
> Finding the source of a race (which, again, is just a guess) is  
> always /very/ difficult, and adding debug messages may actually  
> change the internal timing of the application, effectively hiding the  
> bug…
> 
> Hope this helps,
> Albrecht.

------quoted attachment------
> _______________________________________________
> balsa-list mailing list
> [email protected]
> https://mail.gnome.org/mailman/listinfo/balsa-list
> 
_______________________________________________
balsa-list mailing list
[email protected]
https://mail.gnome.org/mailman/listinfo/balsa-list