Mailbox grows endlessly, heavy traffic

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

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.

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.

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.

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

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.

(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)

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.

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.

Can any of ou seeing the issue give Irving (on the cc mist) access to such a server so he can investigate ?

Logged as per Comment 7.

See https://bugs.launchpad.net/ubuntu/+source/thunderbird/+bug/1068921/comments/15

with attachment:

https://bugs.launchpad.net/ubuntu/+source/thunderbird/+bug/1068921/+attachment/3410591/+files/tbird.log.gz

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)

Created attachment 674310
Message which triggers it

Here is a message which triggers it. Fortunately, it only contains spam :)

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 <email address hidden>
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 <email address hidden>
date: Tue Jun 19 09:00:03 2012 -0700
summary: Bug 740453: Investigate download whole message vs. download in chunks,r=bienvenu

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.

Irving: I do not have it checked and am seeing the issue (re Comment 14)

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.

Created attachment 674524
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.

(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

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

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:Create...

*** Bug 805265 has been marked as a duplicate of this bug. ***

*** Bug 804100 has been marked as a duplicate of this bug. ***

Created attachment 675206
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

Created attachment 675293
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 :/

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

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.

Created attachment 675465
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.

Created attachment 675468
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 on attachment 675468
call DiscardNewMessage properly, only update size when downloading full message

Review of attachment 675468:
-----------------------------------------------------------------

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)

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.

Trunk: https://hg.mozilla.org/comm-central/rev/e41fcf967c2b
Aurora: https://hg.mozilla.org/releases/comm-aurora/rev/dec20675b05e
Beta: https://hg.mozilla.org/releases/comm-beta/rev/e89e3afc6144
Release: https://hg.mozilla.org/releases/comm-release/rev/cce1d52502cc

*** Bug 806172 has been marked as a duplicate of this bug. ***

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.

*** Bug 802217 has been marked as a duplicate of this bug. ***

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.

802217 seems not to be reopened. And it is _not_ the same. Please reopen 802217.

Just found 806760, sorry.