Bug 392440 - UID consistency error
Summary: UID consistency error
Status: RESOLVED UPSTREAM
Alias: None
Product: trojita
Classification: Unmaintained
Component: IMAP (show other bugs)
Version: git
Platform: Other Linux
: NOR normal
Target Milestone: ---
Assignee: Trojita default assignee
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-03-28 08:05 UTC by Erik Quaeghebeur
Modified: 2023-04-13 20:15 UTC (History)
1 user (show)

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

Attachments
Add an attachment

Note You need to log in before you can comment on or make changes to this bug.
Description Erik Quaeghebeur 2018-03-28 08:05:32 UTC 
While on a flaky connection that disappeared/appeared intermittently, I started getting the following error when selecting one of my folders on a FastMail account (~Cyrus):

“The IMAP server sent us a reply which we could not parse. This might either mean that there's a bug in Trojitá's code, or that the IMAP server you are connected to is broken. Please report this as a bug anyway. Here are the details:

MailboxException: FETCH response: UID consistency error for message #3 -- expected UID 27637, got UID 27643 FETCH 3 ( FLAGS "\Seen $X-ME-Annot-2" MODSEQ "742122" UID "27643")”

More detailed:

09:51:49.054 >>> y144 SELECT INBOX (QRESYNC (1164751602 742116 (3 27637)))␍␊
09:51:49.156 <<< * OK [CLOSED] Ok␍␊
09:51:49.156 <<< * 8 EXISTS␍␊
09:51:49.156 <<< * 0 RECENT␍␊
09:51:49.156 <<< * FLAGS (\Answered \Flagged \Draft \Deleted \Seen […]
09:51:49.156 <<< * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen […]
09:51:49.156 <<< * OK [UNSEEN 5] Ok␍␊
09:51:49.157 <<< * OK [UIDVALIDITY 1164751602] Ok␍␊
09:51:49.157 <<< * OK [UIDNEXT 27660] Ok␍␊
09:51:49.157 <<< * OK [HIGHESTMODSEQ 742361] Ok␍␊
09:51:49.157 <<< * OK [URLMECH INTERNAL] Ok␍␊
09:51:49.157 <<< * OK [ANNOTATIONS 65536] Ok␍␊
09:51:49.157 <<< * VANISHED (EARLIER) 27647:27650,27653:27656␍␊
09:51:49.157 <<< * 3 FETCH (FLAGS (\Seen $X-ME-Annot-2) UID 27643 MODSEQ (742122))␍␊
09:51:49.157 <<< * 4 FETCH (FLAGS (\Seen $X-ME-Annot-2) UID 27651 MODSEQ (742221))␍␊
09:51:49.157 <<< * 5 FETCH (FLAGS ($X-ME-Annot-2) UID 27652 MODSEQ (742226))␍␊
09:51:49.157 <<< * 6 FETCH (FLAGS ($X-ME-Annot-2 $IsMailingList) UID 27657 MODSEQ (742347))␍␊
09:51:49.157 <<< * 7 FETCH (FLAGS (\Seen $X-ME-Annot-2) UID 27658 MODSEQ (742349))␍␊
09:51:49.157 <<< * 8 FETCH (FLAGS (\Seen $X-ME-Annot-2) UID 27659 MODSEQ (742360))␍␊
09:51:49.157 <<< y144 OK [READ-WRITE] Completed␍␊
09:51:49.157 conn Opening mailbox...
09:51:49.159  Warning: unhandled untagged OK with a response code
09:51:49.159 ThreadingMsgListModel for INBOX ThreadingMsgListModel::wantThreading: THREAD contains info about UID 27646 (or higher), mailbox has 27643
09:51:49.160 ThreadingMsgListModel for INBOX 4 messages have 0 UID
09:51:49.160  Warning: unhandled untagged OK with a response code
09:51:49.160  Warning: unhandled untagged OK with a response code
09:51:49.161 Imap::Mailbox::KeepMailboxOpenTask attached to INBOX Failed: The connection is being killed for unspecified reason
09:51:49.161 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING INBOX Failed: The connection is being killed for unspecified reason
09:51:49.161 *** Connection killed.
09:51:49.161 MailboxException FETCH response: UID consistency error for message #3 -- expected UID 27637, got UID 27643␍␊FETCH 3 ( FLAGS "\Seen $X-ME-Annot-2" MODSEQ "742122" UID "27643")␊␊

If I look at the folder with another client (that does not have a cache), I see that indeed there is no message with UID 27637.

I need this account to work, so I am going to rename the cache file (hoping this will clear things up), but keep it for a while for later tests, if needed.
Comment 1 Erik Quaeghebeur 2018-11-13 14:33:49 UTC 
It happened again today:

15:23:11.1691  ThreadingMsgListModel for INBOX ThreadingMsgListModel::wantThreading: THREAD contains info about UID 30512 (or higher), mailbox has 30512
15:23:11.1711  [task] Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_WAIT_FOR_CONN INBOX Activated
15:23:11.1721  [task] conn Opening mailbox...
15:23:11.1781  [sync] Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING INBOX Synchronizing mailbox
15:23:11.1861  >>>  y11 SELECT INBOX (QRESYNC (1164751602 953107 (3,5 30494,30512)))
15:23:11.2811  <<<  * 5 EXISTS
15:23:11.2811  <<<  * 0 RECENT
15:23:11.2811  <<<  * FLAGS (\Answered \Flagged \Draft \Deleted \Seen […])
15:23:11.2811  <<<  * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen […] \*)] Ok
15:23:11.2811  <<<  * OK [UNSEEN 4] Ok
15:23:11.2821  <<<  * OK [UIDVALIDITY 1164751602] Ok
15:23:11.2821  <<<  * OK [UIDNEXT 30515] Ok
15:23:11.2821  <<<  * OK [HIGHESTMODSEQ 953323] Ok
15:23:11.2821  <<<  * OK [URLMECH INTERNAL] Ok
15:23:11.2821  <<<  * OK [ANNOTATIONS 65536] Ok
15:23:11.2821  <<<  * 4 FETCH (FLAGS ($X-ME-Annot-2 $IsMailingList) UID 30513 MODSEQ (953162))
15:23:11.2821  <<<  * 5 FETCH (FLAGS ($X-ME-Annot-2) UID 30514 MODSEQ (953322))
15:23:11.2821  <<<  y11 OK [READ-WRITE] Completed
15:23:11.2831   Warning: unhandled untagged OK with a response code
15:23:11.2831   Warning: unhandled untagged OK with a response code
15:23:11.2831  [task] Imap::Mailbox::KeepMailboxOpenTask attached to INBOX Failed: The connection is being killed for unspecified reason
15:23:11.2831  [task] Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING INBOX Failed: The connection is being killed for unspecified reason
15:23:11.2831  >>>  *** Connection killed.
15:23:11.2831  [err] MailboxException FETCH response: UID consistency error for message #4 -- expected UID 30511, got UID 30513␍␊FETCH 4 ( FLAGS "$X-ME-Annot-2 $IsMailingList" MODSEQ "953162" UID "30513")

I guess this is an upstream (FastMail) issue. I'll point them to this bug report.
Comment 2 Erik Quaeghebeur 2020-09-13 10:10:58 UTC 
Still getting this issue, now on a mailbox folder with ‘delete after 31 days’-functionality. I'll check with the email provider again as well.

Message:

MailboxException: FETCH response: UID consistency error for message #651 -- expected UID 46311, got UID 46318 FETCH 651 ( FLAGS "\Seen $X-ME-Annot-2 $IsMailingList $SIGNED" MODSEQ "3103894" UID "46318")


From the log:

11:58:42.5313  ThreadingMsgListModel for Trash ThreadingMsgListModel::wantThreading: THREAD contains info about UID 46317 (or higher), mailbox has 46317
11:58:42.5313  ThreadingMsgListModel for Trash 294 messages have 0 UID
11:58:42.5313  >>>  DONE
11:58:42.6223  <<<  y10 OK Completed
11:58:42.6233  [task] Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_WAIT_FOR_CONN Trash Activated
11:58:42.6243  [task] conn Waiting for another mailbox...
11:58:42.6303  [sync] Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING Trash Synchronizing mailbox
11:58:42.6343  >>>  y11 SELECT Trash (QRESYNC (1164751602 3102859 (330,496,579,620,641,651,656,659 45985,46152,46237,46278,46299,46309,46314,46317)))
11:58:42.7243  <<<  * OK [CLOSED] Ok
11:58:42.7253  <<<  * 653 EXISTS
11:58:42.7253  <<<  * 0 RECENT
11:58:42.7253  <<<  * FLAGS (\Answered \Flagged \Draft \Deleted \Seen $X-ME-Annot-2 $IsMailingList $IsNotification $HasAttachment $HasTD $SIGNED jobs prive $ATTACHMENT werk ict $NotJunk onderzoek klacht admin onderwijs review $INVITATION sipta familie $IsTrusted presieved $AutoSent call $TODO)
11:58:42.7253  <<<  * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen $X-ME-Annot-2 $IsMailingList $IsNotification $HasAttachment $HasTD $SIGNED jobs prive $ATTACHMENT werk ict $NotJunk onderzoek klacht admin onderwijs review $INVITATION sipta familie $IsTrusted presieved $AutoSent call $TODO \*)] Ok
11:58:42.7253  <<<  * OK [UNSEEN 617] Ok
11:58:42.7253  <<<  * OK [UIDVALIDITY 1164751602] Ok
11:58:42.7253  <<<  * OK [UIDNEXT 46321] Ok
11:58:42.7263  <<<  * OK [HIGHESTMODSEQ 3104931] Ok
11:58:42.7263  <<<  * OK [URLMECH INTERNAL] Ok
11:58:42.7263  <<<  * OK [ANNOTATIONS 65536] Ok
11:58:42.7263  <<<  * VANISHED (EARLIER) 45637:45643,46204:46205
11:58:42.7263  <<<  * 651 FETCH (FLAGS (\Seen $X-ME-Annot-2 $IsMailingList $SIGNED) UID 46318 MODSEQ (3103894))
11:58:42.7263  <<<  * 652 FETCH (FLAGS (\Seen $X-ME-Annot-2 $HasAttachment $ATTACHMENT) UID 46319 MODSEQ (3104680))
11:58:42.7263  <<<  * 653 FETCH (FLAGS (\Seen $X-ME-Annot-2 $HasAttachment $ATTACHMENT) UID 46320 MODSEQ (3104682))
11:58:42.7263  <<<  y11 OK [READ-WRITE] Completed
11:58:42.7263  [task] conn Opening mailbox...
11:58:42.7283   Warning: unhandled untagged OK with a response code
11:58:42.7283   Warning: unhandled untagged OK with a response code
11:58:42.7283   Warning: unhandled untagged OK with a response code
11:58:42.7303  [task] Imap::Mailbox::KeepMailboxOpenTask attached to Trash Failed: The connection is being killed for unspecified reason
11:58:42.7303  [task] Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING Trash Failed: The connection is being killed for unspecified reason
11:58:42.7303  >>>  *** Connection killed.
11:58:42.7313  [err] MailboxException FETCH response: UID consistency error for message #651 -- expected UID 46311, got UID 46318␍␊FETCH 651 ( FLAGS "\Seen $X-ME-Annot-2 $IsMailingList $SIGNED" MODSEQ "3103894" UID "46318")
Comment 3 Bron Gondwana 2020-09-18 06:40:25 UTC 
If this is a but in the Cyrus IMAP QRESYNC code (which is definitely possible, very few clients use QRESYNC) then it's been present for about 10 years since I rewrote the data model for Cyrus 2.4.  It was also almost certainly worse before then.

I'm going to install Trojita on my own desktop and use it for a bit, see if I can get a re-creation of the problem on an account with serious telemetry turned on!
Comment 4 Erik Quaeghebeur 2020-09-18 07:14:34 UTC 
(In reply to Bron Gondwana from comment #3)
> I'm going to install Trojita on my own desktop and use it for a bit, see if
> I can get a re-creation of the problem on an account with serious telemetry
> turned on!
Thanks for your effort. I'd like to emphasize that this is currently only happening for Trash with auto-delete-after-31-days turned on.

To further approximate my situation, consider appending some messages to Trash with an internal date well different from the Date header, which should be well beyond the 31 days.
Comment 5 Bron Gondwana 2020-09-18 07:16:55 UTC 
(In reply to Erik Quaeghebeur from comment #4)
> (In reply to Bron Gondwana from comment #3)
> > I'm going to install Trojita on my own desktop and use it for a bit, see if
> > I can get a re-creation of the problem on an account with serious telemetry
> > turned on!
> Thanks for your effort. I'd like to emphasize that this is currently only
> happening for Trash with auto-delete-after-31-days turned on.
> 
> To further approximate my situation, consider appending some messages to
> Trash with an internal date well different from the Date header, which
> should be well beyond the 31 days.

Sounds good.  I might even set up a folder which gets lots of random emails appended and deleted randomly at high speed, which should allow any bugs to be found quickly!
Comment 6 Bron Gondwana 2020-10-14 12:21:11 UTC 
Weell.... what do you know:

2020-08-13T08:28:33-04:00 imap10 (notice) sloti10d1t16/imapnew[2607440]:  inefficient qresync (2896913 > 2883786) fastmail.fm!user.xxx.Trash
2020-09-12T16:27:44-04:00 imap10 (notice) sloti10d1t16/imapnew[2340095]:  inefficient qresync (3041269 > 3014441) fastmail.fm!user.xxx.Trash
2020-10-07T05:48:41-04:00 imap10 (notice) sloti10d1t16/imapnew[3996222]:  inefficient qresync (3240758 > 3102859) fastmail.fm!user.xxx.Trash

That looks suspiciously like it might align with the problem!  This is what happens when there qresync is against a state from before the last data that was cleaned up by an expunge.  Interesting.  This suggests there's a bug which is bumping the deletedmodseq value too high inside the cyrus index, which is leading to us falling back to the "report all gaps" algorithm, and THAT must be buggy!
Comment 7 Erik Quaeghebeur 2020-10-14 12:35:11 UTC 
(In reply to Bron Gondwana from comment #6)
> […]  This suggests there's a bug
> which is bumping the deletedmodseq value too high inside the cyrus index,
> which is leading to us falling back to the "report all gaps" algorithm, and
> THAT must be buggy!
Nice to hear that there might be a lead. I hope it doesn't lead to a wild-goose chase.