dovecot - May 2008 - deliver exits with status 89 on some but not all mails of a batch

Hi,

I'm trying to get dovecot's LDA 'deliver' to deliver mails that
come in through a postfix daemon on the same box. I'm talking
about dovecot version 1.0.rc15 (on CentOS 5 as Linux-VServer guest on a CentOS 5
host).

Configuration
-------------

# /etc/dovecot.conf
ssl_cert_file: /etc/pki/selfmade/server.crt
ssl_key_file: /etc/pki/selfmade/server.key
login_dir: /var/run/dovecot/login
login_executable(default): /usr/libexec/dovecot/imap-login
login_executable(imap): /usr/libexec/dovecot/imap-login
login_executable(pop3): /usr/libexec/dovecot/pop3-login
verbose_proctitle: yes
mail_extra_groups: mail
mail_location: maildir:~/Maildir
mail_executable(default): /usr/libexec/dovecot/imap
mail_executable(imap): /usr/libexec/dovecot/imap
mail_executable(pop3): /usr/libexec/dovecot/pop3
mail_plugin_dir(default): /usr/lib/dovecot/imap
mail_plugin_dir(imap): /usr/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/lib/dovecot/pop3
auth default:
  verbose: yes
  passdb:
    driver: ldap
    args: /etc/dovecot-ldap.conf
  userdb:
    driver: ldap
    args: /etc/dovecot-ldap.conf
  socket:
    type: listen
    client:
      path: /var/spool/postfix/private/auth
      mode: 432
      user: postfix
      group: postfix
    master:
      path: /var/run/dovecot/auth-master
      mode: 384
      user: dovecot
      group: dovecot


dovecot-ldap.conf looks like this:

uris = ldap://dbserver
dn = cn=dovecot,ou=services,dc=company,dc=net
dnpass = secret
ldap_version = 3
base = ou=people,dc=company,dc=net
scope = onelevel
user_attrs = homeDirectory=home,uidNumber=uid,gidNumber=gid
user_filter = (&(objectClass=posixAccount)(uid=%n))
pass_attrs = uid=user,userPassword=password
pass_filter = (&(objectClass=posixAccount)(uid=%u))
default_pass_scheme = LDAP-MD5


postfix has mailbox_transport set to dovecot, and master.cf contains the
following:

dovecot   unix  -       n       n       -       -       pipe
    flags=DRhu user=fry:fry argv=/usr/libexec/dovecot/lda/deliver -d
${recipient}


Problem
-------

When a lot of mails come in 'at the same time', for example because an
employee mailed all other (local) employees, the
following happens: Some mails are being delivered as advertised, but on some
mails, deliver exits with status 89 and the message
bounces. Here is a (postfix) log that illustrates the problem. I replaced all
receivers with 'xy', but they are in fact all
different.

May 13 17:58:32 mail1 postfix/smtpd[28164]: connect from unknown[192.168.0.103]
May 13 17:58:32 mail1 postfix/smtpd[28164]: 1D6508FD93FF:
client=unknown[192.168.0.103]
May 13 17:58:33 mail1 postfix/cleanup[28165]: 1D6508FD93FF:
message-id=<200805131758288906193 at company.net>
May 13 17:58:33 mail1 postfix/qmgr[27255]: 1D6508FD93FF: from=<zz at
company.net>, size=1613090, nrcpt=31 (queue active)
May 13 17:58:33 mail1 postfix/smtpd[28164]: disconnect from
unknown[192.168.0.103]
May 13 17:58:33 mail1 postfix/pipe[28169]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=1.9, delays=1.5/0/0/0.35, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:33 mail1 postfix/pipe[28299]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=1.9, delays=1.5/0.02/0/0.34, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:33 mail1 postfix/pipe[28168]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=1.9, delays=1.5/0/0/0.35, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:33 mail1 postfix/pipe[28298]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=1.9, delays=1.5/0.01/0/0.34, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:34 mail1 postfix/pipe[28362]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.7, delays=1.5/0.21/0/0.95, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:34 mail1 postfix/pipe[28304]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.7, delays=1.5/0.1/0/1.1, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:34 mail1 postfix/pipe[28320]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.7, delays=1.5/0.13/0/1, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:34 mail1 postfix/pipe[28311]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.7, delays=1.5/0.12/0/1, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:34 mail1 postfix/pipe[28313]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.7, delays=1.5/0.12/0/1, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:34 mail1 postfix/pipe[28306]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.7, delays=1.5/0.11/0/1.1, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:34 mail1 postfix/pipe[28333]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.7, delays=1.5/0.14/0/1, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:34 mail1 postfix/pipe[28317]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.7, delays=1.5/0.12/0/1.1, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:34 mail1 postfix/pipe[28337]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.7, delays=1.5/0.16/0/1, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:34 mail1 postfix/pipe[28342]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.8, delays=1.5/0.17/0/1.1, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:34 mail1 postfix/pipe[28368]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=2.9, delays=1.5/0.23/0/1.1, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:35 mail1 postfix/pipe[28364]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=3.1, delays=1.5/0.22/0/1.4, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:35 mail1 postfix/pipe[28350]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=3.2, delays=1.5/0.19/0/1.5, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:35 mail1 postfix/pipe[28376]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=3.3, delays=1.5/0.26/0/1.6, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:35 mail1 postfix/pipe[28375]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=3.3, delays=1.5/0.25/0/1.6, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:35 mail1 postfix/pipe[28334]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=3.3, delays=1.5/0.15/0/1.7, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:35 mail1 postfix/pipe[28347]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=3.3, delays=1.5/0.18/0/1.6, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:35 mail1 postfix/pipe[28372]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=3.3, delays=1.5/0.24/0/1.6, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:35 mail1 postfix/pipe[28355]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=3.5, delays=1.5/0.2/0/1.7, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:35 mail1 postfix/pipe[28340]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=3.5, delays=1.5/0.17/0/1.8, dsn=2.0.0, status=sent (delivered via dovecot
service)
May 13 17:58:36 mail1 postfix/pipe[28366]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=4, delays=1.5/0.23/0/2.2, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:36 mail1 postfix/pipe[28325]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=4.2, delays=1.5/0.13/0/2.5, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:36 mail1 postfix/pipe[28323]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=4.2, delays=1.5/0.13/0/2.5, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:36 mail1 postfix/pipe[28330]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=4.2, delays=1.5/0.14/0/2.5, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:36 mail1 postfix/pipe[28359]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=4.3, delays=1.5/0.2/0/2.5, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:36 mail1 postfix/pipe[28354]: 1D6508FD93FF: to=<xy at
city.company.net>, orig_to=<xy at company.net>, relay=dovecot,
delay=4.4, delays=1.5/0.19/0/2.6, dsn=5.3.0, status=bounced (Command died with
status 89: "/usr/libexec/dovecot/lda/deliver")
May 13 17:58:51 mail1 postfix/smtp[28292]: 1D6508FD93FF: to=<xy at
company.net>, relay=10.10.0.1[10.10.0.1]:25, delay=20,
delays=1.5/0.09/1.3/17, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
3E8611881EB)
May 13 17:58:52 mail1 postfix/cleanup[28160]: F0CE98FD9453:
message-id=<20080513095851.F0CE98FD9453 at mail1.city.company.net>
May 13 17:58:52 mail1 postfix/qmgr[27255]: F0CE98FD9453: from=<>,
size=7408, nrcpt=1 (queue active)
May 13 17:58:52 mail1 postfix/bounce[28379]: 1D6508FD93FF: sender non-delivery
notification: F0CE98FD9453
May 13 17:58:52 mail1 postfix/qmgr[27255]: 1D6508FD93FF: removed


Does anybody have an idea what could cause this behaviour? How to debug?

Patrick.

-- 
STAR Software (Shanghai) Co., Ltd.            http://www.star-group.net/
Phone:    +86 (21) 5427 7799 x 826             Fax:   +86 (21) 6485 0071

PGP key:         https://stshacom1.star-china.net/keys/patrick_nagel.asc
Fingerprint:           E09A D65E 855F B334 E5C3 5386 EF23 20FC E883 A005
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: This is a digitally signed message part.
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20080513/d760c9cf/attachment-0002.bin>

On 5/13/2008, Patrick Nagel (patrick.nagel at star-group.net)
wrote:
> I'm trying to get dovecot's LDA 'deliver' to deliver mails
that come
> in through a postfix daemon on the same box. I'm talking about
> dovecot version 1.0.rc15 (on CentOS 5 as Linux-VServer guest on a
> CentOS 5 host)
Upgrade...

It may or may not fix this particular problem, but rc15 is very old and
buggy...

atrpms has rpms for Centos5...

-- 

Best regards,

Charles