GNOME Bugzilla – Bug 736838
IMAP messages not updated from server
Last modified: 2015-08-07 06:26:09 UTC
Debian Sid/unstable with Evolution 3.12.6 is used. In the morning everything worked fine. The system was upgrade in between and shut down. In the evening the messages for one IMAP account are not downloaded. The server is running Debian Wheezy with Courier IMAP (4.10.0-20120615-1). IMAP with Google Mail works fine.
Big thanks to dwmw2 for helping me in #evolution@irc.gnome.org. Let’s see what the problem turns out to be.
One difference I notice is that the router owner seems to have enable IPv6. So I have two IPv6 addresses now (one public, one local) in addition to the IPv4 address. I did not see any other difference. Judging from the debug log `CAMEL_DEBUG=imapx evolution` the command A00013 UID FETCH 1:* (UID FLAGS) does not complete. Manually running the commands in an IMAP session with openssl s_client -connect $server:143 -crlf -starttls imap the commands completes successfully. * 16096 FETCH (UID 53280 FLAGS (\Recent)) A00013 OK FETCH completed. The log of Evolution stop at: […] * 16050 FETCH (UID 53103 FLAGS (\Seen)) * 16051 FETCH (UID 53105 FLAGS (\Answered \Seen))' […] [imapx:C] got untagged response [imapx:C] Have token 'FETCH' id 16051 So for some reason it does not get the last 45 entries(?) or it does not output them. Here is one backtrace I captured during a hang.
+ Trace 234102
Thread 7 (Thread 0x9bf42b40 (LWP 26667))
The end of that log looks like this: [imapx:A] got untagged response [imapx:A] Have token 'FETCH' id 16051 imapx_find_connection_unlocked: for-expensive:1 will return:0x9a884dc0 cmd-count:1 has-expensive:1 found:1; connections opened:1 max:5 cmds:1 has-expensive:1 avail:0 cinfo:0x9a884dc0 server:0xb8c28d38 [imapx:A] Removed folder INBOX from connection folder list - op done (evolution:26494): GLib-GObject-CRITICAL **: g_closure_unref: assertion 'closure->ref_count > 0' failed (evolution:26494): GLib-GObject-CRITICAL **: g_closure_unref: assertion 'closure->ref_count > 0' failed (evolution:26494): GLib-GObject-CRITICAL **: g_closure_unref: assertion 'closure->ref_count > 0' failed (evolution:26494): GLib-GObject-CRITICAL **: g_closure_unref: assertion 'closure->ref_count > 0' failed (evolution:26494): GLib-GObject-CRITICAL **: g_closure_unref: assertion 'closure->ref_count > 0' failed imapx_find_connection_unlocked: for-expensive:0 will return:0x9a884dc0 cmd-count:1 has-expensive:1 found:1; connections opened:1 max:5 cmds:1 has-expensive:1 avail:0 cinfo:0x9a884dc0 server:0xb8c28d38 [imapx:A] adding command, format = 'UID FETCH %t (BODY.PEEK[])' [imapx:A] completing command buffer is [28] 'UID FETCH 9393 (BODY.PEEK[])' [imapx:A] enqueue job 'UID FETCH 9393 (BODY.PEEK[])' [imapx:A] ** Starting next command [imapx:A] - we're selected on 'INBOX', current jobs? [imapx:A] - 10 'FETCH' [imapx:A] -- Checking job queue [imapx:A] -- 100 'FETCH'? [imapx:A] Not yet sending duplicate fetch/refresh FETCH command [imapx:A] Selecting mailbox 'INBOX' for command 'FETCH'(0xac161b18) I don't understand why we don't receive anything in the FETCH response after item 16051, and no completion for the FETCH command A00013. And why are we in camel_imapx_store_op_done() if we haven't seen the completion? Is this a (locking?) issue with the multiple-connection support?
Restarting the system today and *not* removing the IPv6 addresses the FETCH command completed. So it looks like – (un)fortunately – the problem is not always reproducible. (The IP address is still used instead of the server name in the configuration. I’ll test with the hostname in the evening.) What happened above should be figured out nontheless and Evolution should deal with it gracefully and tell the user what or that something went wrong and not just hang. As I own the server I’ll try to also enable more debugging for Courier IMAP and maybe try to dump the traffic with Tcpdump. If somebody knows about the appropriate options/switches to use for that, please tell me as I have never done that before.
After another restart it worked also with the domain name in the server field. So I am unable to reproduce this issue until now.
Thanks for a bug report. There's a similar bug report downstream: https://bugzilla.redhat.com/show_bug.cgi?id=1148293 It's similar in a sense that the backtrace shows pending operations in the IMAPx, but the imapx_parser_thread is idle, which means either the pending job was forgotten between queues or there happened something with a connection which was serving the job and the job was not rescheduled. I still do not quite understand (and know) what would cause this, unfortunately.
The changes from bug #745545 address this, I believe, because all the job scheduling and so on is done differently, thus I'm closing this.