[Users] Puzzling freeze when reading news

Sat Nov 24 20:47:55 CET 2012

Here is the --debug output that I see when I get a long, several
minute, freeze when reading news, the symptom is that I click on the
news folder and nothing happens for some time, then, after the WARNING
message suddenly everything flies along until the next time.

Anyone have any ideas about this, I've been seeing it for a while with
Claws and Zen's news server. I can't put my finger on exactly what
happens to cause it.

The annoying thing is that while this is happening the UI is
essentially unresponsive.

Debug output below...

nntp-thread.c:624:nntp date run - end 3
nntp-thread.c:256:generic_cb
nntp-thread.c:639:nntp date - end

** (claws-mail:3332): WARNING **: [19:41:05] NNTP connection to news.zen.co.uk:119 has been disconnected. Reconnecting...

session.c:226:session (0x21d9600): destroyed
** Message: Account 'Brian news': Connecting to NNTP server: news.zen.co.uk:119...

nntp-thread.c:245:found nntp 0x2179b70
nntp-thread.c:351:deleting old nntp 0x2179b70
nntp-thread.c:111:removing newsnntp 0x2179b70
nntp-thread.c:245:found nntp 0x2599400
[19:41:05] NNTP< 200 Zen Internet NNRP reader03.nrc01.news.zen.net.uk Service Ready (posting ok) 
nntp-thread.c:256:generic_cb
nntp-thread.c:368:connect ok 0 with nntp 0x2599400
nntp-thread.c:854:nntp mode_reader - begin
nntp-thread.c:245:found nntp 0x2599400
nntp-thread.c:245:found nntp 0x2599400
[19:41:05] NNTP> MODE READER 
[19:41:05] NNTP< 200 Zen Internet NNRP reader03.nrc01.news.zen.net.uk Service Ready (posting ok) 
nntp-thread.c:846:nntp mode_reader run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:860:nntp mode_reader - end
nntp-thread.c:811:nntp group - begin
nntp-thread.c:245:found nntp 0x2599400
nntp-thread.c:245:found nntp 0x2599400
[19:41:05] NNTP> GROUP cam.transport 
[19:41:05] NNTP< 211 820 119509 120328 cam.transport 
nntp-thread.c:803:nntp group run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:819:nntp group - end
news.c:1030:removing old messages from 119509 to 120328 in /home/bdm/.claws-mail/newscache/news.zen.co.uk
msgcache.c:275:TIMING msgcache_get_msg_list : 0s000ms
folder.c:1219:Counting total number of messages...
main.c:993:The name com.google.code.Awn was not provided by any .service files
folder.c:2158:Scanning folder uk.radio.amateur for cache changes.
nntp-thread.c:811:nntp group - begin
nntp-thread.c:245:found nntp 0x2599400
nntp-thread.c:245:found nntp 0x2599400
[19:41:05] NNTP> GROUP uk.radio.amateur 
[19:41:05] NNTP< 211 5437 684898 690334 uk.radio.amateur 
nntp-thread.c:803:nntp group run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:819:nntp group - end
news.c:1030:removing old messages from 684898 to 690334 in /home/bdm/.claws-mail/newscache/news.zen.co.uk
msgcache.c:275:TIMING msgcache_get_msg_list : 0s001ms
folder.c:1219:Counting total number of messages...
main.c:993:The name com.google.code.Awn was not provided by any .service files
folder.c:2158:Scanning folder zen.announce for cache changes.
nntp-thread.c:811:nntp group - begin
nntp-thread.c:245:found nntp 0x2599400
nntp-thread.c:245:found nntp 0x2599400
[19:41:05] NNTP> GROUP zen.announce 
[19:41:05] NNTP< 211 1 15 15 zen.announce 
nntp-thread.c:803:nntp group run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:819:nntp group - end
news.c:1030:removing old messages from 15 to 15 in /home/bdm/.claws-mail/newscache/news.zen.co.uk
msgcache.c:275:TIMING msgcache_get_msg_list : 0s000ms
folder.c:2244:Remembered message 15 for fetching
** Message: getting xover 15 - 15 in zen.announce...

nntp-thread.c:903:nntp xover - begin
nntp-thread.c:245:found nntp 0x2599400
nntp-thread.c:245:found nntp 0x2599400
[19:41:05] NNTP> XOVER 15-15 
[19:41:05] NNTP< 224 data follows 
[19:41:05] NNTP< . 
nntp-thread.c:895:nntp xover run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:913:nntp xover - end
nntp-thread.c:956:nntp xhdr - begin
nntp-thread.c:245:found nntp 0x2599400
nntp-thread.c:245:found nntp 0x2599400
[19:41:05] NNTP> XHDR newsgroups -1 
[19:41:05] NNTP< 221 newsgroups data follows 
[19:41:05] NNTP< . 
nntp-thread.c:948:nntp xhdr run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:966:nntp xhdr - end
nntp-thread.c:956:nntp xhdr - begin
nntp-thread.c:245:found nntp 0x2599400
nntp-thread.c:245:found nntp 0x2599400
[19:41:05] NNTP> XHDR to -1 
[19:41:05] NNTP< 221 to data follows 
[19:41:05] NNTP< . 
nntp-thread.c:948:nntp xhdr run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:966:nntp xhdr - end
nntp-thread.c:956:nntp xhdr - begin
nntp-thread.c:245:found nntp 0x2599400
nntp-thread.c:245:found nntp 0x2599400
[19:41:05] NNTP> XHDR cc -1 
[19:41:05] NNTP< 221 cc data follows 
[19:41:05] NNTP< . 
nntp-thread.c:948:nntp xhdr run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:966:nntp xhdr - end
folder.c:1219:Counting total number of messages...
main.c:993:The name com.google.code.Awn was not provided by any .service files
folder.c:2158:Scanning folder zen.support for cache changes.
nntp-thread.c:811:nntp group - begin
nntp-thread.c:245:found nntp 0x2599400
nntp-thread.c:245:found nntp 0x2599400
[19:41:05] NNTP> GROUP zen.support 
[19:41:05] NNTP< 211 1 11117 11117 zen.support 
nntp-thread.c:803:nntp group run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:819:nntp group - end
news.c:1030:removing old messages from 11117 to 11117 in /home/bdm/.claws-mail/newscache/news.zen.co.uk
msgcache.c:275:TIMING msgcache_get_msg_list : 0s000ms
folder.c:1219:Counting total number of messages...
main.c:993:The name com.google.code.Awn was not provided by any .service files
folderview.c:1231:called inc_unlock (lock count 0)
folderview.c:1158:called inc_lock (lock count 1)
mh.c:235:MH scan not required: /home/bdm/Mail/inbox (1349103549 <= 1349103549)
folder.c:2158:Scanning folder inbox for cache changes.
mh.c:293:mh_get_num_list(): Scanning inbox ...
mh.c:1398:MH: forced mtime of inbox to 1349103549
msgcache.c:275:TIMING msgcache_get_msg_list : 0s000ms
folder.c:1219:Counting total number of messages...
main.c:993:The name com.google.code.Awn was not provided by any .service files
msgcache.c:275:TIMING msgcache_get_msg_list : 0s000ms
mh.c:235:MH scan not required: /home/bdm/Mail/sent (1342554019 <= 1342554019)
mh.c:235:MH scan not required: /home/bdm/Mail/draft (1352828150 <= 1352828150)
mh.c:235:MH scan not required: /home/bdm/Mail/queue (1353146596 <= 1353146596)
mh.c:235:MH scan not required: /home/bdm/Mail/trash (1348535085 <= 1348535085)
folderview.c:1231:called inc_unlock (lock count 0)
inc.c:1527:added timer = 6728
nntp-thread.c:639:nntp date - end

** (claws-mail:3332): WARNING **: [19:41:05] NNTP connection to news.zen.co.uk:119 has been disconnected. Reconnecting...

session.c:226:session (0x21d9600): destroyed
** Message: Account 'Brian news': Connecting to NNTP server: news.zen.co.uk:119...

nntp-thread.c:245:found nntp 0x2599400
nntp-thread.c:351:deleting old nntp 0x2599400
nntp-thread.c:111:removing newsnntp 0x2599400
nntp-thread.c:245:found nntp 0x25f5b80
[19:41:05] NNTP< 200 Zen Internet NNRP reader03.nrc01.news.zen.net.uk Service Ready (posting ok) 
nntp-thread.c:256:generic_cb
nntp-thread.c:368:connect ok 0 with nntp 0x25f5b80
nntp-thread.c:854:nntp mode_reader - begin
nntp-thread.c:245:found nntp 0x25f5b80
nntp-thread.c:245:found nntp 0x25f5b80
[19:41:05] NNTP> MODE READER 
[19:41:05] NNTP< 200 Zen Internet NNRP reader03.nrc01.news.zen.net.uk Service Ready (posting ok) 
nntp-thread.c:846:nntp mode_reader run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:860:nntp mode_reader - end
nntp-thread.c:811:nntp group - begin
nntp-thread.c:245:found nntp 0x25f5b80
nntp-thread.c:245:found nntp 0x25f5b80
[19:41:05] NNTP> GROUP cam.misc 
[19:41:05] NNTP< 211 1119 467611 468729 cam.misc 
nntp-thread.c:803:nntp group run - end 0
nntp-thread.c:256:generic_cb
nntp-thread.c:819:nntp group - end
news.c:1030:removing old messages from 467611 to 468729 in /home/bdm/.claws-mail/newscache/news.zen.co.uk
msgcache.c:275:TIMING msgcache_get_msg_list : 0s000ms
folder.c:1219:Counting total number of messages...
main.c:993:The name com.google.code.Awn was not provided by any .service files
folder.c:4428:processing cam.misc
folder.c:4431:called inc_lock (lock count 1)
msgcache.c:275:TIMING msgcache_get_msg_list : 0s000ms
filtering.c:212:checking 1119 messages
filtering.c:249:no more messages to move/copy/del
folder.c:4482:called inc_unlock (lock count 0)
folder.c:2048:TIMING folder_item_open : 240s921ms
summaryview.c:1044:showing From , must show From 
summaryview.c:1248:called inc_lock (lock count 1)
fancy_viewer.c:342:fancy_clear_viewer
summaryview.c:1346:Scanning folder (cam.misc)...
msgcache.c:275:TIMING msgcache_get_msg_list : 0s000ms
summaryview.c:1210:TIMING summary_check_consistency : 0s000ms
summaryview.c:1453:TIMING summary_show removing hidden: 0s000ms
summaryview.c:3097:	Setting summary from message data...
addr_compl.c:315:read 475 items in (null)
addr_compl.c:376:start_address_completion((null)) ref count 1
procmsg.c:311:TIMING procmsg_get_thread_tree : 0s001ms
summaryview.c:3138:TIMING summary_set_ctree_from_list threaded: 0s025ms
addr_compl.c:683:end_address_completion ref count 0
summaryview.c:3185:done.
summaryview.c:3188:	msgid hash table size = 1119
summaryview.c:2960:Sorting summary...summaryview.c:2974:done.
summaryview.c:2981:TIMING summary_sort : 0s042ms
summaryview.c:3207:TIMING summary_set_ctree_from_list bold_unread: 0s001ms
summaryview.c:3212:TIMING summary_set_ctree_from_list : 0s073ms
summaryview.c:1578:
summaryview.c:1583:called inc_unlock (lock count 0)
summaryview.c:1584:TIMING summary_show : 0s254ms
folder.c:2577:Total cache memory usage: 6235113
folder.c:2582:Trying to free cache memory
folder.c:2535:Cache unused time: 413 (Expire time: 900)
folder.c:2535:Cache unused time: 416 (Expire time: 900)
folder.c:2535:Cache unused time: 414 (Expire time: 900)
folder.c:2535:Cache unused time: 414 (Expire time: 900)
folder.c:2535:Cache unused time: 228 (Expire time: 900)
folder.c:2535:Cache unused time: 414 (Expire time: 900)
folder.c:2535:Cache unused time: 414 (Expire time: 900)
folder.c:2535:Cache unused time: 409 (Expire time: 900)
folder.c:2535:Cache unused time: 414 (Expire time: 900)
folder.c:2535:Cache unused time: 409 (Expire time: 900)
folder.c:2535:Cache unused time: 241 (Expire time: 900)
folder.c:2535:Cache unused time: 0 (Expire time: 900)
folder.c:2535:Cache unused time: 414 (Expire time: 900)
folder.c:2535:Cache unused time: 0 (Expire time: 900)
folder.c:2535:Cache unused time: 0 (Expire time: 900)
folder.c:2535:Cache unused time: 0 (Expire time: 900)
folder.c:2535:Cache unused time: 0 (Expire time: 900)
folderview.c:2240:TIMING folderview_selected : 241s360ms
folderview.c:2118:newly selected 0x17a7240, opened 0x17a7240
folderview.c:2122:TIMING folderview_selected : 0s000ms
manage_window.c:54:Focus out event: window: 0x138f070 - Brian - Claws Mail 3.9.0cvs20

-- 

Brian Morrison

                "I am not young enough to know everything"
                                                          Oscar Wilde