The imap CLOSE command crash imapd

[brong]

From: Alain Spineux
Bugzilla-Id: 2986
Version: 2.3.x
Owner: Ken Murchison

[brong]

From: Alain Spineux

Send a CLOSE command when a folder is selected crash the imap server.
This append with 2.3.8 and 2.3.9 (the openpkg version in a kolab environement)
This was not happening with version 2.2.x.

I posted a lot of info in the thread :
http://cyrusimap.web.cmu.edu/archive/message.php?mailbox=archive.info-cyrus&msg=44371

Here is a cut&past of the most relevant info:

== cyrmaster.log ==

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

== a python script that show the problem ==

import imaplib, sys, types

imap_server='localhost'
imap_port=143
imap_login='manager'
imap_password='vishnou'

mailbox='user/catchall.teta.loc/donald.duck@teta.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)

== the output ==

OK, ['Completed']=SETACL user/catchall.teta.loc/donald.duck@teta.loc
OK, ['1']=SELECT user/catchall.teta.loc/donald.duck@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

== related problemes ==

• the CLOSE command is used by thunderbird when renaming, moving, deleting a folder! And then carsh imapd too
• I wrote a python script that was monitoring some mailbox. Because of the need to reopen the connection the log where growing light fast and the disk was full in a short time, with some database corruption. Thanks to cyrus :-)

[brong]

From: Ken Murchison

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?

[brong]

From: Alain Spineux

(In reply to comment #1)
> 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?
>
Someone else running kolab-2.2 got hte same problem.
I will investigate.

How can I generate this backtrace ? I didn't found any info on your site.

I imagine I have to :

compile imapd with -g
I will try to do a

make all CFLAGS=-g

then how to get the coredump ?
run

gdb master -d

or add some line in imapd.conf or cyrus.conf ?
and wait for coredump to be generated somewhere ?

Regards

[brong]

From: Ken Murchison

I usually will do the following:

cd /tmp
ulimit -c unlimited
/usr/cyrus/bin/master &

Any core dumps should be written in /tmp. Once you get one, do:

gdb /usr/cyrus/bin/imap /tmp/<corefile>
bt

[brong]

From: Alain Spineux

(In reply to comment #3)
> I usually will do the following:
>
> cd /tmp
> ulimit -c unlimited
> /usr/cyrus/bin/master &
>
> Any core dumps should be written in /tmp. Once you get one, do:
>
> gdb /usr/cyrus/bin/imap /tmp/<corefile>
> bt
>

As you said :-)
This is very easy to correct, this is a bug in the logging
(gdb) where
#0 0x0805536c in cmd_close (tag=0x8f7ae38 "EEED5") at imapd.c:3517
#1 0x0804e2d5 in cmdloop () at imapd.c:1169
#2 0x0804d2a3 in service_main (argc=1, argv=0x8f6f008, envp=0xbfc98e64)
at imapd.c:796
#3 0x0804c1d7 in main (argc=3, argv=0xbfc98e54, envp=0xbfc98e64)
at service.c:539
(gdb) print r
$1 = 0
(gdb) print tag
$2 = 0x8f7ae38 "EEED5"
(gdb) print imapd_userid
$3 = 0x8f7abd0 "manager"
(gdb) print imapd_mailbox
$4 = (struct mailbox *) 0x0

index_closemailbox(imapd_mailbox);
mailbox_close(imapd_mailbox);
imapd_mailbox = 0;

if (r) {
    prot_printf(imapd_out, "%s NO %s\r\n", tag, error_message(r));
}
else {
    prot_printf(imapd_out, "%s OK %s\r\n", tag,
                error_message(IMAP_OK_COMPLETED));

>>>>>THIS LINE is 3517
syslog(LOG_DEBUG, "cmd_expunge: user %s, mailbox %s, sequence %s",
imapd_userid, imapd_mailbox->name, "''");
}

I moved the imapd_mailbox=0 at the end to try

Then I have no more crash and no more error in my python script

Regards

[brong]

From: Alain Spineux

(In reply to comment #4)
> index_closemailbox(imapd_mailbox);
> mailbox_close(imapd_mailbox);
> imapd_mailbox = 0;
>
> if (r) {
> prot_printf(imapd_out, "%s NO %s\r\n", tag, error_message(r));
> }
> else {
> prot_printf(imapd_out, "%s OK %s\r\n", tag,
> error_message(IMAP_OK_COMPLETED));
> >>>>>THIS LINE is 3517
> syslog(LOG_DEBUG, "cmd_expunge: user %s, mailbox %s, sequence %s",
> imapd_userid, imapd_mailbox->name, "''");
> }
>
>
> I moved the imapd_mailbox=0 at the end to try
>

but then the message is probably wrong

Aug 31 16:22:22 eg01.emailgency.loc <debug> imap[23675]: open: user manager opened user/catchall.teta.loc@teta.loc
Aug 31 16:22:22 eg01.emailgency.loc <debug> imap[23675]: cmd_expunge: user manager, mailbox (NULL), sequence ''

the imap_close and maybe more must go to the end.

[brong]

From: Ken Murchison

The LOG_DEBUG message that is causing your problem is not in the stock Cyrus 2.3.x codebase. This is either part of the Kolab patch, or some other third-party patch.

[brong]

From: Alain Spineux

(In reply to comment #6)
> The LOG_DEBUG message that is causing your problem is not in the stock Cyrus
> 2.3.x codebase. This is either part of the Kolab patch, or some other
> third-party patch.
>
Thanks for your help.

I fact this is related to

https://bugzilla.andrew.cmu.edu/show_bug.cgi?id=2964

The submitted patch is the faulty one :-)
I already wrote a new one, we will submit is soon.
I have also submitted this patch to the openpkg mailing list.

I thing you can close this bug.

I take advantage I know you will read this post to say I already
posted 2 email to the cyrus-mailing list about bug with lot of details.
One about string "loker ???" appearing as a response to an IMAP command. this is in 2.2.X, this is probably an error message from berkeley db flowing through an unclosed file descriptor through the imap socket.
Another about the way cyrus is daemonized: file descriptor not closed and probably no double fork that make CTRL-C terminate the cyrus daemons. this is about 2.2.x and also 2.3.x

Regards