[Dovecot] Dovecot raw backtrace when copying to folder
Seeing a problem with a certain user causing dovecot to crash when copying mail to a folder. This looks similar to a bug someone on the mailing list posted recently.
Since the backtrace mentions the index, I tried deleting all of the index files for the user (including subfolders) but it had no effect. Seems that the bug still happens when creating the index for the first time.
Unfortunately, I can't pin down if there is a particular message causing the problem but I'll see if I can track it using strace.
Lines are broken for clarity. This is dovecot 1.0.5 on CentOS 4.5.
Sep 27 16:41:42 cookie dovecot: imap-login: Login: user=user@domain, method=PLAIN, rip=::ffff:xx.xx.xx.xx, lip=::ffff:yy.yy.yy.yy, TLS Sep 27 16:41:53 cookie dovecot: IMAP(user@domain): Trying to allocate 0 bytes Sep 27 16:41:53 cookie dovecot: IMAP(user@domain): Raw backtrace: imap [0x80ad7d4] -> imap [0x80ad239] -> imap [0x80b5624] -> imap(i_malloc+0x1b) [0x80b0e1b] -> imap [0x8083037] -> imap [0x80833e6] -> imap(index_storage_search_init+0xf4) [0x80836f4] -> imap(cmd_copy+0x145) [0x8056d15] -> imap(cmd_uid+0x7c) [0x805a74c] -> imap [0x805b2d5] -> imap [0x805b25e] -> imap(_client_input+0x8c) [0x805b43c] -> imap(io_loop_handler_run+0x169) [0x80b3e09] -> imap(io_loop_run+0x28) [0x80b3178] -> imap(main+0x49f) [0x806384f] -> /lib/tls/libc.so.6(__libc_start_main+0xd3) [0x506de3] -> imap [0x8055db1] Sep 27 16:41:53 cookie dovecot: child 26079 (imap) killed with signal 6
Julian Cowley wrote:
Seeing a problem with a certain user causing dovecot to crash when copying mail to a folder. This looks similar to a bug someone on the mailing list posted recently.
Hi,
first of all I would like to report success with moving from UW-imapd to Dovecot 1.0.5 for a ~100 user setup on Debian Etch. Everything works nicely, including the snarf plugin.
Only a small problem: In the last four days Dovecot crashed twice with a similar error message posted in this thread:
dovecot: 2007-09-25 16:54:08 Panic: Lost login process PID 420 dovecot: 2007-09-25 16:54:08 Error: Raw backtrace: dovecot [0x805616a] -> dovecot [0x8055fdc] -> dovecot [0x804d83a] -> dovecot [0x8050572] -> dovecot [0x8059e0e] -> dovecot [0x8059780] -> dovecot [0x80587a8] -> dovecot [0x8050f5c] -> /lib/tls/libc.so.6(__libc_start_main+0xc8) [0xb7eb1ea8] -> dovecot [0x804a391]
dovecot: 2007-09-27 12:13:02 Panic: Lost login process PID 5160 dovecot: 2007-09-27 12:13:02 Error: Raw backtrace: dovecot [0x805616a] -> dovecot [0x8055fdc] -> dovecot [0x804d83a] -> dovecot [0x8050572] -> dovecot [0x8059e0e] -> dovecot [0x8059780] -> dovecot [0x80587a8] -> dovecot [0x8050f5c] -> /lib/tls/libc.so.6(__libc_start_main+0xc8) [0xb7e24ea8] -> dovecot [0x804a391]
I witnessed the first crash, an user moved some messages out of a larger mbox file to the trash, using Thunderbird 2.0.0.6/Windows + IMAP.
After starting the move, TB showed an hourglas for approx. 10 minutes, then the messages were moved. I guess during these 10 minutes Dovecot crashed and was restarted through new TB commands send to the server. Dovecot is started through inetd.
I am not sure if I can reproduce the bug because the user with the first crash uses Dovecot already for several months and he said he saw this problem already several times but he was unable to tell me a procedure to reproduce the bug.
Greetings, Bernd Kuhls
PS: My config
# dovecot -n # 1.0.5: /etc/dovecot/dovecot.conf log_path: /var/log/dovecot/dovecot.main log_timestamp: %Y-%m-%d %H:%M:%S protocols: imap imaps pop3 pop3s disable_plaintext_auth: no login_dir: /var/run/dovecot/login login_executable(default): /usr/lib/dovecot/imap-login login_executable(imap): /usr/lib/dovecot/imap-login login_executable(pop3): /usr/lib/dovecot/pop3-login login_max_processes_count: 256 mail_extra_groups: mail mail_location: mbox:~/.imap_mail:INBOX=/var/mail/%u:INDEX=/var/mail/indexes/%u mail_executable(default): /usr/lib/dovecot/imap mail_executable(imap): /usr/lib/dovecot/imap mail_executable(pop3): /usr/lib/dovecot/pop3 mail_plugins(default): quota imap_quota mbox_snarf mail_plugins(imap): quota imap_quota mbox_snarf mail_plugins(pop3): mbox_snarf mail_plugin_dir(default): /usr/lib/dovecot/modules/imap mail_plugin_dir(imap): /usr/lib/dovecot/modules/imap mail_plugin_dir(pop3): /usr/lib/dovecot/modules/pop3 imap_client_workarounds(default): outlook-idle netscape-eoh tb-extra-mailbox-sep delay-newmail imap_client_workarounds(imap): outlook-idle netscape-eoh tb-extra-mailbox-sep delay-newmail imap_client_workarounds(pop3): outlook-idle pop3_uidl_format(default): pop3_uidl_format(imap): pop3_uidl_format(pop3): %08Xv%08Xu auth default: passdb: driver: pam userdb: driver: passwd plugin: quota: fs mbox_snarf: ~/.imap_mail/inbox
On 2007-09-29 20:06:45 +0200, Bernd Kuhls wrote:
dovecot: 2007-09-25 16:54:08 Panic: Lost login process PID 420 dovecot: 2007-09-25 16:54:08 Error: Raw backtrace: dovecot [0x805616a] -> dovecot [0x8055fdc] -> dovecot [0x804d83a] -> dovecot [0x8050572] -> dovecot [0x8059e0e] -> dovecot [0x8059780] -> dovecot [0x80587a8] -> dovecot [0x8050f5c] -> /lib/tls/libc.so.6(__libc_start_main+0xc8) [0xb7eb1ea8] -> dovecot [0x804a391]
your dovecot binaries are stripped. those backtraces are more or less useless without your binaries/system. can you install the debuginfo package or rebuild your installation without stripping?
darix
-- openSUSE - SUSE Linux is my linux openSUSE is good for you www.opensuse.org
On Sat, 2007-09-29 at 20:06 +0200, Bernd Kuhls wrote:
dovecot: 2007-09-25 16:54:08 Panic: Lost login process PID 420 .. Dovecot is started through inetd.
Running from inetd hasn't been tested all that much. I'll see if I can get this fixed, but you could avoid this by not using inetd.
Timo Sirainen wrote:
On Sat, 2007-09-29 at 20:06 +0200, Bernd Kuhls wrote:
dovecot: 2007-09-25 16:54:08 Panic: Lost login process PID 420 .. Dovecot is started through inetd.
Running from inetd hasn't been tested all that much. I'll see if I can get this fixed, but you could avoid this by not using inetd.
Hi,
unless you can provide another way to restrict access to IMAP and POP3 to our local IP range this is not an option for us. Debian Etchs tcpwrapper has been patched http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=377154 to allow a syntax like this:
# imap 143: 127.0.0.1, x.y.z. # imaps 993: ALL
# pop3 110: 127.0.0.1, x.y.z. # pop3s 995: ALL
which requires starting Dovecot using inetd.
I re-compiled Dovecot 1.0 yesterday using the latest hg checkout:
# hg parents changeset: 5419:f85adea35b74 tag: tip user: Timo Sirainen tss@iki.fi date: Mon Sep 24 11:15:48 2007 +0300 summary: Don't crash with empty messagesets.
removing dh_strip from debian/rules to provide a better backtrace:
#!/bin/sh cd /home/kuhls rm -rf ./dovecot_compile mkdir ./dovecot_compile cd ./dovecot_compile hg clone http://hg.dovecot.org/dovecot-1.0/ wget http://ftp.debian.org/debian/pool/main/d/dovecot/dovecot_1.0.5-1.dsc wget http://ftp.debian.org/debian/pool/main/d/dovecot/dovecot_1.0.5-1.diff.gz cd dovecot-1.0 zcat ../dovecot_1.0.5-1.diff.gz | patch -p1 -E chown -R root * grep -v dh_strip ./debian/rules > ./debian/rules2 mv ./debian/rules2 ./debian/rules chmod +x ./debian/rules ./autogen.sh dpkg-buildpackage -uc -us -b
# build snarf-plugin ->
http://www.mail-archive.com/dovecot%40dovecot.org/msg02174.html
export DOVECOT=/home/kuhls/dovecot_compile/dovecot-1.0
wget http://dovecot.org/patches/1.0/mbox-snarf-plugin.c
gcc -fPIC -shared -Wall -I$DOVECOT -I$DOVECOT/src/lib
-I$DOVECOT/src/lib-storage -I$DOVECOT/src/lib-mail
-I$DOVECOT/src/lib-imap -DHAVE_CONFIG_H
mbox-snarf-plugin.c -o ../mbox_snarf_plugin.so
I hope this is sufficient to provide the necessary informations. Until now no new crash in the logs. I will try to reproduce the bug.
Greetings, Bernd
On Sun, 2007-09-30 at 16:01 +0200, Bernd Kuhls wrote:
Timo Sirainen wrote:
On Sat, 2007-09-29 at 20:06 +0200, Bernd Kuhls wrote:
dovecot: 2007-09-25 16:54:08 Panic: Lost login process PID 420 .. Dovecot is started through inetd.
Running from inetd hasn't been tested all that much. I'll see if I can get this fixed, but you could avoid this by not using inetd.
Hi,
unless you can provide another way to restrict access to IMAP and POP3 to our local IP range this is not an option for us.
iptables?
Until now no new crash in the logs. I will try to reproduce the bug.
I suppose this fixes it: http://hg.dovecot.org/dovecot-1.0/rev/8d6433652a33
Timo Sirainen wrote:
On Sun, 2007-09-30 at 16:01 +0200, Bernd Kuhls wrote:
unless you can provide another way to restrict access to IMAP and POP3 to our local IP range this is not an option for us.
iptables?
Until now no new crash in the logs. I will try to reproduce the bug.
I suppose this fixes it: http://hg.dovecot.org/dovecot-1.0/rev/8d6433652a33
Hi,
first the good news, since using Dovecot including the patch mentioned above there were no new crashes this week, well done!
/var/log/dovecot# grep Panic * dovecot.main:dovecot: 2007-09-25 16:54:08 Panic: Lost login process PID 420 dovecot.main:dovecot: 2007-09-27 12:13:02 Panic: Lost login process PID 5160 dovecot.main:dovecot: 2007-09-30 15:26:34 Panic: Lost login process PID 9091
But now my syslog is filled with this once every 10 minutes:
Oct 6 14:11:42 server inetd[16124]: pop3s/tcp: bind: Address already in use Oct 6 14:11:42 server inetd[16124]: pop3/tcp: bind: Address already in use Oct 6 14:11:42 server inetd[16124]: imaps/tcp: bind: Address already in use Oct 6 14:11:42 server inetd[16124]: imap/tcp: bind: Address already in use
But Dovecots behaviour has changed somehow. When updating dovecot.conf all I had to do to activate the new config was to kill the master process. Client-side connections let inetd restart dovecot, this is not the case anymore. Now I have to start /usr/sbin/dovecot on the shell to reactivate the IMAP/POP service. Debians /etc/init.d/dovecot has to be changed to reflect your patch, right? Currently it contains
# The init script should do nothing if dovecot or another imap/pop3 server # is being run from inetd, and dovecot is configured to run as an imap or # pop3 service for p in
sed -r "s/^ *(([^:]+|\[[^]]+]|\*):)?(pop3s?|imaps?)[ \t].*/\3/;t;d" \ /etc/inetd.confdo for q insed -r "s/^[ \t]*protocols[ \t]*=[ \t]*(([^\"]*)|\"(.*)\")/\2\3/;t;d" \ ${CONF}do if [ $p = $q ]; then exit 0 fi done done
Greetings, spiralvoice
On Sat, 2007-10-06 at 14:27 +0200, Bernd Kuhls wrote:
But now my syslog is filled with this once every 10 minutes:
Oct 6 14:11:42 server inetd[16124]: pop3s/tcp: bind: Address already in use Oct 6 14:11:42 server inetd[16124]: pop3/tcp: bind: Address already in use Oct 6 14:11:42 server inetd[16124]: imaps/tcp: bind: Address already in use Oct 6 14:11:42 server inetd[16124]: imap/tcp: bind: Address already in use
But Dovecots behaviour has changed somehow. When updating dovecot.conf all I had to do to activate the new config was to kill the master process. Client-side connections let inetd restart dovecot, this is not the case anymore. Now I have to start /usr/sbin/dovecot on the shell to reactivate the IMAP/POP service. Debians /etc/init.d/dovecot has to be changed to reflect your patch, right?
That patch didn't do any changes to the behavior. It just fixed those assert-crashes. inetd should still restart dovecot if it's not running. I just tested and it worked.
On Thu, 2007-09-27 at 17:07 -1000, Julian Cowley wrote:
Lines are broken for clarity. This is dovecot 1.0.5 on CentOS 4.5. .. imap(i_malloc+0x1b) [0x80b0e1b] -> imap [0x8083037] -> imap [0x80833e6] -> imap(index_storage_search_init+0xf4) [0x80836f4] ->
Are you sure it's 1.0.5? This looks a lot like the crash that empty messagesets caused with post-1.0.5 hg version: http://hg.dovecot.org/dovecot-1.0/rev/f85adea35b74
Getting a proper gdb backtrace of the crash would anyway be better than this raw backtrace: http://dovecot.org/bugreport.html
Or at least I'd like to know what gdb says with:
gdb /usr/local/libexec/dovecot/imap l *0x8083037 l *0x80833e6
On Sun, 30 Sep 2007, Timo Sirainen wrote:
On Thu, 2007-09-27 at 17:07 -1000, Julian Cowley wrote:
Lines are broken for clarity. This is dovecot 1.0.5 on CentOS 4.5. .. imap(i_malloc+0x1b) [0x80b0e1b] -> imap [0x8083037] -> imap [0x80833e6] -> imap(index_storage_search_init+0xf4) [0x80836f4] ->
Are you sure it's 1.0.5? This looks a lot like the crash that empty messagesets caused with post-1.0.5 hg version: http://hg.dovecot.org/dovecot-1.0/rev/f85adea35b74
You're right, it's not strictly 1.0.5 since I added the following patches. I'm not using the above empty messagesets patch though. Should I be?
My patch file name hg revision ================================ ============ dovecot-cmd-create-fix.patch 6bbb20cdaf1e dovecot-deliver-dup-db-fix.patch 9d4e89fa62d0 dovecot-mailbox-idle-check.patch afb48abd91c0 dovecot-search-not-fix.patch d144e54f09e6 dovecot-search-opt-p1.patch fa89431f893e dovecot-search-opt-p2.patch 92b2bd6b6c2d dovecot-search-opt-p3.patch 678626efb942
In addition there are a few patches in my spec file which are inherited from the original by Axel Thimm, but these have been in there for donkey's years and are unlikely to be related to the problem.
Getting a proper gdb backtrace of the crash would anyway be better than this raw backtrace: http://dovecot.org/bugreport.html
Or at least I'd like to know what gdb says with:
gdb /usr/local/libexec/dovecot/imap l *0x8083037 l *0x80833e6
Unfortunately, it looks like I've built dovecot with stripped binaries, so there is no symbol information for the above locations. I'll rebuild with -g enabled and see if the bug can be reproduced.
BTW, I have an strace of the crash if you are interested. I haven't posted it here since it contains user information, but I could send it directly to you.
participants (4)
-
Bernd Kuhls
-
Julian Cowley
-
Marcus Rueckert
-
Timo Sirainen