1123094 - Folder contents may not be correct with CONDSTORE enabled (if EXPUNGE is not notified via IDLE when CONDSTORE support is used, msgDBHdr of EXPUNGEd mail won't be removed by Tb)

Status: NEW

(MailNews Core :: Networking: IMAP, defect)

Description

[rocketraman]

Attachment: imap-with-condstore.log

Setup:

Create a new blank profile in Thunderbird. Create a new e-mail account on my Cyrus Imapd server.

The client is Thunderbird 31.3.0 running on Linux 3.18.2 64 bit (Fedora 21).

The imapd server info is:

name       : Cyrus IMAPD
version    : v2.4.17-Fedora-RPM-2.4.17-7.el7 d1df8aff 2012-12-01
os         : Linux
os-version : 3.16.5-x86_64-linode46

The server supports CONDSTORE and IDLE, and Thunderbird is configured to use both, with only one modification to the IMAP account settings from the default: the account is configured with one connection to the server.


REPRODUCTION RECIPE
===================

See attached imap-with-condstore.log. There are lines in the log "---- MARK xx ----" which correspond with the reproduction recipe below:

1. Open Inbox
imap log MARK 01

2. Deliver two messages into the Inbox (thunderbird shows them correctly)
imap log MARK 02

3. Navigate away from Inbox and back:
imap log MARK 03

4. Break IDLE connection to server by restarting the server (obviously this could be caused by other network issues)
imap log MARK 04

5. Delete and expunge two messages in the Inbox via a second non-Thunderbird client  (thunderbird does not show deletions yet)
imap log MARK 05

6. Deliver two more messages into the Inbox (thunderbird does not show new messages yet)
imap log MARK 06

7. Navigate away from Inbox and back. New messages are shown (correct), but deleted messages are still shown as well (ERROR).
imap log MARK 07

8. Navigate away from the Inbox and back. Deleted messages still show.
imap log MARK 08

9. Compact the Inbox. Deleted messages still show.
imap log MARK 09

10. Work offline. Deleted messages still show.
imap log MARK 10

11. Work online.  Deleted messages still show.
imap log MARK 11

12. Navigate away from the folder and back.
imap log MARK 12

13. Repair folder. Deleted messages are now finally gone.
imap log MARK 13

Steps #8 through #13 should obviously be unnecessary.


WITH CONDSTORE DISABLED
=======================

To compare with the behavior with Thunderbird CONDSTORE disabled, change configuration setting "mail.server.default.use_condstore" to false and restart. The imap log attached is imap-without-condstore.log:

1. Open Inbox
imap log MARK 01

2. Deliver two messages into the Inbox (thunderbird shows them correctly)
imap log MARK 02

3. Navigate away from Inbox and back:
imap log MARK 03

4. Break IDLE connection to server by restarting the server (obviously this could be caused by other network issues)
imap log MARK 04

5. Delete and expunge two messages in the Inbox via a second non-Thunderbird client  (thunderbird does not show deletions yet)
imap log MARK 05

6. Deliver two more messages into the Inbox (thunderbird does not show new messages yet)
imap log MARK 06

7. Navigate away from Inbox and back:
imap log MARK 07

Now Thunderbird correctly displays only the new messages.

Comment 1

[rocketraman]

Attachment: imap-without-condstore.log

Comment 2

[rocketraman]

NOTE: I'm sorry, it looks like my MARK's did not find their way into my logs, I guess because Thunderbird had the log file open. If there is another way to help make this easier to grok, please let me know.

Comment 3

[WADA:World Anti-bad-Duping Agency]

1) First select Inbox => no mail in Inbox HIGHESTMODSEQ=118
   IDLE
         <= 2 new mails aare added. UID=48(MODSEQ=119), UID=48(MODSEQ=120)
2) UID=48(MODSEQ=119), UID=48(MODSEQ=120) is normally fetched
3) Connection is stolen by Trash, so no notification via IDLE for Inbox
         <= UID=48/49 is delteed at Inbox, nd is expunged by other client,
         <= UID=52(MODSEQ=128), UID=52(MODSEQ=128) is added to Inbox
4) 8 select "INBOX" (CONDSTORE)
      * 2 EXISTS
      * 2 RECENT
      * OK [UNSEEN 1] Ok
      * OK [UIDNEXT 54] Ok
      * OK [HIGHESTMODSEQ 129]
5) 10 UID fetch 1:* (FLAGS) (CHANGEDSINCE 120)
      * 1 FETCH (FLAGS (\Recent) UID 52 MODSEQ (128))
      * 2 FETCH (FLAGS (\Recent) UID 53 MODSEQ (129))
   10 OK Completed (0.000 sec)

If no CONDSTORe, this response == UID 1 to 51 doesn't exist.
When CONDSTORE, information about MODSEQ=121 to 127, which is for Delete/Expunge in this case, should be notified from server.
However, request in this case == "fetch 1:* (FLAGS) (CHANGEDSINCE 120)".
So information about non-existing UID won't be passed from server.

Even when CoNDSTORE can be used, "first FETCH after SELECT" shold be "uid fetch 1:+ flags"(without CHANGEDSINCE),
and Tb should clear msgDBHdr for non-existing UID.
Covered by QRESYNC?
https://tools.ietf.org/html/rfc7162

Comment 4

[WADA:World Anti-bad-Duping Agency]

I tried similar test with Tb 31.3.0 using Gmail IMAP.
I could see select "INBOX" (CONDSTORE), but I couldn't see UID fetch 1:* (FLAGS) (CHANGEDSINCE nnnn).
I saw "UID fetch 1:* (FLAGS)" as first uid fetch after SELECT, then old msgDBHdr are automatically removed by Tb.

Offline-Use=On/Off is relevant? (I checked with Offline-Use=Off).
IMAP delete model is relevant? (I checked with Just maark it s deleted)
I clcked Inbox to force SELECT Inbox. SELECT Inbox by Biff8new mil check) is needed?

Comment 5

[rocketraman]

(In reply to WADA from comment #4)
> Offline-Use=On/Off is relevant? (I checked with Offline-Use=Off).

No, I just wanted to show in step 10 that even "forcing" the synchronization of a folder by going offline was not sufficient to remove the phantom (expunged but visible) messages.

> IMAP delete model is relevant? (I checked with Just maark it s deleted)

I don't think its relevant -- it may work the same way with delete and read flags rather than expunge, but I haven't checked yet.

> I clcked Inbox to force SELECT Inbox. SELECT Inbox by Biff8new mil check) is
> needed?

Not sure what you mean. AFAIK there was no mail check by any notification system.

With Gmail, did you do the equivalent of step #4 (restarting the server to drop IDLE)? One way would be to lose the IDLE connection may be a timed out NAT state. I think losing the IDLE is necessary.

Comment 6

[WADA:World Anti-bad-Duping Agency]

(In reply to WADA from comment #4)
> I clcked Inbox to force SELECT Inbox. SELECT Inbox by Biff(new maill check) is needed?

Bingo.
I could see "UID fetch 1:* (FLAGS) (CHANGEDSINCE nnnn)" after "SELECT Inbox (CONDSTORE)" by periodical new mail check, with Gmail IMAP.
1. max cached connections=1, to force "loss of IDLE at Inbox" by other folder click. Check new message every 1 minute.
2. When Tb knows UID=A(MODSEQ=M), click FolderX => selected Mbox=FolderX
    Opened status of Inbox is kept.
3. Delete UID=A, Expunge by other client, send new mail of UID=B(MODSEQ=N)
4. Inbox is accessed by new mail check
    SELECT INBOX (CONDSTORE)
    uid fetch 1:* flags (CHANGEDSINCE M) => data about UID=B only is returned
    => Tb knows "new mail of UID=B" only. Tb can't know delete/expunge of UID=A.

This phenomenon can not be observed on Inbox and Trash usually, because Tb reserves one cached connection for Inbox and Inbox is always selected at the connection and Tb reserves one cached connection for Trash and Trash is perhaps always selected at the connection, and IDLE is enabled by default.
If Inbox and if IDLE is used and Inbox is already SELECTed at a cched connection, EXPUNGE is notified via IDLE, so this bug won't occur.

If Inbox and IDLE is disabled, Tb issues "uid fetch NextUID:* fetch flags" at a cached connection, so this bug can occur.
If Gmail IMAP, Gmaail IMAP returns information of CurrentHighestUID(=NextUD-1), so if deleted state(\Deleted is stored) is detected by "uid fetch NextUID:* fetch flags" before expunge, Tb removes msgDBHdr of UID=CurrentHighestUID(=NextUD-1) if Imap Delete model=Move to trsh or Remove it immediately, so this bug won't be exposed on the currently newest mail.

If other than Inbox/Trash, cached connection, where an Mbox is selected and IDLE state for the Mbox, can be stolen by other Mbox. So, if "check new mail every NN minutes" is enabled for the Mbox, this bug can occur on the Mbox, regardless of IDLE is used or not..

I guess major cause of bug 517461(bug 885220 was produced by change of bug 517461), because not only "Unread count of Mbox" but also "Total number of mails in Mbox" becomes incorrect by this bug.

Comment 7

[WADA:World Anti-bad-Duping Agency]

(In reply to rocketraman from comment #5)
> (In reply to WADA from comment #4)
> > Offline-Use=On/Off is relevant? (I checked with Offline-Use=Off).
> No, I just wanted to show in step 10 that even "forcing" the synchronization
> of a folder by going offline was not sufficient to remove the phantom (expunged but visible) messages.

Offline-Use=On/Off I called is per folder property for auto-sync of message body.
(Work) Offline/Online you call is File/Work Offline is Checked/Unchecked.

A reason why going Offline/Online is not sufficient to remove the phantom (expunged but visible) messages.
    "uid fetch NextUID(HighestUID Tb knows + 1):* flags" is used by Tb instead of "uid fetch 1:* flags"
    even after Work Offline/Work Online and first SELECT of Mbox after going back to Onlie.

Comment 8

[WADA:World Anti-bad-Duping Agency]

Utilizing QRESYNC may be better than "uid fetch 1:* flags without CHANGEDSINCE always if just after SELECT".

> https://tools.ietf.org/html/rfc7162#section-1
>  1. Introduction
> The Quick Mailbox Resynchronization (QRESYNC) IMAP extension is an extension to CONDSTORE that allows
> a reconnecting client to perform full resynchronization, including discovery of expunged messages, in a single round trip. 
> QRESYNC also introduces a new response, VANISHED, that allows for a more compact representation of a list of expunged messages.

Comment 9

[WADA:World Anti-bad-Duping Agency]

FYI.
Although mail of "not removed in Thunderbird but already expunged at server Mbox" can be observed inrentionally, it's hard to see mail of "permanently not removed in Thunderbird".

If mbox is not selected at any cached connection and if Mbox new open by folder click, Tb issues "uid fetch 1:* Flags"(full sync).
If mbox is not selected at any cached connection and if mbox is accessed by new mail check first, Tb uses STATUS for new mail check.
   * STATUS "DraftsX" (MESSAGES 4 RECENT 0 UIDNEXT 42 UNSEEN 0) 
Because both MESSAGES and UIDNEXT are contained in response, "mail is expunged" and "mail is added" can be known always, and "uid fetch 1:* Flaags" is issued sooer or later.
If mbox is selected at a cached connection and IDLE is not enabled, "nn EXPUNGE" is usually returned to NOOP or CHECK which Tb issues before "uid fetch NextUID: Flags" for new mail check.
If mbox is selected at a cached connection and IDLE is used, unsol "nn EXPUNGE" response is returned.

Comment 10

[WADA:World Anti-bad-Duping Agency]

A reason of "Deletd/EXPUNGEd by other client is not removed Tb" was that "* n EXPUNGE" response to noop is ignored when IDLE is not used and CONDSTORE is used.
0.   imap.gmail.com definition, IDLE command use  Disabled, IMAP delete model = Move to Trash
      Max cached connections = 3, so Inbox is always selected at a cached connection.
      6 mails are held. UID=819, 820, 821, 822, 823,  825

1.  at imap.googlemil.com
     delete UID~819, EXPUNGE, chaange Tag of UID=825(MODSEQ =187430)

2. at imap.gmail.com, next new mail fetch by Biff is kicked.
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:SendData: 362 noop 
> [3944] 2612[10121d0]: 9886800:imap.gmail.com:S-[Gmail]/All Mail:SendData: 189 noop 
> [3944] 2612[10121d0]: ReadNextLine [stream=119993a0 nb=16 needmore=0]
> [3944] 2612[10121d0]: 9886800:imap.gmail.com:S-[Gmail]/All Mail:CreateNewLineFromSocket: 189 OK Success 
> [3944] 3488[10119f0]: ReadNextLine [stream=11999340 nb=13 needmore=0]
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 1 EXPUNGE 
> [3944] 3488[10119f0]: ReadNextLine [stream=11999340 nb=12 needmore=0]
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 5 EXISTS 
> [3944] 3488[10119f0]: ReadNextLine [stream=11999340 nb=16 needmore=0]
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: 362 OK Success 
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:SendData: 363 getquotaroot "INBOX" 
> [3944] 3488[10119f0]: ReadNextLine [stream=11999340 nb=24 needmore=0]
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * QUOTAROOT "INBOX" "" 
> [3944] 3488[10119f0]: ReadNextLine [stream=11999340 nb=36 needmore=0]
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * QUOTA "" (STORAGE 6229 15728640) 
> [3944] 3488[10119f0]: ReadNextLine [stream=11999340 nb=16 needmore=0]
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: 363 OK Success 
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:SendData: 364 UID fetch 826:* (FLAGS) 
> [3944] 3488[10119f0]: ReadNextLine [stream=11999340 nb=76 needmore=0]
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 5 FETCH (UID 825 MODSEQ (187430) FLAGS ($label4 NonJunk tag4 tag_after)) 
> [3944] 3488[10119f0]: ReadNextLine [stream=11999340 nb=16 needmore=0]
> [3944] 3488[10119f0]: 922a000:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: 364 OK Success 

3.Because \Delete flag of UID=819 is not notified to Tb, msgDBHdr of UID=819 is not removed.
   "* 1 EXPUNGE" ws returned to noop, so I thought some kind of action like "uid fetch 819 Flags" is done, but nothing was executedd for UID=819.
   (* 1 EXPUNGE == message #1 is EXPUNGEd, or 1 message was EXPUNGEd)
   And msgDBHdr for UID=819 was not removed.
   If UID=819 is clcked, blank message body was shown.
   Inbox is Offline-Use=Off folder. IIRC, I clicked UID=819 once aaand small text mail, so data was held in Disk or Memory Cache.
   It looks Disk/Memory Cache data is cleared by * 1 EXPUNGE.
   Because "uid fetch 1:* Flags"(without CHANGEDSINCE) won't be issued, there is no chance to remove UID=819.

5. Go Work Offline, Go Work Online, click Inbox
    => "uid fetch 1:* Flags"(without CHANGEDSINCE)  was issued, so msgDBHdr for UID=819 was removed.
    If first access is by new mail fetch of Bifff, it might be "uid fetch 1:* Flags (CHANGEDSINCE 187430)".

In above case, cause of this bug was "* 1 EXPUNGE response to noop was ignored". But I guess there is possibility of  that both "\Deleted flag of a UID is not notified" and "* n EXPUNGE is not returned to a deleted UID" can occur.
I believe "Full Sync by uid fetch 1:* Flags(without CHANGEDSINCE) just after SELECT" is mandatory if CONDSTORE is used, unless QRESYNC is used.
And, a way to force "SELECT Inbox again"  or "Force Full Sync" is better provided for Inbox, because "Go Work Offline/Go Work Online/explicitly click Inbox again" is redundant operation for users for recovery purpose, and because "Repair Folder" can not be appropriate procedure in such cases.

Comment 11

[WADA:World Anti-bad-Duping Agency]

(In reply to rocketraman from comment #5)
> (In reply to WADA from comment #4)
> > Offline-Use=On/Off is relevant? (I checked with Offline-Use=Off).
> No, I just wanted to show in step 10 that even "forcing" the synchronization
> of a folder by going offline was not sufficient to remove the phantom (expunged but visible) messages.

"Reason why going Offline/Online is not sufficient to remove the phantom (expunged but visible) messages" was:
After Go Work Offline(=> connection is closed) and Go Work Online, When CONDSTORE is used,
  If Mbox is selected at a cached connection by folder click at folder pane(explicit Mbox open)
     uid fetch 1:* Flags without CHANGEDSINCE is used(full sync).
  If Mbox is selected at a cached connection by new mail check of Biff, because Mbox open is not "explicit Mbox open",
     uid fetch 1:* Flags (CHANGEDSINCE known_modseq) is used(partial sync).

This non-explicit-mbox-open is also seen in mail copy/filter move/junk move, and, if POP3, it produces phenomenon of bug 495760.
A reason why "explicit Mbox open" is not executed upon new mail download ;
    In POP3, to avoid Rebuild-Index just before start of download, to avoid Rebuuld-Index while downloding.
I think difference of used commnd is difference between : explicit Mbox open=OpenWithReparse  and non-explicit-mbox=OpenWithoutReparse.
If IMAP, internal Rebuil-Index due to "outdated msf condition" doesn't exist.
I think explcit Mbox open, OpenWitReparse, is better used if IMAP, even when new mail check by Biff, as done upon mail folder click.

Comment 12

[WADA:World Anti-bad-Duping Agency]

For * 1 EXPUNGE which is returned to noop upon new mail check by Biff, when a mail is deleted/expunged by other client and IDLE is not used :
   If CONDSTORE support is disabled, msgDBHdr of the deleted UID was normlly removed after * 1 EXPUNGE .
It looks CONDSTORE only problem.

Comment 13

[WADA:World Anti-bad-Duping Agency]

FYI.
I've opened seprate Bug 1124569 for problem of comment #10.

Comment 14

[gene smith]

CONDSTORE needs to be revisited since it seems like a useful feature, especially for users having huge mailboxes, but has been disabled by default since it caused other problems (e.g., detection of new mail via IDLE).