373366 - "Wait before marking messages read" broken on large IMAP messages

Status: RESOLVED DUPLICATE of bug 662792

(MailNews Core :: Networking: IMAP, defect)

Description

[Michael Schaap]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.2) Gecko/20070219 Firefox/2.0.0.2 mscha/1968.9.17
Build Identifier: Thunderbird 2.0pre (Windows/20070309)

When "Wait ___ seconds before marking a message as read" is enabled, large IMAP messages are still immediately marked as read as soon as they are selected.
("Large": for me, this happens with messages with about 30KB of body text.)

This happens with the latest 1.8 branch build (Thunderbird 2.0pre (Windows/20070309)) as well as TB 2.0b2.
It works fine in TB 1.5.0.*, so this is a regression.

Although this seems similar to bug 310847, I don't think it's a duplicate, since that bug appeared in 1.5 and this one doesn't.

Reproducible: Always

Steps to Reproduce:
1. Ensure you have an IMAP account.  For easier testing, make sure the folder is _not_ selected for offline use.  (If selected for offline use, the problem occurs for new messages, but not for messages you have already seen.)
2. Enable "Wait N seconds before marking messages as read", and set it to a large enough value that you see the difference.  (I use 99999.)
3. Make sure the message pane is enabled.
4. Send a message to this IMAP account with at least 30KB of body text.
5. Restart Thunderbird, and open the IMAP Inbox.
6. Select the message.
Actual Results:  
Message is immediately marked read.

Expected Results:  
Message should not be marked read for N seconds.

I tried to debug this a bit, and found the following:

The message is actually marked read _before_ onMsgLoaded() in mailWindowOverlay.js is called, so it appears to happen in C++ code.
Interestingly, if you turn mark_message_read.delay _off_, the message _does_ remain unread until OnMsgLoaded() is called, and there it is marked read in the "else" part of

    if (msgHdr && !msgHdr.isRead)
    {
      if (markReadOnADelay && wintype == "mail:3pane") // only use the timer if viewing using the 3-pane preview pane and the user has set the pref
      {
        ClearPendingReadTimer();
        if (markReadOnADelayInterval > 0)
          gMarkViewedMessageAsReadTimer = setTimeout(MarkCurrentMessageAsRead, markReadOnADelayInterval * 1000);
      }
      else {
        MarkCurrentMessageAsRead();
      }
    }

So, there is a difference, outside of this function, depending on whether mark_message_read.delay is set.
The only other place in the code where this is used, is in nsImapService.cpp, nsImapService::DisplayMessage:

    PRBool forcePeek = PR_FALSE; // should the message fetch force a peak or a traditional fetch? 

    if (NS_SUCCEEDED(rv) && prefBranch) 
       prefBranch->GetBoolPref("mailnews.mark_message_read.delay", &forcePeek);

    rv = FetchMessage(imapUrl, forcePeek ? nsIImapUrl::nsImapMsgFetchPeek : nsIImapUrl::nsImapMsgFetch, folder, imapMessageSink,
      aMsgWindow, aDisplayConsumer, msgKey, PR_FALSE, (mPrintingOperation) ? "print" : nsnull, aURL);

i.e., FetchMessage is called with nsImapMsgFetchPeek instead of nsImapMsgFetch when mark_message_read.delay is set.

So, it looks like FetchMessage(..., nsImapMsgFetchPeek, ...) marks messages read, if they are larger than a certain size, while FetchMessage(..., nsImapMsgFetch, ...) doesn't mark them read in either case.

This is as far as I got without actually building Thunderbird myself (and understanding the IMAP code a lot better...).

Comment 1

[Michael Schaap]

Set the "blocking-thunderbird2?" flag, since it's a regression from 1.5, and it's really causing me trouble.

Also changed the category from "Mail Window Fromt End" to "General", since the problem might appear in the front end, but it's certainly a back end bug.
Is there a better category than "General" to use for back end bugs?  If so, I can't seem to find it...

Comment 2

[Michael Schaap]

Just tested: still broken in 2.0rc1 (version 2.0.0.0 (20070326))

Comment 3

[David :Bienvenu]

Peek means don't mark the message read. An imap protocol log of a session where this happens might help.

http://www.mozilla.org/quality/mailnews/mail-troubleshoot.html#imap

Comment 4

[Michael Schaap]

Attachment: Attachment for "small" message that doesn't get marked read

Comment 5

[Michael Schaap]

Attachment: imap log for "large" message that DOES get marked read

Comment 6

[Michael Schaap]

I attached (the appropriate part of) IMAP protocol log for two cases:

1)
- open Thunderbird 2.0rc1
- open a folder with two messages, a small one (19KB) and a large one (43KB), both still unread
- select the SMALL message
- it is loaded, and remains marked UNREAD

2)
- open Thunderbird 2.0rc1
- open a folder with two messages, a small one (19KB) and a large one (43KB), both still unread
- select the LARGE message
- it is loaded, and gets marked READ

There are some immediately apparent differences.  The IMAP commands sent for loading the small message are:
- UID fetch 4 (UID RFC822.SIZE BODY.PEEK[]<0.10240>)
- UID fetch 4 (UID RFC822.SIZE BODY.PEEK[]<10240.9348>)
while for the large message, they are:
- UID fetch 3 (BODYSTRUCTURE)
- UID fetch 3 (UID RFC822.SIZE BODY[]<0.10240>)
- UID fetch 3 (UID RFC822.SIZE BODY[]<10240.10240>)
- UID fetch 3 (UID RFC822.SIZE BODY[]<20480.12288>)
- UID fetch 3 (UID RFC822.SIZE BODY[]<32768.11833>)

I.e, for the small message, the message body is retrieved in 10KB chunks, with PEEK, while for the large message, first the body structure is fetched, and then the message body, in 10KB chunks, but *without* PEEK.

So, there appears to be a difference in handling in TB for "large" messages (however that is defined; seems to be > about 30KB).  And only the "small" message handling sets PEEK correctly.

 - Michael

Comment 7

[Michael Schaap]

"about 30KB" is exactly 30000 bytes, by the way.  It's preference mail.imap.mime_parts_on_demand_treshold, which defaults to 30000.
A workaround is thus - I tested it - to set this preference to a much larger value.

Comment 8

[Michael Schaap]

Make that mail.imap.mime_parts_on_demand_threshold, of course.  :-[

Comment 9

[Bob Triffles]

I have the same issue with Thunderbird 2.0.0.14.  The mime_parts_on_demand feature does seem to be a likely culprit.  I tried to debug the issue with VS 2005, but Thunderbird does not appear to be included on the Mozilla symbol server:
http://developer.mozilla.org/en/docs/Using_the_Mozilla_symbol_server

I also noticed that the problem occurs not only for 30 kB of body text, but also when attached images (totaling over 30 kB) are displayed inline.  If I disable View -> Display Attachments Inline, the message is not immediately marked as read.  In this case, the IMAP commands look like:
- 14 UID fetch 6313 (BODYSTRUCTURE)
- 15 UID fetch 6313 (BODY.PEEK[HEADER] BODY.PEEK[1.MIME] BODY.PEEK[1.1.MIME] BODY.PEEK[1.2.MIME] BODY.PEEK[2.MIME] BODY.PEEK[3.MIME])
- 16 UID fetch 6313 (BODY.PEEK[1.1])
- 17 UID fetch 6313 (BODY.PEEK[1.2])

Comment 10

[Wayne Mery (:wsmwk)]

Davidb, is there also a pop issue with mime parts?  (making component imap, but perhaps it should be something else)

Bob, I think 2.0.0.14 should be there. If not, can you try current beta?
  http://www.mozillamessaging.com/en-US/thunderbird/early_releases/

Comment 12

[Magnus Melin [:mkmelin]]

Anybody see this with thunderbird3 beta1?
http://www.mozillamessaging.com/en-US/thunderbird/early_releases/

Comment 13

[hansen]

Just tested 2009-01-18 trunk. I can reproduce this on some messages. Only few.

Most messages get read after X seconds, but a few gets marked immediately.

I can supply msg or log, if needed.

Comment 14

[Magnus Melin [:mkmelin]]

(In reply to comment #13)
> I can supply msg or log, if needed.

An imap log with trunk could be useful, yes.

Comment 15

[WADA:World Anti-bad-Duping Agency]

Timestamp of log is usually required to analyze time related issue, but timestamp feature of NSPR logging is still under construction(Bug 86396). On MS Win, "NSPR logging + DebugView" is a current solution. See Bug 402793 and Bug 86396.
> Bug 402793 Comment #1 : Getting NSPR log
> Bug 402793 Comment #6 : Getting NSPR log with timestamp using DebugView on Win

Comment 16

[hansen]

Attachment: IMAP5 log via DebugView as requested

Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1b3pre) Gecko/20090208 Shredder/3.0b2pre ID:20090208031125

First I marked a 4KB message, which was marked after 5 seconds.
Then I marked a 95KB message, which was marked as read instantly.

Comment 17

[WADA:World Anti-bad-Duping Agency]

Log data:
(1) "store flag \Seen" is issued for UID=5
> 00000000	0.00000000	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:SendData: DONE 	
> 00000002	0.00996412	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:CreateNewLineFromSocket: 6 OK IDLE completed 	
> 00000005	0.01037031	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:SendData: 7 uid store 5 +Flags (\Seen) 	
> 00000007	0.01470578	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:CreateNewLineFromSocket: * 5 FETCH (UID 5 FLAGS (\Seen)) 	
> 00000009	0.01507817	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:CreateNewLineFromSocket: 7 OK STORE completed. 	

>
> 00000010	0.01537933	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:SendData: 8 IDLE 	
> 00000012	0.01653087	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:CreateNewLineFromSocket: + entering idle mode 	
> 00000013	1.63417590	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:SendData: DONE 	
> 00000015	1.63652277	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:CreateNewLineFromSocket: 8 OK IDLE completed 	

(2) fetch (BODYSTRUCTURE) for UID=3
> 00000018	1.65490222	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:SendData: 9 UID fetch 3 (BODYSTRUCTURE) 	
> 00000020	1.65928078	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:CreateNewLineFromSocket: * 3 FETCH (UID 3 BODYSTRUCTURE (("text" "plain" ("charset" "iso-8859-1" "format" "flowed") NIL NIL "8bit" 633 21 NIL NIL NIL)("image" "png" ("name" "=?iso-8859-1?B?Zvhyc3RlIHVka2FzdC5QTkc=?=") NIL NIL "base64" 95234 NIL ("attachment" ("filename" "=?iso-8859-1?B?Zvhyc3RlIHVka2FzdC5QTkc=?=")) NIL) "mixed" ("boundary" "----=_NextPart_000_1b_2e29_132d") NIL NIL)) 	
> 00000022	1.65946460	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:CreateNewLineFromSocket: 9 OK FETCH completed. 	

(3) fetch BODY[] for UID=3 => Whole mail data including attachment is downloaded
> 00000023	1.65962791	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:SendData: 10 UID fetch 3 (UID RFC822.SIZE BODY[]) 	
>(many logs for downloaded data)
> 00003219	1.84192121	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:STREAM:CLOSE: Normal Message End Download Stream	

(4) Server returned flag of "\Seen" to fetch at step (3)
> 00003221	1.86039031	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:CreateNewLineFromSocket: * 3 FETCH (FLAGS (\Seen)) 	
> 00003223	1.86051917	[1700] 784[6dfb9b0]: 64641e0:10.0.0.5:S-INBOX.Projects.www brugerindflydelse:CreateNewLineFromSocket: 10 OK FETCH completed. 	


> (A) First I marked a 4KB message, which was marked after 5 seconds.

What operation do you mean by "I marked"?
"after 5 second" from what operation or event?

I can say nothing about (A), because no log for (A) other than "7 uid store 5 +Flags (\Seen)" is provided by you.

> (B) Then I marked a 95KB message, which was marked as read instantly.

Server returned "\Seen" for FETCH by IMAP.
( See RFC 3502. http://www.faqs.org/rfcs/rfc3501.html )

Comment 18

[hansen]

All messages were marked unread via Thunderbird before I did the logging.

Let me do another run, where I reset the flags on the server with a new profile.

I'm not using this feature, but just thought I would help kill some bugs.

Comment 19

[WADA:World Anti-bad-Duping Agency]

Possible flow.
 (1) You changed all mails to "Unread" => Tb send store flag -\Seen
 (2) Mail of UID=5 is already downloaded(by your action, due to small mail etc.)
     => Read mail of UID=5  => No need to FETCH
     => After "Wait seconds ...", Tb sends store flag \Seen
 (3) Mail data of UID=3 is not downloaded yet.
     => Read mail of UID=3
     => FETCH(with non-PEEK) is issued, and server sets \Seen flag,
        because FETCH is "client has read the mail" for server.

By the way, value in "Order Received" column is "UID of the mail" when IMAP folder. Display "Order Received" columns during test, and check the UID upon each operation. It'll help your log analysis.

Comment 20

[Bob Triffles]

I can confirm that this bug continues to occur in Thunderbird 2.0.0.21 and Thunderbird 3 beta 2.  For version 3, it even occurs when "automatically mark messages as read" is completely disabled.

Thunderbird is incorrectly issuing a "FETCH ... BODY" instead of a "FETCH ... BODY.PEAK".  This inherently causes the message to be marked as read (\Seen).  It appears to have something to do with the "MIME parts on demand" logic.

I have looked at the source, but I couldn't find any obvious connection between BODY.PEEK and MIME parts on demand.  I tried to debug the release version using the symbol server and downloaded source files, but I am unable to set breakpoints.  Is this even possible?

Speaking of the symbol server, I had to manually download the PDB files with symchk.exe because VS 2005 couldn't retrieve them on its own.  Furthermore, the symbol server documentation neglects to mention that Thunderbird symbols are under symbols.mozilla.org/thunderbird, not /firefox.

Comment 22

[Wayne Mery (:wsmwk)]

(In reply to comment #20)
> For version 3, it even occurs when "automatically mark
> messages as read" is completely disabled.

Bob, do you still see this v3 anomaly with 3.0pre?  that would be really disturbing given bug 297534, fixed   2008-08-23

Comment 23

[M. LaPlante]

Confirmed still broken on Beta 4... is there a newer build to test?

Comment 24

[Bob Triffles]

(In reply to comment #22)
> Bob, do you still see this v3 anomaly with 3.0pre?  that would be really
> disturbing given bug 297534, fixed   2008-08-23

Yes, it even occurs on the official build of RC 1.  I don't think Thunderbird is intentionally marking the messages as read, but rather it is a side effect of send the wrong "FETCH ... BODY" command.  As a result, this bug happens regardless of all "mark as read" features, including bug 297534.

Comment 25

[Nikolay Shopik]

I can't reproduce that on Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US; rv:1.9.2.9pre) Gecko/20100804 Lightning/1.0b2 Lanikai/3.1.3pre

Comment 26

[David :Bienvenu]

bug 662792 has a fix for this.