GNOME Bugzilla – Bug 740585
[IMAPx] Ignore timeout when no command is running
Last modified: 2014-11-28 13:04:55 UTC
Gnome 3.12.2, Ubuntu 14.04.1 LTS, Evolution 3.12.8. Immediately after upgrading to the new version I started seeing this in my syslog: Nov 21 16:35:13 localhost imapd: DISCONNECTED, user=chris, ip=[::ffff:127.0.0.1], headers=33141, body=0, rcvd=421, sent=46672, time=16882 Nov 21 16:35:13 localhost imapd: DISCONNECTED, user=chris, ip=[::ffff:127.0.0.1], headers=234210, body=10174, rcvd=1816330, sent=140547693, time=16882 Nov 21 16:35:22 localhost imapd: Connection, ip=[::ffff:127.0.0.1] Nov 21 16:35:23 localhost imapd: LOGIN, user=chris, ip=[::ffff:127.0.0.1], port=[35601], protocol=IMAP Nov 21 16:37:03 localhost imapd: DISCONNECTED, user=chris, ip=[::ffff:127.0.0.1], headers=20224, body=0, rcvd=20336, sent=1482006, time=100 Nov 21 16:37:21 localhost imapd: Connection, ip=[::ffff:127.0.0.1] Nov 21 16:37:22 localhost imapd: LOGIN, user=chris, ip=[::ffff:127.0.0.1], port=[35603], protocol=IMAP Nov 21 16:37:22 localhost imapd: Connection, ip=[::ffff:127.0.0.1] Nov 21 16:37:22 localhost imapd: LOGIN, user=chris, ip=[::ffff:127.0.0.1], port=[35604], protocol=IMAP and so on even up until this minute: Nov 23 11:30:47 localhost imapd: DISCONNECTED, user=chris, ip=[::ffff:127.0.0.1], headers=0, body=0, rcvd=16935, sent=1438722, time=92 Nov 23 11:31:15 localhost imapd: Connection, ip=[::ffff:127.0.0.1] Nov 23 11:31:15 localhost imapd: LOGIN, user=chris, ip=[::ffff:127.0.0.1], port=[51672], protocol=IMAP I have several Debug commands I could use but I'm not sure which one would work for this: CAMEL_DEBUG=mail:io evolution >& /home/chris/evodebug1.txt CAMEL_DEBUG=imapx:io evolution >& /home/chris/Evo-Debug-Logs/imapx-io-112314.txt CAMEL_DEBUG=imapx:debug,imapx:extra evolution >& /home/chris/evodebugfull.txt CAMEL_DEBUG=all evolution >& /home/chris/Evo-Debug-Logs/evo_debug.log CAMEL_DEBUG=imapx:io evolution &>/home/chris/log.txt I've restarted the Courier IMAP daemon which made no difference.
Thanks for a bug report. As I indicated on the mailing list [1]: it's not a bug, or at least part of it. There had been added a 90 seconds timeout for connections, thus if there's an inactivity for the 90 seconds, the IMAPx disconnects automatically (to be honest, I thought the timeout is relevant only for ongoing requests, not for "idle" connection state). More interesting is why IMAPx reconnected short after the disconnect. Were you working with evolution till that ~22:00, or it was doing this on its own? By working with evolution I mean message reading, downloading, folder operations and such, basically anything what would do something with the connection to the server and keep it alive or require it, thus reconnect. The debugging command to use is: $ CAMEL_DEBUG=imapx:io,imapx:conman evolution &>log.txt As always, make sure you'll not expose any private information, like passwords, server addresses, emails and so on (the log will contain raw communication, thus anything what you download from it, including messages content). [1] https://mail.gnome.org/archives/evolution-list/2014-November/msg00139.html
As soon as I close down Evolution for the night the issue ceases. I've attached three files: 1) Output of the debug command you noted above. 2) My hourly syslog snippets sent to me. Note - the 2300 snippet is for the time period from 2200 - 2259 and the 0000 snippet is from 2300 - 2359. For instance, I shut down Evolution last night at Nov 24 22:43:23 and went to bed. The issue stopped at that point. I've also noticed that the timeout isn't consistent as below: Nov 24 22:38:20 localhost imapd: DISCONNECTED, user=chris, ip= [::ffff:127.0.0.1], headers=0, body=0, rcvd=16964, sent=1431659, time=90 Nov 24 22:38:50 localhost imapd: Connection, ip=[::ffff:127.0.0.1] Nov 24 22:38:50 localhost imapd: LOGIN, user=chris, ip=[::ffff:127.0.0.1], port=[57686], protocol=IMAP Nov 24 22:40:25 localhost imapd: DISCONNECTED, user=chris, ip= [::ffff:127.0.0.1], headers=0, body=0, rcvd=17060, sent=1451073, time=95 Nov 24 22:40:50 localhost imapd: Connection, ip=[::ffff:127.0.0.1] Nov 24 22:40:50 localhost imapd: LOGIN, user=chris, ip=[::ffff:127.0.0.1], port=[57749], protocol=IMAP Nov 24 22:42:22 localhost imapd: DISCONNECTED, user=chris, ip= [::ffff:127.0.0.1], headers=0, body=0, rcvd=17060, sent=1451073, time=92 Here is where I shut down for the night: Nov 24 22:43:12 localhost imapd: DISCONNECTED, user=chris, ip= [::ffff:127.0.0.1], headers=0, body=9293, rcvd=17165, sent=1460871, time=22
Created attachment 291460 [details] 2300 Syslog Snippet
Created attachment 291461 [details] 0000 Syslog snippet
Debug output is located here: http://pastebin.com/hczeEVUb as it was too large for bugzilla.
Do you have that often check for new mails set? Like each two minutes (or one) or such? Anyway, I think it's safe to ignore the timeout error when there was no command waiting for a result, thus I made this change. A workaround might be to limit number of connections for that account to 1 and/or enable "Listen for server change notifications", which will not let the connection timeout. Created commit 28ddf2e in eds master (3.13.9+) [1] Created commit 4033576 in eds evolution-data-server-3-12 (3.12.9+) [1] https://git.gnome.org/browse/evolution-data-server/commit/?id=28ddf2e
Yes, I do have it set to check for new mail every 2 minutes. Per your post above I've set the number of connections to 1 and have enabled 'listen for server change notifications'. Thank you Milan for your quick response to this.
Following up to let you know that the work-around has fixed the issue.