[Dovecot] Bug report - crash on group lookup
Hi
I was doing some migration from a 1.2 installation to a 2.1. While testing my new installation dovecot crashed at two test-cases constantly with with a "Panic: Trying to allocate 0 bytes" message.
Both times it was because I was using a wrong group (or none) in my config.
The output I got by dovecot was not that helpful. I only figured it out, that it has something to do with the group by looking at the code, to figure out where the stacktrace I got could come from.
Unfortunately, I don't remember one of the examples anymore that correctly (except that it was also a group configuration related issue). The other example, was that I was testing the quota warning scripts:
Normal delivery worked fine, but as soon as dovecot should send a quota warning, after the mail got already delivered, I received said panic. For the MTA the mail delivery failed (-> bounce), although the LDA already delivered the mail, but failed in post processing (sending the quota warning).
My fix was to add:
unix_listener quota-warning { group = mail mode = 0660 }
to the quota warning service. The LDA process has an own user per mailbox and the mail group. It looks to me as it would panic by looking up the user of the lda process, but that's pure guess.
Attached is a debug output and the configuration that triggered the problem.
I see two problems:
- Don't panic while "looking" up a group
- Give a meaningful error messages.
If you have any further questions, please let me know.
~pete
==> /var/log/dovecot/debug.log <== May 25 12:19:50 lda: Debug: Loading modules from directory: /usr/lib/dovecot May 25 12:19:50 lda: Debug: Module loaded: /usr/lib/dovecot/lib10_quota_plugin.so May 25 12:19:50 lda: Debug: Module loaded: /usr/lib/dovecot/lib90_sieve_plugin.so May 25 12:19:50 lda: Debug: auth input: dovecot@example.com home=/var/mail/dovecot@example.com uid=41407 gid=12 quota_rule=*:storage=1M May 25 12:19:50 lda: Debug: Added userdb setting: plugin/quota_rule=*:storage=1M May 25 12:19:50 lda(dovecot@example.com): Debug: Effective uid=41407, gid=12, home=/var/mail/dovecot@example.com May 25 12:19:50 lda(dovecot@example.com): Debug: Quota root: name=User quota backend=maildir args= May 25 12:19:50 lda(dovecot@example.com): Debug: Quota rule: root=User quota mailbox=* bytes=1048576 messages=0 May 25 12:19:50 lda(dovecot@example.com): Debug: Quota rule: root=User quota mailbox=INBOX.Trash bytes=+104857 (10%) messages=0 May 25 12:19:50 lda(dovecot@example.com): Debug: Quota warning: bytes=996147 (95%) messages=0 reverse=no command=quota-warning 95 dovecot@example.co, May 25 12:19:50 lda(dovecot@example.com): Debug: Quota warning: bytes=838860 (80%) messages=0 reverse=no command=quota-warning 80 dovecot@example.com May 25 12:19:50 lda(dovecot@example.com): Debug: Namespace inbox: type=private, prefix=INBOX., sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/mail/dovecot@example.com May 25 12:19:50 lda(dovecot@example.com): Debug: maildir++: root=/var/mail/dovecot@example.com/mail, index=, control=, inbox=/var/mail/dovecot@example.com/mail, alt= May 25 12:19:50 lda(dovecot@example.com): Debug: Quota root: name=User quota backend=maildir args= May 25 12:19:50 lda(dovecot@example.com): Debug: Quota rule: root=User quota mailbox=* bytes=0 messages=0 May 25 12:19:50 lda(dovecot@example.com): Debug: Quota rule: root=User quota mailbox=INBOX.Trash bytes=0 (10%) messages=0 May 25 12:19:50 lda(dovecot@example.com): Debug: Quota warning: bytes=0 (95%) messages=0 reverse=no command=quota-warning 95 raw mail ur May 25 12:19:50 lda(dovecot@example.com): Debug: Quota warning: bytes=0 (80%) messages=0 reverse=no command=quota-warning 80 raw mail ur May 25 12:19:50 lda(dovecot@example.com): Debug: none: root=, index=, control=, inbox=, alt= May 25 12:19:50 lda(dovecot@example.com): Debug: Destination address: dovecot@example.com (source: -a parameter) May 25 12:19:50 lda(dovecot@example.com): Debug: sieve: user's script path /var/mail/dovecot@example.com/dovecot.sieve doesn't exist (usinglobal script path in stead) May 25 12:19:50 lda(dovecot@example.com): Debug: sieve: using sieve path for user's script: /var/lib/dovecot-sieve/default.sieve May 25 12:19:50 lda(dovecot@example.com): Debug: sieve: opening script /var/lib/dovecot-sieve/default.sieve May 25 12:19:50 lda(dovecot@example.com): Debug: sieve: script binary /var/lib/dovecot-sieve/default.svbin successfully loaded May 25 12:19:50 lda(dovecot@example.com): Debug: sieve: binary save: not saving binary /var/lib/dovecot-sieve/default.svbin, because its already stored May 25 12:19:50 lda(dovecot@example.com): Debug: sieve: executing script from /var/lib/dovecot-sieve/default.svbin May 25 12:19:51 lda(dovecot@example.com): Debug: quota: Executing warning: quota-warning 80 dovecot@example.com
==> /var/log/dovecot/deliver-errors.log <== May 25 12:19:51 lda(dovecot@example.com): Panic: Trying to allocate 0 bytes May 25 12:19:51 lda(dovecot@example.com): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0 [0xbd4e70] -> /usr/lib/dovecot/libdoveco t.so.0(default_fatal_handler+0x43) [0xbd4f63] -> /usr/lib/dovecot/libdovecot.so.0 [0xbd4784] -> /usr/lib/dovecot/libdovecot.so.0 [0xbd 241d] -> /usr/lib/dovecot/libdovecot.so.0(t_malloc0+0x29) [0xbd2619] -> /usr/lib/dovecot/libdovecot.so.0(restrict_get_groups_list+0x43 ) [0xbef183] -> /usr/lib/dovecot/libdovecot.so.0 [0xbd2b39] -> /usr/lib/dovecot/libdovecot.so.0 [0xbd2dd2] -> /usr/lib/dovecot/libdove cot.so.0 [0xbd34c6] -> /usr/lib/dovecot/lib10_quota_plugin.so(quota_transaction_commit+0x5ff) [0xeeeaff] -> /usr/lib/dovecot/lib10_quo ta_plugin.so [0xef3f6c] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_transaction_commit_get_changes+0x42) [0xc922d2] -> /usr/li b/dovecot/libdovecot-storage.so.0(mailbox_transaction_commit+0x33) [0xc92323] -> /usr/lib/dovecot/libdovecot-sieve.so.0 [0xd4cfa4] -> /usr/lib/dovecot/libdovecot-sieve.so.0 [0xd44821] -> /usr/lib/dovecot/libdovecot-sieve.so.0(sieve_result_execute+0x2d1) [0xd44b41] -> /usr/lib/dovecot/libdovecot-sieve.so.0(sieve_execute+0x69) [0xd550f9] -> /usr/lib/dovecot/lib90_sieve_plugin.so [0x11211c] -> /usr/lib /dovecot/libdovecot-lda.so.0(mail_deliver+0x4c) [0x843e1c] -> /usr/libexec/dovecot/deliver(main+0x725) [0x804a185] -> /lib/i686/nosegn eg/libc.so.6(__libc_start_main+0xdc) [0x65ce9c] -> /usr/libexec/dovecot/deliver [0x80498c1]
== config # dovecot -n # 2.1.6: /etc/dovecot/dovecot.conf # OS: Linux 2.6.18-238.el5xen i686 CentOS release 5.8 (Final) xfs debug_log_path = /var/log/dovecot/debug.log dict { expire = sqlite:/etc/dovecot/dovecot-expire.conf.ext } disable_plaintext_auth = no first_valid_gid = 12 first_valid_uid = 40001 info_log_path = /var/log/dovecot/infos.log lda_mailbox_autocreate = yes log_path = /var/log/dovecot/error.log mail_debug = yes mail_location = maildir:/var/mail/%u/mail maildir_very_dirty_syncs = yes managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave mbox_write_locks = fcntl namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = INBOX. } passdb { args = /usr/libexec/dovecot/checkpassword-bcrypt/checkpassword-bcrypt.rb driver = checkpassword } plugin { expire = INBOX.Trash 14 INBOX.Trash/* 14 INBOX.Spam 14 INBOX.spam 14 INBOX.Papierkorb 14 INBOX.Papierkorb/* 14 INBOX.Junk 14 expire_dict = proxy::expire quota = maildir:User quota quota_rule = *:storage=0 quota_rule2 = INBOX.Trash:storage=+10%% quota_warning = storage=95%% quota-warning 95 %u quota_warning2 = storage=80%% quota-warning 80 %u sieve = ~/dovecot.sieve sieve_default = /var/lib/dovecot-sieve/default.sieve sieve_dir = ~/sieve sieve_global_dir = /var/lib/dovecot-sieve/global/ } postmaster_address = postmaster@example.com protocols = imap pop3 sieve service managesieve-login { inet_listener sieve { port = 4190 } inet_listener sieve_deprecated { port = 2000 } } service quota-warning { executable = script /usr/libexec/dovecot/quota-warning.sh } ssl_cert =
On Fri, 2012-05-25 at 18:52 +0200, Peter Meier wrote:
I was doing some migration from a 1.2 installation to a 2.1. While testing my new installation dovecot crashed at two test-cases constantly with with a "Panic: Trying to allocate 0 bytes" message. .. I see two problems:
- Don't panic while "looking" up a group
- Give a meaningful error messages.
Asserts/Panics can't give very meaningful error messages to users, because they only happen when there's a bug in the code. The resulting raw backtrace is helpful to coders though :) Fixed: http://hg.dovecot.org/dovecot-2.1/rev/fe688ecd7564
participants (2)
-
Peter Meier
-
Timo Sirainen