Bug 4559 - Claws Mail randomly decides to refetch huge list of invalid UIDs from IMAP folder
Summary: Claws Mail randomly decides to refetch huge list of invalid UIDs from IMAP fo...
Status: REOPENED
Alias: None
Product: Claws Mail (GTK 2)
Classification: Unclassified
Component: Folders/IMAP (show other bugs)
Version: 3.18.0
Hardware: PC Linux
: P3 normal
Assignee: users
URL:
Depends on:
Blocks:
 
Reported: 2021-12-29 11:12 UTC by Thomas Petazzoni
Modified: 2022-07-14 19:03 UTC (History)
1 user (show)

See Also:


Attachments
Extract from Claws Mail logs (298.62 KB, text/x-log)
2022-07-14 14:43 UTC, Thomas Petazzoni
no flags Details
Lock patch (2.87 KB, patch)
2022-07-14 19:03 UTC, Colin Leroy
no flags Details | Diff

Description Thomas Petazzoni 2021-12-29 11:12:13 UTC
I am a very heavy user of Claws Mail with an IMAP server. I have folders with several hundreds of thousands of e-mails, and Claws Mail handles that very well.

The only issue I encounter is that in a seemingly random fashion, about 5-10 times a day, Claws Mail decides to refetch all UIDs from a given IMAP folder, sometimes even from folders that are completely empty (such as the Queue folder). Claws Mail is literally contacting the IMAP server about each and every UID from 1 to <significant number>, and while it does that it consumes a lot of CPU and Claws Mail operations are sluggish.

I have posted at https://bootlin.com/~thomas/claws-issue.txt a log file that illustrates the problem.

At line 2052 the problem starts with:
imap.c:4723:removing old messages from /home/thomas/.claws-mail/imapcache/mail.gandi.net/thomas.petazzoni@bootlin.com/Queue

Then, there is a huge list of:
folder.c:2269:Remembered message 1 for fetching

It says that for 312301 messages, until:
folder.c:2269:Remembered message 312301 for fetching

in line 296117 of the log file.

And then it starts contacting the IMAP server for each and every UID for 1 to 312301. 

Note that the log file ends with UID FETCH 46198 because I killed Claws Mail. But you can clearly see it is trying to fetch all UIDs from 1 to 46198.
Comment 1 Thomas Petazzoni 2021-12-29 11:17:33 UTC
Following discussions with "claws" on IRC, I have:
- Dropped 1687 .bak files from my local imapcache folder for the Queue folder
- Discarded the "folder cache" for the Queue folder from the Claws Mail UI
Comment 2 Paul 2021-12-29 11:20:37 UTC
claws-mail does not create *.bak files in the imap cache. This is some kind of user error.
Comment 3 Thomas Petazzoni 2021-12-29 14:53:01 UTC
Claws Mail can create .bak files in the IMAP cache. The function imap_add_msgs() in src/imap.c calls copy_file() to create files in the IMAP cache folder. This function copy_file() will create a .bak file to backup the destination file if it already exists. So it does seem that Claws Mail can create .bak files in the IMAP cache (based on my admittedly limited understanding of the code base).
Comment 4 Thomas Petazzoni 2021-12-29 14:54:25 UTC
Also, it's kind of difficult to understand/imagine what could be the relationship between the existence of .bak files and the bug that I am reporting. Of course, such a relationship could exist, but it's not been made very clear what such a relationship could be.
Comment 5 Paul 2021-12-29 15:28:11 UTC
(In reply to Thomas Petazzoni from comment #3)
Your statement is untrue.
Comment 6 Thomas Petazzoni 2022-07-14 14:42:35 UTC
Since the behavior reported in this bug report is still occurring frequently for me (between one to several times per day), I've tried to look a little bit more into it, hoping to collect enough information to make this bug report a bit more useful.

I see a sequence like this:

(1) folder.c:2184:Scanning folder Queue for cache changes.

(2) imap.c:533:locking session 0x56446e667000 (0)

(3) [2022-07-14 11:31:41] IMAP> 424 SELECT Queue 

This looks all reasonable to me.

Then right after the answer to this "SELECT Queue", there is apparently something happening with Inbox, because:

imap-thread.c:1435:imap select run - end 0
imap-thread.c:473:generic_cb
folder.c:4662:Folder Bootlin wants sync
folder.c:4662:Folder Bootlin wants sync
folder.c:4662:Folder Bootlin wants sync
folder.c:4662:Folder Bootlin wants sync
folder.c:4662:Folder Bootlin wants sync
folder.c:4662:Folder Bootlin wants sync
imap.c:1600:trying to fetch cached /home/thomas/.claws-mail/imapcache/mail.gandi.net/thomas.petazzoni@bootlin.com/INBOX/355005
procmsg.c:2020:Unsetting flags for message 355005 in folder INBOX
imap.c:1646:getting session...
imap.c:533:locking session 0x56446e667000 (1)
imap.c:535:         SESSION WAS LOCKED !!      

This continues with:

(4) [2022-07-14 11:31:41] IMAP> 425 SELECT INBOX 

So now, the INBOX mailbox is selected in the IMAP session.

It then does an UID FETCH 355005:

(5) [2022-07-14 11:31:41] IMAP> 426 UID FETCH 355005 BODY.PEEK[] 

Which seems reasonable as this is the e-mail it wanted to fetch.

but then I guess it goes back to:

[2022-07-14 11:31:43] IMAP> 428 UID SEARCH ALL 
folder.c:4662:Folder Bootlin wants sync
[2022-07-14 11:31:44] IMAP< * SEARCH 1 88638 88639 88640 88641 88642 88643 88644 88645 886[... - 548 bytes more]
[2022-07-14 11:31:44] IMAP< 8738 88739 88740 88741 88742 88743 88744 88745 88746 88747 887[... - 960 bytes more]
[2022-07-14 11:31:44] IMAP<  88909 88910 88911 88912 88913 88914 88915 88916 88917 88918 8[... - 960 bytes more]
[2022-07-14 11:31:44] IMAP< 79 89080 89081 89082 89083 89084 89085 89086 89087 89088 89089[... - 960 bytes more]
[2022-07-14 11:31:44] IMAP< 9250 89251 89252 89253 89254 89255 89256 89257 89258 89259 892[... - 960 bytes more]
... many many more of these ...

[2022-07-14 11:31:44] IMAP< 354994 354995 354997 354998 354999 355000 355001 355002 355003[... - 167 bytes more]
[2022-07-14 11:31:44] IMAP< 428 OK Search completed (0.727 + 0.000 + 0.726 secs). 
imap-thread.c:1750:imap search run - end 0
imap-thread.c:473:generic_cb
imap-thread.c:457:found imap 0x564468edca40
imap-thread.c:1775:imap search - end
imap.c:546:unlocking session 0x56446e667000
folder.c:4662:Folder Bootlin wants sync
folder.c:4662:Folder Bootlin wants sync
imap.c:4720:get_num_list: got 237263 msgs
imap.c:4730:removing old messages from /home/thomas/.claws-mail/imapcache/mail.gandi.net/thomas.petazzoni@bootlin.com/Queue
imap.c:4734:get_num_list - ok - 237263
msgcache.c:270:TIMING msgcache_get_msg_list : 0s000ms
folder.c:2270:Remembered message 1 for fetching
folder.c:2270:Remembered message 88638 for fetching
folder.c:2270:Remembered message 88639 for fetching
folder.c:2270:Remembered message 88640 for fetching
folder.c:2270:Remembered message 88641 for fetching
folder.c:2270:Remembered message 88642 for fetching
folder.c:2270:Remembered message 88643 for fetching
folder.c:2270:Remembered message 88644 for fetching
folder.c:2270:Remembered message 88645 for fetching
folder.c:2270:Remembered message 88646 for fetching
folder.c:2270:Remembered message 88647 for fetching
folder.c:2270:Remembered message 88648 for fetching
folder.c:2270:Remembered message 88649 for fetching
folder.c:2270:Remembered message 88650 for fetching
folder.c:2270:Remembered message 88651 for fetching
.... many more of these ....

and after that it goes and does an UID FETCH of 1, 88638, 88639... none of which exist in the Queue folder.

So my impression is that Claws starts by scanning for the Queue folder and selects it, then gets "interrupted" to do something in the INBOX folder, but when it gets back to doing its job on the Queue folder, it doesn't reselect it.

Of course, this is pure guess, but it clearly leads to Claws looping on hundreds of thousands of UIDs that don't exist in the Queue folder.

I'm attaching the extract from the log. I can provide a more complete log upon request.
Comment 7 Thomas Petazzoni 2022-07-14 14:43:02 UTC
Created attachment 2291 [details]
Extract from Claws Mail logs
Comment 8 Colin Leroy 2022-07-14 19:00:55 UTC
This log shows that Claws Mail was refreshing the Queue folder, when you tried to read an email in INBOX. This selected INBOX to fetch the mail, then the Queue scan continued while INBOX was selected.

There are huge concurrency issues in imap.c, and the lock_session/unlock_session mechanism is not there to address them (it adresses crashes while removing an account during an IMAP operation).
Comment 9 Colin Leroy 2022-07-14 19:03:04 UTC
Created attachment 2292 [details]
Lock patch

This patch checks the lock before fetching a mail, or changing its flag.

It should solve your problem, but is still crap, as you'll get an error, and will have to re-open the email after scanning is over.

I'm still interested in whether it resolves (well, changes) your issue.

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