dovecot 2.2.13: LMTP delivery with multiple recipients incorrectly mixes users

Arkadiusz Miśkiewicz arekm at maven.pl
Mon Sep 1 09:14:06 UTC 2014 

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

More information about the dovecot mailing list