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
balsa-list gnome org
https://mail.gnome.org/mailman/listinfo/balsa-list


[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]