1960105 - sporadically can't compact [Gmail]/Trash folder

Status: RESOLVED FIXED

(MailNews Core :: Database, defect, P1)

Description

[ujx51]

Attachment: Error Message

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:137.0) Gecko/20100101 Firefox/137.0

Steps to reproduce:

Using T-Bird mail normally. After reading a message I click the delete button and get an error message about not being able to compact the [Gmail]/Trash folder.

This is new since the update to 137.0. I'm using 137.0.1. The OS is Linux.

Actual results:

I get an error message about not being able to compact the [Gmail]/Trash folder. The exact message is: The folder '[Gmail]/Trash on [e-mail]' could not be compacted because writing to folder failed. Verify that you have enough disc space, and that your have write privileges to the file system, then try again. Sometimes after that the entry inbox goes blank and I have to restart T-Bird

Expected results:

Read email should have been moved to Trash folder with on issues or error messages.

Comment 1

[Corey Bryant]

Can you try to repair the Trash folder?

Kai, any thoughts?

Comment 2

[ujx51]

I'm pretty sure I tried repairing the folder previously but I just did it again to be sure. I will update status in a couple of days.

Comment 3

[Kai Engert [:KaiE:]]

Have there been any recent changes to folder compact code?

Comment 4

[Kai Engert [:KaiE:]]

Can this be reproduced using any gmail account, or just with some?

Comment 5

[Heather Ellsworth]

Have there been any recent changes to folder compact code?

Here is some recent folder compact changes: bug 1925117

Comment 6

[Ben Campbell]

Does the refusal to compact happen consistently (i.e. every time you delete a message in that folder), or is it more sporadic?
Is it only that folder, or are there others?

Comment 7

[ujx51]

It's sporadic and so far it's only happened on this folder.

Comment 8

[ujx51]

Happened again just now. Nothing done any different than normal. Just deleted a read email and got the pop up about not being able to compact.

Comment 9

[Ben Campbell]

Stupidly, it only just occurred to me that compaction has logging, so switching it on might throw up some clues!
eg export MOZ_LOG="compact:3"
(or even "compact:5", but that prints out logging for every single message in the folder being compacted).

The log message at the start of the compaction is:
"AsyncCompactFolders() starting compaction of {n} folders"
So it'd be interesting to see from there to wherever the error is thrown up.

Comment 10

[ujx51]

Two questions: 1) I'm embarrassed to say that I am unable to determine where T-Bird is logging any compaction errors. I did the export MOZ_LOG="compact:3" and then restarted T-Bird from the command line. Multiple errors show up but nothing regarding compaction so any help with that would be appreciated. 2) Since the Trash folder that's having the issues is linked directly to my Gmail account, why is T-Bird even trying to compact this folder since it resides (I think) on Google's servers?

Comment 11

[Magnus Melin [:mkmelin]]

See https://wiki.mozilla.org/MailNews:Logging#MOZ_LOG_FILE

Comment 12

[Magnus Melin [:mkmelin]]

Compaction is the operation of cleaning up the file that stores messages, locally. When a message is deleted it's first only marked as deleted and hidden. Then compaction comes along and removes it from the actual storage later.

Comment 13

[ujx51]

Attachment: Compaction Logs

Magnux Melin - Thank you for the link.

Here are logs of two events where compaction of the Trash folder fails:

Comment 14

[ujx51]

Attachment: log_file.moz_log

Comment 15

[ujx51]

Magnux Melin - Thank you for the link.

Here are logs of two events where compaction of the Trash folder fails:

2025-04-22 19:53:11.020421 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=2503942, purgeThreshold=15728640
2025-04-22 22:42:20.568851 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=5495291, purgeThreshold=15728640
2025-04-23 00:46:55.572952 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=6612486, purgeThreshold=15728640
2025-04-23 11:28:59.908906 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=7318919, purgeThreshold=15728640
2025-04-23 15:50:39.071391 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=9779199, purgeThreshold=15728640
2025-04-23 17:41:27.793379 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=13106631, purgeThreshold=15728640
2025-04-23 20:33:08.789352 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=14784073, purgeThreshold=15728640
2025-04-23 23:10:24.038985 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=19352216, purgeThreshold=15728640
2025-04-23 23:10:24.038998 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: okToCompact=true
2025-04-23 23:10:24.046116 UTC - [Parent 3559662: Main Thread]: I/compact AsyncCompactFolders() starting compaction of 5 folders
2025-04-23 23:10:24.059924 UTC - [Parent 3559662: Main Thread]: I/compact BeginCompacting() folder='mailbox://nobody@Local%20Folders/Drafts'
2025-04-23 23:10:24.060487 UTC - [Parent 3559662: Main Thread]: I/compact MboxCompactor - Compacting '/home/<XXX>/.thunderbird/1o7n9bgp.default/Mail/Local Folders/Drafts' into '/home/<XXX>/.thunderbird/1o7n9bgp.default/Mail/Local Folders/.compact-temp/Drafts.compacting'.
2025-04-23 23:10:24.132792 UTC - [Parent 3559662: Main Thread]: I/compact OnCompactionComplete(status=0x0)
2025-04-23 23:10:24.133576 UTC - [Parent 3559662: Main Thread]: I/compact OnFinalSummary(status=0x0 oldSize=1013491 newSize=220986)
2025-04-23 23:10:24.133754 UTC - [Parent 3559662: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<XXX>[e-mail]/[Gmail]/Trash' now. Queued for retry.
2025-04-23 23:10:24.136400 UTC - [Parent 3559662: Main Thread]: I/compact BeginCompacting() folder='imap://<XXX>[e-mail]/[Gmail]/Spam'
2025-04-23 23:10:24.137062 UTC - [Parent 3559662: Main Thread]: I/compact MboxCompactor - Compacting '/home/<XXX>/.thunderbird/1o7n9bgp.default/ImapMail/imap.googlemail.com/[Gmail].sbd/Spam' into '/home/<XXX>/.thunderbird/1o7n9bgp.default/ImapMail/imap.googlemail.com/[Gmail].sbd/.compact-temp/Spam.compacting'.
2025-04-23 23:10:24.177541 UTC - [Parent 3559662: Main Thread]: I/compact OnCompactionComplete(status=0x0)
2025-04-23 23:10:24.178753 UTC - [Parent 3559662: Main Thread]: I/compact OnFinalSummary(status=0x0 oldSize=2757754 newSize=2666755)
2025-04-23 23:10:24.236289 UTC - [Parent 3559662: Main Thread]: I/compact BeginCompacting() folder='imap://<XXX>[e-mail]/[Gmail]/Sent Mail'
2025-04-23 23:10:24.244796 UTC - [Parent 3559662: Main Thread]: I/compact MboxCompactor - Compacting '/home/<XXX>/.thunderbird/1o7n9bgp.default/ImapMail/imap.googlemail.com/[Gmail].sbd/Sent Mail' into '/home/<XXX>/.thunderbird/1o7n9bgp.default/ImapMail/imap.googlemail.com/[Gmail].sbd/.compact-temp/Sent Mail.compacting'.
2025-04-23 23:10:26.807621 UTC - [Parent 3559662: Main Thread]: I/compact OnCompactionComplete(status=0x0)
2025-04-23 23:10:26.856530 UTC - [Parent 3559662: Main Thread]: I/compact OnFinalSummary(status=0x0 oldSize=223497833 newSize=223292296)
2025-04-23 23:10:26.857094 UTC - [Parent 3559662: Main Thread]: I/compact BeginCompacting() folder='imap://<XXX>[e-mail]/INBOX'
2025-04-23 23:10:26.859728 UTC - [Parent 3559662: Main Thread]: I/compact MboxCompactor - Compacting '/home/<XXX>/.thunderbird/1o7n9bgp.default/ImapMail/imap.googlemail.com/INBOX' into '/home/<XXX>/.thunderbird/1o7n9bgp.default/ImapMail/imap.googlemail.com/.compact-temp/INBOX.compacting'.
2025-04-23 23:10:27.692674 UTC - [Parent 3559662: Main Thread]: I/compact OnCompactionComplete(status=0x0)
2025-04-23 23:10:27.710920 UTC - [Parent 3559662: Main Thread]: I/compact OnFinalSummary(status=0x0 oldSize=90504073 newSize=80089687)
2025-04-23 23:10:27.711207 UTC - [Parent 3559662: Main Thread]: I/compact BatchCompactor: Attempt 1. Retrying 1 folders in 3000ms
2025-04-23 23:10:30.767892 UTC - [Parent 3559662: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<XXX>[e-mail]/[Gmail]/Trash' now. Queued for retry.
2025-04-23 23:10:30.767910 UTC - [Parent 3559662: Main Thread]: I/compact BatchCompactor: Attempt 2. Retrying 1 folders in 3000ms
2025-04-23 23:10:33.772668 UTC - [Parent 3559662: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<XXX>[e-mail]/[Gmail]/Trash' now. Queued for retry.
2025-04-23 23:10:33.772688 UTC - [Parent 3559662: Main Thread]: I/compact BatchCompactor: Attempt 3. Retrying 1 folders in 3000ms
2025-04-23 23:10:36.786727 UTC - [Parent 3559662: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<XXX>[e-mail]/[Gmail]/Trash' now. Queued for retry.
2025-04-23 23:10:36.786744 UTC - [Parent 3559662: Main Thread]: I/compact BatchCompactor: Attempt 4. Retrying 1 folders in 3000ms
2025-04-23 23:10:39.807797 UTC - [Parent 3559662: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<XXX>[e-mail]/[Gmail]/Trash' now. Queued for retry.
2025-04-23 23:10:39.807823 UTC - [Parent 3559662: Main Thread]: E/compact BatchCompactor: too many attempts. Bailing out.
2025-04-23 23:10:39.808012 UTC - [Parent 3559662: Main Thread]: E/compact Failed to compact folder='imap://<XXX>[e-mail]/[Gmail]/Trash', status=0x8000ffff
2025-04-23 23:10:43.601516 UTC - [Parent 3559662: Main Thread]: I/compact BatchCompactor complete: 4 folders compacted, 1 failed, TotalBytesRecovered=11503427
2025-04-24 00:22:54.336557 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=28695555, purgeThreshold=15728640
2025-04-24 00:22:54.336570 UTC - [Parent 3559662: Main Thread]: I/compact AutoCompactEvent check: okToCompact=true
2025-04-24 00:22:54.342840 UTC - [Parent 3559662: Main Thread]: I/compact AsyncCompactFolders() starting compaction of 4 folders
2025-04-24 00:22:54.354514 UTC - [Parent 3559662: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<XXX>[e-mail]/[Gmail]/Trash' now. Queued for retry.
2025-04-24 00:22:54.356652 UTC - [Parent 3559662: Main Thread]: I/compact BeginCompacting() folder='imap://<XXX>[e-mail]/[Gmail]/Spam'
2025-04-24 00:22:54.357394 UTC - [Parent 3559662: Main Thread]: I/compact MboxCompactor - Compacting '/home/<XXX>/.thunderbird/1o7n9bgp.default/ImapMail/imap.googlemail.com/[Gmail].sbd/Spam' into '/home/<XXX>/.thunderbird/1o7n9bgp.default/ImapMail/imap.googlemail.com/[Gmail].sbd/.compact-temp/Spam.compacting'.
2025-04-24 00:22:54.435185 UTC - [Parent 3559662: Main Thread]: I/compact OnCompactionComplete(status=0x0)
2025-04-24 00:22:54.436642 UTC - [Parent 3559662: Main Thread]: I/compact OnFinalSummary(status=0x0 oldSize=2666755 newSize=2666755)
2025-04-24 00:22:54.489235 UTC - [Parent 3559662: Main Thread]: I/compact BeginCompacting() folder='imap://<XXX>[e-mail]/[Gmail]/Sent Mail'
2025-04-24 00:22:54.497458 UTC - [Parent 3559662: Main Thread]: I/compact MboxCompactor - Compacting '/home/<XXX>/.thunderbird/1o7n9bgp.default/ImapMail/imap.googlemail.com/[Gmail].sbd/Sent Mail' into '/home/<XXX>/.thunderbird/1o7n9bgp.default/ImapMail/imap.googlemail.com/[Gmail].sbd/.compact-temp/Sent Mail.compacting'.
2025-04-24 00:22:56.333174 UTC - [Parent 3559662: Main Thread]: I/compact OnCompactionComplete

Comment 16

[Kai Engert [:KaiE:]]

(In reply to ujx51 from comment #15)

2025-04-23 23:10:36.786744 UTC - [Parent 3559662: Main Thread]: I/compact BatchCompactor: Attempt 4. Retrying 1 folders in 3000ms
2025-04-23 23:10:39.807797 UTC - [Parent 3559662: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<XXX>[e-mail]/[Gmail]/Trash' now. Queued for retry.
2025-04-23 23:10:39.807823 UTC - [Parent 3559662: Main Thread]: E/compact BatchCompactor: too many attempts. Bailing out.
2025-04-23 23:10:39.808012 UTC - [Parent 3559662: Main Thread]: E/compact Failed to compact folder='imap://<XXX>[e-mail]/[Gmail]/Trash', status=0x8000ffff

Looks like a scenario that was introduced in bug 1903174.

It seems the attempt to compact the trash folder has repeatedly happened during 15 seconds, and because of a limit that was introduced in bug 1903174, the code gives up and decides to report the error.

Could it be a valid scenario that there were pending operations for 15 seconds, that prevented compact to start?

Comment 17

[Kai Engert [:KaiE:]]

Ben, could this be a regression of bug 1925117 ?
Would it make sense to create an experimental build that backs out bug 1925117 and ask reporters of these new issues, whether their new problems go away?

Comment 18

[Kai Engert [:KaiE:]]

Experimental backout build, no guarantees:
https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=045559abba7e44191df263550590e2856de41b22

Comment 19

[Ben Campbell]

@ujx51: Thanks for the logs - very useful!

Looking at the log in Comment #15, I can see that of the 5 folders picked for compaction, 4 of them were compacted without problem, but one (the Trash folder) it refused to compact.

The go/no-go decision is made by CanCompactNow():
https://searchfox.org/comm-central/rev/45f8c5bb09a833038a6d3ff06a3ee552663b45e5/mailnews/base/src/FolderCompactor.cpp#850

So it looks like it's refusing to proceed because there is outstanding IMAP activity (pseudo ops, or offline ops).

Annoyingly I can't tell which exact reason is triggering because the logging level is Debug (MOZ_LOG:"compact:4").
But I don't think that information would help much anyway.

My guess is that it's an offline op. The move-to-trash happened, but maybe the IMAP server either could not access the server, or took long enough to respond that the compaction had already started. In any case there was an operation still pending when the compaction triggered.
This seems like it could be the same thing as Bug 1959858.

Assuming that's the case, I don't think there's much the compaction code can actually do here. I think the options are:

1. the compaction could just ignore folders with outstanding IMAP operations (and not pop up an error message), in the hope that a future compaction will succeed.
2. the compaction code could just keep retrying that folder for longer...
3. the autocompact check shouldn't be done immediately after such operations anyway. It should just be an idle-time check that occurs at regular intervals when nothing much else is happening!

I'd vote for doing 1 for now, followed by 3 as a separate project.

The real solution is for IMAP to not be maintaining pseudoOps or offline operations at all! But that's a much much larger project, which is definitely on the radar but won't happen any time soon.

Comment 20

[Ben Campbell]

Attachment: Bug 1960105 - Tweak log levels for IMAP compaction refusal reasons. r=#thunderbird-reviewers

Comment 21

[Ben Campbell]

Easy to replicate when you know how:

1. run a profile with an IMAP account
2. disable the connection to the server (Don't use the in-app "go-offline" button, as that'll prevent "compact" appearing in the folder context menu! Either turn off networking, or kill the server, if you control it)
3. delete a message in a folder
4. right click on the folder and pick "Compact"

Wait 15 seconds for it to finish retrying.
Boom.

Same happens for autocompaction, but it's harder to trigger on demand obviously.

Comment 22

[Kai Engert [:KaiE:]]

(In reply to Ben Campbell from comment #19)

1. the compaction could just ignore folders with outstanding IMAP operations (and not pop up an error message), in the hope that a future compaction will succeed.

Sounds good to me.

2. the compaction code could just keep retrying that folder for longer...

I think there should be no harm in doing so.

I'd vote for doing 1 for now, followed by 3 as a separate project.

Should we do both 1 and 2 ?

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/8a261253dcb7
Tweak log levels for IMAP compaction refusal reasons. r=aleca

Comment 24

[Ben Campbell]

Attachment: Bug 1960105 - Suppress error dialog when folder compaction is blocked due to offline/pseudo ops. r=#thunderbird-back-end-reviewers

Folders can't be safely compacted if there are outstanding offline or pseudo
ops. When that happens, the BatchCompactor will retry such folders a few times
before giving up.
This can happen relatively often on intermittent/unreliable network
connections, so it's just intrusive to have a dialog box pop up.
A later compaction will succeed once the network connection is
restored and the offline/pseudo ops have been cleared.

Comment 25

[Ben Campbell]

That patch suppresses the error message when we can't compact a folder because there are pending ops.

I was looking at being a bit more fancy about increasing the delay between subsequent retries, but then I realised that you might get an autocompaction trigger while a manual compaction was retrying. That wouldn't cause any big problems (the lockout is done on a per-folder basis), but it seems a bit messy and could potentially lead to annoying dialog box errors (we should add a new message: "Sorry, this folder can't be compacted because it's being compacted" :- ).

So I left it at 5 retries, and increased the retry delay to 5 seconds. 25 seconds seems like reasonable compromise. If the offline ops aren't cleared by then the folder will just have to wait for the next compaction attempt.

Comment 26

[Kai Engert [:KaiE:]]

Let's leave this open after landing for a while, to allow discussion and more feedback

Comment 27

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/ae800480c1a3
Suppress error dialog when folder compaction is blocked due to offline/pseudo ops. r=mkmelin

Comment 28

[Magnus Melin [:mkmelin]]

Closing now not to confuse uplifts etc.
Probably worth getting this into 139 beta?

Comment 29

[Kai Engert [:KaiE:]]

(In reply to Magnus Melin [:mkmelin] from comment #28)

Probably worth getting this into 139 beta?

agreed

Comment 30

[Kai Engert [:KaiE:]]

Comment on attachment 9484709 [details]
Bug 1960105 - Suppress error dialog when folder compaction is blocked due to offline/pseudo ops. r=#thunderbird-back-end-reviewers

Uplift Approval Request

• Please state case for uplift consideration and ensure bug severity is set: Speedy testing of a potential fix for an issue affecting many users
• User impact if declined: User's annoyed by warnings
• Is this code covered by automated tests?: No
• Has the fix been verified in Daily?: Yes
• Has the fix been verified in Beta?: No
• Needs manual test from QA?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): Change timing of retries, and suppress a user visible prompt in a well understood scenario. Only minor tweaking of existing code.
• String changes made/needed:

Comment 31

[Corey Bryant]

Comment on attachment 9484709 [details]
Bug 1960105 - Suppress error dialog when folder compaction is blocked due to offline/pseudo ops. r=#thunderbird-back-end-reviewers

[Triage Comment]
Approved for beta

Comment 32

[Corey Bryant]

Comment on attachment 9484709 [details]
Bug 1960105 - Suppress error dialog when folder compaction is blocked due to offline/pseudo ops. r=#thunderbird-back-end-reviewers

[Triage Comment]
Approved for release

Comment 33

[Daniel Darnell [:dandarnell]]

Thunderbird 139.0b2:
https://hg.mozilla.org/releases/comm-beta/rev/0f39c9f9e53d

Comment 34

[Corey Bryant]

Thunderbird 138.0.2:
https://hg.mozilla.org/releases/comm-release/rev/4b1a1c997e4d