[Dovecot] New mail not appearing consistently in Outlook 2003

[Karl von Randow]

James Turnbull wrote:
> Karl von Randow wrote:
>> I will observe what is logged when I receive this message from the
>> mailing list (and CC'd to myself). Is there any guide or advice from
>> previous debugging-using-outlook-logs experience that would make my
>> bug reporting more valuable?
> 
> No specific advice.  I guess the obvious statement is to compare the
> logging for two messages - one that appeared and one that didn't. 

Here is a scenario that just occurred. This was for a newsletter list that
I'm subscribed to twice with two different email addresses that both receive
the same email shortly after each other.

The first message has a UID of 17706 in the logs and was received at
18:30:35 and the second a UID of 17707 and was received at 18:30:35.

My reading of the logs is that Outlook IDLEs then receives notification of
message 825. I then read message 824. Outlook IDLEs then receives
notification of message 828, Outlook fetches, result is UID 17707. We've
skipped messages 826 and 827. Message 827 is UID 17706 as above. Message 826
is the first message to this list from Kevin Bowling. Note I have asked
Outlook to download headers and bodies. With the caveat that I'm not versed
with the IMAP protocol!

Here are excerpts from the logs. Starting with an IDLE and the notification
of message 825. I will intersperse with comments of where I think important
activity is occurring.

IMAP: 18:26:28 [tx] gti7 IDLE
IMAP: 18:26:28 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:26:28 [rx] + idling
IMAP: 18:26:49 [tx] DONE
IMAP: 18:26:49 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:26:49 [rx] gti7 OK Idle completed.
IMAP: 18:26:49 [tx] fywj NOOP
IMAP: 18:26:49 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:26:49 [rx] * 825 EXISTS
IMAP: 18:26:49 [rx] * 10 RECENT
IMAP: 18:26:49 [rx] fywj OK NOOP completed.
IMAP: 18:26:49 [tx] jqqy IDLE
IMAP: 18:26:49 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:26:49 [rx] + idling
IMAP: 18:26:50 [tx] DONE
IMAP: 18:26:50 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:26:50 [rx] jqqy OK Idle completed.
IMAP: 18:26:50 [tx] 0uaw UID FETCH 119071:* (UID FLAGS RFC822.SIZE
BODY.PEEK[HEADER] INTERNALDATE)
IMAP: 18:26:50 [tx] dftr UID FETCH 17703 (UID FLAGS BODY.PEEK[]
INTERNALDATE)
IMAP: 18:26:50 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:26:50 [rx] * 825 FETCH (UID 17704 FLAGS (\Recent) RFC822.SIZE 6955
INTERNALDATE "26-Mar-2007 18:26:24 +1200" BODY[HEADER] {1282}
IMAP: 18:26:50 [rx] Buffer (literal) of length 1282
IMAP: 18:26:50 [rx] )
IMAP: 18:26:50 [rx] 0uaw OK Fetch completed.
IMAP: 18:26:50 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:26:50 [rx] * 824 FETCH (UID 17703 FLAGS (\Recent) INTERNALDATE
"26-Mar-2007 18:26:13 +1200" BODY[] {4962}
IMAP: 18:26:50 [rx] Buffer (literal) of length 3988
IMAP: 18:26:50 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:26:50 [rx] Buffer (literal) of length 974
IMAP: 18:26:50 [rx] )
IMAP: 18:26:50 [rx] dftr OK Fetch completed.
IMAP: 18:26:50 [tx] mls9 IDLE
IMAP: 18:26:50 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:26:50 [rx] + idling
IMAP: 18:27:26 [tx] DONE
IMAP: 18:27:26 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:26 [rx] mls9 OK Idle completed.
IMAP: 18:27:26 [tx] lsk6 UID FETCH 17704 (UID FLAGS BODY.PEEK[]
INTERNALDATE)
IMAP: 18:27:26 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:26 [rx] * 825 FETCH (UID 17704 FLAGS (\Recent) INTERNALDATE
"26-Mar-2007 18:26:24 +1200" BODY[] {6955}
IMAP: 18:27:26 [rx] Buffer (literal) of length 4000
IMAP: 18:27:26 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:26 [rx] Buffer (literal) of length 2955
IMAP: 18:27:26 [rx] )
IMAP: 18:27:27 [rx] lsk6 OK Fetch completed.
IMAP: 18:27:27 [tx] t5zm IDLE
IMAP: 18:27:27 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:27 [rx] + idling
IMAP: 18:27:27 [tx] DONE
IMAP: 18:27:27 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:27 [rx] t5zm OK Idle completed.
IMAP: 18:27:27 [tx] 6xct UID STORE 17704 +FLAGS (\Seen)
IMAP: 18:27:27 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:27 [rx] * 825 FETCH (UID 17704 FLAGS (\Seen \Recent))
IMAP: 18:27:27 [rx] 6xct OK Store completed.
IMAP: 18:27:27 [tx] 8vn8 IDLE
IMAP: 18:27:27 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:27 [rx] + idling
IMAP: 18:27:45 [tx] DONE
IMAP: 18:27:45 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:45 [rx] 8vn8 OK Idle completed.
IMAP: 18:27:45 [tx] gw2m UID STORE 17704 -FLAGS (\Seen)
IMAP: 18:27:45 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:45 [rx] * 825 FETCH (UID 17704 FLAGS (\Recent))
IMAP: 18:27:45 [rx] gw2m OK Store completed.
IMAP: 18:27:45 [tx] vcz2 IDLE
IMAP: 18:27:45 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:45 [rx] + idling
IMAP: 18:27:51 [tx] DONE
IMAP: 18:27:51 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:51 [rx] vcz2 OK Idle completed.
IMAP: 18:27:51 [tx] tx53 UID STORE 17703 +FLAGS (\Seen)
IMAP: 18:27:51 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:51 [rx] * 824 FETCH (UID 17703 FLAGS (\Seen \Recent))
IMAP: 18:27:51 [rx] tx53 OK Store completed.

Finished with 824 and 825. IDLE and then get notified of 828.

IMAP: 18:27:51 [tx] fajb IDLE
IMAP: 18:27:51 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:27:51 [rx] + idling
IMAP: 18:29:51 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:29:51 [rx] * OK Still here
IMAP: 18:30:52 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:30:52 [rx] * 828 EXISTS
IMAP: 18:30:52 [tx] DONE
IMAP: 18:30:52 [rx] * 13 RECENT
IMAP: 18:30:52 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:30:52 [rx] fajb OK Idle completed.
IMAP: 18:30:52 [tx] dkfx UID FETCH 119071:* (UID FLAGS RFC822.SIZE
BODY.PEEK[HEADER] INTERNALDATE)
IMAP: 18:30:52 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:30:52 [rx] * 828 FETCH (UID 17707 FLAGS (\Recent) RFC822.SIZE 29505
INTERNALDATE "26-Mar-2007 18:30:35 +1200" BODY[HEADER] {924}
IMAP: 18:30:52 [rx] Buffer (literal) of length 924
IMAP: 18:30:52 [rx] )
IMAP: 18:30:52 [rx] dkfx OK Fetch completed.
IMAP: 18:30:52 [tx] nf9h IDLE

The rest of the log from this session is idling and notification of message
829.

I then restart Outlook and it gets a list of all of the messages, sees the
missing messages and requests them:

IMAP: 18:53:27 [rx] * 823 FETCH (UID 17702 FLAGS (\Seen))
IMAP: 18:53:27 [rx] * 824 FETCH (UID 17703 FLAGS (\Seen))
IMAP: 18:53:27 [rx] * 825 FETCH (UID 17704 FLAGS ())
IMAP: 18:53:27 [rx] * 826 FETCH (UID 17705 FLAGS ())
IMAP: 18:53:27 [rx] * 827 FETCH (UID 17706 FLAGS ())
IMAP: 18:53:27 [rx] * 828 FETCH (UID 17707 FLAGS ())
IMAP: 18:53:27 [rx] * 829 FETCH (UID 17708 FLAGS (\Seen))
IMAP: 18:53:27 [rx] cous OK Fetch completed.
IMAP: 18:53:27 [tx] p946 UID FETCH 17701,17705:17706 (UID FLAGS RFC822.SIZE
BODY.PEEK[HEADER] INTERNALDATE)
IMAP: 18:53:27 [tx] 4i7s NOOP
IMAP: 18:53:27 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:53:27 [rx] * 822 FETCH (UID 17701 FLAGS () RFC822.SIZE 4460
INTERNALDATE "26-Mar-2007 18:25:11 +1200" BODY[HEADER] {2989}
IMAP: 18:53:27 [rx] Buffer (literal) of length 2989
IMAP: 18:53:27 [rx] )
IMAP: 18:53:27 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:53:27 [rx] * 826 FETCH (UID 17705 FLAGS () RFC822.SIZE 3321
INTERNALDATE "26-Mar-2007 18:30:33 +1200" BODY[HEADER] {2552}
IMAP: 18:53:27 [rx] Buffer (literal) of length 2552
IMAP: 18:53:27 [rx] )
IMAP: 18:53:28 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 18:53:28 [rx] * 827 FETCH (UID 17706 FLAGS () RFC822.SIZE 29502
INTERNALDATE "26-Mar-2007 18:30:35 +1200" BODY[HEADER] {929}
IMAP: 18:53:28 [rx] Buffer (literal) of length 929
IMAP: 18:53:28 [rx] )
Etc

Is my reading of this correct that Dovecot is not notifying Outlook of the
existence of some messages? Or should Outlook be looking for messages with
missing numbers and in which case Outlook requires a workaround?

There is a regular "new mail" checking thread which appears to check for new
mail in all of my other mail boxes. This appears to run every 5 minutes. It
ran at 18:26:49 through 18:27:27 and again at 18:31:53 through 18:32:42.

I hope this yields some information!

Kind regards,
Karl