dovecot - Feb 2013 - lmtp problem with wrong index path

Hello,

we've been using dovecot for pop3 and imap for some time now and we're 
in the middle of deploying lmtp as well, however we're run into a 
problem we can't solve.
Specifically for some reason it seems that dovecot tries to write to the 
wrong index file during some, but not all, lmtp deliveries.
If lmtp tries to deliver to person user_a at domain, sometimes it'll try to 
write to index directory user_b at domain using user_a euid.
We haven't found and pattern in the problem. A user may receive multiple 
mails with only 1 in 20 or more deliveries having problems.
The only things that we know is that user_b (the wrong one) is always 
from the same domain as the correct user and always (so far) also a 
recipient in the same mail.

Feb 25 09:07:01 pop02 dovecot: lmtp(20931, sub1ika at ika.gr): Error: 
stat(/indexes/2/b/0/diefecon.log at ika.gr/.imap/INBOX/dovecot.index.log) 
failed: Permission denied (euid=10054601(<unknown>)
egid=165(<unknown>)
missing +x perm: /indexes/2/b/0/diefecon.log at ika.gr, dir owned by 
10107819:165 mode=0700)
Feb 25 09:07:01 pop02 dovecot: lmtp(20931, sub1ika at ika.gr): Error: 
nfs_flush_chown_uid: 
stat(/indexes/2/b/0/diefecon.log at ika.gr/.imap/INBOX) failed: Permission 
denied
Feb 25 09:07:01 pop02 dovecot: lmtp(20931, sub1ika at ika.gr): Error: 
stat(/indexes/2/b/0/diefecon.log at ika.gr/.imap/INBOX/dovecot.index) 
failed: Permission denied (euid=10054601(<unknown>)
egid=165(<unknown>)
missing +x perm: /indexes/2/b/0/diefecon.log at ika.gr, dir owned by 
10107819:165 mode=0700)
Feb 25 09:07:01 pop02 dovecot: lmtp(20931, sub1ika at ika.gr): 
T8WxCGwHK1HDUQAAB7uMaw: msgid=<542C6CCE00F7433B9F5E0860C32F87FE at sofia>:
save failed to INBOX: Timeout while waiting for lock

As you can see below it seems that failure to write to the index doesn't 
stop the mail being delivered.

Feb 25 10:47:36 pop08 dovecot: lmtp(19139, d.lefkona at kep.gov.gr): Error: 
stat(/var/index/dovecot/4/c/6/d.irakleias-serron at
kep.gov.gr/.imap/INBOX/dovecot.index.log)
failed: Permission denied (euid=10096573(<unknown>)
egid=165(<unknown>)
missing +x perm: /var/index/dovecot/4/c/6/d.irakleias-serron at kep.gov.gr, 
dir owned by 10096925:165 mode=0700)
Feb 25 10:47:36 pop08 dovecot: lmtp(19139, d.lefkona at kep.gov.gr): Error: 
stat(/var/index/dovecot/4/c/6/d.irakleias-serron at
kep.gov.gr/.imap/INBOX/dovecot.index)
failed: Permission denied (euid=10096573(<unknown>)
egid=165(<unknown>)
missing +x perm: /var/index/dovecot/4/c/6/d.irakleias-serron at kep.gov.gr, 
dir owned by 10096925:165 mode=0700)
Feb 25 10:47:36 pop08 dovecot: lmtp(19139, d.lefkona at kep.gov.gr): 
ua0ANmIeK1HDSgAADehEhg: sieve: 
msgid=<E299E69CBA0EFA4C9870A944ACBC4DCC03AA9C3F at
SYZ3MAIL01.exchange.n3.syzefxis.gov.gr>:
stored mail into mailbox 'INBOX'

Our current setup is 3 directors (dovecot 2.1.12) proxying pop3/imap and 
lmtp to a farm of 8 dovecot servers (all of them 2.1.15).
All of our mailboxes are stored in NFS.
A seperate farm of postfix MX servers will be responsible to send mails 
via lmtp to our directors.
Currently we're keeping dovecot indexes locally but we're beginning to 
move them to NFS as well (we've changed 2 of the 8 servers and hopefully 
today the 6 remaining)

Our configuration is :

# 2.1.15: /opt/dovecot-2.1.15/etc/dovecot/dovecot.conf
# OS: Linux 2.6.18-92.1.22.el5 x86_64 CentOS release 5.9 (Final)
auth_cache_negative_ttl = 10 mins
auth_cache_size = 5 M
auth_cache_ttl = 10 mins
auth_verbose = yes
default_client_limit = 5000
default_process_limit = 500
disable_plaintext_auth = no
first_valid_uid = 20
lda_mailbox_autocreate = yes
lda_mailbox_autosubscribe = yes
listen = *
log_timestamp = "%Y-%m-%d %H:%M:%S "
login_greeting = OTENET ready
login_trusted_networks = 83.235.66.0/24
mail_access_groups = mail otemail disk root
mail_fsync = always
mail_location = mbox:INDEX=/var/index/dovecot/%1Mu/%2.1Mu/%3.1Mu/%u
mail_nfs_index = yes
mail_nfs_storage = 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 imapflags notify
mbox_lock_timeout = 3 secs
mbox_read_locks = dotlock fcntl
mmap_disable = yes
passdb {
   args = /opt/dovecot/etc/dovecot/dovecot-ldap.conf.ext
   driver = ldap
}
plugin {
   quota = dirsize:User quota
   quota_warning = storage=95%% quota-warning 95 %u
   sieve = ~/.sieve
   sieve_dir = ~/sieve
   sieve_extensions = +notify +imapflags
}
postmaster_address = postmaster at otenet.gr
quota_full_tempfail = yes
service auth-worker {
   user = dovenull
}
service imap-login {
   inet_listener imap {
     port = 143
   }
   inet_listener imaps {
     port = 993
     ssl = yes
   }
}
service lmtp {
   client_limit = 1
   inet_listener lmtp {
     port = 24
   }
}
service pop3-login {
   inet_listener pop3 {
     port = 110
   }
   inet_listener pop3s {
     port = 995
     ssl = yes
   }
}
service quota-warning {
   executable = script /opt/dovecot/etc/dovecot/quota-warning.sh
   user = dovecot
}
ssl = no
userdb {
   args = /opt/dovecot/etc/dovecot/dovecot-ldap.conf.ext
   driver = ldap
}
verbose_proctitle = yes
protocol lmtp {
   mail_plugins = " sieve"
}
protocol lda {
   mail_plugins = " sieve quota"
}
protocol imap {
   imap_client_workarounds = delay-newmail tb-extra-mailbox-sep
   mail_max_userip_connections = 100
}
protocol pop3 {
   mail_max_userip_connections = 100
   pop3_client_workarounds = outlook-no-nuls oe-ns-eoh
   pop3_fast_size_lookups = yes
   pop3_lock_session = yes
   pop3_reuse_xuidl = yes
   pop3_uidl_format = %08Xu%08Xv
}

[root at pop02 ~]# egrep -v "^#|^$" 
/opt/dovecot/etc/dovecot/dovecot-ldap.conf.ext
hosts = 62.103.147.203
dn = "cn=*****,ou=people,dc=otenet,dc=gr"
dnpass = *****
base = ou=people,dc=otenet,dc=gr
scope = onelevel
user_attrs = 
folderPath=home,mailQuota=quota_rule=*:storage=%$M,uidNumber=uid,gidNumber=gid,mailPath=mail=mbox:~/:INBOX=%$:INDEX=/indexes/%1Mu/%2.1Mu/%3.1Mu/%u
user_filter = 
(&(|(objectClass=otenetMailAccount)(objectClass=otenetservices))(|(uid=%u)(mail=%u)(mailAlternateAddress=%u)))
pass_attrs = mail=user,userpassword=password
pass_filter = 
(&(|(objectClass=otenetMailAccount)(objectClass=otenetservices))(|(uid=%u)(mail=%u)(mailAlternateAddress=%u)))
default_pass_scheme = CRYPT

Dimos Alevizos

On 25.2.2013, at 13.28, Dimos Alevizos <dalevizo at otenet.gr> wrote:
> we've been using dovecot for pop3 and imap for some time now and
we're in the middle of deploying lmtp as well, however we're run into a
problem we can't solve.
> Specifically for some reason it seems that dovecot tries to write to the
wrong index file during some, but not all, lmtp deliveries.
> If lmtp tries to deliver to person user_a at domain, sometimes it'll
try to write to index directory user_b at domain using user_a euid.
> We haven't found and pattern in the problem. A user may receive
multiple mails with only 1 in 20 or more deliveries having problems.
> The only things that we know is that user_b (the wrong one) is always from
the same domain as the correct user and always (so far) also a recipient in the
same mail.
> 
> Feb 25 09:07:01 pop02 dovecot: lmtp(20931, sub1ika at ika.gr): Error:
stat(/indexes/2/b/0/diefecon.log at ika.gr/.imap/INBOX/dovecot.index.log)
failed: Permission denied (euid=10054601(<unknown>)
egid=165(<unknown>) missing +x perm: /indexes/2/b/0/diefecon.log at
ika.gr, dir owned by 10107819:165 mode=0700)
> Feb 25 09:07:01 pop02 dovecot: lmtp(20931, sub1ika at ika.gr): Error:
nfs_flush_chown_uid: stat(/indexes/2/b/0/diefecon.log at ika.gr/.imap/INBOX)
failed: Permission denied
..
> Our current setup is 3 directors (dovecot 2.1.12) proxying pop3/imap and
lmtp to a farm of 8 dovecot servers (all of them 2.1.15).
> All of our mailboxes are stored in NFS.
Since you're using directors, you can use mail_nfs_index=no and
mail_nfs_storage=no. The performance will be better.
> mail_location = mbox:INDEX=/var/index/dovecot/%1Mu/%2.1Mu/%3.1Mu/%u
This isn't a valid mail_location. Better to remove it entirely so it
won't be accidentally used, except..:
> user_attrs =
folderPath=home,mailQuota=quota_rule=*:storage=%$M,uidNumber=uid,gidNumber=gid,mailPath=mail=mbox:~/:INBOX=%$:INDEX=/indexes/%1Mu/%2.1Mu/%3.1Mu/%u
> user_filter =
(&(|(objectClass=otenetMailAccount)(objectClass=otenetservices))(|(uid=%u)(mail=%u)(mailAlternateAddress=%u)))
> pass_attrs = mail=user,userpassword=password
> pass_filter =
(&(|(objectClass=otenetMailAccount)(objectClass=otenetservices))(|(uid=%u)(mail=%u)(mailAlternateAddress=%u)))
The main problem here is that you create indexes using %u, but there are 3
different valid %us: uid, mail and mailAlternateAddress. So you're most
likely hitting problems for users whose mails are being delivered using
mailAlternateAddress. Those alias expansions should normally be handled by your
MTA.

With the above config you should be able to solve this by not using %u but the
LDAP's mail field. So something like (with cleaning up the whole config):

user_attrs = \
  =user=%{ldap:mail}, \
  =home=%{ldap:folderPath}, \
  =quota_rule=*:storage=%{ldap:mailQuota}M, \
  =uid=%{ldap:uidNumber}, \
  =gid=%{ldap:gidNumber}, \
 
=mail=mbox:~/:INBOX=%{ldap:mailPath}:INDEX=/indexes/%1M{ldap:mail}/%2.1M{ldap:mail}/%3.1M{ldap:mail}/%{ldap:mail}

Easier of course would be if you could determine mailPath using a static
template, then you could just use the global mail_location and %u directly,
because the %u gets normalized to same as "mail" field.