User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.79 Safari/535.11 Steps to reproduce: Open an e-mail with 24 parts sized at approximately 2.2 megabytes. Actual results: A 2.2 megabyte file with 24 parts generated 60 megabytes of network traffic when it has 25 parts in it. Over a local network, this is not that big of a deal. But our remote workers are experienceing major delays on certain email files. This was verified using tcpdump, while the account was seto so that checking messages on startup and scheduled checking was turned off. The tcpdump was turned on using the following command: sudo tcpdump -s 0 -n -w /tmp/tcpdump.raw -i eth2 'port 993' After the command was ran. I clicked on an e-mail with an approximate size of 2.2 megabytes. The total tcpdump is around 61 megabytes. There are 24 parts in this message. After the e-mail was fully downloaded, I killed the dump and exited thunderbird. The thunderbird log was about 215 megabytes, so if you need it, let me know. To keep this bug report small, I am only including 2 screenshots and the commands sent to dovecot which was captured by rawlog. I'd like to let you know, we experience the exact same problem on our exchange server as well. This same traffic pattern will occur when forwarding the same message to a new recipient. Attachment 20120329-091445-12004.in shows the client commands sent to the dovecot server. I don't know much about the IMAP protocol, but it looks like the client is repeatedly asking for the same thing; "fetch 99 (UID RFC822.SIZE BODY[])" was repeated 24 times. Expected results: Thunderbird should have asked for the entire message only once.

I just wanted to let you know that I captured the dovecot rawlog for a roundcube client session accessing the exact same message and it shows a total output size of 3 megabytes. Much better than the 60 megabytes of data generated using the Thunderbird 11 client.

generally the way this is supposed to work is that the full message fetch should get cached, either in the necko disk/memory cache, or the offline store, and then subsequent fetch requests should go through the cache. Have you turned off either cache?

are there any parts in the message that we won't display inline?

All parts are displayed inline.

I created a brand new profile and confirmed that it still happens. I am assuming the caches are all enabled by default. The only thing I changed after creating a new profile in the profile manager is to turn off synchronization for my IMAP account.

Daniel, are you able to set up a test installation of Thunderbird 14 to see if it still has the problem?

(In reply to :aceman from comment #6) > Daniel, are you able to set up a test installation of Thunderbird 14 to see > if it still has the problem? Bienvenu and I were able to confirm this yesterday using trunk builds, so I don't think Daniel needs to test TB 14 unless he really wants to.

OK, it just wasn't noted in the bug. I also assume platform=All.

(In reply to :aceman from comment #8) > OK, it just wasn't noted in the bug. I also assume platform=All. I think so. The problem exists on a Windows XP machine and two Linux machines (x864_64)

When I reproduced this, it was from copying a message from a local folder to the imap server, which resulted in a message that started with "From ", which is not a valid rfc822 header. We shouldn't have copied the "from" envelope to the imap server, but in any case, we should be able to deal with it better. This fix changes the code that tries to do a validation check on the start of the cache entry to allow the first line to start with "From ". The validation on the cache entry is there because the necko disk cache can get corrupted, so this is a quick sanity check on that. I had also set my disk cache size to 0 to test some other stuff, which also makes this bug happen, I believe. In any case, with this patch, the test message loads fine for me, and we use the disk cache for the other parts. I don't know if the reporter's issue was caused by the same issue (I kinda doubt it) but I can't know for sure w/o knowing what the start of the message looked like for the reporter.

Very beginning of the email is: Message-ID: <4F7258C0.5030102@REDACTED> Date: Tue, 27 Mar 2012 17:18:08 -0700 From: REDACTED User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:11.0) Gecko/20120310 Thunderbird/11.0 MIME-Version: 1.0 To: REDACTED Subject: REDACTED References: <4F72553D.10905@REDACTED> In-Reply-To: <4F72553D.10905@REDACTED> Content-Type: multipart/alternative; boundary="------------030009090802040609090809" I'll try to setup a build for Thunderbird 11 and test the patch tonight.

(In reply to David :Bienvenu from comment #10) > fix case of message beginning with "From " > When I reproduced this, it was from copying a message from a local folder to > the imap server, which resulted in a message that started with "From ", > which is not a valid rfc822 header. We shouldn't have copied the "from" > envelope to the imap server, but in any case, we should be able to deal with it better. Are you talking about non escaped "From ..." line in local mail data such as local mail folder file, .eml file, IMAP offline-store file? Or Unix Mbox separator line in local mail folder of Tb? If Unix Mbox separator line, it's Bug 426651. "Such line in .eml file" should also be cared.

I'm talking about the mbox separator that Thunderbird uses for local mail (though it's not unix-specific).

(In reply to daniel from comment #0) > Open an e-mail with 24 parts sized at approximately 2.2 megabytes. > but it looks like the client is repeatedly asking for the same thing; > "fetch 99 (UID RFC822.SIZE BODY[])" was repeated 24 times. If HTML mail with embed image by <img src=cid:...>, Tb applied mime part on demaand, and fetch BODY[m.n] was issued for each image part. So I checked with inline text only mail. Following is IMAP log for download of 256KB mail(HTML with 20 inline text/plain parts) to Offline-use=Off folder. > :SendData: 30 UID fetch 12140 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)]) > :CreateNewLineFromSocket: * 1 FETCH (UID 12140 RFC822.SIZE 256238 FLAGS (\Seen) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)] {314} > :STREAM:OPEN Size: 256238: Begin Message Download Stream > :STREAM:CLOSE: Normal Message End Download Stream > :SHELL: Loading message, using cached shell. > :SendData: 31 UID fetch 12140 (UID RFC822.SIZE BODY[]<0.147456>) > :CreateNewLineFromSocket: * 1 FETCH (UID 12140 RFC822.SIZE 256238 BODY[]<0> {147456} > :STREAM:OPEN Size: 256238: Begin Message Download Stream > :CreateNewLineFromSocket: 31 OK Success > :SendData: 32 UID fetch 12140 (UID RFC822.SIZE BODY[]<147456.108782>) > :CreateNewLineFromSocket: * 1 FETCH (UID 12140 RFC822.SIZE 256238 BODY[]<147456> {108782} > :STREAM:CLOSE: Normal Message End Download Stream > :CreateNewLineFromSocket: 32 OK Success Because all part is displayed in Inline, "mime parts on demand" is not applied, and "uid xxx fetch BODY[]" was used, but it was executed with requesting Offset & Size and Size was approximately 128KB in my environment. 2.2MB/128KB == 18. Was "UID RFC822.SIZE BODY[]" without Offset/Size executed 24 times in your test? It was 24 times of "UID RFC822.SIZE BODY[]<Offset.128KB>", wasn't it?

Bienvenu: Unfortunately, your patch did not fix the problem I am experiencing. WADA: Sometimes, it repeatedly asks "fetch 99 (UID RFC822.SIZE BODY[])". Other times, it has another pattern of fetching. It looks like it fetches from the beginning of the e-mail up to the end of the inline image, then starts over at 0 again to fetch the next image. It is not fetching in parts incrementally. That pattern can be found in the attachment of this comment. The attachment outlines what I am seeing and the network summaries to support my position. There is an inflation of network traffic that is directly correlated with how many parts are in the message. This has caused small messages with many parts to generate a lot more traffic than it should.

(In reply to daniel from comment #15) > Created attachment 611146 [details] > multipart inflation proof #2 > > Bienvenu: Unfortunately, your patch did not fix the problem I am > experiencing. Yes, if your message begins with a valid header, I would not expect my patch to fix the issue you're seeing. But it's still fixes a real problem that causes the same symptoms. I notice in your initial summary of fetch commands, the first command is a PEEK - do you have TB set to not mark messages read when you read them? Or was that first peek fetch from the junk mail filter plugin? If you clear the disk cache (tools, options, advanced, network & disk space tab, clear now button) and restart, and click on a message that showed the problem, does it happen again?

Daniel, A client side IMAP protocol log of a reduced test case would be useful: https://wiki.mozilla.org/MailNews:Logging our imap protocol logging gives a bit more info than a tcp log.

(In reply to David :Bienvenu from comment #17) > Daniel, > > A client side IMAP protocol log of a reduced test case would be useful: > > https://wiki.mozilla.org/MailNews:Logging > > our imap protocol logging gives a bit more info than a tcp log. Clicking on the 1.6 megabyte message produced a 204MB log file. I grepped out "fetch" (case insensitive) from the file and here's a 74k log. If you want me to use another grep command, or would like the whole log file attached let me know (I'm not sure about the size limit).

(In reply to David :Bienvenu from comment #16) > (In reply to daniel from comment #15) > > Created attachment 611146 [details] > > multipart inflation proof #2 > > > > Bienvenu: Unfortunately, your patch did not fix the problem I am > > experiencing. > Yes, if your message begins with a valid header, I would not expect my patch > to fix the issue you're seeing. But it's still fixes a real problem that > causes the same symptoms. > > I notice in your initial summary of fetch commands, the first command is a > PEEK - do you have TB set to not mark messages read when you read them? Or > was that first peek fetch from the junk mail filter plugin? That first attachment was invalidated by my second attachment as it contains more information and was tested in a cleaner state, in a brand new profile. However, the first peek was probably me opening the folder before clicking on the message. Junk mail filter was off. > If you clear the disk cache (tools, options, advanced, network & disk space > tab, clear now button) and restart, and click on a message that showed the > problem, does it happen again? It looks like the cache size is 1024mb. I cleared it, closed Thunderbird, opened Thunderbird, then before clicking on the message, I turned on my tcpdump to capture packets to/from 993 and it again generated 17 megabytes of network traffic and took 50 seconds to display the 1.6 megabyte file.

do you happen to have access to a different imap server (e.g., gmail) that you could try the same message on and see if the issue happens?

(In reply to David :Bienvenu from comment #20) > do you happen to have access to a different imap server (e.g., gmail) that > you could try the same message on and see if the issue happens? If you open up https://bugzilla.mozilla.org/attachment.cgi?id=611146 you will see I have the same problem on my gmail account and documented it as well. A lot of your questions can probably be answered my looking through all of those files.

Here's the protocol logging from Thunderbird to my gmail account.

hmm, your test message works for me with gmail. You're running on linux? I'm on Windows... You could try toggling mail.server.default.fetch_by_chunks to false, restarting, clearing the disk cache, and see if you still see the issue.

(In reply to David :Bienvenu from comment #23) > hmm, your test message works for me with gmail. You're running on linux? I'm > on Windows... > > You could try toggling mail.server.default.fetch_by_chunks to false, > restarting, clearing the disk cache, and see if you still see the issue. Did you capture the tcp dump and see how much total traffic was generated? Did you setup a brand new profile and turn off synchronization and junk settings only for the IMAP account? I am experiencing the same problem on multiple systems (Ubuntu 10.04 (x86_64), Ubuntu 10.04 (i686) and Windows XP Pro). I'll reboot into Windows XP Pro and capture the dump from my router and the logs from Thunderbird.

(In reply to daniel from comment #24) > (In reply to David :Bienvenu from comment #23) > > hmm, your test message works for me with gmail. You're running on linux? I'm > > on Windows... > > > > You could try toggling mail.server.default.fetch_by_chunks to false, > > restarting, clearing the disk cache, and see if you still see the issue. > > Did you capture the tcp dump and see how much total traffic was generated? I did an imap protocol log which tells me what I need to know about the traffic being generated. I also verified in the debugger that we're using the disk cache entry for the message, the one stored there by the initial fetch, for all the subsequent fetches. I verified that synchronization is turned off, and that we don't have a copy of the message in the offline store. > Did you setup a brand new profile and turn off synchronization and junk > settings only for the IMAP account? I am experiencing the same problem on > multiple systems (Ubuntu 10.04 (x86_64), Ubuntu 10.04 (i686) and Windows XP > Pro). I'll reboot into Windows XP Pro and capture the dump from my router > and the logs from Thunderbird. I don't think more protocol level logs are going to be helpful...for some reason, we're not using the disk cache when you recreate this issue. You could try adding the log module cache:5 to the logging and see what it says. If you click away from the message, and click back to it, do we refetch the messge 24 times again? That would pretty clear evidence the necko cache is not getting used. The log could tell us if we're trying to use it, and potentially what's failing.

Before making the report, (In reply to David :Bienvenu from comment #23) > > You could try toggling mail.server.default.fetch_by_chunks to false, > restarting, clearing the disk cache, and see if you still see the issue. Before filing the bug I tried all manners of the mime parts and chunk prefs and could not find any set of prefs that would make the problem go away. Keep in mind that the latest tests all involved a brand new Thunderbird profile, so there were no changes done to those prefs. I also wanted to point out that if you capture the tcp data through tcpdump (tcpdump -s 0 to get full packets) and the total size of the dump is less than the actual size of the e-mail, then it probably pulled the e-mail from a local cache. The tcp data needs to be captured before Thunderbird has had a chance to cache it before viewing the message.

This is what my cache:5 log looks like - you can see TB using the fully cached message for the full message fetch, after looking for the part in the cache, for each of the inline images.

Test Scenario 3 (Ubuntu 10.04 (i686) with a brand new Thunderbird profile) Re-send a 1.6MB file with 8 inline images 1.) Start tcp dump of 993 from my system only. 2.) Open Thunderbird. 3.) Go to Gmail/Sent folder 4.) Right-click test message and click Edit as New... 5.) Wait for images to download again. (Entire message fetched 8 times with a 0.5 - 1.25 second delay between each fetch) 6.) Click Send 7.) Wait a long time for atachments (Entire message fetched 8 times with a 6 second delay between each fetch) 8.) Close Thunderbird 9.) Examine the tcpdump. Elapsed time from the first packet to the last packet took a little over 100 seconds. I can see 16 peaks on the io graph which would correlate it to fetching the entire message 16 times. The tcp dump size was 26 megabytes. 1.6 megabytes * 16 = 25.6 megabytes. What's crazy is the delay between the fetches during the time it is attaching the images to the new message is 4-5 times longer than when generating the message in the first place.

(In reply to David :Bienvenu from comment #25) > (In reply to daniel from comment #24) > > (In reply to David :Bienvenu from comment #23) > > > hmm, your test message works for me with gmail. You're running on linux? I'm > > > on Windows... > > > > > > You could try toggling mail.server.default.fetch_by_chunks to false, > > > restarting, clearing the disk cache, and see if you still see the issue. > > > > Did you capture the tcp dump and see how much total traffic was generated? > > I did an imap protocol log which tells me what I need to know about the > traffic being generated. I also verified in the debugger that we're using > the disk cache entry for the message, the one stored there by the initial > fetch, for all the subsequent fetches. I verified that synchronization is > turned off, and that we don't have a copy of the message in the offline > store. > > > Did you setup a brand new profile and turn off synchronization and junk > > settings only for the IMAP account? I am experiencing the same problem on > > multiple systems (Ubuntu 10.04 (x86_64), Ubuntu 10.04 (i686) and Windows XP > > Pro). I'll reboot into Windows XP Pro and capture the dump from my router > > and the logs from Thunderbird. > > I don't think more protocol level logs are going to be helpful...for some > reason, we're not using the disk cache when you recreate this issue. You > could try adding the log module cache:5 to the logging and see what it says. > > If you click away from the message, and click back to it, do we refetch the > messge 24 times again? That would pretty clear evidence the necko cache is > not getting used. The log could tell us if we're trying to use it, and > potentially what's failing. I did this and captured the tcp dump as well as IMAP:5. The log file generated was 121 megabytes and zipped down to 26 megabytes. I attached a screenshot of the io graph which shows the message was fetched at least 16 times. I need to

You can download the IMAP:5 and CACHE:5 captured logs from: https://docs.google.com/file/d/0B_amC2e_K15MOTRTbzFZU3hRSEt6MFk1RTRndzhUZw/edit?pli=1 This is a capture of a session where I: 1.) Clicked on the 1.6 megabyte email with 8 parts 2.) After the message was loaded, click on a different e-mail with only one part. 3.) Click on the same message as step 1. This is the same session that is shown by the attached screenshot of the tcpdump io graph on comment 29.

I could reproduce reported phenomenon by uploading .eml file which doesn't have CRLF at end(multipart/mixed, text/html + multiple image/jpeg). Phenomenon was observed in testing of bug 727324 comment #39, because I fortunately used ".eml file which was used for test of bug 523796. Last part of fetched mail is as follows if no CRLF at end of .eml(no CRLF after close boundary). > d45d000:imap.gmail.com:S-YY:CreateNewLineFromSocket: /DV//9k= > ReadNextLine [stream=cd27820 nb=10 needmore=0] > d45d000:imap.gmail.com:S-YY:CreateNewLineFromSocket: --Bdy--) > d45d000:imap.gmail.com:S-YY:STREAM:CLOSE: Normal Message End Download Stream > ReadNextLine [stream=cd27820 nb=15 needmore=0] > d45d000:imap.gmail.com:S-YY:CreateNewLineFromSocket: 66 OK Success If CRLF is added(CRLF exists after close boundary), log is as follows, and problem doesn't occur. > d45d000:imap.gmail.com:S-YY:CreateNewLineFromSocket: /DV//9k= > ReadNextLine [stream=cd27820 nb=9 needmore=0] > d45d000:imap.gmail.com:S-YY:CreateNewLineFromSocket: --Bdy-- > ReadNextLine [stream=cd27820 nb=3 needmore=0] > d45d000:imap.gmail.com:S-YY:CreateNewLineFromSocket: ) > d45d000:imap.gmail.com:S-YY:STREAM:CLOSE: Normal Message End Download Stream > ReadNextLine [stream=cd27820 nb=15 needmore=0] > d45d000:imap.gmail.com:S-YY:CreateNewLineFromSocket: 65 OK Success "No CRLF after close boundary" can't occur if mail is sent via SMTP or if mail is downloaded via POP3. "No CRLF after close boundary" is generated by one of next. (a) Mail is generated by Web mail system, and is held in IMAP Mbox by the Web mail system without actual transmission via SMTP. (b) Such mail is saved to .eml file by a mailer(other than Mozilla family) or user intentionally removes CRLF at end of .eml file, and user uploads the .eml file to IMAP server.

Following is IMAP log for mail sent by Gmail's Web mailer to myself(html mail with 4 image attachments, hinotori.jpg, ButaJ.gif, hinotori.ico, hinotori.gif in this order). As seen in "--20cf300e50ed4b808204bc936c7f--)" before "S-INBOX:STREAM:CLOSE: Normal Message End Download Stream", Gmail's Web mail doess't add CRLF ater close boundary, and phenomenon of "uid fetch BODY[] for each image attachment part" is observed. > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:SendData: 14 UID fetch 12141 (UID RFC822.SIZE BODY[]) > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 2 FETCH (UID 12141 RFC822.SIZE 17982 BODY[] {17982} > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:STREAM:OPEN Size: 17982: Begin Message Download Stream > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: MIME-Version: 1.0 > (snip) > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: --20cf300e50ed4b808204bc936c7f--) > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:STREAM:CLOSE: Normal Message End Download Stream > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: 14 OK Success > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:ProcessCurrentURL: entering > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:ProcessCurrentURL:imap://yatter%2Eone%40gmail%2Ecom@imap.gmail.com:993/fetch%3EUID%3E/INBOX%3E12141?part=1.2&type=image/jpeg&filename=hi-no-tori.jpg: = currentUrl > [3720] 0[100f140]: queuing url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.3&type=image/gif&filename=ButaJ.gif > [3720] 0[100f140]: considering playing queued url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.3&type=image/gif&filename=ButaJ.gif > [3720] 0[100f140]: creating protocol instance to play queued url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.3&type=image/gif&filename=ButaJ.gif > [3720] 0[100f140]: failed creating protocol instance to play queued url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.3&type=image/gif&filename=ButaJ.gif > [3720] 0[100f140]: queuing url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.4&type=image/x-icon&filename=hi-no-tori.ico > [3720] 0[100f140]: considering playing queued url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.3&type=image/gif&filename=ButaJ.gif > [3720] 0[100f140]: creating protocol instance to play queued url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.3&type=image/gif&filename=ButaJ.gif > [3720] 0[100f140]: failed creating protocol instance to play queued url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.3&type=image/gif&filename=ButaJ.gif > [3720] 0[100f140]: queuing url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.5&type=image/gif&filename=hi-no-tori.gif > [3720] 0[100f140]: considering playing queued url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.3&type=image/gif&filename=ButaJ.gif > [3720] 0[100f140]: creating protocol instance to play queued url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.3&type=image/gif&filename=ButaJ.gif > [3720] 0[100f140]: failed creating protocol instance to play queued url:imap://yatter.one@gmail.com@imap.gmail.com:993/fetch>UID>/INBOX>12141?part=1.3&type=image/gif&filename=ButaJ.gif > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:SendData: 15 UID fetch 12141 (BODYSTRUCTURE) > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 2 FETCH (UID 12141 BODYSTRUCTURE ((("TEXT" "PLAIN" ("CHARSET" "UTF-8") NIL NIL "7BIT" 28 1 NIL NIL NIL)("TEXT" "HTML" ("CHARSET" "UTF-8") NIL NIL "7BIT" 53 1 NIL NIL NIL) "ALTERNATIVE" ("BOUNDARY" "20cf300e50ed4b807d04bc936c7d") NIL NIL)("IMAGE" "JPEG" ("NAME" "hi-no-tori.jpg") NIL NIL "BASE64" 2076 NIL ("ATTACHMENT" ("FILENAME" "hi-no-tori.jpg")) NIL)("IMAGE" "GIF" ("NAME" "ButaJ.gif") NIL NIL > [3720] 2288[1011800]: "BASE64" 5562 NIL ("ATTACHMENT" ("FILENAME" "ButaJ.gif")) NIL)("IMAGE" "X-ICON" ("NAME" "hi-no-tori.ico") NIL NIL "BASE64" 4466 NIL ("ATTACHMENT" ("FILENAME" "hi-no-tori.ico")) NIL)("IMAGE" "GIF" ("NAME" "hi-no-tori.gif") NIL NIL "BASE64" 4210 NIL ("ATTACHMENT" ("FILENAME" "hi-no-tori.gif")) NIL) "MIXED" ("BOUNDARY" "20cf300e50ed4b808204bc936c7f") NIL NIL)) > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: 15 OK Success > [3720] 2288[1011800]: 317a400:imap.gmail.com:S-INBOX:SendData: 16 UID fetch 12141 (UID RFC822.SIZE BODY[])

Comment on attachment 610994 [details] fix case of message beginning with "From " Do we need this test at all? If we accepted something the first time, and put it in the cache, can't we just assume it's OK? I suppose that requires us to validate things before we cache them, and I don't know whether we do that. That said, the code looks fine.

(In reply to Irving Reid (:irving) from comment #33) > Comment on attachment 610994 [details] > fix case of message beginning with "From " > > Do we need this test at all? If we accepted something the first time, and > put it in the cache, can't we just assume it's OK? necko disk cache corruption seems to happen over time, so validation before use seems the safest strategy.

http://hg.mozilla.org/comm-central/rev/cc21e9b859a5 pushed for "From " issue.

From Daniel's combined cache+imap log, we're definitely dooming the cache entry for the fully downloaded message before we can use it for the part fetches. This isn't happening to me, and I'm not quite sure why it's happening to him. We doom cache entries when the connection is lost, or the load group cancelled, or we don't have the correct access rights for the cache entry, or we're looking for a part when we need to fallback to the full message. I'm pretty sure the connection isn't getting lost, and I doubt the load group is cancelled. I'll try this on my mac just to get a different environment.

I stepped through a couple of message loads in the debugger on my test case, and I was seeing the cache lookups fail because the message size didn't match at http://mxr.mozilla.org/comm-central/source/mailnews/imap/src/nsImapProtocol.cpp#9062

(In reply to Irving Reid (:irving) from comment #37) > I stepped through a couple of message loads in the debugger on my test case, > and I was seeing the cache lookups fail because the message size didn't > match at > http://mxr.mozilla.org/comm-central/source/mailnews/imap/src/nsImapProtocol. > cpp#9062 yeah, could be a line ending issue, which would explain why it generally works on windows, since the rfc mandated protocol line ending matches the platform line ending.

For my big message with attachments, I'm seeing the IMAP message size property as reported by the server, in the protocol log, as 934804: 2012-04-03 02:41:10.634328 UTC - 693637120[1205ab980]: 294eb000:imap.googlemail.com:S-INBOX:ProcessCurrentURL:imap://<redacted>%40gmail%2Ecom@imap.googlemail.com:993/fetch%3EUID%3E/INBOX%3E166: = currentUrl 2012-04-03 02:41:10.648679 UTC - 693637120[1205ab980]: 294eb000:imap.googlemail.com:S-INBOX:SHELL: Loading message, using cached shell. 2012-04-03 02:41:10.648990 UTC - 693637120[1205ab980]: 294eb000:imap.googlemail.com:S-INBOX:SendData: 26 UID fetch 166 (UID RFC822.SIZE BODY[]<0.507904>) 2012-04-03 02:41:10.839161 UTC - 693637120[1205ab980]: ReadNextLine [stream=200777c0 nb=59 needmore=0] 2012-04-03 02:41:10.839199 UTC - 693637120[1205ab980]: 294eb000:imap.googlemail.com:S-INBOX:CreateNewLineFromSocket: * 22 FETCH (UID 166 RFC822.SIZE 934804 BODY[]<0> {507904} during the cache check in nsImapProtocol.cpp:9062, messageSize is 934804 but entrySize (the reported size of the cache entry) is 922127 For a smaller, text only message (1500-ish bytes), the message header size matches the cache entry size. For a small (2462 bytes) MIME multipart message where one part is text and the other part is an attached RFC822 text message, the sizes match and the cache is used. Tests with one or two small .png image attachments also work fine. All my test messages have been done the same way - composed in Thunderbird, sent through Mozilla's SMTP server to the same gmail account and retrieved over IMAP. I tried both text messages with images dragged into the attachment box, and an HTML message with the image inserted into the message body and transmitted as an attachment (referred to with a cid:part1.xxx link from the HTML body)

(In reply to David :Bienvenu from comment #38) > yeah, could be a line ending issue, which would explain why it generally > works on windows, since the rfc mandated protocol line ending matches the > platform line ending. Isn't that something WADA was noticing in comment 31?

(In reply to David :Bienvenu from comment #38) > yeah, could be a line ending issue, which would explain why it generally > works on windows, since the rfc mandated protocol line ending matches the > platform line ending. My case is this bug in special condition(No CRLF after close boundary. Emulation of Gmail's Web mailer), with systems of "the rfc mandated protocol line ending matches the platform line ending". Attached is a quick check result with multipart/mixed mail of "No CRLF after close boundary". It looks for me next phenomenon. (1) If "CRLF after close boundary" doesn't exist, MIME or ImageLib fails to obtain data for image to show in inline from full message data in Disk Cache. (2) Then fetch of each image part is queued for each image part. (3) In processing of queued URL for image part, (3-A) If all mime parts is inline-displayable, "uid fetch BODY[]" is issued for each fetch request for image part. (3-B) If not all mime parts is inline-displayable, mime-parts-on-demand becomes effective, and "uid fetch BODY[N]" is issued for each fetch request for image part, but excess "uid fetch BODY[1]" for message body part is also issued. I think above is different from "broken Disk cache" case, "psuedo broken Disk Cache due to From line as first message header" case, "wrong RFC822.SIZE" case. Above is perhaps relevant to "line ending mismatch between IMAP RFC" case.

To daniel@monstertool.com(bug opener): Do you see new line at end of mail data from Gmail IMAP in your IMAP log? If sequence like next, no new line exists between "close boundary" and "ending token of )". > CreateNewLineFromSocket: --Clode_Boundary_of_multipart_mail--) > :STREAM:CLOSE: Normal Message End Download Stream > :CreateNewLineFromSocket: 88 OK Success If sequence like next, new line exists between "close boundary" and "ending token of )". > CreateNewLineFromSocket: --Clode_Boundary_of_multipart-- > CreateNewLineFromSocket: ) > :STREAM:CLOSE: Normal Message End Download Stream > :CreateNewLineFromSocket: 88 OK Success You say you tested with mail in [Gmail]/Sent Mail. Was the mail sent by Gmail's Web mail? Or Sent mail by mail client like Tb using Gmail's SMTP server? You say next in Comment #11. > Very beginning of the email is: > Message-ID: <4F7258C0.5030102@REDACTED> >(snip) > User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:11.0) Gecko/20120310 Thunderbird/11.0 It looks mail sent by Tb and mail sent using Gmail's SMTP. If so, one of CRLF, LF, CR is sent after end of mail data by Tb to Gmail's SMTP server, and I think Gmail's SMTP/Gmail/Gmail IMAP puts new line at end of mail data in [Gmail]/Sent Mail(and [Gmail]/Sent Mail). If new line is sent from Gmail IMAP to Tb after end of mail data for this mail, David's guess on new line character relevant issue(CRLF of IMAP vs. LF on Linux) is perhaps correct in your case.

I tried this on the mac. The exact same message that works fine on windows doesn't work correctly on the mac, both with up to date trunk builds. I confess I don't remember if we try to make the line endings platform-specific before writing the message to the cache. I'll have to check.

ok, so this is a line ending issue - nsImapProtocol::HandleMessageDownLoadLine makes sure we're using the native platform line ending, which alters the size of the data we put in the cache. If I turn this off, by setting canonicalLineEnding to true and rebuilding, everything works fine. So we have a few choices 1. stop using canonical line endings for imap, which hardly anyone would notice (I think it might affect saving as a .eml file, but maybe not). It would also make us more consistent with the online size of the message. 2 keep careful count of how much we've changed the message size, and use that in our calculation of the message size. 3. Fudge message size comparison based on the number of lines - we do that for the offline store, but it's less than ideal.

this just makes us use the canonical line ending - I've requested a try server build with this, though I think daniel can also apply patches by hand. mac purists might hate this, but this approach would mean less difference between mac and windows (and linux) builds, which would be a win for the non-windows builds stability. And this really is an internal matter, I believe. Users should care what the offline store line endings are...

Yes, I made the same change and recompiled and can verify that the problem is fixed for most messages. Also, the reply and attaching behavior is much improved. However, the problem still exists, as WADA pointed out, for messages that do not end properly. It is behaving just like my Windows XP Pro system, which has the same problem with the same message. The message was composed in gmail and is in the Gmail/Sent folder. The messages that now work were replies to the same message composed in Thunderbird.

yeah, if we normalize line endings, the size will change. So perhaps we do have to adjust the expected size based on normalization.

By manipulating the preferences for imap chunk handling, I'm pretty sure I've confirmed my suspicions: I have *not* applied :bienvenu's patch, and I'm running on Mac OS X, so if there is a problem with line endings I don't have a fix for it. By going into the prefs editor (Options/Advanced/General/Config Editor...) searching for "chunk" and setting mail.imap.chunk_size and mail.imap.min_chunk_size_threshold back to their default (relatively small) values, I ensure that TB is downloading the large message in chunks. Then, Options/Advanced/Network.../Clear Now to flush my necko cache, and then click on a large message with in-line images. NSPR_LOG_MODULES=imap:5 trace shows me that the message gets downloaded multiple times. By looking at the log, I can see that the client is downloading chunks that total up to exactly the number of bytes reported in the IMAP RFC822.SIZE response, which turns out to *not* be the entire message. The downloaded message is added to the necko cache, but the cache entry ends up having fewer bytes than the recorded RFC822.SIZE message size. Then, when we try to retrieve the message from the cache, the check at http://mxr.mozilla.org/comm-central/source/mailnews/imap/src/nsImapProtocol.cpp#9062 rejects the cached data so we download the message again. Then, in the prefs editor I set mail.server.default.fetch_by_chunks to 'false', cleared the necko cache again, and re-displayed the same message. The imap trace shows that we issue a FETCH for the entire body, the server responds with the number of bytes it's sending (which is significantly more than the RFC822.SIZE number), and we download the entire message once. The message gets cached, and all further attempts to retrieve the message from the cache succeed because the size of the cached object matches the RFC822.SIZE value. I can re-display the message, and the message is never downloaded again. Daniel, can you test an unpatched Thunderbird by setting mail.server.default.fetch_by_chunks to 'false' and see if that resolves the problem?

I think only some servers lie about the rfc822 size (Exchange is one; I don't know if GMail is an other. I doubt Dovecot is.). But at one point, I added some code to adjust the message size based on the string literal length returned by the fetch command (I forgot about that; should have mentioned it before). But as you say, fetching by chunks won't get all the message if we don't have the right size. If we were to add code to fetch past the end just in case, we'd also want to add code to adjust our idea of what the message size is to reflect the new response.

gmail certainly does lie about RFC822 size, that's where I've been testing and seeing the problem. https://bugzilla.mozilla.org/show_bug.cgi?id=92111 and its many duplicates contain the sad story.

Sneaking suspicion that both problems come into play, line ending translation *and* message truncation. Here's how: For messages smaller than the size where chunking kicks in, we download the entire message, strip the line endings down, and then record the adjusted message size *both in our database and in the cache*. From then on, we get the message from the cache. For messages larger than the chunking size, we download in chunks and *don't* adjust the size, so our database records the byte count we got in the RFC822.SIZE from the server. 1) If we translate CR/LF to local line endings, the cache records the object size after translation, so the message database size doesn't match the cache size, and we re-download the message. 2) If the server lies about the message size, we either (a) truncate the message if the server lies on the small side; for CR/LF systems from them on we successfully cache the truncated message leading to the broken attachment problems in bug 390795 and bug 92111 (b) Download the entire message if the server lies on the large side, but then fail to re-use the cache because the cache records the actual size but the message db records the lie Now, if we fix the chunked downloads to download the entire message, and record the actual downloaded size, everything should work OK even if we keep storing messages using local line endings - because all the sizes are calculated after the line endings are converted.

(In reply to Irving Reid (:irving) from comment #48) > Daniel, can you test an unpatched Thunderbird by setting > mail.server.default.fetch_by_chunks to 'false' and see if that resolves the > problem? Yes, I've just tested it gain with an unpatched Thunderbird 11.0. I reset the cache and set mail.server.default.fetch_by_chunks to 'false' and restarted it before capturing via tcpdump. It generated 17 megabytes of traffic for the 1.6 megabyte email. It's probably a nuance of the same bug that I'm not seeing.

This patch adds an extra parameter to nsIImapMessageSink.normalEndMessageDownloadStream() so that the IMAP protocol can signal the message database to update the DB's idea of the actual size of the message. I'm looking for comments on a number of aspects of the patch: In nsImapMailFolder::NormalEndMsgWriteStream, in the case where we're downloading the message for offline use, the EndNewOfflineMessage() call does a bunch of its own munging of the stored actual size of the message; we might want to reconcile this with the new code I added so that we do the same thing for both offline and online messages; we also re-fetch the header a dozen lines later under some circumstances, do we care about optimizing to not re-fetch? nsImapMailFolder::ParseAdoptedMsgLine() also updates the DB's idea of the message size, on the fly as blocks of message bytes are downloaded; this only happens for offline stored messages, so I suspect it's redundant with EndNewOfflineMessage(); should we remove the size update from here and move it to NormalEndMsgWriteStream()? Updating fSizeOfMostRecentMessage (normally RFC822.SIZE) with the actual downloaded message size in nsImapServerResponseParser::msg_fetch_literal() turned out to be ineffective in the on-line message case, because no code paths copied that info anywhere. By counting bytes in nsImapProtocol::PostLineDownloadEvent() we get an accurate count even when the protocol code stuffs in extra senders for XSENDER verification. Taking this code out of msg_fetch_literal also allowed removal of SetFetchingEverythingRFC822(). I haven't figured out how to make a unit test for the underlying issue, which was that we re-download the message body each time the UI asks for the message, if the IMAP RFC822.SIZE doesn't match the actual number of bytes we store in the Necko cache. It would be nice to have one, because this is a pretty sticky issue and there are lots of ways it could regress. Also, it seems strange that we need to re-parse the entire message to extract each of the inline parts when we're already streaming the entire message through the MIME parser. Is this a separate regression?

Proposed patch has some minor dependencies on my existing patch for bug 92111

Updating my patch to bug 92111 caused one hunk of this to not apply cleanly - the part that included David's change to the default for normalizing CRLF.

Comment on attachment 627998 [details] [diff] [review] Track actual downloaded message size in IMAP protocol and pass to folder listener (updated because of bug 92111 patch update) So you're sure that we never want to update the message size when m_offlineHeader is true? + PRInt32 updatedMessageSize) { if (m_offlineHeader) EndNewOfflineMessage(); + else if (updatedMessageSize != -1) { + // Not offline message, but retrieve the message header to update size other than that, this patch looks reasonable.

Aside from the comments on previous patches, this one includes: Update the size for offline messages too; this made the size update in nsIImapMessageSink::parseAdoptedMsgLine unnecessary - and it turned out that the old code only worked for messages smaller than the size of the buffer we passed into parseAdoptedMessageLine() so it needed fixed anyway. Chunk size handling from my bug 92111 patch wasn't being done correctly for "peek" downloads; that's now in this patch - if you really want, I could move it over to the 92111 patch but I'd be just as happy to just land both of these together. The way we build the request string in imapProtocol::FetchMessage() should be refactored to make errors like this one less likely. I observed the same "no CRLF after the final part boundary" IMAP spec violation that WADA described in his comments on this bug; with this patch we handle them correctly at least for chunk-downloaded messages, I'll do another check to make sure we're OK for messages that are downloaded whole.

you might try setting OfflineMessageSize, since I think that's what we compare with the size we find in the cache.

For the necko cache we're using GetMessageSize() (see http://mxr.mozilla.org/comm-central/source/mailnews/imap/src/nsImapProtocol.cpp#9045) It looks like nsMsgDBFolder::EndNewOfflineMessage() does roughly the right thing, storing the actual number of bytes in the offline store in that field and checking it against the message size (that I'm setting) accounting for most of the added headers etc.

Ah, you're right. So what are the STR to reproduce the issue where the size wasn't being persisted correctly?

(In reply to David :Bienvenu from comment #60) > Ah, you're right. So what are the STR to reproduce the issue where the size > wasn't being persisted correctly? Probably easiest to see with NSPR_LOG_MODULES=imap:5 to make the message downloads obvious. Set up an IMAP account to a server that incorrectly reports size (Exchange or a Gmail account with older messages), configured for no offline storage. View a message; it should be downloaded (only once, even if it has in-line image parts). View a different message and then come back to the first one; the first one should be fetched from the necko cache for the second viewing. Exit and restart TB without clearing the cache (There may be a mistake in my testing here - the way I exited and restarted could possibly have flushed the cache). View the first message again - TB will re-download it, the log messages added to imap:5 by my patch should show that it starts out looking for the original incorrect size.

Move some changes from this patch to the Bug 92111 patch because they are related to chunked downloads rather than necko cache.

Sorry about the review spam. Forgot to hg qref before i uploaded the patch.

Comment on attachment 631082 [details] [diff] [review] Track actual downloaded message size in IMAP protocol and pass to folder listener, this time with added hg qrefresh this logs some stuff that I think we don't want to log: I think we only want to log when updatedMessageSize isn't -1 here: + m_offlineHeader->GetMessageSize(&msgSize); + PR_LOG(IMAP, PR_LOG_ALWAYS, ("Offline message old size %u, new size %d", + msgSize, updatedMessageSize)); + if (updatedMessageSize != -1) + m_offlineHeader->SetMessageSize(updatedMessageSize); EndNewOfflineMessage(); + } and here, I think only log if msgSize != updatedMessageSize + else if (updatedMessageSize != -1) { + // Not offline message, but retrieve the message header to update size + nsCOMPtr<nsIMsgDBHdr> msgHeader; + nsresult rv = GetMessageHeader(uidOfMessage, getter_AddRefs(msgHeader)); + if (NS_SUCCEEDED(rv)) { + PRUint32 msgSize; + msgHeader->GetMessageSize(&msgSize); + PR_LOG(IMAP, PR_LOG_ALWAYS, ("On line message old size %u, new size %d", + msgSize, updatedMessageSize)); + msgHeader->SetMessageSize(updatedMessageSize); I think we probably do want to try a commit when we're changing the message size, e.g., if (mDatabase) mDatabase->Commit(nsMsgDBCommitType::kLargeCommit) just to make sure the change gets written to the db. maybe this code could be tightened up by doing something like this: if (updatedMessageSize != -1) { nsCOMPtr<nsIMsgDBHdr> messageHdr = m_offlineHeader; if (!messageHdr) GetMessageHeader(uidOfMessage, getter_AddRefs(messageHdr)); if (messageHdr) { msgHeader->GetMessageSize(&msgSize); if (msgSize != updatedMsgSize) { PR_LOG(IMAP, PR_LOG_ALWAYS, ("On line message old size %u, new size %d", msgSize, updatedMessageSize)); msgHeader->SetMessageSize(updatedMessageSize); } } else NS_WARNING(...) }

Comment on attachment 631082 [details] [diff] [review] Track actual downloaded message size in IMAP protocol and pass to folder listener, this time with added hg qrefresh Other than my previous comments, I'm reasonably happy with this patch...if you can get me a patch that addresses those comments, I promise to review it quickly. Clearing review request.

Took a run at rearranging the logic for getting and updating the message header as suggested.

Comment on attachment 634145 [details] [diff] [review] Track actual downloaded message size in IMAP protocol and pass to folder listener, fixed bienvenu's comments on log messages this is relatively rare, right? +#ifdef DEBUG + PRUint32 msgSize; + msgHeader->GetMessageSize(&msgSize); + PR_LOG(IMAP, PR_LOG_DEBUG, ("Updating stored message size from %u, new size %d", + msgSize, updatedMessageSize)); +#endif if so, I don't think we need #ifdef DEBUG around it. Logging that's not in release builds is sooooo much less useful.

Carrying forward r=bienvenu from the previous version of the patch. PR_LOG is enabled by #ifdef (DEBUG || FORCE_PR_LOG) and #defines PR_LOGGING, so I changed the #ifdef to be PR_LOGGING.

Comment on attachment 634391 [details] [diff] [review] Track actual downloaded message size in IMAP protocol and pass to folder listener, one more tweak to logging FYI, I think the #ifdef just makes the code harder to read. We don't do that for any of the other logging calls, and getMessageSize is a trivial accessor function, so in the unlikely event that there are ever builds w/o pr_logging compiled on, it's not a big deal.

fixed on trunk, without #ifdef - http://hg.mozilla.org/comm-central/rev/0401e822b882