Re: [Imap-protocol] Gmail flags issue, timing-sensitive

I'll file a bug
On Mar 25, 2015 7:55 AM, "Kostya Vasilyev" <[email protected]> wrote:

> Hi,
>
> I apologize for a Gmail specific message, but for lack of a better place...
>
> Recently I've started seeing strange stuff with message flags, the Gmail
> IMAP server returns out of date information on STORE +FLAGS and IDLE
> connections.
>
> There is a longer log below, but the the short of it is:
>
> 14:39:06.189: [IMAP.5455] Sending: kman10 UID STORE 86 +FLAGS (\Seen)
> {{{---}}}
> 14:39:06.490: [IMAP_RAW.5455] Data is <84>:
> 14:39:06.490: * 58 FETCH (FLAGS (\Seen) UID 86)
> 14:39:06.490: * 58 FETCH (UID 86 FLAGS ())
> 14:39:06.490: kman10 OK Success
>
> I understand that the second line is an unsolicited response, and that it
> would represent the message getting changed back to unread on another
> connection, except...
>
> There is no other connection here, and anyway, both responses are in the
> same data packet which is too fast to send a change made by another
> connection if there was one.
>
> I've spent a fair amount of time tweaking my IMAP commands trying to make
> it go away, and came to conclude that:
>
> - The time from receiving the message to the STORE command has to be very
> short, a matter of several seconds.
>
> - Seems to happen more often with the larger messages (> 5-10 K of message
> text).
>
> - Seems to happen more often when doing a partial (as opposed to full)
> text fetch during mail sync.
>
> The user sees a new, unread, message and goes to read it immediately,
> boom, it's still marked unread.
>
> If I wait a minute or so before opening the message (which is what
> triggers the STORE +\Seen), the issue doesn't happen and I get this:
>
> 16:35:13.874 * 65 FETCH (FLAGS (\Seen) UID 99)
> 16:35:13.874 * 65 FETCH (UID 99 FLAGS (\Seen))
>
> Again, an unsolicited response (valid, but redundant), but now it actually
> reflects the just changed message flags.
>
> It gets more interesting when there are IDLE connections, which then also
> receive outdated (no \Seen) message flags about ten seconds after the STORE
> +\Seen, but I'll save it for later (I do have logs for that too).
>
> A more detailed log:
>
> The STORE +\Seen here is done ~three seconds after initial fetch (and very
> soon after the message got into the account).
>
> No IDLE, no CONDSTORE, very basic commands.
>
> ### Sync
>
> Initial connect and auth (omitted)
> Select INBOX (omitted)
>
> 14:39:02.329: [IMAP.5455] Sending: kman5 UID SEARCH RETURN (ALL) UNSEEN
> UNDELETED
> {{{---}}}
> 14:39:02.376: [IMAP_RAW.5455] Data is <73>:
> 14:39:02.376: * ESEARCH (TAG "kman5") UID ALL 86
> 14:39:02.376: kman5 OK SEARCH completed (Success)
>
> Get flags and UIDs
>
> 14:39:02.378: [IMAP.5455] Sending: kman6 FETCH 34:58 (UID FLAGS)
> {{{---}}}
> 14:39:02.421: [IMAP_RAW.5455] Data is <772>:
> 14:39:02.421: * 34 FETCH (UID 53 FLAGS (\Seen))
> 14:39:02.421: * 35 FETCH (UID 54 FLAGS (\Seen))
> ...
> 14:39:02.426: [IMAP_RAW.5455] Data is <116>:
> 14:39:02.426: 56 FETCH (UID 75 FLAGS (\Seen))
> 14:39:02.426: * 57 FETCH (UID 85 FLAGS (\Seen))
> 14:39:02.426: * 58 FETCH (UID 86 FLAGS ())
> 14:39:02.426: kman6 OK Success
>
> Get BODYSTRUCTURE and headers
>
> 14:39:02.481: [IMAP.5455] Sending: kman7 FETCH 58 (UID
> BODY.PEEK[HEADER.FIELDS (DATE MESSAGE-ID LIST-ID SUBJECT FROM REPLY-TO TO
> CC BCC X-PRIORITY RESENT-FROM REFERENCES DISPOSITION-NOTIFICATION-TO)]
> BODYSTRUCTURE RFC822.SIZE INTERNALDATE)
> {{{---}}}
> 14:39:02.525: [IMAP_RAW.5455] Data is <514>:
> 14:39:02.525: * 58 FETCH (UID 86 RFC822.SIZE 11273 INTERNALDATE
> "25-Mar-2015 11:38:56 +0000" BODYSTRUCTURE ("TEXT" "HTML" ("CHARSET"
> "utf-8") NIL NIL "BASE64" 8934 115 NIL NIL NIL) BODY[HEADER.FIELDS (DATE
> MESSAGE-ID LIST-ID SUBJECT FROM REPLY-TO TO CC BCC X-PRIORITY RESENT-FROM
> REFERENCES DISPOSITION-NOTIFICATION-TO)] {307}
> 14:39:02.525: From: =?koi8-r?B?68/O09TBztTJziD3wdPJzNjF1w==?= <....>
> 14:39:02.525: To: [email protected]
> 14:39:02.525: Subject:
> =?koi8-r?B?RndkOiBbS29zdHlhJ3MgbGl0dGxlIGFwcHNdIFBsZWFzZSBtb2RlcmF0ZTogIu3PySDQ0s/H0sHNzdkg?=
> 14:39:02.525:  =?koi
> 14:39:02.536: [IMAP_RAW.5455] Data is <107>:
> 14:39:02.536: 8-r?B?KFJVKSI=?=
> 14:39:02.536: Message-Id: <[email protected]>
> 14:39:02.536: Date: Wed, 25 Mar 2015 14:38:55 +0300
> 14:39:02.536:
> 14:39:02.537: [IMAP_RAW.5455] Data is <21>:
> 14:39:02.537: )
> 14:39:02.537: kman7 OK Success
>
> Get text (partial)
>
> 14:39:02.552: [IMAP.5455] Sending: kman8 FETCH 58 (UID
> BODY.PEEK[1]<0.5120>)
> {{{---}}}
> 14:39:02.595: [IMAP_RAW.5455] Data is <1339>:
> 14:39:02.595: * 58 FETCH (UID 86 BODY[1]<0> {5120}
> ...
> 14:39:02.600: [IMAP_RAW.5455] Data is <21>:
> 14:39:02.600: )
> 14:39:02.600: kman8 OK Success
>
> ### User opened message, need to mark read
>
> Checking if connection is alive
>
> 14:39:06.063: [IMAP.5455] Sending: kman9 NOOP
> {{{---}}}
> 14:39:06.113: [IMAP_RAW.5455] Data is <18>:
> 14:39:06.113: kman9 OK Success
>
> Setting \Seen
>
> 14:39:06.189: [IMAP.5455] Sending: kman10 UID STORE 86 +FLAGS (\Seen)
> {{{---}}}
> 14:39:06.490: [IMAP_RAW.5455] Data is <84>:
> 14:39:06.490: * 58 FETCH (FLAGS (\Seen) UID 86)
> 14:39:06.490: * 58 FETCH (UID 86 FLAGS ())
> 14:39:06.490: kman10 OK Success
>
> The unsolicited response lacks the just set "\Seen", it's old data.
>
> -- K
>
>
>
> _______________________________________________
> Imap-protocol mailing list
> [email protected]
> http://mailman13.u.washington.edu/mailman/listinfo/imap-protocol
>

_______________________________________________
Imap-protocol mailing list
[email protected]
http://mailman13.u.washington.edu/mailman/listinfo/imap-protocol