Bug 259151 - Moving/copying messages to folders causes redownload of the entire folder [Exchange server]
Summary: Moving/copying messages to folders causes redownload of the entire folder [Ex...
Status: RESOLVED FIXED
Alias: None
Product: Akonadi
Classification: Frameworks and Libraries
Component: IMAP resource (show other bugs)
Version: 1.4.80
Platform: Compiled Sources Linux
: NOR major
Target Milestone: ---
Assignee: Kevin Ottens
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-12-07 18:48 UTC by Thiago Macieira
Modified: 2011-08-03 10:07 UTC (History)
4 users (show)

See Also:
Latest Commit:
Version Fixed In:
Sentry Crash Report:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Thiago Macieira 2010-12-07 18:48:06 UTC
Version:           1.4.80 (using Devel) 
OS:                Linux

If I copy or move an email to a different folder from KMail2 on my Exchange 2010 server (no UIDPLUS support), the IMAP resource proceeds to redownload everything in that folder. There appears to be some faulty logic in kdepim/runtime/resources/imap/retrieveitemstask.cpp in RetrieveItemsTask::onFinalSelectDone.

If I apply the following patch to that file:
-    kDebug(5327) << "UIDNEXT check failed, refetching mailbox";
+    kDebug(5327) << "UIDNEXT check failed (old UIDNEXT =" << oldNextUid
+                 << "but current UIDNEXT =" << nextUid << "), refetching mailbox";

I see in my debug output:

akonadi_imap_resource_0(12064)/kdepimlibs (kimap) RetrieveItemsTask::onFinalSelectDone: UIDNEXT check failed (old UIDNEXT = 3012 but current UIDNEXT = 3013 ), refetching mailbox

The commands conversation with the server that was logged, relating to that mailbox is:

[last SELECT before the copy]
C: A000727 SELECT "INBOX/~done/_other"
S: * 2762 EXISTS
S: * 0 RECENT
S: * FLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )
S: * OK Permanent flags [ PERMANENTFLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )  ]
S: * OK Is the first unseen message [ UNSEEN 2762  ]
S: * OK UIDVALIDITY value [ UIDVALIDITY 969  ]
S: * OK The next unique identifier value [ UIDNEXT 3012  ]
S: A000727 OK SELECT completed. [ READ-WRITE  ]

[the copy]
C: A000008 UID COPY 30037 "INBOX/~done/_other"
S: A000008 OK COPY completed.
C: A000009 UID STORE 30037 +FLAGS (\Deleted)
S: * 7 FETCH ( FLAGS (\Seen \Deleted) )
S: A000009 OK STORE completed.
C: A000010 SELECT "INBOX/~done/_other"
S: * 2763 EXISTS
S: * 1 RECENT
S: * FLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )
S: * OK Permanent flags [ PERMANENTFLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )  ]
S: * OK Is the first unseen message [ UNSEEN 2762  ]
S: * OK UIDVALIDITY value [ UIDVALIDITY 969  ]
S: * OK The next unique identifier value [ UIDNEXT 3013  ]
S: A000010 OK SELECT completed. [ READ-WRITE  ]
C: A000011 UID SEARCH HEADER Message-ID <2D4CD7082D79B34AACB04EE0C7414656180A2B8040@NOK-EUMSG-03.mgdnok.nokia.com>
S: * SEARCH 3012
S: A000011 OK SEARCH completed.

[when syncing, just after the copy]
C: A000130 SELECT "INBOX/~done/_other"
S: * 2763 EXISTS
S: * 0 RECENT
S: * FLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )
S: * OK Permanent flags [ PERMANENTFLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )  ]
S: * OK Is the first unseen message [ UNSEEN 2762  ]
S: * OK UIDVALIDITY value [ UIDVALIDITY 969  ]
S: * OK The next unique identifier value [ UIDNEXT 3013  ]
S: A000130 OK SELECT completed. [ READ-WRITE  ]
C: A000131 EXPUNGE
S: A000131 OK EXPUNGE completed.
C: A000132 SELECT "INBOX/~done/_other"
S: * 2763 EXISTS
S: * 0 RECENT
S: * FLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )
S: * OK Permanent flags [ PERMANENTFLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )  ]
S: * OK Is the first unseen message [ UNSEEN 2762  ]
S: * OK UIDVALIDITY value [ UIDVALIDITY 969  ]
S: * OK The next unique identifier value [ UIDNEXT 3013  ]
S: A000132 OK SELECT completed. [ READ-WRITE  ]

It's during the last section that the debug message is printed.

Reproducible: Always




$ akonadiserver --version
Akonadi 1.4.80 (revision: d0502b1)
kdepim revision 1204307
OS: Linux (i686) release 2.6.35.2-server-1mnb
Compiler: gcc
Comment 1 Thiago Macieira 2010-12-07 18:51:59 UTC
Taking the liberty of setting this to Major, as it makes Akonadi very hard to use for people with servers without UIDPLUS (Exchange 2005, 2007, 2010).
Comment 2 András Manţia 2010-12-07 19:46:06 UTC
Fixed in r1204522.
Comment 3 Thiago Macieira 2010-12-08 11:53:58 UTC
Sorry, this still happens if more than one email is moved.

INBOX = 14 emails
INBOX/processed = 1 email

Everything is synced up, kmail2 is idle.

Last SELECT to INBOX/processed:
C: A000072 SELECT "INBOX/processed"
S: * 1 EXISTS
S: * 0 RECENT
S: * FLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )
S: * OK Permanent flags [ PERMANENTFLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )  ]
S: * OK UIDVALIDITY value [ UIDVALIDITY 1074  ]
S: * OK The next unique identifier value [ UIDNEXT 8555  ]
S: A000072 OK SELECT completed. [ READ-WRITE  ]

Move 2 emails from INBOX to INBOX/processed:
C: A000522 UID COPY 30082 "INBOX/processed"
S: A000522 OK COPY completed.
C: A000523 UID STORE 30082 +FLAGS (\Deleted)
S: * 12 FETCH ( FLAGS (\Seen \Deleted) )
S: A000523 OK STORE completed.
C: A000524 SELECT "INBOX/processed"
S: * 2 EXISTS
S: * 1 RECENT
S: * FLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )
S: * OK Permanent flags [ PERMANENTFLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )  ]
S: * OK UIDVALIDITY value [ UIDVALIDITY 1074  ]
S: * OK The next unique identifier value [ UIDNEXT 8556  ]
S: A000524 OK SELECT completed. [ READ-WRITE  ]
C: A000525 UID SEARCH HEADER Message-ID <201012081039.oB8AdJgL005803@mgw-sa01.nokia.com>
S: * SEARCH 8555
S: A000525 OK SEARCH completed.
C: A000526 SELECT "INBOX"
S: * 14 EXISTS
S: * 0 RECENT
S: * FLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )
S: * OK Permanent flags [ PERMANENTFLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )  ]
S: * OK Is the first unseen message [ UNSEEN 14  ]
S: * OK UIDVALIDITY value [ UIDVALIDITY 553  ]
S: * OK The next unique identifier value [ UIDNEXT 30085  ]
S: A000526 OK SELECT completed. [ READ-WRITE  ]
C: A000527 UID COPY 30083 "INBOX/processed"
S: A000527 OK COPY completed.
C: A000528 UID STORE 30083 +FLAGS (\Deleted)
S: * 13 FETCH ( FLAGS (\Seen \Deleted) )
S: A000528 OK STORE completed.
C: A000529 SELECT "INBOX/processed"
S: * 3 EXISTS
S: * 1 RECENT
S: * FLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )
S: * OK Permanent flags [ PERMANENTFLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )  ]
S: * OK UIDVALIDITY value [ UIDVALIDITY 1074  ]
S: * OK The next unique identifier value [ UIDNEXT 8557  ]
S: A000529 OK SELECT completed. [ READ-WRITE  ]
C: A000530 UID SEARCH HEADER Message-ID <201012081030.oB8AUQIZ026905@mgw-sa02.nokia.com>
S: * SEARCH 8553 8556
S: A000530 OK SEARCH completed.

Now synchronise INBOX/processed.
C: A000005 SELECT "INBOX/processed"
S: * 3 EXISTS
S: * 0 RECENT
S: * FLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )
S: * OK Permanent flags [ PERMANENTFLAGS ( \Seen \Answered \Flagged \Deleted \Draft $MDNSent )  ]
S: * OK UIDVALIDITY value [ UIDVALIDITY 1074  ]
S: * OK The next unique identifier value [ UIDNEXT 8557  ]
S: A000005 OK SELECT completed. [ READ-WRITE  ]

The agent prints:
akonadi_imap_resource_0(30643)/kdepimlibs (kimap) RetrieveItemsTask::triggerExpunge: "INBOX/processed"
akonadi_imap_resource_0(30643)/kdepimlibs (kimap) RetrieveItemsTask::onFinalSelectDone: UIDNEXT check failed (old UIDNEXT = 8556 but current UIDNEXT = 8557 ), refetching mailbox
akonadi_imap_resource_0(30643)/kdepimlibs (kimap) RetrieveCollectionMetadataTask::doStart: "/processed"

C: A000006 FETCH 1:3 (RFC822.SIZE INTERNALDATE BODY.PEEK[] FLAGS UID)
[...]
Comment 4 Thiago Macieira 2010-12-08 11:55:06 UTC
Note: one message was a copy of the other, that's why they have the same message-id, but the problem happens with two different messages.
Comment 5 Thiago Macieira 2010-12-08 15:19:38 UTC
Actually, come to think of it, I think the entire code is bogus. There's never a good reason to redownload the entire mailbox as long as the UIDVALIDITY remains the same.

The RFC says (2.3.1.1):
   [...] Unique identifiers
   are assigned in a strictly ascending fashion in the mailbox; [...]

   The unique identifier of a message MUST NOT change during the
   session, and SHOULD NOT change between sessions.  Any change of
   unique identifiers between sessions MUST be detectable using the
   UIDVALIDITY mechanism discussed below.
[...]
         1) Unique identifiers MUST be strictly ascending in the
            mailbox at all times. [...]

It looks to me like the code is checking the wrong parameter. The only valid reason for redownloading everything is a change in UIDVALIDITY. As long as the UIDVALIDITY remains the same, the client should simply download any UIDs it did not know about.
Comment 6 Allen Winter 2011-04-11 16:16:49 UTC
adding to showstoppers
Comment 7 Volker Krause 2011-04-16 19:19:12 UTC
Some observations from researching this:
- the UIDNEXT check will fail if the message-id is non-unique and the server does not support UIDPLUS (see MoveItemTask::onSearchDone()).
- the UIDNEXT check is necessary to catch the case of an equal amount of mails removed and added while we were not looking, the simple check for the message count is not enough for that (the complete download is obviously a bug though)
Comment 8 Volker Krause 2011-04-16 20:05:10 UTC
See https://git.reviewboard.kde.org/r/101142/ for a possible fix.
Comment 9 Volker Krause 2011-04-21 17:28:31 UTC
Git commit 6adf3ac1bf26662d9e81fa43aced445ecb659d4f by Volker Krause.
Committed on 21/04/2011 at 11:50.
Pushed by vkrause into branch 'master'.

Try to recover from UIDNEXT mismatch.

In case the IMAP resource ends up with an mismatch in current and last seen
UIDNEXT values, it tries to recover from that with a full re-download. With
online IMAP that's not too bad, but for the offline case this can be a huge
problem. This patch tries to do the recovery in a less drastic way, given
some conditions are met.

The assumption is that this case can happen because of an equal amount of
emails being added and deleted while we were not looking. Then the message
count check passes (we still have the same amount locally and remotely),
but the UIDNEXT check fails. Given UIDs are strictly ascending, the
maximum amount of changed messages is (newUidnext - oldUidnext). So,
instead of downloading everything, we now only download that many messages,
since download is done by sequence number, we are guaranteed to get the
newest ones and thus we cover all new messages. Deletion of the old ones is
done by the subsequent flag fetch step, just as in the normal case.

Thiago's problem shown in bug 259151 is slightly different, there we do the
same modification locally and remotely but fail to obtain the new UID due
to the server not supporting UIDPLUS and the message-id being non-unique.
However, this should work with the above approach as well.

BUG: 259151
REVIEW: 101142

M  +11   -1    resources/imap/retrieveitemstask.cpp     
M  +35   -0    resources/imap/tests/testretrieveitemstask.cpp     

http://commits.kde.org/kdepim-runtime/6adf3ac1bf26662d9e81fa43aced445ecb659d4f