Hi.
I'm using exim that delivers email over LMTP to dovecot 2.2.13.
I noticed that dovecot LMTP service is sometimes (reare but repeats) mixing users. Example below. There is one mail (msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>) that is going to be delivered to multiple local recipients.
Some recipients are delivered properly:
Sep 1 05:40:33 host dovecot: lmtp(3176): Connect from local Sep 1 05:40:34 host dovecot: lmtp(3176, gbuser1): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, jpuser2): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, rkuser3): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, gbruser4): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, pbauser5): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, mwauser6): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, mdyuser7): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: saved mail to INBOX
but some are not:
Sep 1 05:40:34 host dovecot: lmtp(3176, lkrzyuser8): Error: lstat(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist.lock) failed: Permission denied Sep 1 05:40:34 host dovecot: lmtp(3176, lkrzyuser8): Error: file_dotlock_create(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist) failed: Permission denied (euid=28371(<unknown>) egid=17373(<unknown>) missing +x perm: /var/lib/dovecot/control/gbuser1, dir owned by 67593:17373 mode=0700)
Notice it was trying to deliver to user "lkrzyuser8" but it tries to access some other user files (dovecot-uidlist). euid=28371 is indeed "lkrzyuser8" but why it tries to access "gbuser1" files?
Sep 1 05:40:34 host dovecot: lmtp(3176, lkrzyuser8): Error: lstat(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist.lock) failed: Permission denied Sep 1 05:40:34 host dovecot: lmtp(3176, lkrzyuser8): Error: file_dotlock_create(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist) failed: Permission denied (euid=28371(<unknown>) egid=17373(<unknown>) missing +x perm: /var/lib/dovecot/control/gbuser1, dir owned by 67593:17373 mode=0700) Sep 1 05:40:34 host dovecot: lmtp(3176, lkrzyuser8): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: save failed to INBOX: BUG: Unknown internal error
Above is again the same case.
Sep 1 05:40:34 host dovecot: lmtp(3176, wm1user9): Error: lstat(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist.lock) failed: Permission denied Sep 1 05:40:34 host dovecot: lmtp(3176, wm1user9): Error: file_dotlock_create(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist) failed: Permission denied (euid=128065(<unknown>) egid=17373(<unknown>) missing +x perm: /var/lib/dovecot/control/gbuser1, dir owned by 67593:17373 mode=0700) Sep 1 05:40:34 host dovecot: lmtp(3176, wm1user9): Error: lstat(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist.lock) failed: Permission denied Sep 1 05:40:34 host dovecot: lmtp(3176, wm1user9): Error: file_dotlock_create(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist) failed: Permission denied (euid=128065(<unknown>) egid=17373(<unknown>) missing +x perm: /var/lib/dovecot/control/gbuser1, dir owned by 67593:17373 mode=0700) Sep 1 05:40:34 host dovecot: lmtp(3176, wm1user9): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: save failed to INBOX: BUG: Unknown internal error
And here again the same problem but with user "wm1user9"
Sep 1 05:40:34 host dovecot: lmtp(3176): Disconnect from local: Successful quit
# doveadm user gbuser1 field value uid 67593 gid 17373 home /var/mail/gbuser1/ mail maildir:/var/mail/gbuser1/:CONTROL=/var/lib/dovecot/control/gbuser1
# doveadm user lkrzyuser8 field value uid 28371 gid 17373 home /var/mail/lkrzyuser8/ mail maildir:/var/mail/lkrzyuser8/:CONTROL=/var/lib/dovecot/control/lkrzyuser8
# doveadm user wm1user9 field value uid 128065 gid 17373 home /var/mail/wm1user9/ mail maildir:/var/mail/wm1user9/:CONTROL=/var/lib/dovecot/control/wm1user9
Later exim retries delivery and dovecot lmtp succeeds:
Sep 1 05:41:34 host dovecot: lmtp(4737): Connect from local Sep 1 05:41:34 host dovecot: lmtp(4737, lkrzyuser8): b9F+OsHqA1SBEgAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: saved mail to INBOX Sep 1 05:41:34 host dovecot: lmtp(4737, wm1user9): b9F+OsHqA1SBEgAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E@KRMXA41>: saved mail to INBOX Sep 1 05:41:34 host dovecot: lmtp(4737): Disconnect from local: Successful quit
The problem is not reasily repeatable. It happens several times a day for different users each time (while thousands users are logging in), so I guess some race condition takes place.
# dovecot -n # 2.2.13: /etc/dovecot/dovecot.conf doveconf: Warning: service auth { client_limit=1000 } is lower than required under max. load (8000) doveconf: Warning: service anvil { client_limit=1000 } is lower than required under max. load (6003) # OS: Linux 3.14.17-1 x86_64 xfs auth_mechanisms = plain login auth_username_chars = abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_@= auth_username_translation = @= auth_verbose = yes default_process_limit = 2000 default_vsz_limit = 512 M disable_plaintext_auth = no first_valid_gid = 1500 first_valid_uid = 1500 lda_mailbox_autocreate = yes lmtp_save_to_detail_mailbox = yes login_greeting = Mail server ready. mail_location = maildir:/var/mail/%Ln:CONTROL=/var/lib/dovecot/control/%Ln mail_log_prefix = "%s(%u): session=<%{session}>, " mail_plugins = zlib quota namespace { hidden = no inbox = yes location = prefix = INBOX. separator = . type = private } passdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } plugin { mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename quota = fs:User quota:user quota2 = fs:Group quota:group } postmaster_address = postmaster@somwehere.pl service auth { unix_listener auth-userdb { mode = 0666 } } service imap { process_limit = 2048 } service pop3 { process_limit = 1024 }
userdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } protocol lmtp { auth_username_format = %Ln auth_username_translation = } protocol imap { imap_logout_format = bytes=%i/%o mail_max_userip_connections = 20 mail_plugins = zlib quota imap_quota mail_log notify } protocol pop3 { mail_max_userip_connections = 20 mail_plugins = mail_log notify pop3_client_workarounds = outlook-no-nuls oe-ns-eoh pop3_logout_format = top=%t/%p, retr=%r/%b, del=%d/%m, size=%s, bytes=%i/%o pop3_uidl_format = %Mf }
Arkadiusz Miśkiewicz, arekm / maven.pl