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