Last Comment Bug 803843 - IMAP folders/mailfiles keep growing to gigabyte size because partially downloaded message is being incorrectly stored
: IMAP folders/mailfiles keep growing to gigabyte size because partially downlo...
Status: RESOLVED FIXED
[GS][regression:tb16.0;fixed in 16.0.2]
: perf, regression
Product: MailNews Core
Classification: Components
Component: Database (show other bugs)
: 16
: All All
: -- major with 5 votes (vote)
: Thunderbird 19.0
Assigned To: :Irving Reid (No longer working on Firefox)
:
Mentors:
https://getsatisfaction.com/mozilla_m...
: 802217 804100 805265 806172 (view as bug list)
Depends on:
Blocks: 92111
  Show dependency treegraph
 
Reported: 2012-10-20 07:55 PDT by lohner
Modified: 2015-11-28 20:12 PST (History)
21 users (show)
vseerror: in‑testsuite?
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
fixed
fixed
fixed


Attachments
Message which triggers it (714.05 KB, message/rfc822)
2012-10-23 12:00 PDT, Chris Coulson
no flags Details
WIP: Call DiscardNewMessage() with non-null stream to avoid early exit (2.21 KB, patch)
2012-10-23 20:43 PDT, :Irving Reid (No longer working on Firefox)
no flags Details | Diff | Review
Only correct the message size when storing the message offline (1.07 KB, patch)
2012-10-25 11:03 PDT, Chris Coulson
no flags Details | Diff | Review
Fix broken size in message db (3.18 KB, patch)
2012-10-25 14:23 PDT, Chris Coulson
no flags Details | Diff | Review
Test message with many inline images (283.06 KB, message/rfc822)
2012-10-25 22:16 PDT, :Irving Reid (No longer working on Firefox)
no flags Details
call DiscardNewMessage properly, only update size when downloading full message (7.38 KB, patch)
2012-10-25 22:23 PDT, :Irving Reid (No longer working on Firefox)
standard8: review+
standard8: approval‑comm‑aurora+
standard8: approval‑comm‑beta+
standard8: approval‑comm‑release+
Details | Diff | Review

Description lohner 2012-10-20 07:55:48 PDT
User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:16.0) Gecko/20100101 Firefox/16.0
Build ID: 20121010234852

Steps to reproduce:

I have dramatically growing mailfiles for subfolders in an IMAP account
This is happening under 16.0.1 under kubuntu. The server appears to be running dovecot:

openssl s_client -connect myhostxxxx.webpack.hosteurope.de:993
* OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.

It was also reporting individual mails with larger (2-5MB) attachments as only having a few (20-30) kb, so my guess is something to do with attachments. Running a repair on the folders fixed it (see below)

I am using this account from a server and a laptop. This may have started when I set up the subfolders (on the laptop as I was traveling) and moved mails into those subfolders. There are two thunderbirds accessing the account at the same time, the server and the laptop (both kubuntu with 16.0.1). The size explosion is happening on the server, and not on the laptop.

I ran out of disk space on /home twice before I saw what the cause was... seems to be as described in bug #463359
I also saw the symptoms as mentioned in bug #802217 with those two folder being continually refreshed (Downloading message x/x in folder1).

INITIAL SIZE:
total 41G
...
-rw------- 1 nils nils  13G Oct 20 15:21 2012-09-folder1
-rw-rw-r-- 1 nils nils  60K Oct 20 15:21 2012-09-folder1.msf
-rw------- 1 nils nils  28G Oct 20 15:49 2012-09-folder2
-rw-rw-r-- 1 nils nils  29K Oct 20 15:49 2012-09-folder2.msf

AFTER REPAIRING ONE IMAP FOLDER
total 13524448
...
-rw------- 1 nils nils 13784117540 Oct 20 15:52 2012-09-folder1
-rw-rw-r-- 1 nils nils       62679 Oct 20 15:52 2012-09-folder1.msf
-rw------- 1 nils nils    43021098 Oct 20 15:51 2012-09-folder2
-rw-rw-r-- 1 nils nils       35978 Oct 20 15:52 2012-09-folder2.msf

AFTER REPAIRING THE SECOND IMAP FOLDER
total 74832
-rw------- 1 nils nils 25172143 Oct 20 15:53 2012-09-folder1
-rw-rw-r-- 1 nils nils    60789 Oct 20 15:53 2012-09-folder1.msf
-rw------- 1 nils nils 43021098 Oct 20 15:51 2012-09-folder2
-rw-rw-r-- 1 nils nils    36180 Oct 20 15:53 2012-09-folder2.msf
Comment 1 lohner 2012-10-21 03:44:15 PDT
Also saw this in the Inbox and Sent folders this morning, repairing them fixed the problem- the individual mails had the right size, and the mailbox (which was huge but underreporting its size in the folder pane) as well.
Comment 2 James Ferguson 2012-10-22 10:55:36 PDT
A number of us are seeing this problem in our organization.  Compacting the mailbox is a temporary fix, but it starts growing again immediately.  My INBOX is ~80MB when compacted.  Grew to 20GB over a few hours.
Comment 3 lohner 2012-10-22 11:09:59 PDT
I'm seeing it again as well on a second machine (laptop accessing the same IMAP account and folders). Inbox reports 6MB with 43 messages... only 4-5 above 500kb (so the summed size in the folder display is consistent with the individual mail sizes _reported_ in the message list). On disk the Inbox has 230MB. And individual mails that have attachments report their size (correctly) in the attachment list at the bottom as 3-4 MB, but are listed as 30kb in the message list.

I have a feeling that this might have something to do with the mail having a graphic in the signature, and separate attachments, but I'm not sure. Those mails are coming from Outlook. I'm fairly sure that this didn't happen with TB15, but not 100% sure.
Comment 4 lohner 2012-10-22 12:59:30 PDT
Bug 803326 may be the same issue. Launchpad has the mailfile size bug which also reports huge mail files: https://bugs.launchpad.net/ubuntu/+source/thunderbird/+bug/1068921
Comment 5 Dietmar 2012-10-22 13:54:38 PDT
I created the report on launchpad.
I'm also connecting to webpack.hosteurope.de
A co-worker reported he also has the issue with another mail provider. I can try to find out what that server is running in order to know if it's related to the server connecting to.
Comment 6 Dietmar 2012-10-22 16:27:57 PDT
(In reply to Dietmar from comment #5)
> I can try to find out what that server is running in order to know if it's related
> to the server connecting to.

It's also running dovecot (dovecot-imapd 1:1.0.15-2.3+lenny1)
Comment 7 lohner 2012-10-22 20:39:09 PDT
I won't get the chance to do logging in the next few days, but if someone could, that would be great:

export NSPR_LOG_MODULES="imap:5,ImapAutoSync:5,mime:5,mgsdb:5,timestamp,sync"
export NSPR_LOG_FILE=/tmp/tbird.log

See https://wiki.mozilla.org/MailNews:Logging for more info.
Comment 8 lohner 2012-10-22 20:54:07 PDT
From the server login from the logfile:
xxx.webpack.hosteurope.de:NA:CreateNewLineFromSocket: 1 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS MULTIAPPEND UNSELECT IDLE CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS QUOTA]

No folders were growing at this point.
Comment 9 Ludovic Hirlimann [:Usul] 2012-10-22 22:08:35 PDT
Can any of ou seeing the issue give Irving (on the cc mist) access to such a server so he can investigate ?
Comment 11 Chris Coulson 2012-10-23 11:59:33 PDT
So, the first broken nightly appears to be https://ftp.mozilla.org/pub/mozilla.org/thunderbird/nightly/2012/06/2012-06-20-03-02-01-comm-central/thunderbird-16.0a1.en-US.linux-x86_64.tar.bz2

(https://ftp.mozilla.org/pub/mozilla.org/thunderbird/nightly/2012/06/2012-06-19-03-02-01-comm-central/thunderbird-16.0a1.en-US.linux-x86_64.tar.bz2 works ok)

I've also tracked it down to a specific message too. There seems to be 2 issues at play:
1) That the message is saved offline at all, as it is larger than the 50kB limit
2) When it is downloaded it never seems to get marked as available offline, so it is downloaded repeatedly every time the folder is updated (and ends up in the mbox file multiple times)
Comment 12 Chris Coulson 2012-10-23 12:00:49 PDT
Created attachment 674310 [details]
Message which triggers it

Here is a message which triggers it. Fortunately, it only contains spam :)
Comment 13 Chris Coulson 2012-10-23 12:14:38 PDT
Just waiting for my local checkout to build so that I can do a proper bisect, but these 2 commits might be a clue:

changeset:   10468:5a6bee217340
user:        Irving Reid <irving@mozilla.com>
date:        Tue Jun 19 08:55:19 2012 -0700
summary:     Bug 92111 (and bug 390795, and many others) - correctly handle case where we're downloading IMAP body in chunks, and the server lies about RFC822.SIZE,r=bienvenu

changeset:   10469:0401e822b882
user:        Irving Reid <irving@mozilla.com>
date:        Tue Jun 19 09:00:03 2012 -0700
summary:     Bug 740453: Investigate download whole message vs. download in chunks,r=bienvenu
Comment 14 :Irving Reid (No longer working on Firefox) 2012-10-23 13:15:55 PDT
Is somebody with the bug willing to test whether it's related to the offline message size limit? Open the Mail Server properties for a folder showing this problem (right click on the mail server, select "Settings...", select the "Synchronization and Storage" settings, and check whether you have "Don't download messages larger than x KB" checked.

If you do have it checked, try un-checking it and see if the problem goes away - your client should download the large messages one more time and then stop.


I've been looking at the log file on the Launchpad bug, and that log only shows us downloading each of the large messages once.
Comment 15 James Ferguson 2012-10-23 13:20:31 PDT
Irving: I do not have it checked and am seeing the issue (re Comment 14)
Comment 16 :Irving Reid (No longer working on Firefox) 2012-10-23 20:35:45 PDT
I've reproduced what I think is this issue on OS X against gmail's IMAP server. The problem comes in two parts, and so far I think I have a fix for part 1. I'll put up a WIP patch.
Comment 17 :Irving Reid (No longer working on Firefox) 2012-10-23 20:43:52 PDT
Created attachment 674524 [details] [diff] [review]
WIP: Call DiscardNewMessage() with non-null stream to avoid early exit

This is part 2 of the fix, when we detect a mismatch between the expected size of a message and the actual size we try to take the message back out of the local store. Because of some interactions with parameter-validity checking, the downloaded message contents weren't actually removed from the local mbox file. This would cause the file to grow, but shrink back to proper size when the folder is compacted.

The immediate trigger for the problem is that we're getting a bogus size for the message at http://mxr.mozilla.org/comm-central/source/mailnews/base/util/nsMsgDBFolder.cpp#1707; I haven't figured out why that's happening yet.
Comment 18 Wayne Mery (:wsmwk, NI for questions) 2012-10-24 03:56:46 PDT
(In reply to Chris Coulson from comment #13)
> summary:     Bug 92111 (and bug 390795, and many others) - correctly handle
> summary:     Bug 740453: Investigate download whole message vs. download in

nice detectiving!  will let you all sort this out
Comment 19 Chris Coulson 2012-10-24 04:31:25 PDT
I set a breakpoint in nsMsgDBFolder::EndNewOfflineMessage() to trigger when this condition occurs, and I made a note of various local variables when it happens (hopefully it will be useful):

Main thread:
tellPos = 4450254
messageOffset = 4271281
curStorePos = 178973
m_offlineHeader->GetMessageSize() returns 1778
m_bytesAddedToLocalMsg = 83
m_numOfflineMsgLines = 2447

On the IMAP thread (in nsImapProtocol::NormalMessageEndDownload()):
m_bytesToChannel = 178890
m_parser.fSizeOfMostRecentMessage = 178890
Comment 20 Chris Coulson 2012-10-24 13:36:47 PDT
Ok, some more info now. With the message attached to this bug report, if I break in nsMsgDBFolder::EndNewOfflineMessage() then I see the following:

Breakpoint 9, nsMsgDBFolder::EndNewOfflineMessage (this=0x7fffca4bb400) at /home/chr1s/src/thunderbird/comm-central/mailnews/base/util/nsMsgDBFolder.cpp:1719
1719           mDatabase->MarkOffline(messageKey, false, nullptr);
(gdb) p messageSize 
$15 = 4294959567
(gdb) p m_numOfflineMsgLines 
$16 = 11791
(gdb) p m_bytesAddedToLocalMsg 
$17 = 83
(gdb) p curStorePos 
$18 = 731268
(gdb) p messageSize + m_numOfflineMsgLines - m_bytesAddedToLocalMsg
$19 = 3979
(gdb) t 22
[Switching to thread 22 (Thread 0x7fffc9dff700 (LWP 22310))]
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
162     ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S: No such file or directory.
(gdb) f 7
#7  0x00007ffff30fb7b1 in nsImapProtocol::NormalMessageEndDownload (this=0x7fffcabae000) at /home/chr1s/src/thunderbird/comm-central/mailnews/imap/src/nsImapProtocol.cpp:3941
3941          m_imapMessageSink->NormalEndMsgWriteStream(m_downloadLineCache->CurrentUID(), imapAction == nsIImapUrl::nsImapMsgFetch, m_runningUrl, updatedMessageSize);
(gdb) p m_bytesToChannel 
$20 = 731185
(gdb) p m_parser.fSizeOfMostRecentMessage 
$21 = 731185

So, the amount of data downloaded matches the size from the server (731185), but doesn't match the size stored in the summary file (3979). Running with NSPR_LOG_MODULES="imap:5,ImapAutoSync:5,mime:5,mgsdb:5,timestamp,sync", I see this logged (uninteresting bits removed):

2012-10-24 17:37:28.538382 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SendData: 9 UID fetch 2:3 (UID X-GM-MSGID X-GM-THRID X-GM-LABELS 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 List-id X-Bugzilla-URL X-Launchpad-Bug X-Generated-By X-Launchpad-Message-Rationale X-Launchpad-Build-State)])
2012-10-24 17:37:28.588550 UTC - -908069120[7fffca734150]: ReadNextLine [stream=ca7fb3a0 nb=370 needmore=0]
2012-10-24 17:37:28.588614 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:CreateNewLineFromSocket: * 1 FETCH (X-GM-THRID 1416729568466002411 X-GM-MSGID 1416729568466002411 X-GM-LABELS () UID 2 RFC822.SIZE 731185 FLAGS (\Seen) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type List-id X-Bugzilla-URL X-Launchpad-Bug X-Generated-By X-Launchpad-Message-Rationale X-Launchpad-Build-State)] {357}
2012-10-24 17:37:28.596380 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:STREAM:OPEN Size: 731185: Begin Message Download Stream

  ** snip **

2012-10-24 17:37:31.973178 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SendData: 12 UID fetch 2 (BODYSTRUCTURE)
2012-10-24 17:37:32.030042 UTC - -908069120[7fffca734150]: ReadNextLine [stream=ca7fb3a0 nb=291 needmore=0]
2012-10-24 17:37:32.030089 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:CreateNewLineFromSocket: * 1 FETCH (UID 2 BODYSTRUCTURE (("TEXT" "PLAIN" ("CHARSET" "us-ascii") NIL NIL "7BIT" 0 0 NIL NIL NIL)("APPLICATION" "MSWORD" ("NAME" "UNITED") NIL NIL "BASE64" 727294 NIL ("ATTACHMENT" ("FILENAME" "UNITED KINGDOM.doc")) NIL) "MIXED" ("BOUNDARY" "0-1859073355-1331973544=:13772") NIL NIL))
2012-10-24 17:37:32.031068 UTC - -908069120[7fffca734150]: ReadNextLine [stream=ca7fb3a0 nb=15 needmore=0]
2012-10-24 17:37:32.031085 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:CreateNewLineFromSocket: 12 OK Success

  ** snip **

2012-10-24 17:37:32.031136 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SendData: 13 UID fetch 2 (BODY.PEEK[HEADER] BODY.PEEK[1.MIME] BODY.PEEK[2.MIME])
2012-10-24 17:37:32.080690 UTC - -908069120[7fffca734150]: ReadNextLine [stream=ca7fb3a0 nb=38 needmore=0]
2012-10-24 17:37:32.080724 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:CreateNewLineFromSocket: * 1 FETCH (UID 2 BODY[HEADER] {3611}
2012-10-24 17:37:32.080753 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:STREAM:OPEN Size: 0: Begin Message Download Stream

  ** snip **

2012-10-24 17:37:32.081880 UTC - -908069120[7fffca734150]: ReadNextLine [stream=ca7fb3a0 nb=15 needmore=0]
2012-10-24 17:37:32.081888 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:CreateNewLineFromSocket: 13 OK Success
2012-10-24 17:37:32.081928 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:STREAM:OPEN Size: 3969: Begin Message Download Stream
2012-10-24 17:37:32.081970 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-MessageRFC822: 0
2012-10-24 17:37:32.081981 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-MessageHeaders: 0
2012-10-24 17:37:32.081988 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-Part-Prefetched: 0
2012-10-24 17:37:32.082006 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-Multipart: 0
2012-10-24 17:37:32.082015 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-Boundary: 0
2012-10-24 17:37:32.082026 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-Leaf: 1
2012-10-24 17:37:32.082034 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-MIMEHeader: 1
2012-10-24 17:37:32.082045 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-Part-Inline: 1
2012-10-24 17:37:32.082052 UTC - -908069120[7fffca734150]: FetchTryChunking: curFetchSize 0
2012-10-24 17:37:32.082072 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SendData: 14 UID fetch 2 (BODY.PEEK[1])
2012-10-24 17:37:32.232584 UTC - -908069120[7fffca734150]: ReadNextLine [stream=ca7fb3a0 nb=30 needmore=0]
2012-10-24 17:37:32.232631 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:CreateNewLineFromSocket: * 1 FETCH (UID 2 BODY[1] {0}
2012-10-24 17:37:32.232662 UTC - -908069120[7fffca734150]: PARSER: fetch_literal chunk = 0, requested 0, receiving 0
2012-10-24 17:37:32.232674 UTC - -908069120[7fffca734150]: ReadNextLine [stream=ca7fb3a0 nb=3 needmore=0]
2012-10-24 17:37:32.232681 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:CreateNewLineFromSocket: )
2012-10-24 17:37:32.232692 UTC - -908069120[7fffca734150]: ReadNextLine [stream=ca7fb3a0 nb=15 needmore=0]
2012-10-24 17:37:32.232698 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:CreateNewLineFromSocket: 14 OK Success
2012-10-24 17:37:32.232715 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-Boundary: 0
2012-10-24 17:37:32.232733 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-Leaf: 2
2012-10-24 17:37:32.232747 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-XHeader: 2
2012-10-24 17:37:32.232753 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-MIMEHeader: 2
2012-10-24 17:37:32.232759 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-Filling: 2
2012-10-24 17:37:32.232766 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SHELL:GENERATE-Boundary-Last: 0
2012-10-24 17:37:32.232773 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:STREAM:CLOSE: Normal Message End Download Stream
2012-10-24 17:37:32.255161 UTC - -134432960[7ffff6c17480]: <html>
2012-10-24 17:37:32.255193 UTC - -134432960[7ffff6c17480]: 
2012-10-24 17:37:32.255199 UTC - -134432960[7ffff6c17480]: <head>
2012-10-24 17:37:32.255203 UTC - -134432960[7ffff6c17480]: 
2012-10-24 17:37:32.255210 UTC - -134432960[7ffff6c17480]: <title>MICROSOFT LOTTERY VIEW ATTACHMENT FOR DETAILS.</title>
2012-10-24 17:37:32.255215 UTC - -134432960[7ffff6c17480]: 
2012-10-24 17:37:32.255219 UTC - -134432960[7ffff6c17480]: <link rel="important stylesheet" href="chrome://messagebody/skin/messageBody.css">
2012-10-24 17:37:32.255224 UTC - -134432960[7ffff6c17480]: 
2012-10-24 17:37:32.255228 UTC - -134432960[7ffff6c17480]: </head>
2012-10-24 17:37:32.255232 UTC - -134432960[7ffff6c17480]: 
2012-10-24 17:37:32.255236 UTC - -134432960[7ffff6c17480]: <body>
2012-10-24 17:37:32.255247 UTC - -134432960[7ffff6c17480]: 
2012-10-24 17:37:32.273329 UTC - -134432960[7ffff6c17480]: <div class="moz-text-plain" wrap=true graphical-quote=true style="font-family: -moz-fixed; font-size: 12px;" lang="x-western"><pre wrap>
2012-10-24 17:37:32.273406 UTC - -134432960[7ffff6c17480]: </pre>
2012-10-24 17:37:32.273419 UTC - -134432960[7ffff6c17480]: </div>
2012-10-24 17:37:32.273534 UTC - -908069120[7fffca734150]: WARNING: Server's RFC822.SIZE 0 actual size 3979: file /home/chr1s/src/thunderbird/comm-central/mailnews/imap/src/nsImapProtocol.cpp, line 3932
2012-10-24 17:37:32.275002 UTC - -134432960[7ffff6c17480]: Updating stored message size from 731185, new size 3979

.....oooooooh :)

then...

2012-10-24 17:37:36.000688 UTC - -908069120[7fffca734150]: FetchTryChunking: curFetchSize 3979
2012-10-24 17:37:36.000737 UTC - -908069120[7fffca734150]: FetchMessage peek: curFetchSize 3979 numBytes 0
2012-10-24 17:37:36.000756 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:SendData: 16 UID fetch 2 (UID RFC822.SIZE BODY.PEEK[])
2012-10-24 17:37:36.220844 UTC - -908069120[7fffca734150]: ReadNextLine [stream=ca7fb3a0 nb=53 needmore=0]
2012-10-24 17:37:36.220900 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:CreateNewLineFromSocket: * 1 FETCH (UID 2 RFC822.SIZE 731185 BODY[] {731185}
2012-10-24 17:37:36.221291 UTC - -908069120[7fffca734150]: ca2bd800:imap.googlemail.com:S-[Google Mail]/Test:STREAM:OPEN Size: 731185: Begin Message Download Stream
2012-10-24 17:37:36.221349 UTC - -908069120[7fffca734150]: PARSER: fetch_literal chunk = 0, requested 3979, receiving 731185

Sorry for the braindump :)
Comment 21 Ludovic Hirlimann [:Usul] 2012-10-25 02:30:43 PDT
*** Bug 805265 has been marked as a duplicate of this bug. ***
Comment 22 Ludovic Hirlimann [:Usul] 2012-10-25 08:59:13 PDT
*** Bug 804100 has been marked as a duplicate of this bug. ***
Comment 23 Chris Coulson 2012-10-25 11:03:22 PDT
Created attachment 675206 [details] [diff] [review]
Only correct the message size when storing the message offline

Would something like this be sufficient to stop the wrong size being saved in the database? It seems to do the trick here, but I'm not familiar with this code enough to know if it breaks something else
Comment 24 Chris Coulson 2012-10-25 14:23:08 PDT
Created attachment 675293 [details] [diff] [review]
Fix broken size in message db

This fixes the broken size in the message db. Again, I'm not really sure if this takes the right approach, as I'm completely unfamiliar with this code :/
Comment 25 Chris Coulson 2012-10-25 14:24:10 PDT
With those changes applied, I see this when I start thunderbird for the first time:

WARNING: Underflow occurred: 'underflowed == false', file /home/chr1s/src/thunderbird/comm-central/mailnews/base/util/nsMsgDBFolder.cpp, line 1721
WARNING: Repairing message size in db: oldSize=3979, newSize=731185: file /home/chr1s/src/thunderbird/comm-central/mailnews/base/util/nsMsgDBFolder.cpp, line 1766

The size is now correct and it has successfully stored the message offline
Comment 26 :Irving Reid (No longer working on Firefox) 2012-10-25 14:36:03 PDT
I'm not comfortable with this approach; the message size we get (which is actually the size of one text part of the message, accidentally set when downloading parts of a MIME multipart message separately) is not guaranteed to be larger or smaller than the number of line breaks in the entire message. It usually is, for very large messages, but this won't be reliable.

I'm pretty close to having a clean way to not record the wrong size when we're downloading a part. I'm not sure how it will work for users with and existing wrong size in their message DB, they may need to manually rebuild the folder.
Comment 27 :Irving Reid (No longer working on Firefox) 2012-10-25 22:16:56 PDT
Created attachment 675465 [details]
Test message with many inline images

When I set the checkbox for maximum message size to store offline, with a limit of 50 kbytes, this message gets downloaded very inefficiently - each image attachment is requested from gmail separately, but for each inline image displayed we download the entire message (including separate downloads of each inline part) - order n^2 on the number of inline attachments.

Un-checking the limit on offline message store significantly reduces the problem.
Comment 28 :Irving Reid (No longer working on Firefox) 2012-10-25 22:23:32 PDT
Created attachment 675468 [details] [diff] [review]
call DiscardNewMessage properly, only update size when downloading full message

This includes my previous patch and also keeps track of when we're downloading an entire message, and only updates the message size in the DB on entire message downloads. This patch seems to fix the example message provided with the original report, after manually compacting or repairing the folder.

While testing this I noticed that there is still a form of message that behaves badly whether this patch is applied or not; I attached an example of that message. I haven't debugged that issue yet.
Comment 29 Mark Banner (:standard8) 2012-10-26 08:15:06 PDT
Comment on attachment 675468 [details] [diff] [review]
call DiscardNewMessage properly, only update size when downloading full message

Review of attachment 675468 [details] [diff] [review]:
-----------------------------------------------------------------

This looks fine afaict. It seems to do the right things and doesn't break existing tests.

::: mailnews/base/util/nsMsgDBFolder.cpp
@@ +1721,5 @@
> +       ReleaseSemaphore(static_cast<nsIMsgFolder*>(this));
> +       if (msgStore)
> +         // this closes the stream
> +         msgStore->DiscardNewMessage(m_tempMessageStream, m_offlineHeader);
> +       else 

nit: blank space on end of line

::: mailnews/imap/src/nsImapProtocol.cpp
@@ +3270,5 @@
>  
>      if (NS_SUCCEEDED(rv))
>         ParseIMAPandCheckForNewMail(commandString.get());
>      GetServerStateParser().SetFetchingFlags(false);
> +    m_fetchingWholeMessage = false;

For the two false cases, please can you include the comment:

// Always clear this flag after every fetch.

as I think it'll just help make it a bit more sense (and reflects what was there before)
Comment 30 lohner 2012-10-26 08:37:25 PDT
I possibly have another related issue... please let me know if it warrants a new bug. Moving one of these messages (not sure if it triggers it, but its in a folder and of a style where it happens often) to a subfolder shows it not arriving in the subfolder. I opened the subfolder on another machine and it was there, restarting tbird on the first machine and going to the folder made it show up there as well. So no data loss, but temporary disappearance.
Comment 32 :aceman 2012-10-29 01:14:25 PDT
*** Bug 806172 has been marked as a duplicate of this bug. ***
Comment 33 Mark Banner (:standard8) 2012-10-29 01:38:24 PDT
Marking as fixed for tracking purposes. This will be released in 16.0.2 later today.

Irving, please spin out the separate case into a new bug. If folks are still seeing issues, please check that new bug, and/or file a bug for your own issue.
Comment 34 Mark Banner (:standard8) 2012-10-29 02:23:13 PDT
*** Bug 802217 has been marked as a duplicate of this bug. ***
Comment 35 lohner 2012-10-29 23:45:46 PDT
Reopened bug 802217 as bug 806760 as that issue (constantly redownloading mails, even though now the mailfile size is not growing any more -- thanks!) is not fixed.
Comment 36 Tomas Gustavsson 2012-11-16 04:21:08 PST
802217 seems not to be reopened. And it is _not_ the same. Please reopen 802217.
Comment 37 Tomas Gustavsson 2012-11-16 04:23:00 PST
Just found 806760, sorry.
Comment 38 Wayne Mery (:wsmwk, NI for questions) 2015-11-28 20:11:52 PST
(In reply to :Irving Reid (No longer working on Firefox) from comment #28)
> ... 
> While testing this I noticed that there is still a form of message that
> behaves badly whether this patch is applied or not; I attached an example of
> that message. I haven't debugged that issue yet.

Does anyone know that a bug was created for the testcase message irving mentions? 
Which must have been attachment 675465 [details].
(I did not find a bug that irving created or cc on to cover this issue. http://mzl.la/1TeuXtT )

And it was never clearly stated, but sound like this was caused by bug 92111. 
Please comment if bug 92111 is not correct

Note You need to log in before you can comment on or make changes to this bug.