1363740 - Thunderbird goes crazy with activity after a bunch of imap folders are repaired

Status: RESOLVED INCOMPLETE

(Thunderbird :: Folder and Message Lists, defect)

Description

[Jonathan Kamens]

(I'm filing this against Thunderbird 45 because that's what I'm using right now, but I'm pretty certain I've seen this before on a newer trunk than that.)

Every once in a while I decide that my MSF files are too big and crufty, and/or some of them are corrupt due to unclean TB shutdowns and causing TB to hang periodically, so I go through all of the folders with large MSF files, open their properties, and click the "Repair folder" button on each of them.

I usually do this on a combination of some folders that are synchronized locally and some that are not. There are also some unsynchronized folders with a mixture of some messages that are local (because they were moved from a folder with synchronization enabled) and others that are headers-only. I'm not sure any of the information in this paragraph matters, but I'm mentioning it just for completeness.

Thunderbird consistently goes CRAZY when it starts working on repairing all the folders. Several "Bringing folder <whatever> up to date" messages appear in the activity manager, but progress on these usually freezes almost immediately and doesn't advance for HOURS.

In the meantime, I watch Thunderbird and watch it advance through three phases:

1) Many, many "Indexing" messages pop up in the activity manager briefly. This goes on for a long time.

2) Many, many "Deleting" messages pop up in the activity manager briefly. This goes on for a long time. Note that messages weren't actually deleted in the folders that the messages say messages are being deleted in.

3) The activity manager stops reporting anything except for the aforementioned frozen "Bringing folder <whatever> up to date" messages. However, in the status bar at the bottom of the main Thunderbird window, I see an infinite sequence of "Opening folder <whatever>" messages flashing by in quick succession. The folder names in these messages appear to be (some of) the ones I repaired. This appears to go on essentially forever, until I quit and restart Thunderbird.

While all of the above is going on TB is sucking tons of CPU, of course.

When I quite and restart Thunderbird, messages are downloaded normally and successfully in the synchronized folders which I had repaired, and everything returns to normal, proper behavior.

Comment 1

[Wayne Mery (:wsmwk)]

All of the things you describe, including slowness and high CPU, are to be expected when doing repair. Repair is not just a local operation, in the case of an imap folder it causes the folder contents to be redownloaded from the imap server.


> Every once in a while I decide that my MSF files are too big and crufty

msf and the related message file is reduced in size when a compact occurs, and compact is enabled by default. So msf should not be getting "bigger" than they should be. Further, folders don't necessarily get corrupt when Thunderbird hangs. 

I fail see why you are doing repairs. Rather, you should avoiding/solving whatever is causing your ills, which one might guess includes perceived slowness after some period of time. But you don't state your OS, which would help inform what advice could be given.

Comment 2

[Jonathan Kamens]

>All of the things you describe, including slowness and high CPU, are to be expected when doing repair. Repair is not just a local operation, in the case of an imap folder it causes the folder contents to be redownloaded from the imap server.

I know that, Wayne. I'm not a newbie. I've been using Thunderbird for decades, I maintain multiple Thunderbird add-ons, code of mine is included in Thunderbird core, and I've been building and maintaining email servers for thirty years.

This is not normal. As I explained quite clearly in my bug report, the messages are NOT being downloaded from the IMAP server, and the third stage I described above continues FOREVER -- really, I mean it, it never stops -- until I quit and restart Thunderbird. The most recent time this happened, earlier today, I waited several hours to see what would happen. It never finished. When I quit and restarted Thunderbird, it was able to download all the missing messages in all the repaired folders in just a few minutes.

>msf and the related message file is reduced in size when a compact occurs, and compact is enabled by default. So msf should not be getting "bigger" than they should be. Further, folders don't necessarily get corrupt when Thunderbird hangs.

That's all well and good, but that's not my personal experience, nor is it the personal experience of many other people. If you Google around a bit you will find many people reporting that Thunderbird starts wedging on them and that repairing all of their folders makes the problem go away. You'll even find Thunderbird support folks recommending that people periodically purge their MSF files and stating explicitly that MSF files can get corrupted as a result of unclean shutdowns. And as the maintainer of the Send Later add-on, I can assure you that I've received many, many verified reports over the years of people's folders getting corrupted and needing to be repaired.

So whether or not folders "necessarily" get corrupt, and whether or not msf files "should" be getting too big, the fact remains that both of these things happen on a regular basis to regular Thunderbird users. Asserting otherwise is not helpful.

>I fail see why you are doing repairs.

I have explained why I am doing repairs.

>Rather, you should avoiding/solving whatever is causing your ills, which one might guess includes perceived slowness after some period of time.

Yes, that's what some developers say every time this issue is raised in bugzilla, the support forums, etc. "There's some underlying problem you need to solve." That's not useful, nor is it even clear that it's true.

>But you don't state your OS, which would help inform what advice could be given.

Ubuntu 17.04.

If I sound annoyed, it's because it simply astounds me to see experienced Thunderbird developers continue, year after year, to deny that MSF corruption is a real problem in Thunderbird. This issue has been reported hundreds if not thousands of times, in various guises, in the support forums and in bugzilla. A small number of those reports were actually investigated and fixed. Most of them, however, are ignored, or "closed incomplete" because the person submitting the bug is unable to determine the root cause of the folder corruption. That's not their fault; it's Thunderbird's fault for having piss-poor logging and error-handling in much of its code base.

So, yeah, you can continue to deny the real, lived experience of someone who is an experienced, knowledgeable developer who wouldn't report an issue if he wasn't confident that it was real, or you can maybe do something else. Thanks.

Comment 3

[Wayne Mery (:wsmwk)]

I'm not a denier. Nowhere did I say that .msf/mork/yadayda isn't without problems.  But they are especially resistant to being debugged and fixed, changes risk widespread data corruption, etc - no one wants to touch it, with good reason.  Further, many msf problems are introduced by *other* bugs which are much easier to fix.  Which ones would you rather we spend time on? (says the person who is not a developer)

> the messages are NOT being downloaded from the IMAP server

Described where? #3?


Bare minimum to go forward, your issue would need to be reproduced in version 52. Or better yet with nightly build.



> Most of them, however, are ignored, or "closed incomplete" because the person submitting the bug is unable to determine the root cause of the folder corruption. 

Here I take exception.  I doubt any of these closed bugs were worth pursuing https://mzl.la/2q63qUA


> That's not their fault; it's Thunderbird's fault for having piss-poor logging and error-handling in much of its code base.

Well, here we can agree. But this requires reproducible conditions, and often a cooperative reporter. These are normally in short supply. 

Anyway, it may interest you to know that aspects of this are being worked on in bug 1176857 and related bugs.

Comment 4

[Wayne Mery (:wsmwk)]

I'd start with quantifying "MSF files are too big and crufty". What exactly does this mean with quantifiable information?  Pick just the worst folder as an example.

Comment 5

[Jonathan Kamens]

>I'd start with quantifying "MSF files are too big and crufty". What exactly does this mean with quantifiable information?  Pick just the worst folder as an example.

That is not what this bug is about.

This bug is about the behavior when I repaired a bunch of folders.

The size and "cruftiness" of the MSF files is irrelevant in the context of this bug, because the first thing Thunderbird does when you repair a folder is delete its MSF file and rebuild it from scratch.

I am happy to collaborate with a Thunderbird developer to attempt to obtain more information about corrupt MSF files, if indeed there is a developer interested in such collaboration, but (a) I am skeptical that it will be successful until/unless a substantial amount of effort is put into fixing missing error logging and handling in the code that works with MSF files, and (b) that work doesn't belong in this bug.

Comment 6

[Jonathan Kamens]

I've spent some more time playing with this in both 45.8.0 and last night's build to try to gain a better understanding of what's going on.

It seems like this manifests slightly differently each time I attempt to reproduce it, e.g., I didn't see a lot of "Deleted" messages this afternoon even though I did this morning. So I think that, at least, is a red herring which can probably be ignored for the time being.

In Thunderbird 45.8.0:

Enabling `NSPR_LOG_MODULES=imap:3` and `NSPR_LOG_FILE=/tmp/imap.log` seems to make the problem go away, so it appears to be timing or race-condition related.

I can reproduce the issue by repairing three folders: the Trash folder on account A which is configured to fetch only headers, and two other folders on account B which are configured to synchronize locally. The headers for the Trash folder get fetched, but then the other two folders just sit there in the activity manager, claiming they're downloading but not.

Once Thunderbird is in that state, it sucks a lot of CPU and generates a lot of traffic on port 993. I don't know what's _in_ that traffic because it's SSL and I can't use NSPR logging because that makes the problem go away.

From what I saw in the IMAP logs when I did have NSPR logging, I have a suspicion that (a) for some reason Thunderbird is fetching the headers of all the messages in the two folders in account B, rather than fetching all the messages, and (b) it's fetching the headers one by one rather than requesting many headers in a single IMAP command, which would be _much_ faster.

Note that even though Thunderbird is sucking CPU and generating a huge amount of traffic on port 993, it doesn't show any downloading activity in the status bar or activity manager.

If I exit and restart Thunderbird, it downloads the missing messages in the two folders in account B, and shows that it is doing so in both the activity manager and the status bar. Note that it's downloading _messages_, not _headers_, here.

I think it is possible that when I repaired a whole bunch of folders and waited several hours without seeing any download activity in the activity manager, for that entire time Thunderbird was downloading message headers from the various folders I had repaired, without telling me what it was doing so there was no indication that that's what was going on. This was clearly _far_ less efficient and _far_ slower than it needs to be, since when I exited and restarted Thunderbird it was able to download all of the missing messages in only a few minutes.

I suspect the the "Indexing" messages I was seeing flash in the activity manager over and over again throughout the hours when Thunderbird seemed to be doing nothing, was in fact Thunderbird indexing the _headers_ it had downloaded. I assume this means if I had waited all of the hours necessary for the header downloads to finish and for Thunderbird to start downloading full messages in those folders instead of headers, then the full messages would have been indexed a second time, replacing the header-only index entries for the same messages. This means that downloading headers for the folders before downloading complete messages means extra for for the full-text indexer in addition to the extra download work.

In nightly:

TL;DR nightly seems better but still seems to have issues.

In the most recently nightly build, I see "Downloading message header # of # in <account-B-folder>..." messages in my status bar, which I did not see in 45.8.0. So while it's still downloading headers when I think it should be downloading complete messages instead, at least it's showing me progress so I know something is going on, which 45.8.0 doesn't.

However, there appears to be some sort of issue with either those status messages or the work that Thunderbird is doing that produces them... I saw a series of messages of the form "Downloading message header X of Y in <folder>..." where X was significantly _higher_ than Y. Furthermore, X was also higher than the number of messages in <folder>.

This could mean that the status reporting is wrong, but it could also mean that Thunderbird is for some reason downloading message headers multiple times, i.e., doing more downloading and more work than it has to. If so, then I don't know whether this particular issue is knew in the nightly build, or is also present in 45.8.0, because these progress messages aren't displayed in 45.8.0.

Another difference between nightly and 45.8.0 is that even while Thunderbird is downloading tons of message headers in nightly, it still occasionally sneaks in a message download as shown by the counts of downloaded messages increasing in the activity manager, whereas in 45.8.0 while the headers are downloading the message download progress is completely frozen (as noted above, for hours at a time).

Once the headers finish downloading, message downloads get very fast and all the messages end up eventaully getting downloaded. Well, sort of. I did notice one other anomaly I'm not quite sure how to categorize.

I tried multiple times to reproduce this issue. During one of those attempts, all of the folders but one finished repairing and downloading properly in the nightly build. That one folder remained stuck on "Paused" in the activity manager. When I noticed that, I also noticed that it was also the folder that was currently selected in the folder list. I then selected a different folder, and immediately the paused folder resumed downloading to completion. I don't understand why this folder was in state "Paused" and Thunderbird was blocked from continuing to download it, or why selecting another folder unblocked it.

I noticed another issue, which may or may not be related to the issue I just described...

When I right-clicked on one of the three folders I repaired, opened its properties, and clicked its "Repair folder" button, Thunderbird cleared the message list and immediately started populating it with the just-downloaded headers for the folder being repaired, _even though that folder was not the one currently highlighted in the folder list._ In other words:

* Folder A is highlighted in the folder list.
* I right-click on Folder B, select "Properties", click "Repair folder" and click "OK".
* Folder B's messages (at least the ones whose headers have been downloaded so far) are now displayed in the message list, but
* Folder A is still highlighted in the folder list.

This seems like a bug. I don't think it is unique to the nightly build; I saw it in 45.8.0 as well.

Comment 7

[Jonathan Kamens]

Spinning off batching IMAP requests as a separate bug, bug 1364158.

Comment 8

[Jonathan Kamens]

Spinning off incorrect progress counts as a separate bug, bug 1364163.

Comment 9

[Jonathan Kamens]

Spinning off incorrect folder's messages being displayed in message list into bug 1364167.

Comment 10

[Jonathan Kamens]

If the three trunk bugs spun off above are all addressed, the overarching issue about which I filed this bug will be almost completely fixed, so I'm going to close this bug in favor of those three. I'm marking it "incomplete", though that isn't really the right status, because there isn't a more accurate status to use.