GNOME Bugzilla – Bug 729172
Cannot retrieve certain messages
Last modified: 2014-07-02 09:00:43 UTC
Created attachment 275408 [details] CAMEL_DEBUG=imapx:io with problematic mail I am finding that Evolution cannot retrieve/display a small number of messages in my INBOX. I get a message: Unable to retrieve message. Error fetching message: unexpected server response: Running with CAMEL_DEBUG=imapx:io I see what looks like a successful retrieval. See attached retrieval-failed.log. Towards the end I see: (evolution:18946): GLib-GIO-CRITICAL **: g_output_stream_write_all: assertion 'buffer != NULL' failed Since the problematic message arrived via the xen-devel list it is archived at http://bugs.xenproject.org/xen/mid/%3C1398703390-5657-1-git-send-email-jfehlig@suse.com%3E (append /raw for a raw version). By contrast retrieval-ok.log shows the successful fetch/display of another message (http://bugs.xenproject.org/xen/mid/%3C535A7A620200006600020ACC@soto.provo.novell.com%3E FWIW). The majority of my mail seems to be fine, I can't figure out what makes this guy special. The server is Exchange accessed via imapx.
Created attachment 275409 [details] CAMEL_DEBUG=imapx:io with mail which is OK
Forgot to mention, this is with evolution 3.12.1-1 from Debian.
Created attachment 275410 [details] Segfault with CAMEL_DEBUG=all Trying CAMEL_DEBUG=all causes a segfault, long before I can select any of the problematic messages, so probably unrelated. See segfault.log for the backtrace.
The crash appeared to be related to recovering messages which I was writing. By selecting not to do so I lost a few drafts but evolution started. Of the ~100 messages which I received overnight last night about 10% are suffering from this issue, which is proving rather inconvenient. Because of that I've bumped the importance up a notch to major, I hope that is not out of line.
A breakpoint in g_return_if_fail_warning gives the following backtrace corresponding to the "assertion 'buffer != NULL' failed" message. gdb) bt
+ Trace 233537
Not the same instance of the assertion but identical in form, at stack frame #2 imapx_untagged_fetch I see: (gdb) print finfo $1 = (struct _fetch_info *) 0x7fff10021660 (gdb) print *finfo $2 = {got = 1537, body = 0x7fffd8037980, text = 0x0, header = 0x0, minfo = 0x0, cinfo = 0x0, size = 0, offset = 20480, flags = 0, modseq = 0, user_flags = 0x0, date = 0x0, section = 0x7fff100215b0 "", uid = 0x7fff1001ef80 "4014981"} (gdb) print finfo->body $3 = (GBytes *) 0x7fffd8037980 (gdb) print *finfo->body $4 = {data = 0x0, size = 0, ref_count = 1, free_func = 0x7ffff3b79700 <g_free>, user_data = 0x0} Is it valid for finfo->body to be empty here?
Created attachment 275532 [details] [review] Debug/hack patch I suspected the issue might be this response: * 147 FETCH (BODY[]<81920> "" UID 4014661) Which contains a zero length string. I applied the attached hack.patch and for a problematic message it produces the output: (evolution:10834): camel-imapx-WARNING **: IMAPX_TOK_STRING: len 0 *out_bytes 0x7f3e6c032190 (evolution:10834): camel-imapx-WARNING **: body 0x7f3e6c032190 size is 0 (evolution:10834): camel-imapx-WARNING **: body size is 0, data is (nil) But also I am now able to view the message. The patch just eats a zero sized entry and returns success. Hopefully that's enough for someone who knows the code to go on!
With the Debug/hack patch from comment 7 applied I am seeing some segfaults. Since I don't know if this is related to my hacks I thought I'd mention it here first before filing a new bug, but my feeling is that this is not related to these changes (it's on outgoing SMTP not incoming imapx) (gdb) bt
+ Trace 233542
A second segfault which might more plausibly be related to me hackery... (gdb) bt
+ Trace 233543
With 3.12.2 plus the IMAPX_TOK_STRING issue fixed via the patch attached here things are very flakey, although I'm no longer seeing segfaults. However I am seeing frequent hangs talking to the IMAP server, e.g. "Scanning for changed messages in ..." and "Scanning folders in ..." hanging indefinitely (as far as I can tell). I'm also suffering from messages randomly disappearing from my INBOX, or reappearing after I've dragged them into another folder, this happens even with frequent expunging (trying to work around the issue). I'm having to kill and restart multiple times an hour and things are pretty much unusable for any real mail management at the moment. I'm seeing messages such as: "Source ID 22433 was not found when attempting to remove it" (which seems to correlate pretty strongly with hangs) and "cmp_array_uids: assertion 'md2 != NULL' failed" (not sure what this correlates with) and "Nonsensical (103% complete) reported on activity "Retrieving message '373784' in INBOX". I'm afraid that unless I get a request to gather specific logs or more information etc shortly I'm going to switch back to 3.8 which was working mostly OK so I can get some work done.
Thanks for a bug report and the message pointer. I imported it into my exchange server and I am able to reproduce the issue too. I guess it has something to do with the message size. I'll investigate it further.
Hi Milan, I think it's something to do with the size too which leads to the "147 FETCH (BODY[]<81920> "" UID 4014661)" reply I mentioned above. I've been running with the patch from comment 7 to handle that case for a couple of months now and I'm no longer seeing this particular issue. But at the same time I'm still seeing the segfaults mentioned above pretty frequently. I think I should put them in another report though since I've become convinced they aren't related to the issue here. I'm also seeing "instability" with the imap provider in the sense of messages winking in and out of existence on refresh (appearing as deleted, then coming back on a subsequent refresh etc). I didn't downgrade to 3.8 in the end because the packages had gone from the Debian mirrors and library dependencies etc etc so I'm still running 3.12.2.
I investigated this and the 'no data' state is valid in the case of an Exchange server, which reports larger message size that it is. In that case IMAPx issues message chunk fetch for a part which is not there, thus the server returns no data for that offset. I'd call it a correct state, the same correct as another workaround in the IMAPx code for Exchange servers which, on the other hand, report too small message size. It seems their reported message size doesn't fit with actual IMAP message size in both directions. I polished your patch and I'm including it into the sources. Created commit d3999fe in eds master (3.13.4+) [1] Created commit d3e2554 in eds evolution-data-server-3-12 (3.12.4+) https://git.gnome.org/browse/evolution-data-server/commit/?id=d3999fe
(In reply to comment #12) > But at the same time I'm still seeing the segfaults mentioned above pretty > frequently. I think I should put them in another report though since I've > become convinced they aren't related to the issue here. I agree, moving those in separate bug reports will be better. There can be soem filled already, for example I added bug #732607 today. > I'm also seeing "instability" with the imap provider in the sense of messages > winking in and out of existence on refresh (appearing as deleted, then coming > back on a subsequent refresh etc). I'd recommend to update evolution-data-server and evolution to 3.12.3, it's the latest stable version for couple weeks now. The 3.12.4 will be released in two weeks.
> I'm including it into the sources. Thanks! > I'd recommend to update evolution-data-server and evolution to 3.12.3, it's the > latest stable version for couple weeks now. The 3.12.4 will be released in two > weeks. Thanks. I'll wait for those versions to hit Debian and see if the issues still occur before I file any further bugs.