CLOSE crash the imap server, NEED HELP

Alain Spineux aspineux at gmail.com
Thu Aug 30 13:14:57 EDT 2007 

Hello

can someone confirm he has (or not) this problem ?
this must be tested on kolab 2.2 running cyrus 2.3.8 or 2.3.9

Can you run this script and look if you get the same error :

dont forget to configure the setting of one of your mailbox

imap_server='localhost'
#imap_server='fc6-eg.asxnet.loc'
imap_port=143
imap_login='manager'
imap_password='vishnou'

mailbox='user/catchall.teta.loc/donald.duck at teta.loc'
#mailbox=' user/catchall.alpha.loc/toto at alpha.loc'

imap_con=imaplib.IMAP4(imap_server, imap_port)
typ, dat=imap_con.login(imap_login, imap_password)

typ, dat=imap_con.setacl(mailbox, imap_login, 'lrd')
print '%s, %s=SETACL %s' % (typ, dat, mailbox)
typ, dat=imap_con.select(mailbox)
print '%s, %s=SELECT %s' % (typ, dat, mailbox)
#typ, dat=imap_con.uid('search', None, 'ALL')
#print '%s, %s=UID SEARCH %s' % (typ, dat, mailbox)
typ, dat=imap_con.close()
print '%s, %s=CLOSE %s' % (typ, dat, mailbox)
typ, dat=imap_con.logout()
print '%s, %s=LOGOUT %s' % (typ, dat, mailbox)

and its output


OK, ['Completed']=SETACL user/catchall.teta.loc/donald.duck at teta.loc
OK, ['1']=SELECT user/catchall.teta.loc/donald.duck at teta.loc
Traceback (most recent call last):
  File "cyrus_bug.py", line 21, in <module>
    typ, dat=imap_con.close()
  File "/kolab/lib/python/imaplib.py", line 376, in close
    typ, dat = self._simple_command('CLOSE')
  File "/kolab/lib/python/imaplib.py", line 1055, in _simple_command
    return self._command_complete(name, self._command(name, *args))
  File "/kolab/lib/python/imaplib.py", line 887, in _command_complete
    raise self.abort('command: %s => %s' % (name, val))
imaplib.abort: command: CLOSE => socket error: EOF



On 8/29/07, Alain Spineux <aspineux at gmail.com> wrote:
>
> Is-it possible for someone running kolab to confirm this problem ?
> Can someone run my python script (dont forget to configure your owne
> server/mailbox)
>
> Here is the response a got from cyrus :
>
> http://bugzilla.andrew.cmu.edu/show_bug.cgi?id=2986
>
> --- Comment #1 from Ken Murchison < murch at andrew.cmu.edu>  2007-08-29
> 12:09:14 ---
> I can't reproduce this problem with an unmodified 2.3.9.  Perhaps this is
> a bug
> with the Kolab patches.  Can you get me a backtrace from an imapd core
> dump?
>
> Regards
>
>
>
>
> On 8/29/07, Alain Spineux <aspineux at gmail.com> wrote:
> >
> > I opened this bug report
> >
> > https://bugzilla.andrew.cmu.edu/show_bug.cgi?id=2986
> >
> > Regards
> >
> > On 8/13/07, Alain Spineux <aspineux at gmail.com> 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/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
> >
> >
> >
> >
> > --
> > Alain Spineux
> > aspineux gmail com
> > May the sources be with you
> >
>
>
>
> --
> Alain Spineux
> aspineux gmail com
> May the sources be with you
>



-- 
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/20070830/195f6af8/attachment-0001.html

More information about the Info-cyrus mailing list