[Dovecot] 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@domain, sometimes it'll try to write to index directory user_b@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@ika.gr): Error: stat(/indexes/2/b/0/diefecon.log@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@ika.gr, dir owned by 10107819:165 mode=0700) Feb 25 09:07:01 pop02 dovecot: lmtp(20931, sub1ika@ika.gr): Error: nfs_flush_chown_uid: stat(/indexes/2/b/0/diefecon.log@ika.gr/.imap/INBOX) failed: Permission denied Feb 25 09:07:01 pop02 dovecot: lmtp(20931, sub1ika@ika.gr): Error: stat(/indexes/2/b/0/diefecon.log@ika.gr/.imap/INBOX/dovecot.index) failed: Permission denied (euid=10054601(<unknown>) egid=165(<unknown>) missing +x perm: /indexes/2/b/0/diefecon.log@ika.gr, dir owned by 10107819:165 mode=0700) Feb 25 09:07:01 pop02 dovecot: lmtp(20931, sub1ika@ika.gr): T8WxCGwHK1HDUQAAB7uMaw: msgid=<542C6CCE00F7433B9F5E0860C32F87FE@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@kep.gov.gr): Error: stat(/var/index/dovecot/4/c/6/d.irakleias-serron@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@kep.gov.gr, dir owned by 10096925:165 mode=0700) Feb 25 10:47:36 pop08 dovecot: lmtp(19139, d.lefkona@kep.gov.gr): Error: stat(/var/index/dovecot/4/c/6/d.irakleias-serron@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@kep.gov.gr, dir owned by 10096925:165 mode=0700) Feb 25 10:47:36 pop08 dovecot: lmtp(19139, d.lefkona@kep.gov.gr): ua0ANmIeK1HDSgAADehEhg: sieve: msgid=<E299E69CBA0EFA4C9870A944ACBC4DCC03AA9C3F@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@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@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@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@domain, sometimes it'll try to write to index directory user_b@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@ika.gr): Error: stat(/indexes/2/b/0/diefecon.log@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@ika.gr, dir owned by 10107819:165 mode=0700) Feb 25 09:07:01 pop02 dovecot: lmtp(20931, sub1ika@ika.gr): Error: nfs_flush_chown_uid: stat(/indexes/2/b/0/diefecon.log@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.
On Mon 25/02/2013 16:39, Timo Sirainen wrote:
Since you're using directors, you can use mail_nfs_index=no and mail_nfs_storage=no. The performance will be better.
Ok but that'll have to wait until we've fully migrated from our current MX servers with direct access to the mailboxes to lmtp.
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.
Alas no. The MTA does handle alias expansions :
root@vader:lmtp $ ldapsearch -h deer -x mail=daleviz1@otenet.gr uid uidNumber gidNumber mail mailAlternateAddress mailPath folderPath -LLL
dn: uid=daleviz1,ou=people,dc=otenet,dc=gr
uid: daleviz1
uidNumber: 69757
gidNumber: 647
mail: daleviz1@otenet.gr
mailAlternateAddress: dovecottest@otenet.gr
mailPath: /var/mail/U/V/H/daleviz1
folderPath: /var/mail/folders/U/V/H/daleviz1
root@vader:lmtp $ telnet deneb.otenet.gr 25 Trying 83.235.66.54... Connected to deneb.otenet.gr (83.235.66.54). Escape character is '^]'. 220 ESMTP helo otenet.gr 250 deneb.otenet.gr mail from:<dalevizo@otenet.gr> 250 2.1.0 Ok rcpt to:<dovecottest@otenet.gr> 250 2.1.5 Ok data 354 End data with <CR><LF>.<CR><LF> test mail . 250 2.0.0 from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as E78418E0023 quit 221 2.0.0 Bye Connection closed by foreign host.
Feb 26 00:19:07 deneb postfix/lmtp[19885]: E78418E0023: to=<daleviz1@otenet.gr>, orig_to=<dovecottest@otenet.gr>, relay=pop08.otenet.gr[83.235.66.47]:24, delay=0.03, delays=0.01/0/0/0.02, dsn=2.0.0, status=sent (250 2.0.0 <daleviz1@otenet.gr> GgW/NcziK1GCKwAADehEhg Saved)
Feb 26 00:19:07 pop08 dovecot: lmtp(11138, daleviz1@otenet.gr): GgW/NcziK1GCKwAADehEhg: msgid=unspecified: saved mail to INBOX
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}
I tried it but unfortunately the problem remains :
Feb 26 00:02:28 pop08 dovecot: lmtp(26796, dinos.mpalanikas@3230.syzefxis.gov.gr): Error: stat(/var/index/dovecot/7/8/3/amalia@3230.syzefxis.go v.gr/.imap/INBOX/dovecot.index.log) failed: Permission denied (euid=10117261(<unknown>) egid=165(<unknown>) missing +x perm: /var/index/dovecot /7/8/3/amalia@3230.syzefxis.gov.gr, dir owned by 10117262:165 mode=0700) Feb 26 00:02:28 pop08 dovecot: lmtp(26796, dinos.mpalanikas@3230.syzefxis.gov.gr): Error: stat(/var/index/dovecot/7/8/3/amalia@3230.syzefxis.go v.gr/.imap/INBOX/dovecot.index) failed: Permission denied (euid=10117261(<unknown>) egid=165(<unknown>) missing +x perm: /var/index/dovecot/7/8 /3/amalia@3230.syzefxis.gov.gr, dir owned by 10117262:165 mode=0700) Feb 26 00:02:28 pop08 dovecot: lmtp(26796, dinos.mpalanikas@3230.syzefxis.gov.gr): QYsqEkjfK1GsaAAADehEhg: sieve: msgid=<19dfa2f0f211951c56596c 9600194384@otenet.gr>: stored mail into mailbox 'INBOX'
These two users, dinos.mpalanikas@3230.syzefxis.gov.gr and amalia@3230.syzefxis.gov.gr have nothing in common apart from belonging to the same domain.
root@vader:lmtp $ ldapsearch -h deer -x mail=dinos.mpalanikas@3230.syzefxis.gov.gr uid uidNumber gidNumber mail mailAlternateAddress mailPath f
olderPath -LLL
dn: uid=3230_syzefxis_gov_gr_user_003,ou=people,dc=otenet,dc=gr
uid: 3230_syzefxis_gov_gr_user_003
uidNumber: 10117261
gidNumber: 165
mail: dinos.mpalanikas@3230.syzefxis.gov.gr
mailPath: /var/mail/C/3/6/3230_syzefxis_gov_gr_user_003
folderPath: /var/mail/folders/C/3/6/3230_syzefxis_gov_gr_user_003
root@vader:lmtp $ ldapsearch -h deer -x mail=amalia@3230.syzefxis.gov.gr uid uidNumber gidNumber mail mailAlternateAddress mailPath folderPath -LLL dn: uid=3230_syzefxis_gov_gr_user_002,ou=people,dc=otenet,dc=gr uid: 3230_syzefxis_gov_gr_user_002 uidNumber: 10117262 gidNumber: 165 mail: amalia@3230.syzefxis.gov.gr mailPath: /var/mail/C/3/6/3230_syzefxis_gov_gr_user_002 folderPath: /var/mail/folders/C/3/6/3230_syzefxis_gov_gr_user_002
However as you can see it tries to write to amalia's index while delivering to dinos.mpalanikas. Of course we're only talking about 1 failure in 578 successful deliveries however that server currently only serves less than 5% of our customres right now and we're worried that if we go full scale the problem will simply become greater.
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.
Indeed but I think that would mean getting rid of our legacy 3-level hashing algorithm and using dovecot's own which in turn would mean having to move mailboxes around for hundrends of thousands of users.
Dimos Alevizos
On 26.2.2013, at 0.36, dalevizo <dalevizo@otenet.gr> wrote:
I tried it but unfortunately the problem remains :
Feb 26 00:02:28 pop08 dovecot: lmtp(26796, dinos.mpalanikas@3230.syzefxis.gov.gr): Error: stat(/var/index/dovecot/7/8/3/amalia@3230.syzefxis.go v.gr/.imap/INBOX/dovecot.index.log) failed: Permission denied (euid=10117261(<unknown>) egid=165(<unknown>) missing +x perm: /var/index/dovecot /7/8/3/amalia@3230.syzefxis.gov.gr, dir owned by 10117262:165 mode=0700) Feb 26 00:02:28 pop08 dovecot: lmtp(26796, dinos.mpalanikas@3230.syzefxis.gov.gr): Error: stat(/var/index/dovecot/7/8/3/amalia@3230.syzefxis.go v.gr/.imap/INBOX/dovecot.index) failed: Permission denied (euid=10117261(<unknown>) egid=165(<unknown>) missing +x perm: /var/index/dovecot/7/8 /3/amalia@3230.syzefxis.gov.gr, dir owned by 10117262:165 mode=0700) Feb 26 00:02:28 pop08 dovecot: lmtp(26796, dinos.mpalanikas@3230.syzefxis.gov.gr): QYsqEkjfK1GsaAAADehEhg: sieve: msgid=<19dfa2f0f211951c56596c 9600194384@otenet.gr>: stored mail into mailbox 'INBOX'
These two users, dinos.mpalanikas@3230.syzefxis.gov.gr and amalia@3230.syzefxis.gov.gr have nothing in common apart from belonging to the same domain.
Here's a guess: Try sending the same mail to two users, so that LMTP gets two RCPT TOs in the same session. You'll probably now see the error?
LMTP always delivers the mail to the first user. Then it tries to copy the first mail to the second user, because in some setups this can be done using hard links. With mbox that of course doesn't work, but looks like instead of failing silently it logs an error. So everything is working as it should, except there are these unnecessary errors logged. I'll see about getting rid of them.
I managed to reproduce the problem, but it required sending 1000 mails with multiple recipients. In every case I checked, the wrong index path is indeed the first RCPT TO's in that session. However it doesn't happen to all other recipients in the session, nor to the same one each time. In any case since the mail get delivered to the correct mbox and you say that the errors are unnecessary we can essentially consider it case closed.
I've got another question about the directors though and what you mentioned in your earlier mail that we can set mail_nfs_index=no and mail_nfs_storage=no. I've noticed that our directors point to different backends if the user logins as "user" vs "user@domain" and as a result there are users ending up in more than one server (several of them use just their username in one client and the full user@domain in another and vice versa). Up till now we didn't think much about it because it's not that common.
Our directors have the following config :
userdb { driver = static args = proxy=y nopassword=y }
We tried changing that to ldap with the same config you posted but it doesn't change anything. I presume it can be configured and we're just missing something ?
Dimos Alevizos
-------- Original Message -------- Subject: Re: [Dovecot] lmtp problem with wrong index path From: Timo Sirainen <tss@iki.fi> Date: 26/02/2013 09:17 πμ
Here's a guess: Try sending the same mail to two users, so that LMTP gets two RCPT TOs in the same session. You'll probably now see the error?
LMTP always delivers the mail to the first user. Then it tries to copy the first mail to the second user, because in some setups this can be done using hard links. With mbox that of course doesn't work, but looks like instead of failing silently it logs an error. So everything is working as it should, except there are these unnecessary errors logged. I'll see about getting rid of them.
On 26.2.2013, at 15.45, Dimos Alevizos <dalevizo@otenet.gr> wrote:
I managed to reproduce the problem, but it required sending 1000 mails with multiple recipients. In every case I checked, the wrong index path is indeed the first RCPT TO's in that session. However it doesn't happen to all other recipients in the session, nor to the same one each time. In any case since the mail get delivered to the correct mbox and you say that the errors are unnecessary we can essentially consider it case closed.
OK, that explains why I couldn't reprodue it easily. Although I'm still not sure why it would happen sometimes and not other times.
I've got another question about the directors though and what you mentioned in your earlier mail that we can set mail_nfs_index=no and mail_nfs_storage=no. I've noticed that our directors point to different backends if the user logins as "user" vs "user@domain" and as a result there are users ending up in more than one server (several of them use just their username in one client and the full user@domain in another and vice versa). Up till now we didn't think much about it because it's not that common.
Do you only have one domain? Maybe easiest would be to set auth_default_realm to that.
Our directors have the following config :
userdb { driver = static args = proxy=y nopassword=y }
This is passdb configuration as a userdb, so it doesn't really work. Except directors don't use userdb, so it doesn't really break either.
We tried changing that to ldap with the same config you posted but it doesn't change anything. I presume it can be configured and we're just missing something ?
You had: pass_attrs = mail=user,userpassword=password
This should have changed the username always to same as "mail" field, which should standardize the usernames with director also.
Do you only have one domain? Maybe easiest would be to set auth_default_realm to that.
No, ~25.000
This is passdb configuration as a userdb, so it doesn't really work. Except directors don't use userdb, so it doesn't really break either.
oops! I see we have some more reading to do...
You had: pass_attrs = mail=user,userpassword=password
This should have changed the username always to same as "mail" field, which should standardize the usernames with director also.
I changed passdb from static to ldap and I think I got it working now
[root@dev-dir dovecot]# egrep 'username changed|started proxying' /var/log/maillog Feb 28 08:16:47 dev-dir-cloud dovecot: imap-login: proxy(webuser2@devwebmail.otenet.gr): started proxying to 83.235.66.71:143: user=<webuser2@devwebmail.otenet.gr>, method=PLAIN, rip=195.170.0.170, lip=83.235.66.70, session=<ECLs1cLWQADDqgCq> Feb 28 08:16:57 dev-dir-cloud dovecot: auth: Debug: auth(webuser2,195.170.0.170,<5dh51sLWUwDDqgCq>): username changed webuser2 -> webuser2@devwebmail.otenet.gr Feb 28 08:16:57 dev-dir-cloud dovecot: imap-login: proxy(webuser2@devwebmail.otenet.gr): started proxying to 83.235.66.71:143: user=<webuser2@devwebmail.otenet.gr>, method=PLAIN, rip=195.170.0.170, lip=83.235.66.70, session=<5dh51sLWUwDDqgCq> Feb 28 08:17:05 dev-dir-cloud dovecot: auth: Debug: auth(dovecottest@otenet.gr,195.170.0.170,<94T21sLWVADDqgCq>): username changed dovecottest@otenet.gr -> webuser2@devwebmail.otenet.gr Feb 28 08:17:05 dev-dir-cloud dovecot: imap-login: proxy(webuser2@devwebmail.otenet.gr): started proxying to 83.235.66.71:143: user=<webuser2@devwebmail.otenet.gr>, method=PLAIN, rip=195.170.0.170, lip=83.235.66.70, session=<94T21sLWVADDqgCq>
Thank you!
Dimos Alevizos
El 26/02/13 14:45, Dimos Alevizos escribió:
I've noticed that our directors point to different backends if the user logins as "user" vs "user@domain" and as a result there are users ending up in more than one server (several of them use just their username in one client and the full user@domain in another and vice versa). Up till now we didn't think much about it because it's not that common.
Sorry for being late; we had a similar problem and solved it with
director_username_hash = %n
HTH
participants (4)
-
dalevizo
-
Dimos Alevizos
-
Joseba Torre
-
Timo Sirainen