mailing list archives

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman13.u.washington.edu/pipermail/imap-protocol/attachments/20150325/969d61c3/attachment.html>

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/eed8b143/attachment.html>

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>

[ With a new apology to list members who'd prefer not seeing any Gmail
specific stuff ]

Here is another case of Gmail and flags being weird.

Hoping it gets fixed too.

A message already has \Answered and \Seen, trying to add \Flagged.

Folder was selected with CONDSTORE.

New state reported without \Answered first (wrong), then with it (right),
and the MODSEQ is the same (which is also wrong).

21:54:31.077 [IMAP.5800] Sending: kman25 UID STORE 196290 +FLAGS (\Flagged)
21:54:31.672  [IMAP_RAW.5800] Data is <167>:
21:54:31.672  * 20927 FETCH (FLAGS (\Flagged \Seen) MODSEQ (20736711) UID
196290)
21:54:31.672 * 20927 FETCH (UID 196290 MODSEQ (20736711) FLAGS (\Answered
\Flagged \Seen))
21:54:31.672  kman25 OK Success

-- K

2015-03-25 19:17 GMT+03:00 Kostya Vasilyev <kmansoft@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.
>>>
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman13.u.washington.edu/pipermail/imap-protocol/attachments/20150325/59abd08e/attachment.html>

Quoting Kostya Vasilyev <kmansoft@gmail.com>:

> New state reported without \Answered first (wrong), then with it (right),
> and the MODSEQ is the same (which is also wrong).
>
> 21:54:31.077 [IMAP.5800] Sending: kman25 UID STORE 196290 +FLAGS (\Flagged)
> 21:54:31.672  [IMAP_RAW.5800] Data is <167>:
> 21:54:31.672  * 20927 FETCH (FLAGS (\Flagged \Seen) MODSEQ (20736711) UID
> 196290)
> 21:54:31.672 * 20927 FETCH (UID 196290 MODSEQ (20736711) FLAGS (\Answered
> \Flagged \Seen))
> 21:54:31.672  kman25 OK Success

This is inefficient.  But it is perfectly acceptable IMAP.

michael

Hi Michael,

On 25/03/2015 19:21, Michael M Slusarz wrote:
> Quoting Kostya Vasilyev <kmansoft@gmail.com>:
>
>> New state reported without \Answered first (wrong), then with it 
>> (right),
>> and the MODSEQ is the same (which is also wrong).
>>
>> 21:54:31.077 [IMAP.5800] Sending: kman25 UID STORE 196290 +FLAGS 
>> (\Flagged)
>> 21:54:31.672  [IMAP_RAW.5800] Data is <167>:
>> 21:54:31.672  * 20927 FETCH (FLAGS (\Flagged \Seen) MODSEQ (20736711) 
>> UID
>> 196290)
>> 21:54:31.672 * 20927 FETCH (UID 196290 MODSEQ (20736711) FLAGS 
>> (\Answered
>> \Flagged \Seen))
>> 21:54:31.672  kman25 OK Success
> This is inefficient.  But it is perfectly acceptable IMAP.
I think this is not correct, because the two responses should use 2 
different MODSEQs, if they return different set of flags.

Michael M Slusarz writes:
> This is inefficient.  But it is perfectly acceptable IMAP.

It's not acceptable: the modseq should change whenever the flags do.

Arnt

2015-03-25 22:30 GMT+03:00 Alexey Melnikov <alexey.melnikov@isode.com>:

> Hi Michael,
>
> On 25/03/2015 19:21, Michael M Slusarz wrote:
>
>> Quoting Kostya Vasilyev <kmansoft@gmail.com>:
>>
>>  New state reported without \Answered first (wrong), then with it (right),
>>> and the MODSEQ is the same (which is also wrong).
>>>
>>> 21:54:31.077 [IMAP.5800] Sending: kman25 UID STORE 196290 +FLAGS
>>> (\Flagged)
>>> 21:54:31.672  [IMAP_RAW.5800] Data is <167>:
>>> 21:54:31.672  * 20927 FETCH (FLAGS (\Flagged \Seen) MODSEQ (20736711) UID
>>> 196290)
>>> 21:54:31.672 * 20927 FETCH (UID 196290 MODSEQ (20736711) FLAGS (\Answered
>>> \Flagged \Seen))
>>> 21:54:31.672  kman25 OK Success
>>>
>> This is inefficient.  But it is perfectly acceptable IMAP.
>>
> I think this is not correct, because the two responses should use 2
> different MODSEQs, if they return different set of flags.


Yes, that's what I meant by "which is also wrong".

Every change to message flags should bump the message's MODSEQ value.

Now in this case, there was no actual change *between* the two lines in the
response, it's the server reporting wrong flags values first and correct
values next (the message already had \Answered and \Seen prior to my adding
\Flagged)...

...and the real issue is new flags reported without \Answered first, then
with it, but...

... the identical MODSEQ values make it harder to work around this real
issue.

-- K
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman13.u.washington.edu/pipermail/imap-protocol/attachments/20150325/4b24c035/attachment.html>

Quoting Arnt Gulbrandsen <arnt@gulbrandsen.priv.no>:

> Michael M Slusarz writes:
>> This is inefficient.  But it is perfectly acceptable IMAP.
>
> It's not acceptable: the modseq should change whenever the flags do.

It sounds like people are agreeing that:

a001 SOME COMMAND
* 1 FETCH (FLAGS (\Foo) MODSEQ (2) UID 1)
[snapshot 1]
* 1 FETCH (FLAGS (\Foo \Bar) MODSEQ (2) UID 1)
[snapshot 2]
a001 OK
[snapshot 3]

...means that the flags on message 1 supposedly "changed" twice.  In  
other words, people are updating internal modseq caches at [snapshot  
1] and [snapshot 2].

I don't see it that way.  I view this series of commands as telling me  
"what is the mailbox state as of snapshot 3".  I don't care about  
snapshot 1 or snapshot 2.  I only care that at the end of the command,  
I look at this and say that MODSEQ 2 is associated with flags (\Foo  
\Bar) since that is what the server reported.  I don't care about  
intermediate transport steps the server took to inform the client of  
this; I only care about the final state.

(I would agree that the Gmail example provided is incorrect *if* the  
FETCH responses were received as unsolicited responses in an IDLE  
command.  But that wasn't the context of the example provided.)

For example, I have definitely seen this before:

a002 UID STORE [...]
* 1 FETCH (MODSEQ (2))
* 1 FETCH (FLAGS (\Foo \Bar) MODSEQ (2) UID 1)
a002 OK

A local synchronized mailbox would be in an invalid state if you  
updated it after the first FETCH.  This response may be broken from a  
protocol standpoint, but it happens and I want/have to be able to deal  
with it.

I think my disconnect with the majority is looking at client commands  
from a transactional perspective rather than each individual FETCH  
component. I'm only interested in committing the changes if the client  
command is fully completed.  If an IMAP session terminates before the  
command is complete, I would much rather toss that data to be on the  
safe side, especially since there is no guarantee that the cached data  
is correct when dealing with servers that may not be 100% protocol  
correct.  Not to mention there can be horrible performance issues with  
a non-transactional approach, depending on the number of FETCH  
responses involved and how the backend client cache storage is  
configured - e.g. if that cache storage is not local.

So just me again confusing strict semantics with implementation  
details.  I shall crawl back into the hole from whence I came and not  
bother this thread any more.

michael

On Thu, Mar 26, 2015, at 06:39 AM, Kostya Vasilyev wrote:
> Yes, that's what I meant by "which is also wrong".
>
> Every change to message flags should bump the message's MODSEQ value.
>
> Now in this case, there was no actual change *between* the two lines
> in the response, it's the server reporting wrong flags values first
> and correct values next (the message already had \Answered and \Seen
> prior to my adding \Flagged)...
>
> ...and the real issue is new flags reported without \Answered first,
> then with it, but...
>
> ... the identical MODSEQ values make it harder to work around this
> real issue.

I'm pretty sure this takes it from "annoying but legitimate" to
"strictly incorrect". That first line should not have the latest
MODSEQ value if it doesn't contain the flags that were set at the time
of that MODSEQ.

I spent a lot of work getting the Cyrus internals right for this
years ago, because there were bugs with the way Cyrus handled
per-user \Seen and modseqs, as well as around expunges. It was a lot
of work, but a half-functioning implementation means that clients
can't rely on anything.

Bron.

--
Bron Gondwana brong@fastmail.fm


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman13.u.washington.edu/pipermail/imap-protocol/attachments/20150326/aa05bf6f/attachment.html>

Michael M Slusarz answers me:
> It sounds like people are agreeing that:
>
> a001 SOME COMMAND
> * 1 FETCH (FLAGS (\Foo) MODSEQ (2) UID 1)
> [snapshot 1]
> * 1 FETCH (FLAGS (\Foo \Bar) MODSEQ (2) UID 1)
> [snapshot 2]
> a001 OK
> [snapshot 3]
>
> ...means that the flags on message 1 supposedly "changed" 
> twice.

No. The MODSEQ clause quite plainly says it changed once. The FLAGS clause 
says twice. The two parts contradict each other.

> ... I 
> don't care about ...

The server has to send coherent protocol precisely so that clients can take 
liberties and don't have to care about everything all the time.

Arnt

( below )

2015-03-25 23:56 GMT+03:00 Michael M Slusarz <slusarz@curecanti.org>:

> Quoting Arnt Gulbrandsen <arnt@gulbrandsen.priv.no>:
>
>  Michael M Slusarz writes:
>>
>>> This is inefficient.  But it is perfectly acceptable IMAP.
>>>
>>
>> It's not acceptable: the modseq should change whenever the flags do.
>>
>
> It sounds like people are agreeing that:
>
> a001 SOME COMMAND
> * 1 FETCH (FLAGS (\Foo) MODSEQ (2) UID 1)
> [snapshot 1]
> * 1 FETCH (FLAGS (\Foo \Bar) MODSEQ (2) UID 1)
> [snapshot 2]
> a001 OK
> [snapshot 3]
>
> ...means that the flags on message 1 supposedly "changed" twice.  In other
> words, people are updating internal modseq caches at [snapshot 1] and
> [snapshot 2].
>
> I don't see it that way.  I view this series of commands as telling me
> "what is the mailbox state as of snapshot 3".  I don't care about snapshot
> 1 or snapshot 2.  I only care that at the end of the command, I look at
> this and say that MODSEQ 2 is associated with flags (\Foo \Bar) since that
> is what the server reported.  I don't care about intermediate transport
> steps the server took to inform the client of this; I only care about the
> final state.
>

RFC 4551 says:

An IMAP server that supports this extension MUST associate a positive
   unsigned 64-bit value called a modification sequence (mod-sequence)
   with every IMAP message.  This is an opaque value updated by the
   server whenever a metadata item is modified.  The server MUST
   guarantee that each STORE command performed on the same mailbox
   (including simultaneous stores to different metadata items from
   different connections) will get a different mod-sequence value.


Since a MODSEQ is associated with each message, there is no valid way (that
I can see) for a message to have different flags and identical MODSEQ value.


> (I would agree that the Gmail example provided is incorrect *if* the FETCH
> responses were received as unsolicited responses in an IDLE command.  But
> that wasn't the context of the example provided.)
>

The most recent one was in the context of a STORE *and* it only works that
way with regards to \Answered and $Forwarded.

For \Seen (original example), it works the other way, new state first, old
state next.

Far too many "special cases" to view it as harmless, cute, and intended
implementation details.


>
> For example, I have definitely seen this before:
>
> a002 UID STORE [...]
> * 1 FETCH (MODSEQ (2))
> * 1 FETCH (FLAGS (\Foo \Bar) MODSEQ (2) UID 1)
> a002 OK
>




>
> A local synchronized mailbox would be in an invalid state if you updated
> it after the first FETCH.  This response may be broken from a protocol
> standpoint, but it happens and I want/have to be able to deal with it.
>
> I think my disconnect with the majority is looking at client commands from
> a transactional perspective rather than each individual FETCH component.
> I'm only interested in committing the changes if the client command is
> fully completed.


That's fine if you use CONDSTORE and have MODSEQ values to pick the most
current one, but if you don't... From my original message:

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

No MODSEQ values here to choose one or the other (SELECT didn't have
CONDSTORE, turned off while investigating).

In web mail and on later syncs, the message is \Seen, so the *first*
response line is correct, and the *second* one is not, and by the time you
get to "command fully completed", you've got wrong state.



> If an IMAP session terminates before the command is complete, I would much
> rather toss that data to be on the safe side, especially since there is no
> guarantee that the cached data is correct when dealing with servers that
> may not be 100% protocol correct.


Agree, but none of my examples had a sudden connection loss.


> Not to mention there can be horrible performance issues with a
> non-transactional approach, depending on the number of FETCH responses
> involved and how the backend client cache storage is configured - e.g. if
> that cache storage is not local.
>

I never said anything updating the database and the UI on every line
received from an IMAP server :)

But I'll take your statement further -- for me personally, IMAP's view of
clients as state machines ready for pretty much any data at pretty much any
time -- seems strange, impractical, and I can't quite wrap my brain around
it. Maybe it's because I never learned LISP.


>
> So just me again confusing strict semantics with implementation details.
> I shall crawl back into the hole from whence I came and not bother this
> thread any more.


But sometimes one gets "reminders" that software is not made of strict
semantics, it's made of implementation details, and sometimes those details
misbehave.

I shall crawl back into my cave too now and keep my fingers crossed for the
Gmail IMAP team to (eventually) fix what I've reported :)

-- K
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman13.u.washington.edu/pipermail/imap-protocol/attachments/20150326/9c5db890/attachment.html>

On 25 Mar 2015 20:59, "Michael M Slusarz" <slusarz@curecanti.org> wrote:
> (I would agree that the Gmail example provided is incorrect *if* the
FETCH responses were received as unsolicited responses in an IDLE command.
But that wasn't the context of the example provided.)
>

There's nothing special about IDLE, it's just a convenient long running
command. The responses were unsolicited responses, just the same. Really,
the only magic about IDLE is that the syntax implies a long wait before the
DONE. In principle, any command with a literal could be used, except
servers reasonably assume the literal will follow shortly, plus you'd never
quite know whether you'd get expunges.

> I think my disconnect with the majority is looking at client commands
from a transactional perspective rather than each individual FETCH
component.

No, I think it's thinking that some responses are more unsolicited than
others.

Dave.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman13.u.washington.edu/pipermail/imap-protocol/attachments/20150326/c6e18718/attachment.html>