dovecot 2.2.13: LMTP delivery with multiple recipients incorrectly mixes users
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
On Monday 01 of September 2014, Arkadiusz Miśkiewicz wrote:
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.
What is worse is that dovecot lmtp can sometimes (if permissions allow that) create mail file, in maildir tree, of user B using user A uid/gid! All that because it mixes users.
That leads to more problems (like when using filesystem quota. Since user A has his files (by uid/gid) stored in directory of user B. A cannot access them, delete them but they still eat user A quota).
Looks to be some major brokeness in dovecot lmtp.
(batch_max = 1 should workaround the problem I think but that's not a solution)
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-uidlis t) 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-uidlis t) 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-uidlis t) 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-uidlis t) 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/wm1user9Later 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
participants (1)
-
Arkadiusz Miśkiewicz