[Dovecot] IDLE timing issue - dovecot or fetchmail issue?
Hi guys,
Thanks for the great product. We've used dovecot for ages as our internal mail server and it works great!
I've recently started using fetchmail 6.3.9 (with IDLE enabled) to download mail from our ISP (Pair networks). The ISP is running Dovecot 1.1.16. I am unable to get the info about the dovecot config at this time.
The IDLE support in fetchmail allows us to deliver mail near instantaneously without the need to poll (which is what we did previously using POP3). However I've noticed an issue where if 2 mails are delivered in quick succession fetchmail will only download the first email, and the second will not download. If I then send in another test email this triggers the download of 2 emails (the original that wasn't downloaded and the test email).
Now I'm wondering whether the issue lies with Dovecot (e.g. a timing issue), or is it fetchmail that isn't implementing the IDLE/download properly.
I've attached the output of a fetchmail session showing this problem in
action (I've added some annotations to this file starting with >>>>>).
The sequence of events are:
* Start fetchmail with IDLE enabled
* Send 2 emails in quick succession.
* Dovecot notifies of the new message
* Fetchmail downloads the message
* Fetchmail initiates a new IDLE
* Then nothing more is delivered. :(
* I then send another email, which triggers the 2 to download.I don't know enough about IMAP to understand whether the problem lies with Dovecot or Fetchmail. Hopefully an IMAP expert will be able to see from the attached IMAP session.
Regards,
-- Matt Doran PaperCut Software International Pty. Ltd. http://www.papercut.com/
Phone: +61 3 9809 5194
fetchmail: 6.3.9-rc2 querying mail.XXXX.com (protocol IMAP) at Tue 12 Jan 2010 13:17:38 EST: poll started Trying to connect to 216.92.193.84/143...connected. fetchmail: IMAP< * OK Dovecot ready. fetchmail: IMAP> A0001 CAPABILITY fetchmail: IMAP< * CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS UIDPLUS LIST-EXTENDED I18NLEVEL=1 QUOTA STARTTLS AUTH=PLAIN AUTH=LOGIN fetchmail: IMAP< A0001 OK Capability completed. fetchmail: will idle after poll fetchmail: IMAP> A0002 STARTTLS fetchmail: IMAP< A0002 OK Begin TLS negotiation now.
<snip TLS stuff>
fetchmail: IMAP> A0003 CAPABILITY fetchmail: IMAP< * CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS UIDPLUS LIST-EXTENDED I18NLEVEL=1 QUOTA AUTH=PLAIN AUTH=LOGIN fetchmail: IMAP< A0003 OK Capability completed. fetchmail: will idle after poll fetchmail: mail.XXXX.com: upgrade to TLS succeeded. fetchmail: IMAP> A0004 LOGIN "matt" * fetchmail: IMAP< A0004 OK Logged in. fetchmail: IMAP> A0005 SELECT "INBOX" fetchmail: IMAP< * FLAGS (\Answered \Flagged \Deleted \Seen \Draft Junk NonJunk) fetchmail: IMAP< * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft Junk NonJunk \*)] Flags permitted. fetchmail: IMAP< * 0 EXISTS fetchmail: IMAP< * 0 RECENT fetchmail: IMAP< * OK [UIDVALIDITY 1227629703] UIDs valid fetchmail: IMAP< * OK [UIDNEXT 76875] Predicted next UID fetchmail: IMAP< A0005 OK [READ-WRITE] Select completed. fetchmail: IMAP> A0006 IDLE fetchmail: IMAP< + idling fetchmail: IMAP< * 1 EXISTS fetchmail: IMAP> DONE fetchmail: IMAP< * 1 RECENT fetchmail: IMAP< A0006 OK Idle completed. fetchmail: IMAP> A0007 SEARCH UNSEEN NOT DELETED fetchmail: IMAP< * SEARCH 1 fetchmail: IMAP< A0007 OK Search completed (0.000 secs). 1 message for matt at mail.XXXX.com. fetchmail: IMAP> A0008 FETCH 1 RFC822.SIZE fetchmail: IMAP< * 1 FETCH (RFC822.SIZE 11068) fetchmail: IMAP< A0008 OK Fetch completed. fetchmail: IMAP> A0009 FETCH 1 RFC822.HEADER fetchmail: IMAP< * 1 FETCH (RFC822.HEADER {1651} reading message matt@XXXX.com:1 of 1 (1651 header octets) Trying to connect to 127.0.0.1/25...connected. fetchmail: SMTP< 220 smaug.XXXXX.com ESMTP Exim 4.69 Tue, 12 Jan 2010 13:17:56 +1100 fetchmail: SMTP> EHLO smaug.XXXXX.com fetchmail: SMTP< 250-smaug.XXXXX.com Hello matt at localhost [127.0.0.1] fetchmail: SMTP< 250-SIZE 52428800 fetchmail: SMTP< 250-PIPELINING fetchmail: SMTP< 250 HELP fetchmail: SMTP> MAIL FROM:<test-orders@XXXX.com> SIZE=11068 fetchmail: SMTP< 250 OK fetchmail: SMTP> RCPT TO:<matt@localhost> fetchmail: SMTP< 250 Accepted fetchmail: SMTP> DATA fetchmail: SMTP< 354 Enter message, ending with "." on a line by itself # fetchmail: IMAP< ) fetchmail: IMAP< A0009 OK Fetch completed. fetchmail: IMAP> A0010 FETCH 1 BODY.PEEK[TEXT] fetchmail: IMAP< * 1 FETCH (BODY[TEXT] {9417} (9417 body octets)**************************.*************.*************.*************.*************.*************.*************.*************.**************.****** fetchmail: IMAP< ) fetchmail: IMAP< A0010 OK Fetch completed. fetchmail: SMTP>. (EOM) fetchmail: SMTP< 250 OK id=1NUWKS-0004rr-5f flushed fetchmail: IMAP> A0011 STORE 1 +FLAGS (\Seen \Deleted) fetchmail: IMAP< * 1 FETCH (FLAGS (\Deleted \Seen \Recent)) fetchmail: IMAP< * 2 EXISTS fetchmail: IMAP< * 2 RECENT fetchmail: IMAP< A0011 OK Store completed. fetchmail: IMAP> A0012 EXPUNGE fetchmail: IMAP< * 1 EXPUNGE fetchmail: IMAP< * 1 RECENT fetchmail: IMAP< A0012 OK Expunge completed. fetchmail: SMTP> QUIT fetchmail: SMTP< 221 smaug.XXXXX.com closing connection fetchmail: IMAP> A0013 IDLE fetchmail: IMAP< + idling
At this point only one message was delivered
The following occurred after I sent in another email which triggered the IDLE notification and both were downloaded
fetchmail: IMAP< * 2 EXISTS fetchmail: IMAP> DONE fetchmail: IMAP< * 2 RECENT fetchmail: IMAP< A0013 OK Idle completed. fetchmail: IMAP> A0014 SEARCH UNSEEN NOT DELETED fetchmail: IMAP< * SEARCH 1 2 fetchmail: IMAP< A0014 OK Search completed (0.000 secs). 2 messages for matt at mail.XXXX.com. fetchmail: IMAP> A0015 FETCH 1:2 RFC822.SIZE fetchmail: IMAP< * 1 FETCH (RFC822.SIZE 14548) fetchmail: IMAP< * 2 FETCH (RFC822.SIZE 1723) fetchmail: IMAP< A0015 OK Fetch completed. fetchmail: IMAP> A0016 FETCH 1 RFC822.HEADER fetchmail: IMAP< * 1 FETCH (RFC822.HEADER {1655} reading message matt@XXXX.com:1 of 2 (1655 header octets) Trying to connect to 127.0.0.1/25...connected. fetchmail: SMTP< 220 smaug.XXXXX.com ESMTP Exim 4.69 Tue, 12 Jan 2010 13:18:27 +1100 fetchmail: SMTP> EHLO smaug.XXXXX.com fetchmail: SMTP< 250-smaug.XXXXX.com Hello matt at localhost [127.0.0.1] fetchmail: SMTP< 250-SIZE 52428800 fetchmail: SMTP< 250-PIPELINING fetchmail: SMTP< 250 HELP fetchmail: SMTP> MAIL FROM:<test-orders@XXXX.com> SIZE=14548 fetchmail: SMTP< 250 OK fetchmail: SMTP> RCPT TO:<matt@localhost> fetchmail: SMTP< 250 Accepted fetchmail: SMTP> DATA fetchmail: SMTP< 354 Enter message, ending with "." on a line by itself # fetchmail: IMAP< ) fetchmail: IMAP< A0016 OK Fetch completed. fetchmail: IMAP> A0017 FETCH 1 BODY.PEEK[TEXT] fetchmail: IMAP< * 1 FETCH (BODY[TEXT] {12893} (12893 body octets)*********************************.*************.*************.*************.*************.*************.******************.*****************.**************.*************.*************.*************.*********** fetchmail: IMAP< ) fetchmail: IMAP< A0017 OK Fetch completed. fetchmail: SMTP>. (EOM) fetchmail: SMTP< 250 OK id=1NUWKx-0004sC-MW flushed fetchmail: IMAP> A0018 STORE 1 +FLAGS (\Seen \Deleted) fetchmail: IMAP< * 1 FETCH (FLAGS (\Deleted \Seen \Recent)) fetchmail: IMAP< A0018 OK Store completed. fetchmail: IMAP> A0019 EXPUNGE fetchmail: IMAP< * 1 EXPUNGE fetchmail: IMAP< * 1 RECENT fetchmail: IMAP< A0019 OK Expunge completed. fetchmail: IMAP> A0020 FETCH 1 RFC822.HEADER fetchmail: IMAP< * 1 FETCH (RFC822.HEADER {1603} reading message matt@XXXX.com:2 of 2 (1603 header octets) fetchmail: SMTP> MAIL FROM:<matt.doran@XXXX.com> SIZE=1723 fetchmail: SMTP< 250 OK fetchmail: SMTP> RCPT TO:<matt@localhost> fetchmail: SMTP< 250 Accepted fetchmail: SMTP> DATA fetchmail: SMTP< 354 Enter message, ending with "." on a line by itself # fetchmail: IMAP< ) fetchmail: IMAP< A0020 OK Fetch completed. fetchmail: IMAP> A0021 FETCH 1 BODY.PEEK[TEXT] fetchmail: IMAP< * 1 FETCH (BODY[TEXT] {120} (120 body octets)********* fetchmail: IMAP< ) fetchmail: IMAP< A0021 OK Fetch completed. fetchmail: SMTP>. (EOM) fetchmail: SMTP< 250 OK id=1NUWL0-0004sC-0s flushed fetchmail: IMAP> A0022 STORE 1 +FLAGS (\Seen \Deleted) fetchmail: IMAP< * 1 FETCH (FLAGS (\Deleted \Seen \Recent)) fetchmail: IMAP< A0022 OK Store completed. fetchmail: IMAP> A0023 EXPUNGE fetchmail: IMAP< * 1 EXPUNGE fetchmail: IMAP< * 0 RECENT fetchmail: IMAP< A0023 OK Expunge completed. fetchmail: SMTP> QUIT fetchmail: SMTP< 221 smaug.XXXXX.com closing connection fetchmail: IMAP> A0024 IDLE fetchmail: IMAP< + idling
On 12.1.2010, at 4.40, Matt Doran wrote:
fetchmail: IMAP> A0006 IDLE fetchmail: IMAP< + idling fetchmail: IMAP< * 1 EXISTS fetchmail: IMAP> DONE fetchmail: IMAP< * 1 RECENT fetchmail: IMAP< A0006 OK Idle completed.
First mail is received, fetchmail starts downloading it.
fetchmail: IMAP> A0011 STORE 1 +FLAGS (\Seen \Deleted) fetchmail: IMAP< * 1 FETCH (FLAGS (\Deleted \Seen \Recent)) fetchmail: IMAP< * 2 EXISTS fetchmail: IMAP< * 2 RECENT fetchmail: IMAP< A0011 OK Store completed.
Second mail is received, Dovecot notifies fetchmail about it.
fetchmail: IMAP> A0013 IDLE fetchmail: IMAP< + idling
Fetchmail is buggy and ignores EXISTS events if they arrive during non-IDLE commands.
On Tue, 12 Jan 2010 16:21:17 +0200 Timo Sirainen <tss@iki.fi> articulated:
On 12.1.2010, at 4.40, Matt Doran wrote:
fetchmail: IMAP> A0006 IDLE fetchmail: IMAP< + idling fetchmail: IMAP< * 1 EXISTS fetchmail: IMAP> DONE fetchmail: IMAP< * 1 RECENT fetchmail: IMAP< A0006 OK Idle completed.
First mail is received, fetchmail starts downloading it.
fetchmail: IMAP> A0011 STORE 1 +FLAGS (\Seen \Deleted) fetchmail: IMAP< * 1 FETCH (FLAGS (\Deleted \Seen \Recent)) fetchmail: IMAP< * 2 EXISTS fetchmail: IMAP< * 2 RECENT fetchmail: IMAP< A0011 OK Store completed.
Second mail is received, Dovecot notifies fetchmail about it.
fetchmail: IMAP> A0013 IDLE fetchmail: IMAP< + idling
Fetchmail is buggy and ignores EXISTS events if they arrive during non-IDLE commands.
Out of curiosity, has this been reported to the Fetchmail developer(s)?
-- Jerry gesbbb@yahoo.com
Jerry wrote:
On Tue, 12 Jan 2010 16:21:17 +0200 Timo Sirainen <tss@iki.fi> articulated:
On 12.1.2010, at 4.40, Matt Doran wrote:
fetchmail: IMAP> A0006 IDLE fetchmail: IMAP< + idling fetchmail: IMAP< * 1 EXISTS fetchmail: IMAP> DONE fetchmail: IMAP< * 1 RECENT fetchmail: IMAP< A0006 OK Idle completed.
First mail is received, fetchmail starts downloading it.
fetchmail: IMAP> A0011 STORE 1 +FLAGS (\Seen \Deleted) fetchmail: IMAP< * 1 FETCH (FLAGS (\Deleted \Seen \Recent)) fetchmail: IMAP< * 2 EXISTS fetchmail: IMAP< * 2 RECENT fetchmail: IMAP< A0011 OK Store completed.
Second mail is received, Dovecot notifies fetchmail about it.
fetchmail: IMAP> A0013 IDLE fetchmail: IMAP< + idling
Fetchmail is buggy and ignores EXISTS events if they arrive during non-IDLE commands.
Out of curiosity, has this been reported to the Fetchmail developer(s)?
I haven't reported this to the fetchmail developers, but I will now that I've confirmed it's their bug.
Thanks Timo for identifying fetchmail protocol error.
Thanks, Matt
Matt Doran wrote:
Jerry wrote:
On Tue, 12 Jan 2010 16:21:17 +0200 Timo Sirainen <tss@iki.fi> articulated:
On 12.1.2010, at 4.40, Matt Doran wrote:
fetchmail: IMAP> A0006 IDLE fetchmail: IMAP< + idling fetchmail: IMAP< * 1 EXISTS fetchmail: IMAP> DONE fetchmail: IMAP< * 1 RECENT fetchmail: IMAP< A0006 OK Idle completed.
First mail is received, fetchmail starts downloading it.
fetchmail: IMAP> A0011 STORE 1 +FLAGS (\Seen \Deleted) fetchmail: IMAP< * 1 FETCH (FLAGS (\Deleted \Seen \Recent)) fetchmail: IMAP< * 2 EXISTS fetchmail: IMAP< * 2 RECENT fetchmail: IMAP< A0011 OK Store completed.
Second mail is received, Dovecot notifies fetchmail about it.
fetchmail: IMAP> A0013 IDLE fetchmail: IMAP< + idling
Fetchmail is buggy and ignores EXISTS events if they arrive during non-IDLE commands.
Out of curiosity, has this been reported to the Fetchmail developer(s)?
I haven't reported this to the fetchmail developers, but I will now that I've confirmed it's their bug.
For those interested, I've raised this on the fetchmail list here:
https://lists.berlios.de/pipermail/fetchmail-users/2010-January/002183.html
Regards, Matt
I haven't reported this to the fetchmail developers, but I will now that I've confirmed it's their bug.
For those interested, I've raised this on the fetchmail list here:
https://lists.berlios.de/pipermail/fetchmail-users/2010-January/002183.html
With the help of Timo and the fetchmail devs, this issue has now been fixed and will be included in fetchmail 6.3.14. See the post to fetchmail list:
https://lists.berlios.de/pipermail/fetchmail-users/2010-January/002238.html
Thanks, Matt
- Matt Doran [2010-01-12 13:40]:
Hi guys,
Thanks for the great product. We've used dovecot for ages as our internal mail server and it works great!
Let me second that.
I've recently started using fetchmail 6.3.9 (with IDLE enabled) to download mail from our ISP (Pair networks). The ISP is running Dovecot 1.1.16. I am unable to get the info about the dovecot config at this time.
The IDLE support in fetchmail allows us to deliver mail near instantaneously without the need to poll (which is what we did previously using POP3).
Oh, this is cool.
However I've noticed an issue where if 2 mails are delivered in quick succession fetchmail will only download the first email, and the second will not download. If I then send in another test email this triggers the download of 2 emails (the original that wasn't downloaded and the test email).
Now I'm wondering whether the issue lies with Dovecot (e.g. a timing issue), or is it fetchmail that isn't implementing the IDLE/download properly.
This is a timing issue, yes, but the IMAP server does what it's supposed to do - when it sees the first message arrive, it notifies fetchmail about it. Fetchmail immediately ends IDLE session by sending DONE and starts fetching that one message. If DONE wasn't sent, the server would issue another response notifying you about the second message, but it doesn't get a chance to do so. Please try this: login to server and enter these commands (to get encrypted connection without using STARTLS you can use command "openssl s_client -connect mail.XXXX.com:993"):
. login <username> <password> . select inbox . idle
Now try send some messages and observe what happens.
When you're done, send these commands to the server
done . logout
Here's what Dovecot sent to me when idling, I sent 5 messages very quickly:
- 1 EXISTS
- 2 EXISTS
- 3 EXISTS
- 5 EXISTS
If I'd terminate the IDLE session after the first line, I won't receive the other lines. So, I'd have to check for new messages myself or start IDLE session again and wait for yet another message to arrive. Then Dovecot would tell me about all new messages and I could go on and fetch them.
I've attached the output of a fetchmail session showing this problem in action (I've added some annotations to this file starting with
). The sequence of events are:
- Start fetchmail with IDLE enabled
- Send 2 emails in quick succession.
- Dovecot notifies of the new message
- Fetchmail downloads the message
- Fetchmail initiates a new IDLE
- Then nothing more is delivered. :(
- I then send another email, which triggers the 2 to download.
I don't know enough about IMAP to understand whether the problem lies with Dovecot or Fetchmail. Hopefully an IMAP expert will be able to see from the attached IMAP session.
Not being an expert, I tried to provide an explanaition of my understanding om IDLE. So, in your case it's fetchmail where logic could be improved.
-- -- Kirill Miazine <km@krot.org>
participants (4)
-
Jerry
-
Kirill Miazine
-
Matt Doran
-
Timo Sirainen