Asheesh Laroia
2007-Oct-21 07:56 UTC
[Dovecot] Problem with fts found against Dovecot hg; examples + trace attached
I've been wanting to try out Squat for full-text indexing for a while now,
so I
finally gave it a whirl. I did a fresh pull from hg. I have it enabled, but
it's taking *forever* to do a query. (Using alpine, I issued a Select
command
for all messages with some word anywhere, which presumably caused the Squat
indexer to run.) I think Dovecot is infinite looping.
I thought something was wrong when I attached strace to it for five minutes and
saw no calls to read() or open(). I can reproduce the "select takes
forever"
on a tiny Maildir with 5 messages:
http://paulproteus.acm.jhu.edu/bug-report/2007-10-21/broken.tar.gz
I've also attached the *.in and *.out files that I think are related to this
IMAP conversation.
On a different IMAP conversation with the same "SEARCH takes forever"
problem,
I attached a gdb to the running Dovecot and got this backtrace:
(gdb) bt
#0 parse_next_body_to_boundary (ctx=0x85746e8, block_r=0xbf92325c)
at message-parser.c:332
#1 0x080c1b7d in message_parser_parse_next_block (ctx=0x85746e8,
block_r=0xbf92325c) at message-parser.c:717
#2 0xb7f582c2 in fts_mailbox_search_next_nonblock (ctx=0x811c0c0,
mail=0x811d380, tryagain_r=0xbf9232bb) at fts-storage.c:175
#3 0x0805f3e6 in cmd_search_more (cmd=0x80feec0) at cmd-search.c:74
#4 0x0805f768 in cmd_search_more_callback (cmd=0x80feec0) at
cmd-search.c:112
#5 0x080ce8eb in io_loop_handle_timeouts (ioloop=0x80fb250,
update_run_now=true) at ioloop.c:264
#6 0x080cf309 in io_loop_handler_run (ioloop=0x80fb250) at
ioloop-poll.c:159
#7 0x080ce7c8 in io_loop_run (ioloop=0x80fb250) at ioloop.c:303
#8 0x08068c9c in main (argc=135213400, argv=0xbf923464, envp=0xbf92346c)
at main.c:293
So I do know that it's using the fts system. Every few minutes, I've
interrupted it in gdb, and I have gotten these messages back from gdb:
Program received signal SIGINT, Interrupt.
parse_next_body_to_boundary (ctx=0x85746e8, block_r=0xbf92325c)
at message-parser.c:332
332 if (data[i] == '\n') {
(gdb) cont
Continuing.
[wait a few minutes]
Program received signal SIGINT, Interrupt.
parse_next_body_to_boundary (ctx=0x85746e8, block_r=0xbf92325c)
at message-parser.c:331
331 for (; i < block_r->size; i++) {
(gdb) cont
Continuing.
[wait a few minutes]
Program received signal SIGINT, Interrupt.
parse_next_body_to_boundary (ctx=0x85746e8, block_r=0xbf92325c)
at message-parser.c:332
332 if (data[i] == '\n') {
The ctx and block_r are the same at each point I interrupt it. This sounds
like an infinite loop to me if it can't exit this for minutes and minutes.
Furthermore, for the past couple of minutes, when I do this:
(gdb) print block_r[0]
$8 = {part = 0x80f3158, hdr = 0x0,
data = 0x8240d08 "\n<DIV><BR></DIV>Perhaps, but it is
important to note
that this is a dissenting<BR>opinion, not part of the actual text of the
Holt bill.<BR><BR><BR>--- In <A
href=\"mailto:TrueVote at yahoogroups.com\">Tru"...,
size = 8192}
I always get the same response back.
I've linked to a fairly small Maildir (five messages) that reproduces the
problem for me. It's possible that only one of those messages is actually
at fault; I haven't tried with any Maildir smaller than five messages.
Is there something more I can do to help fix this problem? I'm happy to do
anything reasonable further if you deem it useful.
-- Asheesh.
--
Bolub's Fourth Law of Computerdom:
Project teams detest weekly progress reporting because it so
vividly manifests their lack of progress.
-------------- next part --------------
00000004 CAPABILITY
00000005 SELECT ttestt
03000006 SEARCH UNANSWERED UNDELETED UNSEEN
03000007 FETCH 5 FLAGS
03000008 FETCH 1:5 (UID ENVELOPE BODY.PEEK[HEADER.FIELDS (Newsgroups Content-MD5
Content-Disposition Content-Language Content-Location resent-to resent-date
resent-from resent-cc resent-subject List-Help List-Unsubscribe List-Subscribe
List-Post List-Owner List-Archive Followup-To References)] INTERNALDATE
RFC822.SIZE FLAGS)
03000009 SEARCH TEXT bbq
-------------- next part --------------
* OK [RAWLOG TIMESTAMP] 2007-10-21 00:45:15
* CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT
LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS UIDPLUS LIST-EXTENDED
00000004 OK Capability completed.
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags
permitted.
* 5 EXISTS
* 0 RECENT
* OK [UNSEEN 1] First unseen.
* OK [UIDVALIDITY 1192952151] UIDs valid
* OK [UIDNEXT 6] Predicted next UID
00000005 OK [READ-WRITE] Select completed.
* SEARCH 1 2 3 4 5
03000006 OK Search completed.
* 5 FETCH (FLAGS ())
03000007 OK Fetch completed.
* 1 FETCH (UID 1 INTERNALDATE "21-Oct-2007 00:35:38 -0700" RFC822.SIZE
49586 FLAGS () ENVELOPE ("Sat, 14 Jul 2007 02:50:43 -0000"
"[TrueVote] Re: More on the thomas.loc.gov link" (("Thomas L.
Jones" NIL "DrJones" "alum.MIT.edu")) ((NIL NIL
"TrueVote" "yahoogroups.com")) (("Thomas L. Jones"
NIL "DrJones" "alum.MIT.edu")) ((NIL NIL
"TrueVote" "yahoogroups.com")) NIL NIL
"<019f01c7c5c0$620b5110$6701a8c0 at your0cdc4f5844>"
"<f79dm3+tng1 at eGroups.com>") BODY[HEADER.FIELDS (NEWSGROUPS
CONTENT-MD5 CONTENT-DISPOSITION CONTENT-LANGUAGE CONTENT-LOCATION RESENT-TO
RESENT-DATE RESENT-FROM RESENT-CC RESENT-SUBJECT LIST-HELP LIST-UNSUBSCRIBE
LIST-SUBSCRIBE LIST-POST LIST-OWNER LIST-ARCHIVE FOLLOWUP-TO REFERENCES)] {67}
List-Unsubscribe: <mailto:TrueVote-unsubscribe at yahoogroups.com>
)
* 2 FETCH (UID 2 INTERNALDATE "21-Oct-2007 00:35:38 -0700" RFC822.SIZE
64455 FLAGS () ENVELOPE ("Fri, 13 Jul 2007 23:39:20 -0400" "Re:
[TrueVote] Re: More on the thomas.loc.gov link" (("Ray Mondor"
NIL "raymondor" "rcn.com")) ((NIL NIL "TrueVote"
"yahoogroups.com")) (("Ray Mondor" NIL "raymondor"
"rcn.com")) ((NIL NIL "TrueVote"
"yahoogroups.com")("Thomas L. Jones" NIL "DrJones"
"alum.MIT.edu")) NIL NIL NIL "<01b101c7c5c8$90a768d0$6701a8c0
at your0cdc4f5844>") BODY[HEADER.FIELDS (NEWSGROUPS CONTENT-MD5
CONTENT-DISPOSITION CONTENT-LANGUAGE CONTENT-LOCATION RESENT-TO RESENT-DATE
RESENT-FROM RESENT-CC RESENT-SUBJECT LIST-HELP LIST-UNSUBSCRIBE LIST-SUBSCRIBE
LIST-POST LIST-OWNER LIST-ARCHIVE FOLLOWUP-TO REFERENCES)] {106}
References: <f79dm3+tng1 at eGroups.com>
List-Unsubscribe: <mailto:TrueVote-unsubscribe at yahoogroups.com>
)
* 3 FETCH (UID 3 INTERNALDATE "21-Oct-2007 00:35:38 -0700" RFC822.SIZE
76507 FLAGS () ENVELOPE ("Sat, 14 Jul 2007 00:53:40 -0400" "Re:
[TrueVote] Re: More on the thomas.loc.gov link" (("Ray Mondor"
NIL "raymondor" "rcn.com")) ((NIL NIL "TrueVote"
"yahoogroups.com")) (("Ray Mondor" NIL "raymondor"
"rcn.com")) ((NIL NIL "jmc27106"
"earthlink.net")(NIL NIL "TrueVote"
"yahoogroups.com")("Thomas L. Jones" NIL "DrJones"
"alum.MIT.edu")) NIL NIL NIL "<01cc01c7c5d2$f2dcd030$6701a8c0
at your0cdc4f5844>") BODY[HEADER.FIELDS (NEWSGROUPS CONTENT-MD5
CONTENT-DISPOSITION CONTENT-LANGUAGE CONTENT-LOCATION RESENT-TO RESENT-DATE
RESENT-FROM RESENT-CC RESENT-SUBJECT LIST-HELP LIST-UNSUBSCRIBE LIST-SUBSCRIBE
LIST-POST LIST-OWNER LIST-ARCHIVE FOLLOWUP-TO REFERENCES)] {119}
References: <3849-22007761442131343 at earthlink.net>
List-Unsubscribe: <mailto:TrueVote-unsubscribe at yahoogroups.com>
)
* 4 FETCH (UID 4 INTERNALDATE "21-Oct-2007 00:35:38 -0700" RFC822.SIZE
66021 FLAGS () ENVELOPE ("Sat, 14 Jul 2007 00:21:31 -0400" "Re:
[TrueVote] Re: More on the thomas.loc.gov link" (("jmc27106 at
earthlink.net" NIL "jmc27106" "earthlink.net")) ((NIL
NIL "TrueVote" "yahoogroups.com")) ((NIL NIL
"jmc27106" "earthlink.net")) (("Ray Mondor" NIL
"raymondor" "rcn.com")(NIL NIL "TrueVote"
"yahoogroups.com")("Thomas L. Jones" NIL "DrJones"
"alum.MIT.edu")) NIL NIL NIL "<3849-22007761442131343 at
earthlink.net>") BODY[HEADER.FIELDS (NEWSGROUPS CONTENT-MD5
CONTENT-DISPOSITION CONTENT-LANGUAGE CONTENT-LOCATION RESENT-TO RESENT-DATE
RESENT-FROM RESENT-CC RESENT-SUBJECT LIST-HELP LIST-UNSUBSCRIBE LIST-SUBSCRIBE
LIST-POST LIST-OWNER LIST-ARCHIVE FOLLOWUP-TO REFERENCES)] {67}
List-Unsubscribe: <mailto:TrueVote-unsubscribe at yahoogroups.com>
)
* 5 FETCH (UID 5 INTERNALDATE "21-Oct-2007 00:35:38 -0700" RFC822.SIZE
61191 FLAGS () ENVELOPE ("Tue, 17 Jul 2007 06:11:48 -0000"
"[TrueVote] Re: More on the thomas.loc.gov link" (("Thomas L.
Jones" NIL "DrJones" "alum.MIT.edu")) ((NIL NIL
"TrueVote" "yahoogroups.com")) (("Thomas L. Jones"
NIL "DrJones" "alum.MIT.edu")) ((NIL NIL
"TrueVote" "yahoogroups.com")) NIL NIL
"<3849-22007761442131343 at earthlink.net>"
"<f7hmj4+tb60 at eGroups.com>") BODY[HEADER.FIELDS (NEWSGROUPS
CONTENT-MD5 CONTENT-DISPOSITION CONTENT-LANGUAGE CONTENT-LOCATION RESENT-TO
RESENT-DATE RESENT-FROM RESENT-CC RESENT-SUBJECT LIST-HELP LIST-UNSUBSCRIBE
LIST-SUBSCRIBE LIST-POST LIST-OWNER LIST-ARCHIVE FOLLOWUP-TO REFERENCES)] {67}
List-Unsubscribe: <mailto:TrueVote-unsubscribe at yahoogroups.com>
)
03000008 OK Fetch completed.
Timo Sirainen
2007-Oct-21 12:14 UTC
[Dovecot] Problem with fts found against Dovecot hg; examples + trace attached
On Sun, 2007-10-21 at 00:56 -0700, Asheesh Laroia wrote:> I thought something was wrong when I attached strace to it for five minutes and > saw no calls to read() or open(). I can reproduce the "select takes forever" > on a tiny Maildir with 5 messages: > http://paulproteus.acm.jhu.edu/bug-report/2007-10-21/broken.tar.gzThanks, fixed: http://hg.dovecot.org/dovecot/rev/d6b2343238f9 -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 189 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20071021/6bf9e2f5/attachment-0002.bin>
Maybe Matching Threads
- Message parser loops on certain messages (e.g. with a trailing CR character)
- Panic with signal 6 core dump with revision 9116:9ae55b68cf61
- fts_squat hanging on some messages
- Dovecot-1.1.2 assertion failure in preparsed_parse_next_header_init
- [Asterisk-Dev] New Astmanproxy Mailing List, and New Version 1.11