450578 - Unnecessary BODY.PEEKs when changing IMAP message flag

Status: RESOLVED WORKSFORME

(MailNews Core :: Networking: IMAP, defect)

Description

[Daniel Watts]

User-Agent:       Opera/9.51 (Windows NT 5.1; U; en)
Build Identifier: 2.0.0.16 (20080708)

When selecting a bunch of messages and 'marking as read' (or unread) the client will send a command to update these message but then commence to take a peek at each message. Normally this is not a problem with 10 messages but when I mark my folder of 1000 messagse as read it floors Thunderbird until all those PEEKs are done.

In its worst instance this completely freezes TB and requires a restart to regain access to mail (well, mail that we actually want to download). Marked as Major rather than Critical even though it causes a crash.


Reproducible: Sometimes

Steps to Reproduce:
You'll need a tcp sniffer such as Wireshark. Just move some messages into a folder, start up your sniffer and mark the messages all as read/unread.

Does NOT happen every time. It is sensible sometimes and just does the one command. Othertimes it will body.peak everything after the flag update. May have something to do with dovecot deciding to go and cache everything in a newly created folder. I notice also that moving 20 messages to a new folder also results in a body.peek of each message. 
Actual Results:  
You'll get a trace similar to the following:

Note: 
c.c.c.c = IP of client
s.s.s.s = IP of server


Source    Destination    Info
c.c.c.c    s.s.s.s    Request: DONE
s.s.s.s    c.c.c.c    Response: 20 OK Idle completed.
c.c.c.c    s.s.s.s    Request: 21 uid store 1:20 -Flags (\Seen)
s.s.s.s    c.c.c.c    Response: * 1 FETCH (UID 1 FLAGS (\Recent NonJunk))
c.c.c.c    s.s.s.s    Request: 22 UID fetch 2 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 2 FETCH (UID 2 RFC822.SIZE 1339 BODY[] {1339}
c.c.c.c    s.s.s.s    Request: 23 UID fetch 3 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 3 FETCH (UID 3 RFC822.SIZE 1342 BODY[] {1342}
c.c.c.c    s.s.s.s    Request: 24 UID fetch 5 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 5 FETCH (UID 5 RFC822.SIZE 1344 BODY[] {1344}
c.c.c.c    s.s.s.s    Request: 25 UID fetch 6 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 6 FETCH (UID 6 RFC822.SIZE 1350 BODY[] {1350}
c.c.c.c    s.s.s.s    Request: 26 UID fetch 7 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 7 FETCH (UID 7 RFC822.SIZE 1344 BODY[] {1344}
c.c.c.c    s.s.s.s    Request: 27 UID fetch 8 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 8 FETCH (UID 8 RFC822.SIZE 1325 BODY[] {1325}
c.c.c.c    s.s.s.s    Request: 28 UID fetch 9 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 9 FETCH (UID 9 RFC822.SIZE 1323 BODY[] {1323}
c.c.c.c    s.s.s.s    Request: 29 UID fetch 10 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 10 FETCH (UID 10 RFC822.SIZE 1338 BODY[] {1338}
c.c.c.c    s.s.s.s    Request: 30 UID fetch 11 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 11 FETCH (UID 11 RFC822.SIZE 1333 BODY[] {1333}
c.c.c.c    s.s.s.s    Request: 31 UID fetch 12 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 12 FETCH (UID 12 RFC822.SIZE 1344 BODY[] {1344}
c.c.c.c    s.s.s.s    Request: 32 UID fetch 13 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 13 FETCH (UID 13 RFC822.SIZE 1335 BODY[] {1335}
c.c.c.c    s.s.s.s    Request: 33 UID fetch 15 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 15 FETCH (UID 15 RFC822.SIZE 1323 BODY[] {1323}
c.c.c.c    s.s.s.s    Request: 34 UID fetch 16 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 16 FETCH (UID 16 RFC822.SIZE 1325 BODY[] {1325}
c.c.c.c    s.s.s.s    Request: 35 UID fetch 17 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 17 FETCH (UID 17 RFC822.SIZE 1333 BODY[] {1333}
c.c.c.c    s.s.s.s    Request: 36 UID fetch 18 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 18 FETCH (UID 18 RFC822.SIZE 1327 BODY[] {1327}
c.c.c.c    s.s.s.s    Request: 37 UID fetch 19 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 19 FETCH (UID 19 RFC822.SIZE 1343 BODY[] {1343}
c.c.c.c    s.s.s.s    Request: 38 UID fetch 20 (UID RFC822.SIZE BODY.PEEK[])
s.s.s.s    c.c.c.c    Response: * 20 FETCH (UID 20 RFC822.SIZE 1337 BODY[] {1337}
c.c.c.c    s.s.s.s    Request: 39 IDLE
s.s.s.s    c.c.c.c    Response: + idling 

Expected Results:  
Source    Destination    Info
c.c.c.c    s.s.s.s    Request: DONE
s.s.s.s    c.c.c.c    Response: 20 OK Idle completed.
c.c.c.c    s.s.s.s    Request: 21 uid store 1:20 -Flags (\Seen) 
s.s.s.s    c.c.c.c    Response: * 1 FETCH (UID 1 FLAGS (\Recent NonJunk)) 
c.c.c.c    s.s.s.s    Request: 22 IDLE
s.s.s.s    c.c.c.c    Response: + idling 

My gut feeling is the caching is trying to be clever and 'cache-ahead'. This can be very damaging to useability when you want fast responses but TB is still busy downloading your 40,000 message archive mailbox which you almost never open (but might have clicked on by mistake during normal use).

Comment 1

[David :Bienvenu]

this is surprising - we don't try to fetch message bodies to mark messages read. The two cases where we fetch message bodies are to analyze messages for junk status, and to store them for offline use. Do you have either of those features turned on?

Client side imap protocol logging might give a bit more info about what the client is trying to do:

https://wiki.mozilla.org/MailNews:Logging

Comment 2

[Wayne Mery (:wsmwk)]

(In reply to David :Bienvenu from comment #1)
> this is surprising - we don't try to fetch message bodies to mark messages
> read. The two cases where we fetch message bodies are to analyze messages
> for junk status, and to store them for offline use. Do you have either of
> those features turned on?
> 
> Client side imap protocol logging might give a bit more info about what the
> client is trying to do:
> 
> https://wiki.mozilla.org/MailNews:Logging

Comment 3

[Wayne Mery (:wsmwk)]

Daniel, will you be able to provide a log?

Comment 4

[Daniel Watts]

Sorry guys for the delay. Please go ahead and close. The bug was reported 4.5 years ago in a long ago version. I have not experienced behaviour that would indicate this is still happening now.

Comment 5

[Phoenix]

Resolved per whiteboard and Comment 4