dovecot 2.2.13: LMTP delivery with multiple recipients incorrectly mixes users

[Arkadiusz Miśkiewicz]

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]

Post by Arkadiusz Miśkiewicz
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)

Post by Arkadiusz Miśkiewicz
Sep 1 05:40:33 host dovecot: lmtp(3176): Connect from local
msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to
msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to
msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to
msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to
msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to
msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to
msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to
INBOX
lstat(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist.lock)
failed: Permission denied Sep 1 05:40:34 host dovecot: lmtp(3176,
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?
lstat(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist.lock)
failed: Permission denied Sep 1 05:40:34 host dovecot: lmtp(3176,
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,
msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: save failed to
INBOX: BUG: Unknown internal error
Above is again the same case.
lstat(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist.lock)
failed: Permission denied Sep 1 05:40:34 host dovecot: lmtp(3176,
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
Error: lstat(/var/lib/dovecot/control/gbuser1/.INBOX/dovecot-uidlist.lock)
failed: Permission denied Sep 1 05:40:34 host dovecot: lmtp(3176,
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
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
Sep 1 05:41:34 host dovecot: lmtp(4737): Connect from local
msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to
msgid=<1ACE53B70631CA45B62348E4EE8757493731A59E at KRMXA41>: saved mail to
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 {
Linux 3.14.17-1 x86_64 xfs
auth_mechanisms = plain login
auth_username_chars =
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
}