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

Status: ASSIGNED

(MailNews Core :: Database, defect)

Description

[Wayne Mery (:wsmwk)]

1. set a low compact threshold in Settings
2. delete sufficient numbers of messages in several folders, of sizes that will well exceed the threshold
3. 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. 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.