dovecot - Sep 2014 - 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

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