1903174 - Automatic compact doesn't compact all folders when it encounters folders to which it does not have write access.

Status: RESOLVED FIXED

(MailNews Core :: Database, defect)

Description

[Wayne Mery (:wsmwk)]

(revised)

1. with Thunderbird shut down, in the OS change a Thunderbird folder's file to read only (rss feed, imap folder, etc)
2. set a low compact threshold in Settings
3. delete sufficient numbers of messages in several folders, of sizes that will well exceed the threshold
4. restart Thunderbird

Results: See that a) status bar only cites one folder (if any)

Restart again, with a different folder selected. Similar results.

I'm writing this from memory, so may not be 100% accurate word for word, but I did reproduce in every attempt.

Comment 1

[Brendan Abolivier [:babolivier]]

I've looked into this a bit, and it looks like this does not necessarily fit within our model for automatically compacting a message.

From what I gather, auto-compaction is done by the individual folder, when it gets updated (as opposed to being done by a centralised compaction service handling all the folders at once). For local folders, "updated" means whenever something gets removed from the folder, or moved to/from it; for IMAP it seems to be any operation on the folder (including downloading new messages).

In other words, rather than a central service that looks at all folders on startup, and then periodically/following specific actions, and decides that it can save up more than X MB of disk space (all folders combined), each folder individually looks at whether compacting itself would save up more than that amount (and kicks off the process if so, but only for themselves).

There does not seem to be any specific logic to kick this off at startup (and when testing with local folders, auto-compaction would generally not happen at startup). I can only guess, but I think what you may be seeing is a result of Thunderbird checking for new messages in the selected folder at startup, and then performing some operation on it that triggers the auto-compaction.

Would this match with your experience Wayne? Or do I seem to be missing something?

Comment 2

[Wayne Mery (:wsmwk)]

There does not seem to be any specific logic to kick this off at startup

That is correct, there is no such logic (specific to startup). And yes, individual folders keep track of their contents that could be compacted.

I should have stated that the steps in comment 0 is not about startup. It is merely a list of steps to trivially trigger automatic compact - because otherwise automatic compact will happen at most once an hour.

The main point of this bug is that automatic compact, when it is triggered, is not compacting ALL - folders which "contain" deleted message, and have recorded they have dead space. Because if they had all been compacted then your next startup would not again be triggering automatic compact.

FWIW, in Bug 1719072 - Compact should never run on (or near) startup - I go into some detail. (And yes, startup does end up triggering compact in real life for average users because of filters moving messages, etc)

Does that clarify?

Comment 3

[Ben Campbell]

(In reply to Wayne Mery (:wsmwk) from comment #0)

Results: See that a) status bar only cites one folder (if any)

Are you sure that it's not just the GUI being stupid and only showing the last folder?
When I rewrote the compaction, I kept the existing GUI calls so as to not have to modify any localisable strings.
It mostly just seems to splat messages into the status bar, overwriting whatever's there. So it's crap for showing operations that happen in quick succession...

The compact logging should help - INFO level should give a good summary of what it's actually doing: export MOZ_LOG="compact:3".

Looking at the autocompaction code:

The AutoCompact check is nsMsgDBFolder::AutoCompact(), and seems to be called after deleting messages.
It's latched to not run more than once per hour.

If it decides a compaction is in order, it kicks off nsMsgDBFolder::HandleAutoCompactEvent.
HandleAutoCompactEvent() looks like it attempts to compact every folder with a non-zero expunge count (i.e. anything with at least one deleted message).
It's an annoyingly complex function, should probably be in the account manager rather than folder code, and treats folders differently based on type (sigh).

Comment 4

[Wayne Mery (:wsmwk)]

(In reply to Ben Campbell from comment #3)

(In reply to Wayne Mery (:wsmwk) from comment #0)

Results: See that a) status bar only cites one folder (if any)

Are you sure that it's not just the GUI being stupid and only showing the last folder?

But I see the compact dialog on every startup.

When I rewrote the compaction, I kept the existing GUI calls so as to not have to modify any localisable strings.
It mostly just seems to splat messages into the status bar, overwriting whatever's there. So it's crap for showing operations that happen in quick succession...

The compact logging should help - INFO level should give a good summary of what it's actually doing: export MOZ_LOG="compact:3".

No compact log entries on multiple attempts

Comment 5

[Ben Campbell]

Hmm. I can't replicate this... it seems to be working fine for me with these steps:

1. I set up compaction logging: export MOZ_LOG="compact:3"
2. I set up a new profile and populate it with fake email (https://github.com/bcampbell/fakemail):
   • IMAP inbox, containing a few hundred messages (some with big attachments).
   • 3 local folders, with a few hundred messages (some with big attachments)
3. I delete a bunch of small messages from various folders (to stay under the auto-compact limit, but I leave one folder untouched, just to make test it's correctly excluded from the autocompact).
4. I delete enough big messages to put me past the auto compact limit
5. shut down TB and restart
6. the "Do you want to compact?" dialog pops up and I click "Yes please!"
7. I see the log output posted below
8. if I restart TB, I do not get another "do you want to compact?" dialog upon startup.

NOTE: I don't automatically get a compaction dialog at step 4... not quite sure why. Not so clear on hour the 1 hour latch time works, or is supposed to work. I think there's always a check at startup (probably just due to general IMAP update), and that resets the time? So maybe if I just left it for an hour?
I do get the dialog at startup, if the expunge conditions for autocompact are met.

Here's the log output I get when an autocompact is triggered (I also had a local "foo" folder, which I left untouched, and it correctly doesn't appear to have been compacted):

[Parent 19658: Main Thread]: I/compact AsyncCompactFolders() starting compaction of 3 folders
[Parent 19658: Main Thread]: I/compact BeginCompacting() folder='mailbox://nobody@Local%20Folders/wibble'
console.error: (new UnknownCollectionError("Unknown Collection \"thunderbird/bounce-tracking-protection-exceptions\"", "resource://services-settings/RemoteSettingsClient.sys.mjs", 188))
[Parent 19658: Main Thread]: I/compact OnCompactionComplete(status=0x0 oldSize=583390594 newSize=497758623)
[Parent 19658: Main Thread]: I/compact BeginCompacting() folder='mailbox://nobody@Local%20Folders/bar'
[Parent 19658: Main Thread]: I/compact OnCompactionComplete(status=0x0 oldSize=745534772 newSize=731545793)
[Parent 19658: Main Thread]: I/compact BeginCompacting() folder='imap://bob@localhost/INBOX'
[Parent 19658: Main Thread]: I/compact OnCompactionComplete(status=0x0 oldSize=1277455371 newSize=1277450216)
[Parent 19658: Main Thread]: I/compact AsyncCompactFolders() finished. TotalBytesRecovered=99626105

So it's exactly what I'd expect.

In your case, it sounds like something is blocking the compaction from even starting! No idea why, but I'll aim to add some "compact" logging to the autocompaction mechanisms to help get to the bottom of it.
I assume a manual right-click->"compact folder" outputs something to the compact log?

Comment 6

[Wayne Mery (:wsmwk)]

I'll aim to add some "compact" logging to the autocompaction mechanisms to help get to the bottom of it.

That would be great.

I assume a manual right-click->"compact folder" outputs something to the compact log?

Oddly, no. No idea why that is failing, given that imap logging was successful.

Comment 7

[Ben Campbell]

Attachment: Bug 1903174 - Add debug logging for AutoCompaction checking. r=#thunderbird-reviewers

Comment 8

[Ben Campbell]

(In reply to Wayne Mery (:wsmwk) from comment #6)

I assume a manual right-click->"compact folder" outputs something to the compact log?

Oddly, no. No idea why that is failing, given that imap logging was successful.

TBH, I don't think that my extra logging will help you out here... there seems to be something more fundamental.
Still worthwhile landing it to have some logging on the autocompact decisions though.

Can you try doing a manual compaction on a single local folder, with "compact:5" logging?
For the local folder compact, the log message is displayed almost immediately and there are very few code paths with don't show at least some logging (even if there's no compaction required!).
That'll at least make sure logging is working or not for you, then we can go from there.

IMAP is a little more complex, as mbox compaction is intertwined with server expunging... (which kind of makes sense from a UI point of view, but really they are unrelated operations).

Comment 9

[Ben Campbell]

(In reply to Ben Campbell from comment #8)

For the local folder compact, the log message is displayed almost immediately and there are very few code paths with don't show at least some logging (even if there's no compaction required!).

Sorry - I was wrong. If there are no deleted messages to compact, the compaction code isn't run - It seems there's a check further out in the JS side that avoids even calling the compaction code if there's nothing to compact. So you'll need to delete a message to get it to compact.

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/313bba014920
Add debug logging for AutoCompaction checking. r=mkmelin

Comment 11

[Worcester12345]

Got a strange message tonight about "can't compact folder Inbox-1". There was an Inbox-1 folder for a few moments, but then it went away.

Comment 12

[Wayne Mery (:wsmwk)]

I still fail at getting logs. But I have seen "all folders" be compacted on systems other than my Mac.
I have a theory, that maybe hitting a newsgroup account short circuits spinning through all the folders.

Comment 13

[Wayne Mery (:wsmwk)]

I found several RSS feeds whose folder files do not have write permissions for the current user (owner was a different Mac user). But the .msf file for the feed did (in most cases) have proper write permissions.

I fixed the write access file permissions and Thunderbird then compacted all folders, and reported an expected value for "xxx GB saved" (about 1.4gb)

Comment 14

[Wayne Mery (:wsmwk)]

However on a subsequent startup I was again prompted to compact, which ran and claimed to have saved 1.2GB. But a third startup did not offer compact.

Comment 15

[Ben Campbell]

(In reply to Wayne Mery (:wsmwk) from comment #14)

However on a subsequent startup I was again prompted to compact, which ran and claimed to have saved 1.2GB. But a third startup did not offer compact.

Hmm... that sounds a little odd that it took two goes, but it got there in the end?

(In reply to Wayne Mery (:wsmwk) from comment #13)

I found several RSS feeds whose folder files do not have write permissions for the current user (owner was a different Mac user). But the .msf file for the feed did (in most cases) have proper write permissions.

Is that likely to be a common case?
Rather than having a special case check here, I'm inclined to think that should just fall out as standard file-related error message popup or something - same as if your hard drive was full, say - although I'd bet the error message is currently not as informative as it probably should be :-)

Comment 16

[Wayne Mery (:wsmwk)]

Is that likely to be a common case?

Hopefully not.

Comment 17

[Wayne Mery (:wsmwk)]

Ramona, does this reproduce with version 102 or 115?

Comment 18

[Magnus Melin [:mkmelin]]

I can confirm this behavior. But I don't know what to expect. Should such folder just get skipped? Why is it read-only? That will be problems very soon anyway, so I'm not sure showing the alert isn't appropriate.

Comment 19

[Toby Pilling [:tobyp]]

Can we close this? This seems like it should behave in this way

Comment 20

[Wayne Mery (:wsmwk)]

(In reply to Toby Pilling [:tobyp] from comment #19)

Can we close this? This seems like it should behave in this way

In this case one could say the file is read-only due to user error. However, a failure could happen for other reasons - two off the top of my head: file locked by some other software (AV for example), file is read-only due to some other software having marked it so.

IMO it should just skip the offending file folder (maybe log something) and continue. No alert is needed.

To constantly fail the entire compact pass

• has potential to cause excessive disk usage
• WILL cause more frequent compacts than would otherwise happen (with attendant performance degradation), because Thunderbird's accounting of "amount of space to be compacted" will never go to zero.

Comment 21

[Ben Campbell]

I agree that a failing folder should not prevent other folders from being compacted (autocompaction or not).

The autocompaction and BatchCompactor code is a bit complicated at the moment - there are some delayed retry rules, but there's no real tracking of errors - the first failure causes the whole thing to bail out. Also, the GUI doesn't really handle multiple compaction very elegantly.
I'm currently rejigging the batch compaction handling to better track errors and retries for each folder (at the moment I think there's a possibility you could get a bad IMAP folder infinitely retrying the compaction every few seconds).

But basically, it won't bail out and complain until everything that can be compacted has been.
I won't do anything with the GUI - if there are multiple failing folders it'll just complain about the first failing one, which I think should be fine.

If the failing folder is the one that is over the threshold, then it will still trigger regular autocompact attempts, but I think that's fine too - all the other folders will be compacted.

Does that sound reasonable?

Comment 22

[Wayne Mery (:wsmwk)]

(In reply to Ben Campbell from comment #21)

I agree that a failing folder should not prevent other folders from being compacted (autocompaction or not).

The autocompaction and BatchCompactor code is a bit complicated at the moment - there are some delayed retry rules, but there's no real tracking of errors - the first failure causes the whole thing to bail out. Also, the GUI doesn't really handle multiple compaction very elegantly.
I'm currently rejigging the batch compaction handling to better track errors and retries for each folder (at the moment I think there's a possibility you could get a bad IMAP folder infinitely retrying the compaction every few seconds).

As long as full compact run doesn't happen more often than once per hour?

Does that sound reasonable?

SGTM

Comment 23

[Ben Campbell]

Attachment: Bug 1903174 - Modify BatchCompactor to attempt compaction on all given folders before reporting failures. r=#thunderbird-back-end-reviewers

This patch makes BatchCompactor collect error codes for failed compactions,
only reporting an error once attempts have been made to compact all target
folders.
Even though it can now track multiple failures, it only reports the first
failing folder via the GUI. This saves modifying error messages, and is
probably quite enough information for the user to be getting on with anyway.

It also tweaks the retry system for IMAP folders which cannot be compacted
yet due to pending offline or psuedo operations. When encountering such a
folder, it waits 3 seconds before retrying and imposes a limit of 5 retries
before failing.

Comment 24

[Ben Campbell]

TBH, this patch doesn't touch the autocompact logic or even the actual compaction code(!). It only affects the chunk which coordinates and tracks compaction of multiple folders.

So the rules which decide whether to kick off an autocompact haven't changed at all. I think those rules were OK as they were. If not, NI me here and I'll take a look.

Comment 25

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/142a1a992423
Modify BatchCompactor to attempt compaction on all given folders before reporting failures. r=mkmelin

Comment 26

[Toby Pilling [:tobyp]]

Hi Ben, does this need to stay open?

Comment 27

[Ben Campbell]

Nope :-)