Bug 3460 - CM gets stuck in a loop while scanning folder tree
Summary: CM gets stuck in a loop while scanning folder tree
Status: RESOLVED INVALID
Alias: None
Product: Claws Mail (GTK 2)
Classification: Unclassified
Component: Folders/IMAP (show other bugs)
Version: 3.11.1
Hardware: PC Linux
: P3 normal
Assignee: users
URL:
Depends on:
Blocks:
 
Reported: 2015-07-05 13:04 UTC by Tore Anderson
Modified: 2015-07-05 18:46 UTC (History)
0 users

See Also:


Attachments
Network log ~12:30 o'clock (131.49 KB, image/png)
2015-07-05 13:04 UTC, Tore Anderson
no flags Details
Network log ~13:00 o'clock (146.54 KB, image/png)
2015-07-05 13:04 UTC, Tore Anderson
no flags Details
claws.log (at a point in time where it is still scanning the folder tree) (22.53 KB, application/gzip)
2015-07-05 13:22 UTC, Tore Anderson
no flags Details
claws.log from completed folder tree scan (50.80 KB, application/gzip)
2015-07-05 14:56 UTC, Tore Anderson
no flags Details

Description Tore Anderson 2015-07-05 13:04:26 UTC
Created attachment 1529 [details]
Network log ~12:30 o'clock

When Claws Mail is scanning the folder tree on my one of my Zimbra account, it gets stuck in a loop, running the same LSUB commands for the same set of folders over and over again. It will sit there for hours, during which the main UI is blocked. I'm not sure what causes it to stop in the end, if it actually manages to break the loop and finish successfully, or if the Zimbra server disconnects it, or anything else.

See attached screenshots of the network log window while this is happening (I'm using screenshots because I cannot copy&paste while the interface is blocked). They're taken during a single "Scanning folder tree..." process, approx. 30 minutes apart, and it shows how it's still working with the same set of folders, even though it should have moved on ages ago.

Tore
Comment 1 Tore Anderson 2015-07-05 13:04:53 UTC
Created attachment 1530 [details]
Network log ~13:00 o'clock
Comment 2 Paul 2015-07-05 13:11:14 UTC
You can attach the file ~/.claws-mail/claws.log
Comment 3 Tore Anderson 2015-07-05 13:22:13 UTC
Created attachment 1531 [details]
claws.log (at a point in time where it is still scanning the folder tree)

The log starts where I subscribed to a folder ("IETF"), at which point it automatically started the folder tree scanning process. It would appear that it has moved on to another part of the folder hierarchy ("zArkiv/*") now, but it is still looping there.
Comment 4 Tore Anderson 2015-07-05 14:56:15 UTC
Created attachment 1532 [details]
claws.log from completed folder tree scan

This new log contains the entire folder tree scan, which appears to have completed successfully after a whopping 2 hours 19 minutes.
Comment 5 Tore Anderson 2015-07-05 18:22:38 UTC
After digging a bit more into this I realise that it is probably the server that's misbehaving, with LSUB reporting the same folder multiple times if the it contains sub-folders. From the log:

[12:23:26] IMAP4> 908 LSUB "" "%" 
[...]
[12:23:35] IMAP4< * LSUB (\NoSelect) "/" "MS" 
[...]
[12:23:35] IMAP4< * LSUB (\NoSelect) "/" "MS" 
[...]
[12:23:35] IMAP4< * LSUB () "/" "MS" 
[...]
[12:23:35] IMAP4< * LSUB (\NoSelect) "/" "MS" 
[...]
[12:23:35] IMAP4< * LSUB (\NoSelect) "/" "MS" 
[...]
[12:23:35] IMAP4< 908 OK LSUB completed 

Predictably enough, this makes CM descend into the "MS" folder five times:

[13:17:31] IMAP4> 2097 LSUB "" "MS/%" 
[13:17:34] IMAP4< * LSUB () "/" "MS/MS0" 
[13:17:34] IMAP4< * LSUB () "/" "MS/QA" 
[13:17:34] IMAP4< * LSUB () "/" "MS/Rootmail" 
[13:17:34] IMAP4< * LSUB () "/" "MS/Vaktlogg" 
[13:17:34] IMAP4< 2097 OK LSUB completed 
[...]
[13:19:13] IMAP4> 2137 LSUB "" "MS/%" 
[13:19:15] IMAP4< * LSUB () "/" "MS/MS0" 
[13:19:15] IMAP4< * LSUB () "/" "MS/QA" 
[13:19:15] IMAP4< * LSUB () "/" "MS/Vaktlogg" 
[13:19:15] IMAP4< * LSUB () "/" "MS/Rootmail" 
[13:19:15] IMAP4< 2137 OK LSUB completed 
[...]
[13:35:44] IMAP4> 2495 LSUB "" "MS/%" 
[13:35:46] IMAP4< * LSUB () "/" "MS/MS0" 
[13:35:46] IMAP4< * LSUB () "/" "MS/QA" 
[13:35:46] IMAP4< * LSUB () "/" "MS/Rootmail" 
[13:35:46] IMAP4< * LSUB () "/" "MS/Vaktlogg" 
[13:35:46] IMAP4< 2495 OK LSUB completed 
[...]
[14:27:55] IMAP4> 3632 LSUB "" "MS/%" 
[14:27:57] IMAP4< * LSUB () "/" "MS/MS0" 
[14:27:57] IMAP4< * LSUB () "/" "MS/QA" 
[14:27:57] IMAP4< * LSUB () "/" "MS/Rootmail" 
[14:27:57] IMAP4< * LSUB () "/" "MS/Vaktlogg" 
[14:27:57] IMAP4< 3632 OK LSUB completed 
[...]
[14:28:08] IMAP4> 3637 LSUB "" "MS/%" 
[14:28:11] IMAP4< * LSUB () "/" "MS/Vaktlogg" 
[14:28:11] IMAP4< * LSUB () "/" "MS/MS0" 
[14:28:11] IMAP4< * LSUB () "/" "MS/Rootmail" 
[14:28:11] IMAP4< * LSUB () "/" "MS/QA" 
[14:28:11] IMAP4< 3637 OK LSUB completed 

With deep folder hierarchies this causes an exponential increase in the amount of scanning to be done, and couple that with the rather slow (multi-second) LSUB performance of the mail server, it's only to be expected that the total time it takes to complete the scan gets very long.

I've opened a bug report with Zibmra about this: https://bugzilla.zimbra.com/show_bug.cgi?id=100321

That said, CM's handling of this situation could possibly be improved here - if it simply ignored any duplicate folders returned, the exponential amount of scanning would have been avoided.

Another thing worth considering is to use the "*" wild-card in order to get the full list of subscribed folders from a single LSUB command:

1 LSUB "" "*"
[...]
* LSUB () "/" "MS/Vaktlogg"
* LSUB () "/" "MS/Rootmail"
* LSUB () "/" "MS/QA"
* LSUB () "/" "MS"
* LSUB () "/" "MS/MS0"
[...]
1 OK LSUB completed

This would cause a considerably faster folder scanning (even disregarding the exponential scanning issue) than currently, because only a single LSUB command is used, rather than one for each folder in the hierarchy. With a big hierarchy and a server like Zimbra which spends a few seconds on each LSUB command, this could cause enormous savings (in my case, it's the difference between "might as well leave for lunch now" and "in the blink of an eye").

Another thing worth mentioning here, is that CM appears trust the entry with the \NoSelect flag, given the conflicting entries above. So even though the "MS" folder is actually a completely regular folder containing messages, I cannot enter it in the CM UI, it is "grayed out". I would suggest to reverse this logic, i.e., only trust that \NoSelect is actually the case IFF all the returned LSUB entries have the flag set.
Comment 6 Paul 2015-07-05 18:46:52 UTC
Your investigatory work enables me to close this.

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