Closed Bug 1959858 Opened 1 year ago Closed 1 year ago

Error message compacting non-empty folder - "The folder 'Inbox on something@xxxx.yyy' could not be compacted because writing to folder failed. Verify that you have enough disk space, and that you have write privileges to the file system, then try again."

Categories

(MailNews Core :: General, defect, P1)

Product:
MailNews Core
Component:
General
Version:
Thunderbird 138
Type:
defect

Tracking

(thunderbird_esr140? fixed, thunderbird138 wontfix, thunderbird141 fixed)

Status:
RESOLVED FIXED
Milestone:
142 Branch
Tracking Flags:
Tracking Status
thunderbird_esr140 ? fixed
thunderbird138 --- wontfix
thunderbird141 --- fixed

People

(Reporter: wsmwk, Assigned: benc)

References

(Regression)

Details

(Keywords: regression, reproducible)

Attachments

(3 files, 2 external files)

Screenshot.png
56.60 KB, image/png
Details
Screenshot 5-31-25.
26.20 KB, image/png
Details
Tbird logging output with "compact:4,append" setting.
4.81 MB, text/plain
Details

Cloned from bug 1935331.

Error - Inbox on vseerror@xxxx.edu
The folder 'Inbox on vseerror@xxxx.edu' could not be compacted because writing to folder failed. Verify that you have enough disk space, and that you have write privileges to the file system, then try again.

This occurred with 138.0b1, on macbook with a profile a few months old with my three primary imap accounts, plus the account which errored [1]. I think I have never compacted this profile - I had auto compact enabled but set to prompt. I removed the prompt requirement, started Thunderbird, and got the error during the compact process.

[1] This particular account vseerror@xxxx.edu "should" have no corruption because the account has no filters, and no messages would have been deleted or moved into it's folders. In other words all the messages would have been downloaded via imap autosync - message sync is enabled. One oddity is the account hasn't been logged into for approximately two months, because the account is gone from the server.

This was found in the process of researching Bug 1952311 - All messages in all folders no longer visible - disappear (don't display) when compacting (auto compact) - shows only after restart - I encountered the following during automatic compact.

Forgot to mention, when the error occurs on startup, the selected folder is not from xxxx.edu account. And afaict there is no attempt by Thunderbird to log in to the account.

This is very reproducible. And even if there is "nothing" to compact - after a few startups the compact still occurs, and ends with "Done compacting (approx. xxxkb saved)". The value for amount saved is no where near the set compact threshold.

Keywords: reproducible
See Also: → 1952311
See Also: → 1960105

Is this a new regression?

Sounds pretty serious, let's upgrade priority until we understand better.

Severity: S3 → S2
Flags: needinfo?(vseerror)
Priority: -- → P1

Do you have STR with a fresh account?

Can anyone else reproduce?

Flags: needinfo?(vlucaci)

(In reply to Kai Engert [:KaiE:] from comment #2)

Is this a new regression?

Sorry, no idea how old. This particular profile is many months old, and I never had allowed compact to occur until I reported the bug.

I do not have better steps. Notable however, is the the fact that the account it fails on cannot be logged in to, the account no longer exists. If that is the precondition, then I wouldn't consider this to be a very severe bug.

Flags: needinfo?(vseerror)

Hello!

We have tried to reproduce this issue on
138.0b1( 20250403012914), 138.0b2(20250410152641) and 128.9.1esr(20250404032315) on macOS Sonoma and unfortunately we couldn’t reproduce the error on any of our accounts.

Flags: needinfo?(vlucaci)

I might have a clue which helps to reproduce that error. I am on Arch Linux, running 137.0.2. During "normal" operation i do not get those errors. However, i get them quite regularly after i wake the laptop up from suspend - and if there is a change in network connection

The wifi which i use during the train ride vanishes, and it takes a few seconds for the ethernet connection in the dock to take over. The "could not be compacted because writing to folder failed" error is already there before network manager announces the switch to the ethernet connection.

Maybe one can reproduce the problem by turning wifi off and use an ethernet connection, then send the laptop to sleep, unplug the ethernet and wait a few minutes before waking up (so that enough time passes that thunderbird will start a compact run).

Thanks to everyone working on thunderbird, have a nice day,
Michael

Thanks, Wayne and Michael - I'm assuming these are IMAP accounts?

I can't reproduce it via a manual compaction - I'm guessing it only happens with autocompact on IMAP accounts, when the server cannot be reached.
Compaction on IMAP also issues an EXPUNGE to the server, and I'm guessing this is what causes the error message.
The fact that the "Done compacting (approx. xxxkb saved)" status message is displayed seems to hint that the local mbox compaction is happening OK. Although maybe the EXPUNGE fail means that the folders expunge counter isn't being correctly updated, hence what you see in comment #1.
I don't think there's anything too serious going on here - just bad coordination between the compact and IMAP EXPUNGE error reporting.

I'll step through the autocompaction code and see what I can see.
The question is: what should the user be told if the local compaction can happen but not the IMAP EXPUNGE? It should be a "can't connect to server error", but I'm inclined to think the error should just be suppressed (or displayed in the status bar) rather than a popup...

Gah. Stalled with Bug 1962927. Will get back to you!

Hmm. I can't replicate this.
I tried by reducing the auto-compact thresholds to 0s delay and 0MB in code, so I can trigger autocompact at will via the "Get Messages" button.

I then deleted a few messages (which also triggers autocompaction, which worked fine).

I then turned off my IMAP server and triggered autocompact (via "Get Messages"), clicked "compact" on to the autocompact confirmation prompt, and it still worked fine.
(The "Get Messages" didn't complain that it couldn't connect to the server, which seems a little odd, but probably unrelated?)

So I don't know how to trigger this.

In any case, the compact log covers autocompaction (somewhat), so running with MOZ_LOG="compact:5" might shed some light? If not I'll add some more logging in to cover the result of IMAP EXPUNGE part of the compaction (the mbox compaction doesn't proceed until the EXPUNGE is completed).

(In reply to Ben Campbell from comment #8)

I don't think there's anything too serious going on here - just bad coordination between the compact and IMAP EXPUNGE error reporting.

In general i would agree, but that error is currently something that i see 3-4 times a day, so it depends on the usecase i guess. Also, this error message is shown every time i hit bug 1952311 - and this bug needs either reopening the folders in a new tab or a restart of thunderbird.

I will start thunderbird with MOZ_LOG="compact:5" , and report back soon. My guess is that i will see that error once i leave the train i am currently in ;)

Thanks for your work,
Michael

(In reply to brot+mozillabt from comment #11)

In general i would agree, but that error is currently something that i see 3-4 times a day, so it depends on the usecase i guess. Also, this error message is shown every time i hit bug 1952311 - and this bug needs either reopening the folders in a new tab or a restart of thunderbird.

Well, during the trainride i just hit #1952311 and did not get the error message. So it may not be everytime.

(In reply to brot+mozillabt from comment #7)

I might have a clue which helps to reproduce that error. I am on Arch Linux, running 137.0.2. During "normal" operation i do not get those errors. However, i get them quite regularly after i wake the laptop up from suspend - and if there is a change in network connection

Ahh, it looks like 137 didn't include a big chunk of the compaction changes I thought it did (see https://bugzilla.mozilla.org/show_bug.cgi?id=1925117#c37 ).
That said, Wayne said he hit it on 138.0b1, which as far as I can tell does have all the changes from Bug 1925117 ...

Hmm. Catching it in the logging should give some clues, and in the meantime I'm going to keep trying to replicate it locally.

(In reply to brot+mozillabt from comment #11)

(In reply to Ben Campbell from comment #8)

I don't think there's anything too serious going on here - just bad coordination between the compact and IMAP EXPUNGE error reporting.

In general i would agree, but that error is currently something that i see 3-4 times a day, so it depends on the usecase i guess.

Sorry, yes - I didn't mean to imply it wasn't a complete pain in the neck :-)

I'm thinking this might be the same as Bug 1960105.

My prediction: the compaction logs will have errors like this:

"E/compact BatchCompactor - Can't compact 'imap://blah@blah/blah/blah' now. Queued for retry."

Which indicates the compaction is refusing to proceed for the folder because of being IMAP pseudoOps or offline ops.

Steps-to-replicate over at: bug 1960105 comment 21

[UPDATE: no longer relevant. We're dealing with some other issue now]

Duplicate of this bug: 1963718

Is there any update on this bug? Any idea if this is widespread or isolated?

Having to close and restart TB several times every day is a real PITB...

There's been progress on bug 1960105 which may be the same

I'm getting the same error message using Tbird 138.0 on Win 11 upon opening Tbird.

Duplicate of this bug: 1964306
Summary: Error message "could not be compacted because writing to folder failed." when compacting (non-empty) folder → Error message compacting non-empty folder - "The folder 'Inbox on something@xxxx.yyy' could not be compacted because writing to folder failed. Verify that you have enough disk space, and that you have write privileges to the file system, then try again."

The fix from Bug 1960105 is going into 139 and I'm reasonably sure this is the same issue.
139 is currently in the beta channel.

I also have this bug sometimes on startup in version 138.0.1 (Win11).

Attached image Screenshot.png —

I have this issue every day in version 138.0.2 on an older computer running Windows 10. It's always been a bit slow, and Tbird would frequently get in a "not responding" state for a minute or two, but it didn't have this problem until recently, maybe v138 or v138.0.1. And sometimes after hitting OK for that message, the message list view would be empty and display "No messages", even though there are messages, and it would require restarting.

I just hit that issue again and in the console there's an error that might be related:

09:41:44.770 An error occurred updating the cmd_downloadSelected command: [Exception... "[JavaScript Error: "gViewWrapper.dbView is null" {file: "chrome://messenger/content/about3Pane.js" line: 6413}]'[JavaScript Error: "gViewWrapper.dbView is null" {file: "chrome://messenger/content/about3Pane.js" line: 6413}]' when calling method: [nsIController::isCommandEnabled]"  nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame :: chrome://messenger/content/globalOverlay.js :: getEnabledControllerForCommand :: line 49"  data: yes] globalOverlay.js:81:13

And then 1000s of warnings (there are a lot of emails in the Inbox) like this:

09:42:08.257 gloda.index_msg: Observed header that claims to be gloda indexed but that gloda has never heard of during compaction. In folder: imap://[redacted]@[redacted].com/INBOX sketchy key: 486001 subject: [redacted] IndexMsg.sys.mjs:1332:21

The first issue was just fixed in bug 1952311 comment 117 and the second one in bug 1963490.

Both of these are not the error message which is subject of this bug.

(In reply to Ben Campbell from comment #21)

The fix from Bug 1960105 is going into 139 and I'm reasonably sure this is the same issue.
139 is currently in the beta channel.

According to comment 24, bug 1960105 which is in 138.0.2 didn't fix the issue.

I have "Compact all folders when it will save over": "8 MB in total" enabled here. Today the error message almost always was shown on startup. Then I've compacted the folder manually and the error seems to be gone (at least for now).

Thunderbird 138.0.2 / Win11

1 POP3 account
1 IMAP account

Installed 139.0.
Still having the same error pop up.

Duplicate of this bug: 1969268
Attached image Screenshot 5-31-25. —

Still seeing this error come up with version 139.

Ben, do we need anything from the user(s) of comment 31 and comment 29?

Flags: needinfo?(benc)

I think running with the compaction log enabled might help:

MOZ_LOG="compact:3"

(Level 3 ("info") to start with, increasing the level to 5 ("verbose") if needed...)

Logs go out to stdout by default, so on windows you might want to output to a file instead:

MOZ_LOG_FILE="filename-goes-here"
Flags: needinfo?(benc)

nedsolot, maik, mozilla, David, can you get a log per comment 33?

More details at https://wiki.mozilla.org/MailNews:Logging#Gecko_Logging

Flags: needinfo?(nedsolot)
Flags: needinfo?(mozilla)
Flags: needinfo?(maik.diessner)
Flags: needinfo?(dvdhbs)

I can try when the error shows up again. After my last comment I didn't see the error anymore.

Flags: needinfo?(maik.diessner)

The bug only shows up for me during automatic compactions, never when I compact manually. I was able to invoke the bug by setting the automatic compaction threshold very low and then repeatedly deleting enough messages to invoke the compaction.

Flags: needinfo?(mozilla)

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

nedsolot, maik, mozilla, David, can you get a log per comment 33?

More details at https://wiki.mozilla.org/MailNews:Logging#Gecko_Logging

Traveling for the next week, so I don't have access to the PC running TB.

Flags: needinfo?(nedsolot)

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

nedsolot, maik, mozilla, David, can you get a log per comment 33?

More details at https://wiki.mozilla.org/MailNews:Logging#Gecko_Logging

I set MOZ_LOG="compact:3", but no messages were logged, so I set it to "compact:4", which output many lines.

The first two times I ran Tbird I got the error popup, but the third time I didn't get it -- so maybe it is doing some compacting despite the error, but it takes more than one go?

I'll attach my log file.

Flags: needinfo?(dvdhbs)

I would like to know on which operating systems this issue is experienced.

If you have recently seen this bug, could you please state which OS you use? Windows, macOS, Linux?

Windows 11 Pro 23H2 here

(In reply to Ramona Gavrilescu from comment #5)

We have tried to reproduce this issue on
138.0b1( 20250403012914), 138.0b2(20250410152641) and 128.9.1esr(20250404032315) on macOS Sonoma and unfortunately we couldn’t reproduce the error on any of our accounts.

Have you tried to reproduce on Windows or Linux?

Flags: needinfo?(ramona)

(In reply to Kai Engert [:KaiE:] from comment #40)

I would like to know on which operating systems this issue is experienced.

If you have recently seen this bug, could you please state which OS you use? Windows, macOS, Linux?

I've experienced it on Windows 10 & 11.

Thanks for confirming it happens on Windows.

Does anyone experience it on Linux or macOS?

(In reply to Kai Engert [:KaiE:] from comment #40)

I would like to know on which operating systems this issue is experienced.

If you have recently seen this bug, could you please state which OS you use? Windows, macOS, Linux?

Win 10 Pro

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

nedsolot, maik, mozilla, David, can you get a log per comment 33?

More details at https://wiki.mozilla.org/MailNews:Logging#Gecko_Logging

Do you still want me to do a log?
If so, can you please point me to instructions and which parameters/levels do you want?

Thanks, I have not done TB logging before.

(In reply to David Hobbs from comment #38)

I set MOZ_LOG="compact:3", but no messages were logged, so I set it to "compact:4", which output many lines.

Are you sure compact:3 didn't output any logging? all the "Info"-level lines (i.e. I/compact ...) would be output at that level.
compact:4 is "Debug" level, and includes the D/compact lines (and there are a lot - it log the compact/don't-compact decision for every message).

"Info" level (compact:3) should be enough here - it shows the basic compaction decisions (just not per-message), logs the beginning and end for each folder, and will include any warnings and errors that might occur.

I'll attach my log file.

Hmm. That log file is clipped - it just finishes mid-line :-( Nothing out of the ordinary up to that point, it all seemed to be chugging away nicely.
But I don't think I've ever seen a log file stop in mid-flow like that, which is odd - it doesn't tell us anything about how the compaction finished...

(In reply to Ben Campbell from comment #47)

(In reply to David Hobbs from comment #38)

I set MOZ_LOG="compact:3", but no messages were logged, so I set it to "compact:4", which output many lines.

Are you sure compact:3 didn't output any logging? all the "Info"-level lines (i.e. I/compact ...) would be output at that level.
compact:4 is "Debug" level, and includes the D/compact lines (and there are a lot - it log the compact/don't-compact decision for every message).

"Info" level (compact:3) should be enough here - it shows the basic compaction decisions (just not per-message), logs the beginning and end for each folder, and will include any warnings and errors that might occur.

I've tried multiple times, and compact:3 does nothing whereas compact:4 outputs both info and debug levels.

Hmm. That log file is clipped - it just finishes mid-line :-( Nothing out of the ordinary up to that point, it all seemed to be chugging away nicely.
But I don't think I've ever seen a log file stop in mid-flow like that, which is odd - it doesn't tell us anything about how the compaction finished...

My log files are always clipped as if the output is buffered and the last of it doesn't make it to disk.

(In reply to David Hobbs from comment #48)

I've tried multiple times, and compact:3 does nothing whereas compact:4 outputs both info and debug levels.
[snip]
My log files are always clipped as if the output is buffered and the last of it doesn't make it to disk.

Oh, I've not seen that before... The gecko logging system has been around forever, so I figure it's solid by now, and would be pretty good at flushing stuff to disk.
It doesn't sound like TB is abruptly crashing, so I'm at a bit of a loss here (probably unrelated to this bug, but it's worrying in it's own right)

Has anyone else here encountered clipped MOZ_LOG files before?

Wayne - are you still able to replicate this bug? If so, any chance I could get you to have a go at generating a log file? (compact:3 should be fine)

Flags: needinfo?(vseerror)

(In reply to David Hobbs from comment #48)

My log files are always clipped as if the output is buffered and the last of it doesn't make it to disk.

May be worth trying MOZ_LOG="compact:3,sync"?
The "sync" forces a flush after each log write, and is really only for cases where things are dying in a hard crash, but hey, worth a go. Might throw up some clues.

Flags: needinfo?(dvdhbs)

(In reply to Ben Campbell from comment #51)

(In reply to David Hobbs from comment #48)

My log files are always clipped as if the output is buffered and the last of it doesn't make it to disk.

May be worth trying MOZ_LOG="compact:3,sync"?
The "sync" forces a flush after each log write, and is really only for cases where things are dying in a hard crash, but hey, worth a go. Might throw up some clues.

Yes, compact:3,sync fixes both problems: the info level messages are being output to my file, and none of the messages are truncated.

Flags: needinfo?(dvdhbs)

Notes, mostly to myself:

There's only one place that ever displays that error message ("compactFolderWriteFailed").
It is used as a catch-all message when a compaction fails with an error we don't have a more specific message for:

https://searchfox.org/comm-central/rev/6be736b17760ed9a9c15bbde8d045e1982b8a6a7/mailnews/base/src/FolderCompactor.cpp#989-1033

The exact error code isn't displayed in the error message, but it is logged. So I'm hoping that someone can capture it happening in a log, which will give some clue as to what is really going wrong.

(In reply to David Hobbs from comment #52)

Yes, compact:3,sync fixes both problems: the info level messages are being output to my file, and none of the messages are truncated.

Fantastic, thanks! Now, if you can catch a log of it happening, there should be a line like E/compact Failed to compact folder='imap://blahblah', status=0x??????? and that status code is what I'm interested in...

(In reply to Ben Campbell from comment #50)

Wayne - are you still able to replicate this bug? If so, any chance I could get you to have a go at generating a log file? (compact:3 should be fine)

I haven't seen it lately. Not sure whether I can force it.
I'll keep the NI for now.

Just seen on daily 141 on Mac. I'll try to get a log.

status-thunderbird138: affected → wontfix
status-thunderbird141: --- → affected
See Also: → 1937431

(In reply to Ben Campbell from comment #54)

Fantastic, thanks! Now, if you can catch a log of it happening, there should be a line like E/compact Failed to compact folder='imap://blahblah', status=0x??????? and that status code is what I'm interested in...

It took a bunch of tries, but I finally got the error again, and the log message was:

E/compact Failed to compact folder='imap://***@imap.***/INBOX', status=0x8052000e

(In reply to David Hobbs from comment #57)

E/compact Failed to compact folder='imap://***@imap.***/INBOX', status=0x8052000e

Thanks David. That code means: NS_ERROR_FILE_IS_LOCKED

Thanks David. That code means: NS_ERROR_FILE_IS_LOCKED

Anitivirus SW ?

I'm not using any antivirus here.

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

Thanks David. That code means: NS_ERROR_FILE_IS_LOCKED

Anitivirus SW ?

No antivirus.

(In reply to Ben Campbell from comment #15)

Steps-to-replicate over at: bug 1960105 comment 21

These steps are no longer any use for this bug.
The NS_ERROR_FILE_IS_LOCKED fail is something different.
I'll be interested to see if Wayne manages to capture it happening on Mac, and if it is indeed the NS_ERROR_FILE_IS_LOCKED error. It could still be windows-specific.

(In reply to David Hobbs from comment #57)

It took a bunch of tries, but I finally got the error again, and the log message was:

E/compact Failed to compact folder='imap://***@imap.***/INBOX', status=0x8052000e

Thanks!

What did the preceeding part of the log look like? Were there any error lines (E/compact ....) before that one?
It'd probably be useful to see a chunk of what was being logged just before that line - it might give some more clues as to how it got there.

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

Thanks David. That code means: NS_ERROR_FILE_IS_LOCKED

Anitivirus SW ?

I use Avast Premium Security which includes a "Mail Shield" component to scan inbound and outbound email.
Avasst just released a new version (1 day ago) If this bug persists with the new release , I can try temporarily disabling the Mail Shield to see if that might isolate the problem.

I've been using Avast for years with TB without this problem, but certainly cannot rule out a software conflict. If other people reporting this TB issue are also using Avast, that would be useful info.

(In reply to Ben Campbell from comment #63)

What did the preceeding part of the log look like? Were there any error lines (E/compact ....) before that one?
It'd probably be useful to see a chunk of what was being logged just before that line - it might give some more clues as to how it got there.

There was one other error message two lines earlier. Here's the whole chunk from the log file:

[Parent 31004: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=22562251, purgeThreshold=2097152
[Parent 31004: Main Thread]: I/compact AutoCompactEvent check: okToCompact=true
[Parent 31004: Main Thread]: I/compact AsyncCompactFolders() starting compaction of 1 folders
[Parent 31004: Main Thread]: I/compact BeginCompacting() folder='imap://<username>%40<mailserver>@imap.<mailserver>/INBOX'
[Parent 31004: Main Thread]: I/compact MboxCompactor - Compacting 'C:\Users\<username>\AppData\Roaming\thunderbird\Profiles\<profile>.default\ImapMail\imap.<mailserver>\INBOX' into 'C:\Users\<username>\AppData\Roaming\thunderbird\Profiles\<profile>.default\ImapMail\imap.<mailserver>\.compact-temp\INBOX.compacting'.
[Parent 31004: Main Thread]: I/compact OnCompactionComplete(status=0x0)
[Parent 31004: Main Thread]: E/compact FolderCompactor - rename 'C:\Users\<username>\AppData\Roaming\thunderbird\Profiles\<profile>.default\ImapMail\imap.<mailserver>\INBOX.msf' to 'C:\Users\<username>\AppData\Roaming\thunderbird\Profiles\<profile>.default\ImapMail\imap.<mailserver>\.compact-temp\INBOX.msf.original' (rv=0x8052000e)
[Parent 31004: Main Thread]: I/compact OnFinalSummary(status=0x8052000e oldSize=952067472 newSize=929505186)
[Parent 31004: Main Thread]: E/compact Failed to compact folder='imap://<username>%40<mailserver>@imap.<mailserver>/INBOX', status=0x8052000e
[Parent 31004: Main Thread]: I/compact BatchCompactor complete: 0 folders compacted, 1 failed, TotalBytesRecovered=0

(In reply to David Hobbs from comment #65)

There was one other error message two lines earlier. Here's the whole chunk from the log file:

[Parent 31004: Main Thread]: I/compact AutoCompactEvent check: totalExpungedBytes=22562251, purgeThreshold=2097152
[Parent 31004: Main Thread]: I/compact AutoCompactEvent check: okToCompact=true
[Parent 31004: Main Thread]: I/compact AsyncCompactFolders() starting compaction of 1 folders
[Parent 31004: Main Thread]: I/compact BeginCompacting() folder='imap://<username>%40<mailserver>@imap.<mailserver>/INBOX'
[Parent 31004: Main Thread]: I/compact MboxCompactor - Compacting 'C:\Users\<username>\AppData\Roaming\thunderbird\Profiles\<profile>.default\ImapMail\imap.<mailserver>\INBOX' into 'C:\Users\<username>\AppData\Roaming\thunderbird\Profiles\<profile>.default\ImapMail\imap.<mailserver>\.compact-temp\INBOX.compacting'.
[Parent 31004: Main Thread]: I/compact OnCompactionComplete(status=0x0)
[Parent 31004: Main Thread]: E/compact FolderCompactor - rename 'C:\Users\<username>\AppData\Roaming\thunderbird\Profiles\<profile>.default\ImapMail\imap.<mailserver>\INBOX.msf' to 'C:\Users\<username>\AppData\Roaming\thunderbird\Profiles\<profile>.default\ImapMail\imap.<mailserver>\.compact-temp\INBOX.msf.original' (rv=0x8052000e)

^^^^^^^ This line is the smoking gun! It pins down the exact operation that's failing with NS_ERROR_FILE_IS_LOCKED.

[Parent 31004: Main Thread]: I/compact OnFinalSummary(status=0x8052000e oldSize=952067472 newSize=929505186)
[Parent 31004: Main Thread]: E/compact Failed to compact folder='imap://<username>%40<mailserver>@imap.<mailserver>/INBOX', status=0x8052000e
[Parent 31004: Main Thread]: I/compact BatchCompactor complete: 0 folders compacted, 1 failed, TotalBytesRecovered=0

The mbox file compaction succeeded (OnCompactionComplete()), the new database file was all built and ready to drop in place.

But it fails when trying to back up the original database file, renaming INBOX.msf to .compact-temp/INBOX.msf.original.
So I would say something is keeping the pre-compaction database file locked (INBOX.msf).
That should be really easy to track down... but the relationship between the database object and the actual file is prettyt opaque and convoluted...

During the compaction preamble, we free the folders hold on the database by calling nsIMsgFolder.closeDatabase():
https://searchfox.org/comm-central/rev/3a9b412a385ce41aaec04b043549d9146639d8db/mailnews/base/src/FolderCompactor.cpp#229

That calls nsIMsgDatabase.forceClosed(), which should release all any open filehandles using the DB file...
forceClosed() will commit any outstanding changes to the DB that haven't yet been written to disk (as it should!), but as far as I'm aware, it's a synchronous operation, so the potentially-locking write should be done by the time it returns.

I wonder if something else is jumping in and opening the database again after that .forceClosed(), but before the compaction has finished? for example, maybe gloda kicks in and tries to index some messages (gloda does write updates to the DB to add gloda-ids)...
That shouldn't happen because the folder (and by extension the database) is "locked" by the compaction... but badly-behaving code will plough ahead anyway and just not check the folder "lock" status... sigh...

NIing Geoff rather arbitrarily here for next week: any ideas on other systems which might try to open a database while the folder is locked during compaction?

Flags: needinfo?(geoff)

David: A bit of a clutching-at-straws suggestion, but does it still happen if you have global message indexing turned off?

"Settings" -> "General" tab -> "Indexing" heading (at the bottom) -> uncheck "Enable Global Search and Indexer"

Flags: needinfo?(dvdhbs)

I have global message indexing turned off here.

(In reply to Ben Campbell from comment #67)

David: A bit of a clutching-at-straws suggestion, but does it still happen if you have global message indexing turned off?

"Settings" -> "General" tab -> "Indexing" heading (at the bottom) -> uncheck "Enable Global Search and Indexer"

I turned indexing off and still got the error.

Flags: needinfo?(dvdhbs)

David, can you quit thunderbird, and then check whether your profile directory contains that file, or any other files in that directory?

C:\Users\<username>\AppData\Roaming\thunderbird\Profiles\<profile>.default\ImapMail\imap.<mailserver>.compact-temp\INBOX.msf.original

(In reply to Ben Campbell from comment #66)

But it fails when trying to back up the original database file, renaming INBOX.msf to .compact-temp/INBOX.msf.original.
So I would say something is keeping the pre-compaction database file locked (INBOX.msf).

Is it possible that the destination file exists and is locked?

I wonder if something else is jumping in and opening the database again after that .forceClosed(), but before the compaction has finished? for example, maybe gloda kicks in and tries to index some messages (gloda does write updates to the DB to add gloda-ids)...
That shouldn't happen because the folder (and by extension the database) is "locked" by the compaction... but badly-behaving code will plough ahead anyway and just not check the folder "lock" status... sigh...

If you wanted to prevent that, it would help if we had a single place where code has to go through to open files. You could temporarily add the filenames that you want to prevent to a global block list. Any code that wants to open a database would have to consult that list, and abort if it attempts to open one of the listed filenames. (Remove the filename from that block list when done with that folder.)

(In reply to Kai Engert [:KaiE:] from comment #70)

David, can you quit thunderbird, and then check whether your profile directory contains that file, or any other files in that directory?

C:\Users\<username>\AppData\Roaming\thunderbird\Profiles\<profile>.default\ImapMail\imap.<mailserver>.compact-temp\INBOX.msf.original

I quit Tbird, saw that .compact-temp did not exist, opened Tbird, saw .compact-temp get created, okayed the failure error message, and saw the .compact-temp get removed.

Despite my other thoughts, I think the source file still being open is the most likely reason for the failure.

Ben you say the database is force closed, but with regards to the mork storage file, it seems that the call m_mdbStore->Release() is the only action to trigger that, unless I miss something.

That's of type nsIMdbStore, which is indirectlry derived from nsISupports, so it's reference counted.

I think that means the object might still survive for another while, and closing of the underlying storage might still be delayed?

I don't know if this is helpful, but it's the first time I've seen the log mention retrying compaction, and it has a different error status code than previous failures:

[Parent 22500: Main Thread]: I/compact AsyncCompactFolders() starting compaction of 2 folders
[Parent 22500: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<acct>/INBOX' now. Queued for retry.
[Parent 22500: Main Thread]: I/compact BeginCompacting() folder='imap://<other-acct>/INBOX'
[Parent 22500: Main Thread]: I/compact MboxCompactor - Compacting 'C:\Users\***\INBOX' into 'C:\Users\***\.compact-temp\INBOX.compacting'.
[Parent 22500: Main Thread]: I/compact OnCompactionComplete(status=0x0)
[Parent 22500: Main Thread]: I/compact OnFinalSummary(status=0x0 oldSize=105303783 newSize=103341033)
[Parent 22500: Main Thread]: I/compact BatchCompactor: Attempt 1. Retrying 1 folders in 5000ms
[Parent 22500: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<acct>/INBOX' now. Queued for retry.
[Parent 22500: Main Thread]: I/compact BatchCompactor: Attempt 2. Retrying 1 folders in 5000ms
[Parent 22500: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<acct>/INBOX' now. Queued for retry.
[Parent 22500: Main Thread]: I/compact BatchCompactor: Attempt 3. Retrying 1 folders in 5000ms
[Parent 22500: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<acct>/INBOX' now. Queued for retry.
[Parent 22500: Main Thread]: I/compact BatchCompactor: Attempt 4. Retrying 1 folders in 5000ms
[Parent 22500: Main Thread]: E/compact BatchCompactor - Can't compact 'imap://<acct>/INBOX' now. Queued for retry.
[Parent 22500: Main Thread]: E/compact BatchCompactor: too many attempts. Bailing out.
[Parent 22500: Main Thread]: E/compact Failed to compact folder='imap://<acct>/INBOX', status=0x80550025
[Parent 22500: Main Thread]: I/compact BatchCompactor complete: 1 folders compacted, 1 failed, TotalBytesRecovered=1962750

Anything could reopen the database while compaction is happening, like in bug 1965686 comment 3. AFAIK, there's no checking of the folder's semaphore before opening. That would be enough to cause Windows to get upset renaming the files.

Flags: needinfo?(geoff)

(In reply to David Hobbs from comment #74)

I don't know if this is helpful, but it's the first time I've seen the log mention retrying compaction, and it has a different error status code than previous failures:

I just reproduced this other failure on Linux with status=0x80550025
(which means: NS_MSG_ERROR_FOLDER_SUMMARY_OUT_OF_DATE )

Note the analysis in this comment is specifically about this one error code, which is different what David saw previously.

I had used a mailbox, local folder, size 4 GB as a starting point.

While not running, I copied that file to a new filename inside the
local folders directory.

I started TB 140, and waited until it had fully scanned that mailbox,
which means the progress bar was gone and the list of messages in
the folder was shown.

I deleted a message in the middle, asked for compact,
then I selected another folder, and selected the folder being compacted
again.

Then I was distracted and when I came back TB had crashed.

When I restart I get the popup about being unable to compact that
new folder.

The error here is triggered by nsMsgBrkMBoxStore::IsSummaryFileValid

It fails at
if (folderSize == fileSize && numUnreadMessages >= 0) {

The folderSize recorded in msf is still the original size (of the
source file that I had copied), but the file on disk is the reduced file.

So compact had succeeded renaming/replacing the mbox file,
but the msf file still corresponds to the original file.

(To debug and analyze, I interrupted TB a couple of times while this prompt was shown, and I got the same error on each restart.)

If I confirm the error prompt and allow TB to continue, and then click the folder, it rebuilds the summary file. And afterwards the folder can be used again, without error message.

That means, for error code NS_MSG_ERROR_FOLDER_SUMMARY_OUT_OF_DATE in particular, telling the user that we couldn't compact isn't useful.

What happens is that we failed during compact, and got inconsistent data, and our code is capable of automatically repairing.

I suspect this is a consequence of David having experienced the file-locked error. Because it was locked, the old msf file was kept, but apparently the new compacted mbox file was shown.

So currently, whenever someone experiences the "file is locked" situation and aborted compact operation, they might get the prompt at least once more, for the inconsistent msf file.

The more I think about it, the more I think this and Bug 1965686 are essentially the same thing:
other parts of the code - likely the main folder view - opening a database that has been closed for compaction and locking the .msf file, so the compaction can't replace it with the compacted version.

(edit: the NS_MSG_ERROR_FOLDER_SUMMARY_OUT_OF_DATE is a different and interesting issue -thanks for the great write up Kai! I'll poke about - the summary-validity stuff is pretty fuzzy and underdocumented - it might be the compaction validates the database before the switchover, so it's being validated against the uncompacted mbox file. There are a bunch of things that set validation behind the scenes, so this could have been masked...)

See Also: → 1965686
Assignee: nobody → benc
Status: NEW → ASSIGNED

(In reply to Kai Engert [:KaiE:] from comment #76)

The folderSize recorded in msf is still the original size (of the
source file that I had copied), but the file on disk is the reduced file.

So compact had succeeded renaming/replacing the mbox file,
but the msf file still corresponds to the original file.

I just had a nasty theory about this:

  1. compaction starts (old DB force closed, start writing into a new DB)
  2. while compaction is running, something else (eg the folder view) opens the DB and makes some changes. The changes can be pretty passive, like marking messages read, or even just some folderinfo housekeeping. These changes stay in RAM for now...
  3. compaction completes, new (compacted) DB file is installed.
  4. Whatever else was using the database decides to do a Commit, and the database data is re-written out to disk, entirely blatting over the compacted DB file with the OLD (pre-compaction) data.

Ugh.

Geoff had the nice simple idea of having the compaction do a nsIMsgDBServicer.ForceFolderDBClosed() just before installing the newly compacted DB file.
That should disrupt whatever else has the DB open, solving both the windows NS_ERROR_FILE_IS_LOCKED issue and this NS_MSG_ERROR_FOLDER_SUMMARY_OUT_OF_DATE issue.

In fact, I think both issues are likely exactly the same thing:
on windows it fails early with a NS_ERROR_FILE_IS_LOCKED, whereas on Linux (and mac?) it continues onward, ultimately blatting over the newly compacted DB and screwing up later with NS_MSG_ERROR_FOLDER_SUMMARY_OUT_OF_DATE.

I'm prepping a patch to do ForceFolderDBClosed() at the end of the compaction.

Try run here, looks OK I think.
https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=f7e2cc41300317ec8a12606b7794fe24cbe462b6

If anyone is feeling intrepid, try out a bleeding-edge binary from that try run and see if the problem still occurs!
https://developer.thunderbird.net/thunderbird-development/fixing-a-bug/try-server#get-an-installable-build-from-a-try-run

Keywords: checkin-needed-tb, leave-open

Pushed by geoff@darktrojan.net:
https://hg.mozilla.org/comm-central/rev/63c6e74363f0
Add extra ForceFolderDBClosed() at end of compaction, in case something else started using the DB. r=darktrojan

Keywords: checkin-needed-tb
Target Milestone: --- → 142 Branch
Duplicate of this bug: 1965686
See Also: 1965686 →
No longer duplicate of this bug: 1965686

Good news:

On Windows, the patch from comment 80 fixes this problem for me (applied to comm-esr140 branch).

On Windows, without the patch, I could reproduce this bug every time I tried.

However, I get different behavior depending on platform.

On Linux I have difficulties reproducing this bug.
On Linux, I could only reproduce it once.
So I don't know if the patch helps on Linux.

Are you comfortable uplifting this to beta?

(In reply to Kai Engert [:KaiE:] from comment #84)

On Linux I have difficulties reproducing this bug.
On Linux, I could only reproduce it once.
So I don't know if the patch helps on Linux.

I spent a while trying to trigger it on linux, but no joy so far. Let me know if you do manage to figure out a way.

(In reply to Corey Bryant from comment #85)

Are you comfortable uplifting this to beta?

It's a tiny change and looks like there's enough benefit on the windows side to justify it, so yeah. I'll flag it for uplift.

Comment on attachment 9497772 [details]
Bug 1959858 - Add extra ForceFolderDBClosed() at end of compaction, in case something else started using the DB. r=#thunderbird-back-end-reviewers

Uplift Approval Request

  • Please state case for uplift consideration and ensure bug severity is set: A lot of folder compaction attempts are failing to complete successfully (especially on windows).
  • User impact if declined: Users confronted by a lot more unhelpful "The Folder 'blah on blah@blah' could not be compacted..." error dialogs than they should be.
  • 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): It's a one-liner which closes a doomed database which should already be closed.
  • String changes made/needed:
Attachment #9497772 - Flags: approval-comm-beta?
Duplicate of this bug: 1965686

(In reply to Ben Campbell from comment #86)

I spent a while trying to trigger it on linux, but no joy so far. Let me know if you do manage to figure out a way.

I can no longer reproduce on Linux, it looks like I made mistake during testing.
The patch seems to work.

Comment on attachment 9497772 [details]
Bug 1959858 - Add extra ForceFolderDBClosed() at end of compaction, in case something else started using the DB. r=#thunderbird-back-end-reviewers

[Triage Comment]
Approved for beta

Attachment #9497772 - Flags: approval-comm-beta? → approval-comm-beta+

The last patch was landed into c-c with "leave-open".

Do we still need that?
Should we resolve this bug?

(In reply to Kai Engert [:KaiE:] from comment #92)

The last patch was landed into c-c with "leave-open".
Do we still need that?

No, I just wasn't sure if it'd work or not.

Should we resolve this bug?

Sounds like it's a working fix, so if any more problems someone can unresolve it :-)

Status: ASSIGNED → RESOLVED
Closed: 1 year ago
Flags: needinfo?(vseerror)
Flags: needinfo?(ramona)
Keywords: leave-open
Resolution: --- → FIXED

One more patch to land (https://phabricator.services.mozilla.com/D255575).

Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Status: REOPENED → ASSIGNED

Pushed by toby@thunderbird.net:
https://hg.mozilla.org/comm-central/rev/d8fe417e9298
Tweaks to compaction logging. r=darktrojan

Status: ASSIGNED → RESOLVED
Closed: 1 year ago → 1 year ago
Keywords: checkin-needed-tb
Resolution: --- → FIXED
Duplicate of this bug: 1977095
Duplicate of this bug: 1937431
See Also: 1937431 →

It would be great to get this uplifted to esr, now that the patch seems to have proved solid on 141 and 142.

Flags: needinfo?(benc)
See Also: → https://support.mozilla.org/en-US/questions/1511829, https://support.mozilla.org/en-US/questions/1511625

Comment on attachment 9497772 [details]
Bug 1959858 - Add extra ForceFolderDBClosed() at end of compaction, in case something else started using the DB. r=#thunderbird-back-end-reviewers

Uplift Approval Request

  • Please state case for uplift consideration and ensure bug severity is set: Ongoing, occasional, spurious compaction failures on windows, with annoying modal error dialog.
  • User impact if declined: Lots of annoying modal errors stating compaction has failed.
  • Is this code covered by automated tests?: No
  • Has the fix been verified in Daily?: Yes
  • Has the fix been verified in Beta?: Yes
  • 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): It's a borderline trivial change. It just adds a line to close a database file before attempting to delete it.
  • Does the fix cause any migrations to be skipped?: No
  • String changes made/needed:
Flags: needinfo?(benc)
Attachment #9497772 - Flags: approval-comm-esr140?

Comment on attachment 9497772 [details]
Bug 1959858 - Add extra ForceFolderDBClosed() at end of compaction, in case something else started using the DB. r=#thunderbird-back-end-reviewers

[Triage Comment]
Approved for esr140

Attachment #9497772 - Flags: approval-comm-esr140? → approval-comm-esr140+

Good news - no more reports of the error message in support forums.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: