dovecot - Jul 2009 - [Bug] dovecot deliver v1.2.1 segfaults

Hello list,

I have noticed strange dovecot behavior with exim system-filter.
I'm using exim+dovecot setup. My exim configuration have system filter
enable, which restrict some attachments, like exe, vbs etc. When message with
forbidden attachment received, exim accept the message, then construct
bounce-message(Reject reason + original message) and returns it to sender.
Trying to deliver such messages, I always get segmentation faults and message
stayed in exim's queue.
Others common delivers work fine. This only happens with bouncing system-filter
messages.

Steps to reproduce:
1) Create message with forbiden attachment
2) Send message.
3) Get segmentation fault.

Here is more details:
exim -d+all -M 1MSn7r-0003hN-BG (this command runs delivery from exim's
queue)

13:14:23 11570 --------> koshikov.n at domain.com <--------
13:14:23 11570 locking /var/spool/exim/db/retry.lockfile
13:14:23 11570 locked /var/spool/exim/db/retry.lockfile
13:14:23 11570 EXIM_DBOPEN(/var/spool/exim/db/retry)
13:14:23 11570 returned from EXIM_DBOPEN
13:14:23 11570 opened hints database /var/spool/exim/db/retry: flags=O_RDONLY
13:14:23 11570 dbfn_read: key=T:koshikov.n at domain.com
13:14:23 11570 no retry record exists
13:14:23 11570 search_tidyup called
13:14:23 11571 changed uid/gid: local delivery to koshikov.n <koshikov.n at
domain.com> transport=local_delivery
13:14:23 11571   uid=8 gid=12 pid=11571
13:14:23 11571   auxiliary group list: <none>
13:14:23 11571   home=NULL current=/
13:14:23 11571 set_process_info: 11571 delivering 1MSn7r-0003hN-BG to koshikov.n
using local_delivery
13:14:23 11571 local_delivery transport entered
13:14:23 11571 direct command:
13:14:23 11571   argv[0] = /usr/libexec/dovecot/deliver
13:14:23 11571   argv[1] = -e
13:14:23 11571   argv[2] = -d
13:14:23 11571   argv[3] = $local_part@$domain
13:14:23 11571 expanding: $local_part@$domain
13:14:23 11571    result: koshikov.n at domain.com
13:14:23 11571 direct command after expansion:
13:14:23 11571   argv[0] = /usr/libexec/dovecot/deliver
13:14:23 11571   argv[1] = -e
13:14:23 11571   argv[2] = -d
13:14:23 11571   argv[3] = koshikov.n at domain.com
13:14:23 11571 Writing message to pipe
13:14:23 11571 writing data block fd=11 size=0 timeout=3600
13:14:23 11573 set_process_info: 11573 reading output from
|/usr/libexec/dovecot/deliver -e -d $local_part@$domain
13:14:23 11571 writing data block fd=11 size=814 timeout=3600
13:14:23 11571 writing data block fd=11 size=0 timeout=3600
13:14:23 11571 local_delivery transport yielded 2
13:14:23 11571 search_tidyup called
13:14:23 11570 local_delivery transport returned FAIL for koshikov.n at
domain.com
13:14:23 11570 post-process koshikov.n at domain.com (2)
13:14:23 11570 LOG: MAIN
13:14:23 11570   <koshikov.n at domain.com>: local_delivery transport
output: Warning: Growing pool 'Plugin strings' with: 1024
13:14:23 11570 LOG: MAIN
13:14:23 11570   ** koshikov.n at domain.com F=<> R=ldap_accept
T=local_delivery: Child process of local_delivery transport (running command
"/usr/libexec/dovecot/deliver -e -d $local_part@$domain") was
terminated by signal 11 (Segmentation fault)
13:14:23 11570 >>>>>>>>>>>>>>>>
deliveries are done
>>>>>>>>>>>>>>>>
13:14:23 11570 changed uid/gid: post-delivery tidying
13:14:23 11570   uid=8 gid=12 pid=11570
13:14:23 11570   auxiliary group list: <none>
13:14:23 11570 set_process_info: 11570 tidying up after delivering
1MSn7r-0003hN-BG
13:14:23 11570 Processing retry items
13:14:23 11570 Succeeded addresses:
13:14:23 11570 koshikov.n at domain.com: no retry items
13:14:23 11570 Failed addresses:
13:14:23 11570 Deferred addresses:
13:14:23 11570 koshikov.n at domain.com: no retry items
13:14:23 11570 koshikov.n at domain.com: no retry items
13:14:23 11570 end of retry processing
13:14:23 11570 LOG: MAIN
13:14:23 11570   Frozen (delivery error message)
13:14:23 11570 delivery deferred: update_spool=1 header_rewritten=0
13:14:23 11570 Writing spool header file
13:14:23 11570 Size of headers = 707
13:14:23 11570 end delivery of 1MSn7r-0003hN-BG
13:14:23 11570 search_tidyup called
13:14:23 11570 search_tidyup called
13:14:23 11570 >>>>>>>>>>>>>>>>
Exim pid=11570 terminating with rc=0
>>>>>>>>>>>>>>>>


dovecot-deliver log, while trying to deliver this message:

==> /var/log/dovecot/dovecot-deliver.log <=Jul 20 13:19:53
deliver(koshikov.n at domain.com): Info: Loading modules from directory:
/usr/lib/dovecot/lda
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: Module loaded:
/usr/lib/dovecot/lda/lib10_quota_plugin.so
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: Module loaded:
/usr/lib/dovecot/lda/lib11_trash_plugin.so
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: Module loaded:
/usr/lib/dovecot/lda/lib20_expire_plugin.so
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: Module loaded:
/usr/lib/dovecot/lda/lib90_sieve_plugin.so
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: auth input: uid=8
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: auth input: gid=12
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: auth input:
home=/data/mail/domain.com/koshikov.n
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Warning: Growing pool
'userdb lookup replys' with: 1024
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: auth input:
mail=maildir:/data/mail/domain.com/koshikov.n/data
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: Quota root:
name=Mailbox quota backend=maildir argsJul 20 13:19:53 deliver(koshikov.n at
domain.com): Info: Quota rule: root=Mailbox quota mailbox=* bytes=524288000
messages=0
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: Quota rule:
root=Mailbox quota mailbox=Trash bytes=52428800 (10%) messages=0
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: Quota warning:
bytes=498073600 (95%) messages=0 command=/etc/dovecot/plugins/quota_warning.sh
95
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Warning: Growing pool
'Expire pool' with: 1024
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: Namespace:
type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: maildir:
data=/data/mail/domain.com/koshikov.n/data
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: maildir++:
root=/data/mail/domain.com/koshikov.n/data, index=, control=,
inbox=/data/mail/domain.com/koshikov.n/data
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: Namespace: type=public,
prefix=#Public/, sep=/, inbox=no, hidden=no, list=1, subscriptions=no
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: maildir:
data=/var/mail/public
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: maildir++:
root=/var/mail/public, index=, control=, inboxJul 20 13:19:53 deliver(koshikov.n
at domain.com): Warning: Growing pool 'mail user' with: 1024
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: trash plugin: Added
'Trash' with priority 1
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: trash plugin: Added
'Spam' with priority 2
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: expire: No expiring in
mailbox: Dovecot Delivery Mail
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: sieve: using sieve path
for user's script: /data/mail/domain.com/koshikov.n/.dovecot.sieve
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: sieve: executed before
user's script(1): /etc/dovecot/sieve/default.sieve
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: sieve: opening script
/etc/dovecot/sieve/default.sieve
Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: sieve: opening script
/data/mail/domain.com/koshikov.n/.dovecot.sieve

In system log I get:

deliver[9476]: segfault at 0 ip b7e16713 sp bfa0ba2c error 4 in
libc-2.9.so[b7da4000+13d000]
deliver[11572]: segfault at 0 ip b7f41713 sp bfb38b4c error 4 in
libc-2.9.so[b7ecf000+13d000]
deliver[12433]: segfault at 0 ip b7e7e713 sp bfb73b8c error 4 in
libc-2.9.so[b7e0c000+13d000]

dovecot -n:
# 1.2.1: /etc/dovecot/dovecot.conf
Warning: Growing pool 'settings' with: 8192
# OS: Linux 2.6.26-gentoo-r4 i686 Gentoo Base System release 1.12.11.1 
log_path: /var/log/dovecot/dovecot-error.log
info_log_path: /var/log/dovecot/dovecot.log
protocols: imaps managesieve
ssl_cert_file: /etc/ssl/dovecot/imaps.crt
ssl_key_file: /etc/ssl/dovecot/imaps.key
disable_plaintext_auth: no
login_dir: /var/run/dovecot/login
login_executable(default): /usr/libexec/dovecot/imap-login
login_executable(imap): /usr/libexec/dovecot/imap-login
login_executable(managesieve): /usr/libexec/dovecot/managesieve-login
login_greeting: Server ready.
login_processes_count: 10
login_max_processes_count: 512
first_valid_uid: 8
last_valid_uid: 8
first_valid_gid: 12
last_valid_gid: 12
mail_debug: yes
mail_drop_priv_before_exec: yes
mail_executable(default): /usr/libexec/dovecot/imap
mail_executable(imap): /usr/libexec/dovecot/imap
mail_executable(managesieve): /usr/libexec/dovecot/managesieve
mail_plugins(default): quota imap_quota trash expire zlib autocreate
mail_plugins(imap): quota imap_quota trash expire zlib autocreate
mail_plugins(managesieve): 
mail_plugin_dir(default): /usr/lib/dovecot/imap
mail_plugin_dir(imap): /usr/lib/dovecot/imap
mail_plugin_dir(managesieve): /usr/lib/dovecot/managesieve
imap_client_workarounds(default): delay-newmail
imap_client_workarounds(imap): delay-newmail
imap_client_workarounds(managesieve): 
namespace:
  type: private
  separator: /
  inbox: yes
  list: yes
  subscriptions: yes
namespace:
  type: public
  separator: /
  prefix: #Public/
  location: maildir:/var/mail/public
  list: yes
auth default:
  mechanisms: plain login
  cache_size: 10240
  cache_negative_ttl: 0
  user: dovecot_auth
  master_user_separator: *
  worker_max_count: 50
  passdb:
    driver: passwd-file
    args: /etc/dovecot/passdb/master.pwd
    master: yes
  passdb:
    driver: passwd-file
    args: /etc/dovecot/passdb/users.pwd
  passdb:
    driver: ldap
    args: /etc/dovecot/dovecot-ldap.conf
  userdb:
    driver: prefetch
  userdb:
    driver: ldap
    args: /etc/dovecot/dovecot-userdb-ldap.conf
  userdb:
    driver: passwd-file
    args: /etc/dovecot/passdb/users.pwd
  socket:
    type: listen
    client:
      path: /var/run/dovecot/auth-client
      mode: 432
      user: mail
      group: dovecot_auth
    master:
      path: /var/run/dovecot/auth-master
      mode: 384
      user: mail
      group: mail
plugin:
  quota_warning: storage=95%% /etc/dovecot/plugins/quota_warning.sh 95
  quota: maildir:Mailbox quota
  quota_rule: *:storage=500M
  quota_rule2: Trash:storage=10%%
  trash: /etc/dovecot/plugins/dovecot-trash.conf
  expire: Trash 30 Spam 30
  expire_dict: proxy::expire
  autocreate: Drafts
  autocreate2: Sent
  autocreate3: Spam
  autocreate4: Trash
  autosubscribe: Drafts
  autosubscribe2: Sent
  autosubscribe3: Spam
  autosubscribe4: Trash
  sieve: ~/.dovecot.sieve
  sieve_dir: ~/sieve
  sieve_extensions: +imapflags +notify
  sieve_before: /etc/dovecot/sieve/default.sieve
dict:
  expire: sqlite:/etc/dovecot/plugins/expire.conf

Linux: Gentoo x86 1.12.11.1
filesystem: ext3

I you need any addition information, please tell.

On 7/20/2009, Nikita Koshikov (koshikov at gmail.com)
wrote:
> When message with forbidden attachment received, exim accept the
> message, then construct bounce-message(Reject reason + original
> message) and returns it to sender.
That is your first problem... you should never accept then bounce...
reject at smtp time anything like this.
> Trying to deliver such messages, I always get segmentation faults and
> message stayed in exim's queue.
This obviously shouldn't happen, so you'd probably want to figure out
whats causing it too, but it does go away when you fix the first problem.

-- 

Best regards,

Charles

Nikita Koshikov schreef:
> Hello list,
> 
> I have noticed strange dovecot behavior with exim system-filter.
> I'm using exim+dovecot setup. My exim configuration have system filter
enable, which restrict some attachments, like exe, vbs etc. When message with
forbidden attachment received, exim accept the message, then construct
bounce-message(Reject reason + original message) and returns it to sender.
Trying to deliver such messages, I always get segmentation faults and message
stayed in exim's queue.
> Others common delivers work fine. This only happens with bouncing
system-filter messages.
> 
> Steps to reproduce:
> 1) Create message with forbiden attachment
> 2) Send message.
> 3) Get segmentation fault.
> 
[...]
> Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: sieve: using sieve
path for user's script: /data/mail/domain.com/koshikov.n/.dovecot.sieve
> Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: sieve: executed
before user's script(1): /etc/dovecot/sieve/default.sieve
> Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: sieve: opening
script /etc/dovecot/sieve/default.sieve
> Jul 20 13:19:53 deliver(koshikov.n at domain.com): Info: sieve: opening
script /data/mail/domain.com/koshikov.n/.dovecot.sieve
Since it fails hereafter it would not surprise me when this is a Sieve 
problem. Could you provide:

1) The Sieve scripts involved in the problem (anonymized if you care):

/etc/dovecot/sieve/default.sieve 
/data/mail/domain.com/koshikov.n/.dovecot.sieve

2) An e-mail message that is known to trigger this failure
> deliver[9476]: segfault at 0 ip b7e16713 sp bfa0ba2c error 4 in
libc-2.9.so[b7da4000+13d000]
> deliver[11572]: segfault at 0 ip b7f41713 sp bfb38b4c error 4 in
libc-2.9.so[b7ecf000+13d000]
> deliver[12433]: segfault at 0 ip b7e7e713 sp bfb73b8c error 4 in
libc-2.9.so[b7e0c000+13d000]
If your Dovecot is compiled with debugging symbols enabled you can 
obtain a useful trace by executing deliver in gdb:

gdb --args /usr/lib/dovecot/deliver -p mail.eml

Type 'r' and press enter and wait until it crashes. Type 'bt' to
obtain
the back trace.

Alternatively, you can obtain a core dump, but I must say that I have 
little experience with producing one. Other people on this list can help 
you with this. Basic information is available at:

http://www.dovecot.org/bugreport.html
> plugin:
[...]
>   sieve: ~/.dovecot.sieve
>   sieve_dir: ~/sieve
>   sieve_extensions: +imapflags +notify
I see that you have enabled deprecated notify support. What version are 
you using? The notify support provided by the last release (0.1.8) is 
not compatible with CMUSieve and it is therefore not (yet) useful to 
enable this.

Regards,

-- 
Stephan Bosch
stephan at rename-it.nl

On Tue, 21 Jul 2009 12:50:05 +0200
Stephan Bosch <stephan at rename-it.nl> wrote:
> Nikita Koshikov wrote:
> > On Mon, 20 Jul 2009 15:24:40 -0400
> > Timo Sirainen <tss at iki.fi> wrote:
> > 
> > 
> > Program received signal SIGSEGV, Segmentation fault.
> > 0xb7ec4713 in strlen () from /lib/libc.so.6
> > (gdb) bt
> > #0  0xb7ec4713 in strlen () from /lib/libc.so.6
> > #1  0xb7e0d742 in sieve_address_parse_envelope_path () from
/usr/lib/dovecot/lda/lib90_sieve_plugin.so
> > #2  0xb7e1ef94 in ?? () from
/usr/lib/dovecot/lda/lib90_sieve_plugin.so
> > #3  0x00000000 in ?? ()
> > 
> We found the bug. It is fixed in the Mercurial repository. The fix is 
> part of a rather large change that I need to test properly first. It 
> will be incorporated asap in the next release.
> 
> Regards,
> 
> Stephan
Thanks for your work and help, Stephan.
Waiting impatiently for new relese.