645664 - Problematic CONDSTORE behaviour - multiple unnecessary full resyncs - requires bug 491445

Status: NEW

(MailNews Core :: Networking: IMAP, defect)

Description

[Adrien de Croy]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/534.16 (KHTML, like Gecko) Chrome/10.0.648.204 Safari/534.16
Build Identifier: 3.1.9

Testing new CONDSTORE extension implementation in our mail server.  Seeing very odd and counter-productive behaviour in TB 3.1.9 wrt CONDSTORE as follows:

Re-opening TB to a mailbox on a server that supports CONDSTORE if there is a new message in the INBOX, seeing the following commands.  The client had previously synced to version 36 of this mailbox (so 2 new messages)

C:<= 5 select "INBOX" (CONDSTORE)
S:=> * 1532 EXISTS
S:=> * 0 RECENT
S:=> * OK [UNSEEN 2]
S:=> * OK [UIDNEXT 1562]
S:=> * OK [UIDVALIDITY 1301299394]
S:=> * FLAGS (\Recent \Seen \Draft \Answered \Flagged \Deleted $Forwarded $MDNSent)
S:=> * OK [PERMANENTFLAGS (\Recent \Seen \Draft \Answered \Flagged \Deleted $Forwarded $MDNSent)]
S:=> * OK [HIGHESTMODSEQ 38]
S:=> 5 OK [READ-WRITE] SELECT command completed
C:<= 6 UID fetch 1:* (FLAGS) (CHANGEDSINCE 0)

This final Fetch is really problematic, it's a full resynch.  To make matters worse, after it got the 1532 untagged responses (with flags), it immediately issued

C:<= 7 UID fetch 1:* (FLAGS)

And got all the flags and UIDs immediately again.  The whole reason we implemented CONDSTORE was to make resynchs faster, but this behaviour makes it about twice as slow.

So far in testing, I see this problem happening any time a message is added to or deleted from a mailbox.  When only flags change, it seems to behave a bit better.

I've pored over the protocol logs and can't see anything the server may be doing wrong, but of course there's always that possibility.

We've seen other weirdness as well.  

If you open TB and it was on the trash folder when it closed, it shows the trash selected when it comes back up, but when it does a SELECT on the inbox, it doesn't send (CONDSTORE).










Reproducible: Always

Steps to Reproduce:
1. Add message to folder on server supporting CONDSTORE
2. Open TB to IMAP folder with new message
3. View debug logs, showing full fetches.


Expected Results:  
expect with a new message for no full resynch to be required, and just do the FETCH with the CHANGEDSINCE parameter from the last synch, not go back to CHANGEDSINCE 0.

Deletes are more problematic due to lack of stored EXPUNGE results (impossible to synch anyway since no UID in untagged EXPUNGE result - where's that IMAP extension?)

Comment 1

[Ludovic Hirlimann [:Usul]]

What server are you using ?

Comment 2

[Adrien de Croy]

Hi Ludovic

sorry, should have specified.

It's a dev build (internal) of WinGate 7, which we are the developers of.

I can make a build available if people need to test, although since the product is not yet released, that would need to be on a request basis.

Regards

Adrien

Comment 3

[Adrien de Croy]

just a bit more info.

From the logs, and checking various changes, I believe we can deduce that TB is making the decision about how to call FETCH after SELECT based on the EXISTS untagged response to SELECT.  This is the only thing that changes and causes it.

If the EXISTS value changes, I see the UID FETCH 1:* (FLAGS) (CHANGEDSINCE 0)

otherwise I see the CHANGEDSINCE with the previous max seq.

Comment 4

[Ludovic Hirlimann [:Usul]]

David might want an account to debug - if debug is needed.

Comment 5

[Adrien de Croy]

no problem.  He can email me for details?

Regards

Adrien

Comment 6

[Ludovic Hirlimann [:Usul]]

he will when/if he looks into it.

Comment 7

[David :Bienvenu]

Until we support the follow-on to CONDSTORE, QRESYNC, that closes the EXPUNGE hole, this is how this is going to work - see https://bugzilla.mozilla.org/show_bug.cgi?id=436151#c6

Comment 8

[Adrien de Croy]

OK.  I read a couple more RFCs on this.

I can see there's a big issue with EXPUNGE (always has been).  Makes you wonder what the point of CONDSTORE even is without addressing this.  Anyway... I guess it has some usefulness for resynching flags on mailboxes that don't really change (which is probably most except INBOX, Trash and Sent).

I also browsed the code on MXR.  There's only one place where CHANGEDSINCE is set (nsImapProtocol.cpp[4037]).  For us to receive a (CHANGEDSINCE 0) that means mFolderLastModSeq is being reset.  I can only see 2 places in code where this is set to 0, and that's in the constructor of the nsImapProtocol object, or an initialiser from a URL.  The code that does a full resynch doesn't even set CHANGEDSINCE.

So there could be some issue there. In any case it shouldn't need to do 2 fetch 1:* to resynch, one should be enough.

I'm also not 100% convinced the heuristic about whether a full resynch is required will catch all cases, or maybe covers more cases that required.

Using things like the number of messages in the mailbox suffers from problems like APPEND STORE \Deleted EXPUNGE, where the number of messages doesn't change, but the mailbox does.  In such cases you'd expect to see UIDNEXT and HIGHESTMODSEQ change.  I see you're looking at these as well, but also looking in your store of flags to count how many are flagged for delete.

Reason I'm going here, is I also see issues when a message is marked for delete but not expunged (by another client when test client is off-line).  When the test client logs in, does a FETCH ... (CHANGEDSINCE xx), it gets the flags for the changed message with \Deleted on it, but then does a full resync as well and sometimes its own EXPUNGE (might be local client config issue there).

Cheers

Adrien

Comment 9

[Adrien de Croy]

p.s.

another option to find the "holes" created by expunge would be a binary search.

In order to work as an IMAP client with EXPUNGE reporting only the index not UID, a client must maintain a map of index <-> UID.

The store map can be tested for consistency against the IMAP server.  E.g. 

tag FETCH X (UID)
will return 
* X (UID Y)

if X and Y still match your cache, you know that up to X in the index, nothing has been expunged.  A binary search then can find the largest value of X where this is true, then do a partial resynch from that point only.  On a large mailbox with changes only really happening at the end (e.g. INBOX) this could save a heap of traffic.

I think there are issues with QRESYNC as well, since it requires clients with large mailboxes to send large protocol messages (including every known UID).  UIDs in a mailbox become sparse with time, so it gets difficult to send a large set of UIDs efficiently.  This is compounded with the fact that normally upload bandwidth for a client (where bandwidth is an issue) is a fraction of available download bandwidth.

Comment 10

[Nikolay Shopik]

I remeber when condstore patched, it was working and not doing UID FETCH 1:* (FLAGS). Some time later it was stoped working for me, probably at time I move to mark-as-delete model. As for now it doesn't seems realy mater if you are using MAD model or not, just keep doing UID FETCH all messages.

Comment 11

[Wayne Mery (:wsmwk)]

This is mitigated by bug 912216

Comment 12

[Ludovic Hirlimann [:Usul]]

Removing myslef on all the bugs I'm cced on. Please NI me if you need something on MailNews Core bugs from me.