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

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