Arkadiusz Miśkiewicz
2014-Sep-01 09:14 UTC
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 at 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 at KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, jpuser2): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, rkuser3): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, gbruser4): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, pbauser5): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, mwauser6): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, mdyuser7): TDO+HNDpA1RoDAAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at 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 at 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 at 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 at KRMXA41>: saved mail to INBOX Sep 1 05:41:34 host dovecot: lmtp(4737, wm1user9): b9F+OsHqA1SBEgAA16XVAg: msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at 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 at 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
Arkadiusz Miśkiewicz
2014-Sep-10 14:00 UTC
dovecot 2.2.13: LMTP delivery with multiple recipients incorrectly mixes users
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 at 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 at KRMXA41>: saved mail to > INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, jpuser2): > TDO+HNDpA1RoDAAA16XVAg: > msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to > INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, rkuser3): > TDO+HNDpA1RoDAAA16XVAg: > msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to > INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, gbruser4): > TDO+HNDpA1RoDAAA16XVAg: > msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to > INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, pbauser5): > TDO+HNDpA1RoDAAA16XVAg: > msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to > INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, mwauser6): > TDO+HNDpA1RoDAAA16XVAg: > msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to > INBOX Sep 1 05:40:34 host dovecot: lmtp(3176, mdyuser7): > TDO+HNDpA1RoDAAA16XVAg: > msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at 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 at 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 at 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 at KRMXA41>: saved mail to > INBOX Sep 1 05:41:34 host dovecot: lmtp(4737, wm1user9): > b9F+OsHqA1SBEgAA16XVAg: > msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at 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 at 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
Apparently Analagous Threads
- Printing problems with samba 3.0.23c and NT4
- More problems with samba 3.0.23c and NT4
- access denied on printer driver upload
- Re: [libvirt] LXC, user namespaces and systemd
- Upgrade 2.2.27 to 2.3.9.2: master(imap): net_connect_unix(imap) failed: Resource temporarily unavailable