I opened this bug report https://bugzilla.andrew.cmu.edu/show_bug.cgi?id=2986
Regards On 8/13/07, Alain Spineux <[EMAIL PROTECTED]> wrote: > > > 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/[EMAIL PROTECTED] > > Here is the ASCII's tcpdump > > ODPO12 SETACL "user/[EMAIL PROTECTED]" 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/[EMAIL PROTECTED]".. > 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/[EMAIL PROTECTED] > 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/[EMAIL PROTECTED] " 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/[EMAIL PROTECTED]".. > 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/[EMAIL PROTECTED] .. > 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 -- Alain Spineux aspineux gmail com May the sources be with you
---- Cyrus Home Page: http://cyrusimap.web.cmu.edu/ Cyrus Wiki/FAQ: http://cyrusimap.web.cmu.edu/twiki List Archives/Info: http://asg.web.cmu.edu/cyrus/mailing-list.html
