CLOSE crash the imap server

[Alain Spineux]

Something strange append with my cyrus-imap 2.3.8 from openpkg
imapd-2.3.8-20070720

When I CLOSE a mailbox, (after a SELECT), the server die and close the
connection !
Look the FIN  (F) packet at 16:14:25.869642

Here are the relevant the cyrus log (around 16:14:25)

cyrmaster.log:Aug 13 16:14:25 eg01 <error> master[32578]: process 21432
exited, signaled to death by 11
cyrmaster.log:Aug 13 16:14:25 eg01 <debug> master[32578]: service imap pid
21432 in BUSY state: terminated abnormally
cyrmaster.log:Aug 13 16:14:25 eg01 <debug> master[21531]: about to exec
/kolab/bin/imapd

imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: myfetch: starting txn
2147484170
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: abort_txn: aborting txn
2147484170
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: myfetch: starting txn
2147484171
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: mystore: reusing txn
2147484171
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: mycommit: committing txn
2147484171
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: myfetch: starting txn
2147484172
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: abort_txn: aborting txn
2147484172
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: myfetch: starting txn
2147484173
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: mystore: reusing txn
2147484173
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: mycommit: committing txn
2147484173
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: myfetch: starting txn
2147484174
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: abort_txn: aborting txn
2147484174
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: myfetch: starting txn
2147484175
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: mystore: reusing txn
2147484175
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: mycommit: committing txn
2147484175
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: myfetch: starting txn
2147484176
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: abort_txn: aborting txn
2147484176
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: myfetch: starting txn
2147484177
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: mystore: reusing txn
2147484177
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: mycommit: committing txn
2147484177
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: myfetch: starting txn
2147484178
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: abort_txn: aborting txn
2147484178
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: myfetch: starting txn
2147484179
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: mystore: reusing txn
2147484179
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: mycommit: committing txn
2147484179
imapd.log:Aug 13 16:14:25 eg01 <debug> imap[21432]: open: user manager
opened user/donald.duck at gamma.loc

Here is the ASCII's tcpdump

ODPO12 SETACL "user/donald.duck at gamma.loc" manager lrd..
16:14:25.857715 IP eg01.imap > eg01.55867: P 457:478(21) ack 544 win 256
<nop,nop,timestamp 47451731 47451730>
ODPO12 OK Completed..
16:14:25.858710 IP eg01.55867 > eg01.imap: P 544:588(44) ack 478 win 290
<nop,nop,timestamp 47451732 47451731>
ODPO13 SELECT "user/donald.duck at gamma.loc"..
16:14:25.859297 IP eg01.imap > eg01.55867: P 478:777(299) ack 588 win 256
<nop,nop,timestamp 47451732 47451732>
* FLAGS (\Answered \Flagged \Draft \Deleted \Seen)..
* OK [PERMANENTFLAGS (\Deleted)]  ..
* 0 EXISTS..
* 0 RECENT..
* OK [UIDVALIDITY 1187010780]  ..
* OK [UIDNEXT 2]  ..
* OK [NOMODSEQ] Sorry, modsequences have not been enabled on this mailbox..
* OK [URLMECH INTERNAL]..
ODPO13 OK [READ-WRITE] Completed..
16:14:25.860638 IP eg01.55867 > eg01.imap: P 588:611(23) ack 777 win 299
<nop,nop,timestamp 47451732 47451732>
ODPO14 UID SEARCH ALL..
16:14:25.860913 IP eg01.imap > eg01.55867: P 777:831(54) ack 611 win 256
<nop,nop,timestamp 47451732 47451732>
* SEARCH..
ODPO14 OK Completed (0 msgs in 0.000 secs)..
16:14:25.862171 IP eg01.55867 > eg01.imap: P 611:625(14) ack 831 win 299
<nop,nop,timestamp 47451732 47451732>
ODPO15 CLOSE..
16:14:25.869642 IP eg01.imap > eg01.55867: F 831:831(0) ack 625 win 256
<nop,nop,timestamp 47451734 47451732>
16:14:25.906271 IP eg01.55867 > eg01.imap: . ack 832 win 299
<nop,nop,timestamp 47451744 47451734>
16:14:25.933508 IP eg01.55867 > eg01.imap: P 625:638(13) ack 832 win 299
<nop,nop,timestamp 47451750 47451734>
ODPO16 NOOP..
16:14:25.933539 IP eg01.imap > eg01.55867: R 3474995568:3474995568(0) win 0
16:14:25.934034 IP eg01.55871 > eg01.imap: S 3508738700:3508738700(0) win
32792 <mss 16396,sackOK,timestamp 47451750 0,nop,wscale 7>
16:14:25.934062 IP eg01.imap > eg01.55871: S 3501230146:3501230146(0) ack
3508738701 win 32768 <mss 16396,sackOK,timestamp 47451750
47451750,nop,wscale 7>
16:14:25.934081 IP eg01.55871 > eg01.imap: . ack 1 win 257
<nop,nop,timestamp 47451750 47451750>
16:14:25.964179 IP eg01.imap > eg01.55871: P 1:117(116) ack 1 win 256
<nop,nop,timestamp 47451758 47451750>
* OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID STARTTLS] eg01 Cyrus IMAP4
v2.3.8-openpkg server ready..
16:14:25.964335 IP eg01.55871 > eg01.imap: . ack 117 win 257
<nop,nop,timestamp 47451758 47451758>
16:14:25.964595 IP eg01.55871 > eg01.imap: P 1:19(18) ack 117 win 257
<nop,nop,timestamp 47451758 47451758>
IECD0 CAPABILITY..


Here is another transcript and logs, but the SEARCH returned some emails, I
delete them then CLOSE and still get the same error


cyrmaster.log:Aug 13 16:41:12 eg01 <error> master[32578]: process 21531
exited, signaled to death by 11
cyrmaster.log:Aug 13 16:41:12 eg01 <debug> master[32578]: service imap pid
21531 in BUSY state: terminated abnormally

imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484246
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: reusing txn
2147484246
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mystore: reusing txn
2147484246
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mycommit: committing txn
2147484246
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mystore: starting txn
2147484247
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mystore: committing txn
2147484247
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484248
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: abort_txn: aborting txn
2147484248
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484249
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mystore: reusing txn
2147484249
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mycommit: committing txn
2147484249
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484250
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: abort_txn: aborting txn
2147484250
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484251
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mystore: reusing txn
2147484251
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mycommit: committing txn
2147484251
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484252
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: abort_txn: aborting txn
2147484252
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484253
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mystore: reusing txn
2147484253
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mycommit: committing txn
2147484253
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484254
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: abort_txn: aborting txn
2147484254
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484255
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mystore: reusing txn
2147484255
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mycommit: committing txn
2147484255
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484256
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: abort_txn: aborting txn
2147484256
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484257
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mystore: reusing txn
2147484257
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mycommit: committing txn
2147484257
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484258
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: abort_txn: aborting txn
2147484258
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: myfetch: starting txn
2147484259
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mystore: reusing txn
2147484259
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mycommit: committing txn
2147484259
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: open: user manager
opened user/alain.spineux at gamma.loc
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: SQUAT failed to open
index file
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: SQUAT failed
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mailbox_expunge:
removing mail gamma.loc!user.alain^spineux:1
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mailbox_expunge:
removing mail gamma.loc!user.alain^spineux:2
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mailbox_expunge:
removing mail gamma.loc!user.alain^spineux:3
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[21531]: mailbox_expunge:
removing mail gamma.loc!user.alain^spineux:4
imapd.log:Aug 13 16:41:12 eg01 <notice> imap[21531]: Expunged 4 messages
from gamma.loc!user.alain^spineux
imapd.log:Aug 13 16:41:12 eg01 <debug> imap[22414]: accepted connection



16:41:12.876898 IP eg01.55871 > eg01.imap: P 640:698(58) ack 355 win 282
<nop,nop,timestamp 47853460 47853460>
IECD15 SETACL "user/alain.spineux at gamma.loc" manager lrd..
16:41:12.884891 IP eg01.imap > eg01.55871: P 355:376(21) ack 698 win 256
<nop,nop,timestamp 47853462 47853460>
IECD15 OK Completed..
16:41:12.885813 IP eg01.55871 > eg01.imap: P 698:744(46) ack 376 win 282
<nop,nop,timestamp 47853462 47853462>
IECD16 SELECT "user/alain.spineux at gamma.loc"..
16:41:12.886621 IP eg01.imap > eg01.55871: P 376:694(318) ack 744 win 256
<nop,nop,timestamp 47853463 47853462>
* FLAGS (\Answered \Flagged \Draft \Deleted \Seen)..
* OK [PERMANENTFLAGS (\Deleted)]  ..
* 4 EXISTS..
* 4 RECENT..
* OK [UNSEEN 1]  ..
* OK [UIDVALIDITY 1186973198]  ..
* OK [UIDNEXT 5]  ..
* OK [NOMODSEQ] Sorry, modsequences have not been enabled on this mailbox..
* OK [URLMECH INTERNAL]..
IECD16 OK [READ-WRITE] Completed..
16:41:12.887616 IP eg01.55871 > eg01.imap: P 744:767(23) ack 694 win 290
<nop,nop,timestamp 47853463 47853463>
IECD17 UID SEARCH ALL..
16:41:12.888135 IP eg01.imap > eg01.55871: P 694:756(62) ack 767 win 256
<nop,nop,timestamp 47853463 47853463>
* SEARCH 1 2 3 4..
IECD17 OK Completed (4 msgs in 0.000 secs)..
16:41:12.888711 IP eg01.55871 > eg01.imap: P 767:840(73) ack 756 win 290
<nop,nop,timestamp 47853463 47853463>
IECD18 UID COPY 1,2,3,4 user/catchall.gamma.loc/alain.spineux at gamma.loc..
16:41:12.903778 IP eg01.imap > eg01.55871: P 756:777(21) ack 840 win 256
<nop,nop,timestamp 47853467 47853463>
IECD18 OK Completed..
16:41:12.904178 IP eg01.55871 > eg01.imap: P 840:884(44) ack 777 win 290
<nop,nop,timestamp 47853467 47853467>
IECD19 UID STORE 1,2,3,4 +FLAGS (\Deleted)..
16:41:12.911896 IP eg01.imap > eg01.55871: P 777:974(197) ack 884 win 256
<nop,nop,timestamp 47853469 47853467>
* 1 FETCH (FLAGS (\Recent \Deleted) UID 1)..
* 2 FETCH (FLAGS (\Recent \Deleted) UID 2)..
* 3 FETCH (FLAGS (\Recent \Deleted) UID 3)..
* 4 FETCH (FLAGS (\Recent \Deleted) UID 4)..
IECD19 OK Completed..
16:41:12.913147 IP eg01.55871 > eg01.imap: P 884:898(14) ack 974 win 299
<nop,nop,timestamp 47853469 47853469>
IECD20 CLOSE..
16:41:12.931917 IP eg01.imap > eg01.55871: F 974:974(0) ack 898 win 256
<nop,nop,timestamp 47853474 47853469>
16:41:12.970379 IP eg01.55871 > eg01.imap: . ack 975 win 299
<nop,nop,timestamp 47853484 47853474>
16:41:12.989151 IP eg01.55871 > eg01.imap: P 898:911(13) ack 975 win 299
<nop,nop,timestamp 47853488 47853474>
IECD21 NOOP..
16:41:12.989193 IP eg01.imap > eg01.55871: R 3501231896:3501231896(0) win 0

Any idea ?



-- 
Alain Spineux
aspineux gmail com
May the sources be with you
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.andrew.cmu.edu/pipermail/info-cyrus/attachments/20070813/d32266ef/attachment-0001.html