[Dovecot] failed creating protocol instance to play queued url

22 Jul 2011


      I run thunderbird (both 3.x and 5.x) against dovecot 2.x and frequently
see delays "loading message". I admit to having a very large mailbox and
running multiple imap clients.
I've turned on thunderbird debugging, and at least one pattern I see in
the log during the delays (maybe a minute long) is the failed protocol
message above. These are no the only delays, but are the ones that catch
my eye. The thunderbird debug logs are not time stamped (that I can
tell), so its difficult to go back and find the delays from the log.
Here is an example of one of the delays. Any thought?
-1215891312[b760f060]: considering playing queued
url:imap://km@mailhost.mathcs.emory.edu:993/addmsgflags>UID>/INBOX>134829>1
-1215891312[b760f060]: creating protocol instance to play queued
url:imap://km@mailhost.mathcs.emory.edu:993/addmsgflags>UID>/INBOX>134829>1
-1215891312[b760f060]: failed creating protocol instance to play queued
url:imap://km@mailhost.mathcs.emory.edu:993/addmsgflags>UID>/INBOX>134829>1
80784240[8db84f80]: ImapThreadMainLoop leaving [this=8f345000]
   a Minute or so delay
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=153 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:A:CreateNewLineFromSocket: * FLAGS
(\Answered \Flagged \Deleted \Seen \Draft NonJunk $notjunk $Forwarded
$label1 $MDNSent junk $junk $label3 junkrecorded $label4 $label2 $label5)
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=187 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:A:CreateNewLineFromSocket: * OK
[PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft NonJunk
$notjunk $Forwarded $label1 $MDNSent junk $junk $label3 junkrecorded
$label4 $label2 $label5 \*)] Flags permitted.
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=16 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:A:CreateNewLineFromSocket: * 60229 EXISTS
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=12 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:A:CreateNewLineFromSocket: * 0 RECENT
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=35 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:A:CreateNewLineFromSocket: * OK
[UNSEEN 60218] First unseen.
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=42 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:A:CreateNewLineFromSocket: * OK
[UIDVALIDITY 1287420195] UIDs valid
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=42 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:A:CreateNewLineFromSocket: * OK
[UIDNEXT 134841] Predicted next UID
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=36 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:A:CreateNewLineFromSocket: * OK
[HIGHESTMODSEQ 16298] Highest
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=37 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:A:CreateNewLineFromSocket: 4 OK
[READ-WRITE] Select completed.
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:SendData: 5 UID fetch
134841:* (FLAGS)
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=44 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket: *
60229 FETCH (UID 134840 FLAGS (NonJunk))
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=23 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket: 5 OK
Fetch completed.
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:SendData: 6 UID fetch 134829
(UID RFC822.SIZE BODY[])
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=82 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket: *
60218 FETCH (UID 134829 RFC822.SIZE 16236 FLAGS (\Seen NonJunk) BODY[]
{16236}
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:STREAM:OPEN Size: 16236:
Begin Message Download Stream
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=50 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket:
Return-Path: <sunray-users-bounces@filibeto.org>
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=68 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket:
Received: from mr5.cc.emory.edu (mr5.cc.emory.edu [170.140.52.94])
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=77 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket:
by cssun.mathcs.emory.edu (8.13.8+Sun/8.13.8) with ESMTP id p6IMb4KL014274
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=67 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket:
for <km@mathcs.emory.edu>; Mon, 18 Jul 2011 18:37:04 -0400 (EDT)
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=73 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket:
Received: from psmtp.com (na3sys009amx258.postini.com [74.125.149.142])
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=66 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket:
by mr5.cc.emory.edu (8.13.1/8.13.1) with SMTP id p6IMap3E019495
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=69 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket:
(version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO)
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=61 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket:
for <km@mathcs.emory.edu>; Mon, 18 Jul 2011 18:36:52 -0400
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=126 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket:
Received: from cora.filibeto.org ([93.123.21.207]) (using TLSv1) by
na3sys009amx258.postini.com ([74.125.148.10]) with SMTP;
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=32 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket: Mon,
18 Jul 2011 17:36:52 CDT
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=57 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineFromSocket:
Received: from cora.filibeto.org (localhost [IPv6:::1])
-1675625616[8e59a5b0]: ReadNextLine [stream=8e5049c8 nb=73 needmore=0]
-1675625616[8e59a5b0]:
9023c800:mailhost.mathcs.emory.edu:S-INBOX:CreateNewLineF

Ken Mandelberg

tags

participants (1)