[dev] Horde_Imap_Client_Base::vanished issues
Michael M Slusarz
slusarz at horde.org
Sun Mar 4 09:01:11 UTC 2012
Quoting Michael J Rubinsky <mrubinsk at horde.org>:
> Quoting Michael J Rubinsky <mrubinsk at horde.org>:
>
>> I've noticed an issue with performing a vanished search. It first
>> happened after the recent API changes were pulled, but I can't
>> definitively say the problem did not exist before this.
>>
>> The issue is, that sometimes calling $imap->vanished($mbox,
>> $lastKnownModSeq) seems to return ALL UIDs that have ever vanished
>> from the mailbox. I first noticed this while working on syncing
>> email via ActiveSync and the server started trying to send over
>> 100k DELETE commands to the client. I've run the following test
>> code in Horde's phpshell:
>>
>> $imap = $registry->mail->imapOb();
>> $mbox = new Horde_Imap_Client_Mailbox('INBOX');
>> // Output so I can track the values as I go.
>> $status = $imap->status($mbox,
>> Horde_Imap_Client::STATUS_HIGHESTMODSEQ |
>> Horde_Imap_Client::STATUS_UIDVALIDITY |
>> Horde_Imap_Client::STATUS_UIDNEXT);
>> var_dump($status);
>>
>> // 445126 is last HIGHTESTMODSEQ value output above.
>> var_dump($imap->vanished($mbox, 445126));
>>
>> At some point, the VANISHED response stops showing the UIDs since
>> the MODSEQ and just returns ALL of them. I can't figure out what
>> causes this to happen. Any pointers/ideas?
>>
>> The IMAP log of one instance when all UIDs were returned. I believe
>> there is also another fetch going on here as well:
>
> <snip old log>
>
> This is a portion of the IMAP log at the first point the VANISHED
> request starts returning all of the UIDs. Earlier portions of the
> log consist mostly of STATUS requests with the resulting
> HIGHTESTMODSEQ == 445892. All previous VANISHED requests that I saw
> after expunging my INBOX worked correctly. The only thing that I
> know of that happened in the INBOX since the last good VANISH at
> this point was the addition of new email - I did not even expunge
> any messages, so none at all should be VANISHED.
>
>
> C: 85 STATUS INBOX (UIDNEXT UIDVALIDITY HIGHESTMODSEQ)
> S: * STATUS "INBOX" (UIDNEXT 103770 UIDVALIDITY 1292457115
> HIGHESTMODSEQ 445892)
> S: 85 OK Status completed.
> C: 86 STATUS INBOX (UIDNEXT UIDVALIDITY HIGHESTMODSEQ)
> S: * STATUS "INBOX" (UIDNEXT 103772 UIDVALIDITY 1292457115
> HIGHESTMODSEQ 445895)
> S: 86 OK Status completed.
> C: 87 EXAMINE INBOX (QRESYNC (1292457115 445892
> 88312,89464,89506,92040,92403,94207,94653,96579,97547,98895,99471,99627,99633,99635:99636,99853,100111,100156,101342,101430,101562,101568,102041,102044,102147,102153,102166,102210,102224,102905,103042,103048,103105,103135,103140:103143,103181,103185,103189,103196,103198,103206,103208:103209,103212,103214,103220:103221,103223,103227:103228,103230,103233:103234,103237,103240,103242,103246,103266,103269,103274:103275,103277:103278,103285,103331,103339,103343,103380,103382:103383,103391,103394,103398,103448,103450,103453,103456:103457,103463:103464,103468,103477,103479,103489:103490,103492:103493,103501,103509,103511,103515,103521,103523:103525,103528,103533,103535:103536,103538,103543,103546,103549,103552,103555,103585,103628,103642,103671,103674,103676,103711,103756,103760,103764:103769))
> S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $Junk $NotJunk
> $Forwarded Test_Tso test_one JunkRecorded)
> S: * OK [PERMANENTFLAGS ()] Read-only mailbox.
> S: * 125 EXISTS
> S: * 7 RECENT
> S: * OK [UNSEEN 119] First unseen.
> S: * OK [UIDVALIDITY 1292457115] UIDs valid
> S: * OK [UIDNEXT 103772] Predicted next UID
> S: * OK [HIGHESTMODSEQ 445895] Highest
> S: 87 OK [READ-ONLY] Select completed.
>>> Expired search results from cache (mailbox: INBOX)
> C: 88 UID SEARCH RETURN (ALL COUNT) ALL
> S: * ESEARCH (TAG "88") UID ALL
> 88312,89464,89506,92040,92403,94207,94653,96579,97547,98895,99471,99627,99633,99635:99636,99853,100111,100156,101342,101430,101562,101568,102041,102044,102147,102153,102166,102210,102224,102905,103042,103048,103105,103135,103140:103143,103181,103185,103189,103196,103198,103206,103208:103209,103212,103214,103220:103221,103223,103227:103228,103230,103233:103234,103237,103240,103242,103246,103266,103269,103274:103275,103277:103278,103285,103331,103339,103343,103380,103382:103383,103391,103394,103398,103448,103450,103453,103456:103457,103463:103464,103468,103477,103479,103489:103490,103492:103493,103501,103509,103511,103515,103521,103523:103525,103528,103533,103535:103536,103538,103543,103546,103549,103552,103555,103585,103628,103642,103671,103674,103676,103711,103756,103760,103764:103771 COUNT
> 125
> S: 88 OK Search completed (0.000 secs).
>>> Saved search results to cache (mailbox: INBOX; id:
>>> e711e5dc23f3f88a379cdd1ed363c2ed)
> C: 89 UID FETCH 1:* () (CHANGEDSINCE 445892)
> S: * 124 FETCH (UID 103770 MODSEQ (445894))
> S: * 125 FETCH (UID 103771 MODSEQ (445895))
> S: 89 OK Fetch completed.
>>> CACHE: Retrieved messages (mailbox: INBOX; UIDs:
>>> 88312,89464,89506,92040,92403,94207,94653,96579,97547,98895,99471,99627,99633,99635:99636,99853,100111,100156,101342,101430,101562,101568,102041,102044,102147,102153,102166,102210,102224,102905,103042,103048,103105,103135,103140:103143,103181,103185,103189,103196,103198,103206,103208:103209,103212,103214,103220:103221,103223,103227:103228,103230,103233:103234,103237,103240,103242,103246,103266,103269,103274:103275,103277:103278,103285,103331,103339,103343,103380,103382:103383,103391,103394,103398,103448,103450,103453,103456:103457,103463:103464,103468,103477,103479,103489:103490,103492:103493,103501,103509,103511,103515,103521,103523:103525,103528,103533,103535:103536,103538,103543,103546,103549,103552,103555,103585,103628,103642,103671,103674,103676,103711,103756,103760,103764:103769)
> C: 90 UID FETCH 103770:103771 (FLAGS) (CHANGEDSINCE 445892)
> S: * 124 FETCH (UID 103770 FLAGS (\Recent) MODSEQ (445894))
> S: * 125 FETCH (UID 103771 FLAGS (\Recent) MODSEQ (445895))
> S: 90 OK Fetch completed.
>>> CACHE: Stored messages (mailbox: INBOX; UIDs: 103770:103771)
> C: 91 UID FETCH 1:* () (VANISHED CHANGEDSINCE 445892)
> S: * VANISHED (EARLIER)
> 1:88311,88313:89463,89465:89505,89507:92039,92041:92402,92404:94206,94208:94652,94654:96578,96580:97546,97548:98894,98896:99470,99472:99626,99628:99632,99634,99637:99852,99854:100110,100112:100155,100157:101341,101343:101429,101431:101561,101563:101567,101569:102040,102042:102043,102045:102146,102148:102152,102154:102165,102167:102209,102211:102223,102225:102904,102906:103041,103043:103047,103049:103104,103106:103134,103136:103139,103144:103180,103182:103184,103186:103188,103190:103195,103197,103199:103205,103207,103210:103211,103213,103215:103219,103222,103224:103226,103229,103231:103232,103235:103236,103238:103239,103241,103243:103245,103247:103265,103267:103268,103270:103273,103276,103279:103284,103286:103330,103332:103338,103340:103342,103344:103379,103381,103384:103390,103392:103393,103395:103397,103399:103447,103449,103451:103452,103454:103455,103458:103462,103465:103467,103469:103476,103478,103480:103488,103491,103494:103500,103502:103508,103510,103512:103514,103516:10
> 3520,103
> 522,103526:103527,103529:103532,103534,103537,103539:103542,103544:103545,103547:103548,103550:103551,103553:103554,103556:103584,103586:103627,103629:103641,103643:103670,103672:103673,103675,103677:103710,103712:103755,103757:103759,103761:103763
> S: * 124 FETCH (UID 103770 MODSEQ (445894))
> S: * 125 FETCH (UID 103771 MODSEQ (445895))
> S: 91 OK Fetch completed.
Your IMAP server is badly broken then. RFC 5162 [3.2]:
The VANISHED UID FETCH modifier instructs the server to report those
messages from the UID set parameter that have been expunged and whose
associated mod-sequence is larger than the specified mod-sequence.
That is, the client requests to be informed of messages from the
specified set that were expunged since the specified mod-sequence.
So this command:
C: 91 UID FETCH 1:* () (VANISHED CHANGEDSINCE 445892)
is asking the server to return the list of all UIDs that have been
expunge between MODSEQ 445892 -> 445895. If the server is returning
the list of all UIDs that have been expunged in the history of the
mailbox (i.e. since MODSEQ 1), that behavior is flat-out incorrect.
I can verify that this does not happen on my server (Dovecot 2.1.1).
With a current MODSEQ of 24672, I see this result:
1 uid fetch 1:* () (VANISHED CHANGEDSINCE 24600)
* VANISHED (EARLIER)
31696,31742,31744:31747,31748:31750,31751:31760,31762:31765
[...]
1 OK Fetch completed.
I can verify that it *looks* like your IMAP server is instead
interpreting the command like this:
100 uid fetch 1:* () (VANISHED CHANGEDSINCE 1)
* VANISHED (EARLIER)
1:27620,27622:30096,30100:31131,31133:31319,31323:31474,31476:31540,31542:31577,31579:31580,31582:31645,31647:31651,31653:31661,31663:31697,31699:31709,31711:31713,31715:31723,31725:31733,31735:31760,31762:31765
[...]
1 OK Fetch completed.
michael
___________________________________
Michael Slusarz [slusarz at horde.org]
More information about the dev
mailing list