MBOX-Line: From kmansoft at gmail.com  Wed Mar 25 09:17:36 2015
To: imap-protocol@u.washington.edu
From: Kostya Vasilyev <kmansoft@gmail.com>
Date: Fri Jun  8 12:34:54 2018
Subject: [Imap-protocol] Gmail flags issue, timing-sensitive
In-Reply-To: <CABa8R6t01i4CMumftDbTdY_xC7WYWLCmh7__Qg+zrsw8dZxHwA@mail.gmail.com>
References: <CAN7dqjCYRb2sbOZS49hiqgrSsfKFTzyT-b5fKHm0U4mBGvDRzA@mail.gmail.com>
	<CABa8R6t01i4CMumftDbTdY_xC7WYWLCmh7__Qg+zrsw8dZxHwA@mail.gmail.com>
Message-ID: <CAN7dqjAxtu=k65vF-gshYYiEdMVeJ_j_ZruB2RLQRHTxouRckA@mail.gmail.com>

Thank you Brandon.

Any way for me or other mail app developers to keep up on how it goes from
there?

Scenario involving IDLE -- what I saved for later in my original message --
looks like this:

Worker connection doing +\Seen:
01:45:58.791: [IMAP.4580] Sending: kman12 UID STORE 196235 +FLAGS (\Seen)
01:45:59.442: [IMAP_RAW.4580] Data is <98>:
01:45:59.442: * 20885 FETCH (FLAGS (\Seen) UID 196235)
01:45:59.442: * 20885 FETCH (UID 196235 FLAGS ())
01:45:59.442: kman12 OK Success

Separate IDLE connection (or conceivably, different device), no \Seen:

01:45:59.977: [IMAP.4572] Data is <37>:
01:45:59.977: * 20885 FETCH (UID 196235 FLAGS ())

Worker connection again:

01:46:05.046: [IMAP.4580] Sending: kman15 UID STORE 196235 +FLAGS
(\Answered)

IDLE  connection again, while above command is still executing: no \Seen
and no \Answered. That's the only data ever received there. So it only get
data that's obsolete, and then nothing more on that message:

01:46:05.890: [IMAP.4572] Data is <34>:
01:46:05.890: * 20885 FETCH (UID 196235 FLAGS ()

Worker connection, command finally done, obsolete state of flags as well:

01:46:05.896: [IMAP_RAW.4580] Data is <108>:
01:46:05.896: * 20885 FETCH (FLAGS (\Answered \Seen) UID 196235)
01:46:05.896: * 20885 FETCH (UID 196235 FLAGS ())
01:46:05.896: kman15 OK Success

And as a sanity check, same issue is also exhibited in Trojita (Linux
desktop).

1 - removing "star" from a message, message in the UI stays "starred":

18:15:27.666 >>> y105 UID STORE 196275 -FLAGS (\Flagged)??
18:15:27.830 <<< y104 OK IDLE terminated (Success)??
18:15:28.254 <<< * 20916 FETCH (FLAGS (\Seen) MODSEQ (20734317) UID
196275)??
18:15:28.254 <<< * 20916 FETCH (UID 196275 MODSEQ (20734310) FLAGS
(\Flagged \Seen))??
18:15:28.260 <<< y105 OK Success??

2 - Opening a freshly received message (same scenario as my original
message), message in the UI stays unread:

18:16:31.950 >>> y109 UID STORE 196276 +FLAGS (\Seen)??
18:16:31.950 >>> y110 UID FETCH 196276 (BODY.PEEK[1])??
18:16:32.652 <<< * 20917 FETCH (FLAGS (\Seen) MODSEQ (20734373) UID
196276)??
18:16:32.652 <<< * 20917 FETCH (UID 196276 MODSEQ (20734328) FLAGS ())??
18:16:32.657 <<< y109 OK Success??
18:16:32.657 Imap::Mailbox::UpdateFlagsTask Completed
18:16:32.663 <<< * 20917 FETCH (UID 196276 MODSEQ (20734328) BODY[1]
{13060}??PGRpdj6aPC9kaXY+PGRpdj48ZGl2PjxkaXYgc3R5bGU9ImNvbG9yOmJsYWNrOyI+PGRpdiBzdHls??ZT0iY29sb3I6YmxhY2s7Ij48cCBzdHlsZT0iY29sb3I6YmxhY2s7Zm9udC1za
(+ 12924 more bytes)
18:16:32.663 <<< y110 OK Success??

Trojita uses CONDSTORE, so it should be possible to filter responses and
take the one with the largest MODSEQ, but...

... I've already tried that in my app, and it doesn't help with wrong data
on IDLE connections, and also doesn't help when you have multiple devices.

-- K


2015-03-25 18:43 GMT+03:00 Brandon Long <blong@google.com>:

> I'll file a bug
> On Mar 25, 2015 7:55 AM, "Kostya Vasilyev" <kmansoft@gmail.com> 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: kmanical@gmail.com
>> 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: <1633401427283535@web7m.yandex.ru>
>> 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
>> Imap-protocol@u.washington.edu
>> http://mailman13.u.washington.edu/mailman/listinfo/imap-protocol
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman13.u.washington.edu/pipermail/imap-protocol/attachments/20150325/7784766c/attachment.html>
