Bug 2739 - Claws-Mail hangs after clicking on MH folder (folder.c:2045:TIMING folder_item_open : 179s974ms)
Summary: Claws-Mail hangs after clicking on MH folder (folder.c:2045:TIMING folder_ite...
Status: RESOLVED WORKSFORME
Alias: None
Product: Claws Mail (GTK 2)
Classification: Unclassified
Component: Folders/MH (show other bugs)
Version: 3.8.1
Hardware: PC Linux
: P3 normal
Assignee: users
URL:
Depends on:
Blocks:
 
Reported: 2012-09-30 12:53 UTC by unsuspicious.fakename+computer
Modified: 2012-10-10 10:50 UTC (History)
0 users

See Also:


Attachments

Description unsuspicious.fakename+computer 2012-09-30 12:53:26 UTC
This happens when I try to change the folder I'm looking at quite often, but only after a certain time: clicking repeatedly on different folders in a short time does not seem to trigger the problem. Letting claws-mail run for a while will have it trigger on the next time I click on a folder sooner or later. 

Usually, claws-mail does not recover from this but needs to be killed. Since I recompiled claws-mail with debug symbols and started it with gdb, it has recovered a few times after waiting a few minutes (not always though - left it run up to one hour with nothing happening)- I never witnessed this recovery happen before / with the "normal" version run directly (it always froze completely there as far as I can tell).

Below is the output from one of those cases where it mysteriously recovered - in cases where it doesn't, it looks about the same, it just doesn't go on after the multiple lines of "folderview" (each click on the claws-mail window gets me 2 more of those lines, but the GUI is not redrawn and nothing seems to happen). 
______________

folderview.c:2118:newly selected 0xe21680, opened 0xe1af60
summaryview.c:1144:called inc_lock (lock count 1)
summaryview.c:1217:empty folder ((nil) (null) (nil) 0)

gtkhtml2_viewer.c:410:gtkhtml2_clear_viewer
summaryview.c:1229:called inc_unlock (lock count 0)
summaryview.c:1239:TIMING summary_show : 0s012ms
folder.c:2738:Save cache for folder #rssyl/MyFeeds/.Computer.RSSFeed
msgcache.c:1169:	Writing message cache to /home/user/.claws-mail/RSSyl/RSSFeed/.claws_cache.new and 
/home/user/.claws-mail/RSSyl/RSSFeed/.claws_mark.new...
msgcache.c:1250:done.
msgcache.c:1251:TIMING msgcache_write : 0s177ms
folder.c:1216:Counting total number of messages...
main.c:984:The name com.google.code.Awn was not provided by any .service files
folderview.c:2164:Folder inbox is selected
folderview.c:2180:Opening folder inbox...
mh.c:231:MH scan not required: /home/user/Mail/inbox (1348994186 <= 1348994186)
msgcache.c:274:TIMING msgcache_get_msg_list : 0s001ms
folder.c:4431:processing inbox
folder.c:4434:called inc_lock (lock count 1)
msgcache.c:274:TIMING msgcache_get_msg_list : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe21680, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe21680, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe21680, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe21680, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe21680, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe21680, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe1ffa0, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms
folderview.c:2118:newly selected 0xe18060, opened (nil)
folderview.c:2139:TIMING folderview_selected : 0s000ms

** (claws-mail:16163): WARNING **: sock_read: No such file or directory

filtering.c:208:checking 2439 messages
filtering.c:245:no more messages to move/copy/del
folder.c:4485:called inc_unlock (lock count 0)
folder.c:2045:TIMING folder_item_open : 179s974ms
summaryview.c:1039:showing From , must show From 
summaryview.c:1144:called inc_lock (lock count 1)
gtkhtml2_viewer.c:410:gtkhtml2_clear_viewer
summaryview.c:1251:Scanning folder (inbox)...
msgcache.c:274:TIMING msgcache_get_msg_list : 0s000ms
summaryview.c:1120:TIMING summary_check_consistency : 0s000ms
summaryview.c:1370:TIMING summary_show removing hidden: 0s000ms
summaryview.c:3025:	Setting summary from message data...
addr_compl.c:316:read 296 items in (null)
addr_compl.c:377:start_address_completion((null)) ref count 1
procmsg.c:287:TIMING procmsg_get_thread_tree thread by subject: 0s001ms
procmsg.c:297:TIMING procmsg_get_thread_tree : 0s005ms
summaryview.c:3066:TIMING summary_set_ctree_from_list threaded: 0s028ms
addr_compl.c:684:end_address_completion ref count 0
summaryview.c:3113:done.
summaryview.c:3116:	msgid hash table size = 2435
summaryview.c:3119:	subject hash table size = 0
summaryview.c:2888:Sorting summary...summaryview.c:2902:done.
summaryview.c:2909:TIMING summary_sort : 0s011ms
summaryview.c:3135:TIMING summary_set_ctree_from_list bold_unread: 0s000ms
summaryview.c:3140:TIMING summary_set_ctree_from_list : 0s043ms
summaryview.c:1502:
summaryview.c:1507:called inc_unlock (lock count 0)
summaryview.c:1508:TIMING summary_show : 0s135ms
folder.c:2574:Total cache memory usage: 3261018
folderview.c:2240:TIMING folderview_selected : 180s328ms
folderview.c:2118:newly selected 0xe21680, opened 0xe21680
folderview.c:2122:TIMING folderview_selected : 0s000ms
session.c:353:session (0x184c000): closed
folder.c:2155:Scanning folder processing for cache changes.
mh.c:289:mh_get_num_list(): Scanning processing ...
mh.c:1400:MH: forced mtime of processing to 1348989983
msgcache.c:602:	Reading swapped message cache from /home/user/.claws-mail/tempfolder/processing/.claws_cache...
msgcache.c:618:using Noop Converter
msgcache.c:790:done. (0 items read)
msgcache.c:791:Cache size: 0 messages, 0 bytes
msgcache.c:821:reading swapped mark file.
msgcache.c:907:reading swapped tags file.
folder.c:2713:TIMING folder_item_read_cache : 0s000ms
folder.c:2574:Total cache memory usage: 3261018
msgcache.c:274:TIMING msgcache_get_msg_list : 0s000ms
msgcache.c:274:TIMING msgcache_get_msg_list : 0s000ms
filtering.c:208:checking 0 messages

** (claws-mail:16163): WARNING **: [10:52:00] Error occurred while processing mail.

mh.c:231:MH scan not required: /home/user/.claws-mail/tempfolder/processing (1348989983 <= 1348989983)
folder.c:2738:Save cache for folder #mh/TEMP_FOLDER/processing
msgcache.c:1169:	Writing message cache to (null) and (null)...
msgcache.c:1250:done.
msgcache.c:1251:TIMING msgcache_write : 0s000ms
Comment 1 Colin Leroy 2012-10-10 10:16:57 UTC
It looks like a very slow processing rule (or pre/post-processing) ?
folder.c:4431:processing inbox
...
folder.c:4485:called inc_unlock (lock count 0)
Comment 2 unsuspicious.fakename+computer 2012-10-10 10:33:11 UTC
Can't reproduce any more since google / gmail is done with its annual certificate rotation mess so... Probably this was somehow related to old and new certificates being switched forth and back constantly although I never saw anything hinting at that in the logs. Anything related to mail retrieval / ssl was far far away from the manifestation of the problem most of the time and looked fine / totally unrelated at that time.
Comment 3 Colin Leroy 2012-10-10 10:36:11 UTC
OK, thanks for your feedback. Maybe you had the alertpanel about changed certificate but it got hidden in the background, or something like that...

Marking worksforme, then !
Comment 4 unsuspicious.fakename+computer 2012-10-10 10:50:48 UTC
There definitely was no alert panel / popup hidden anywhere - I suspected there
to be a frozen / hidden window like that in the background at some point
(compiz sometimes messes stuff like that up) before I started looking at the
logs - but dismissed that idea again, because even after trying it again in
xfwm4 +looking with wmctrl I couldn't find the "suspect" / window. 

I can only make wild guesses at this point though what actually happened... In
retrospect, this is one possibility of how stuff could have happened:
1) Certificate changes.
2) Prompt to accept "new" certificate pops up
3) Connection times out, alert window stays open?
4) Certificate changes (back) AGAIN
5) I come back to the machine and click "accept certificate", walk away again. 
6) Something goes wrong here? 
7) Random unrelated stuff keeps happening. 
8) I come back and click on a Folder. Folderview is waiting for [whatever
should have happened during step (6)]?

Well... maybe I'll figure it out next year.

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