On 27/05/2021 22:24 Jeff Abrahamson <jeff@p27.eu> wrote:


I've started seeing the following error in mail.err for precisely one user on precisely one domain:

Error: mkdir(/var/mail/vmail//jeff/mail) failed: Permission denied (euid=1000(jeff) egid=1001(jeff) missing +w perm: /var/mail/vmail/, dir owned by 4000:4000 mode=0755)
Error: Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred.

In mail.log I see a bit more:

Warning: Failed to parse address from `From_'-line: Missing domain
 Error: mkdir(/var/mail/vmail//jeff/mail) failed: Permission denied (euid=1000(jeff) egid=1001(jeff) missing +w perm: /var/mail/vmail/, dir owned by 4000:4000 mode=0755)
 Error: mkdir(/var/mail/vmail//jeff/mail) failed: Permission denied (euid=1000(jeff) egid=1001(jeff) missing +w perm: /var/mail/vmail/, dir owned by 4000:4000 mode=0755)
 Error: Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information.
 save failed to open mailbox INBOX: Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred.

And yet there's no apparent problem sending and receiving mail for user jeff, for all domains handled by the server. Other users have no issues. The /var/mail/vmail/ hierarchy is all owned by vmail:vmail (4000:4000) and directories are all 0755.
I suspect a red herring except it's been continuing for a week now. I was reading this page (following some searching), but it doesn't seem pertinent in the end.

https://wiki2.dovecot.org/MailLocation/mbox#A.2BAC8-var.2BAC8-mail.2BAC8_dotlocks

Any suggestions what this might be?

This indicates your mail process is being ran as jeff:jeff instead of vmail:vmail.

Can you try `doveadm auth test yourusername` and `doveadm user yourusername` to ensure you are not ending up with uid=jeff gid=jeff somehow?

User jeff (which shouldn't happen but is indicated by the empty From_ message) or jeff@p27.eu (user which manifestly exists and works):

[T] jeff@nantes-m1:~ $ doveadm auth test jeff
doveadm(jeff): Error: net_connect_unix(/var/run/dovecot/stats-writer) failed: Permission denied
Password:
Error: auth-client: conn unix:/var/run/dovecot/auth-client: connect(/var/run/dovecot/auth-client) failed: Permission denied (euid=1000(jeff) egid=1001(jeff) missing +r perm: /var/run/dovecot/auth-client, dir owned by 0:0 mode=0755)
77,[T] jeff@nantes-m1:~ $ doveadm auth test jeff@p27.eu
doveadm(jeff): Error: net_connect_unix(/var/run/dovecot/stats-writer) failed: Permission denied
Password:
Error: auth-client: conn unix:/var/run/dovecot/auth-client: connect(/var/run/dovecot/auth-client) failed: Permission denied (euid=1000(jeff) egid=1001(jeff) missing +r perm: /var/run/dovecot/auth-client, dir owned by 0:0 mode=0755)
77,[T] jeff@nantes-m1:~ $ sudo doveadm auth test jeff
Password:
passdb: jeff auth failed
extra fields:
  user=jeff
77,[T] jeff@nantes-m1:~ $ sudo doveadm auth test jeff@p27.eu
Password:
passdb: jeff@p27.eu auth failed
extra fields:
  user=jeff@p27.eu
77,[T] jeff@nantes-m1:~ $
77,[T] jeff@nantes-m1:~ $ doveadm user jeff
doveadm(jeff): Error: net_connect_unix(/var/run/dovecot/stats-writer) failed: Permission denied
field    value
userdb lookup: user jeff doesn't exist

67,[T] jeff@nantes-m1:~ $ doveadm user jeff@p27.eu
doveadm(jeff): Error: net_connect_unix(/var/run/dovecot/stats-writer) failed: Permission denied
field    valuedoveadm(jeff@p27.eu)<1640907><>: Error: auth-master: userdb lookup(jeff@p27.eu): Auth USER lookup failed

75,[T] jeff@nantes-m1:~ $ sudo doveadm user jeff@p27.eu
[sudo] password for jeff:
field    value
uid    4000
gid    4000
home    /var/mail/vmail/p27.eu/jeff
mail    maildir:/var/mail/vmail/p27.eu/jeff/mail:LAYOUT=fs
[T] jeff@nantes-m1:~ $ sudo doveadm user jeff
field    value
userdb lookup: user jeff doesn't exist

67,[T] jeff@nantes-m1:postfix $

Dovecot processes:

[T] jeff@nantes-m1:~ $ ps axfu | grep dove | grep -v grep
root     1576672  0.0  0.2   4536  2788 ?        Ss   May23   0:02 /usr/sbin/dovecot -F
dovecot  1576683  0.0  0.1   4380  2008 ?        S    May23   0:01  \_ dovecot/anvil
root     1576684  0.0  0.1   4388  1896 ?        S    May23   0:00  \_ dovecot/log
root     1576685  0.0  0.4   5856  4172 ?        S    May23   0:02  \_ dovecot/config
dovecot  1576699  0.0  0.3   5036  3084 ?        S    May23   0:01  \_ dovecot/stats
dovenull 1576804  0.0  0.4   8472  4288 ?        S    May23   0:02  \_ dovecot/imap-login
vmail    1576805  0.0  0.4   7212  4572 ?        S    May23   0:03  \_ dovecot/imap
dovecot  1637614  0.0  0.5   9508  5756 ?        S    04:58   0:00  \_ dovecot/auth
dovenull 1638957  0.0  0.6   8472  6664 ?        S    06:19   0:00  \_ dovecot/imap-login
vmail    1638958  0.0  0.5   9580  5612 ?        S    06:19   0:00  \_ dovecot/imap
dovenull 1640541  0.0  0.6   8472  6660 ?        S    06:39   0:00  \_ dovecot/imap-login
vmail    1640542  0.0  0.4   6136  4584 ?        S    06:39   0:00  \_ dovecot/imap
dovenull 1640591  0.0  0.6   8472  6656 ?        S    06:44   0:00  \_ dovecot/imap-login
dovenull 1640592  0.0  0.6   8472  6580 ?        S    06:44   0:00  \_ dovecot/imap-login
vmail    1640593  0.0  0.6  14732  7000 ?        S    06:44   0:00  \_ dovecot/imap
vmail    1640594  0.0  0.5   6952  5504 ?        S    06:44   0:00  \_ dovecot/imap
dovenull 1640599  0.0  0.6   8472  6676 ?        S    06:45   0:00  \_ dovecot/imap-login
vmail    1640600  0.0  0.5   7092  5764 ?        S    06:45   0:00  \_ dovecot/imap
dovenull 1640601  0.0  0.6   8472  6680 ?        S    06:45   0:00  \_ dovecot/imap-login
vmail    1640602  0.0  0.5   6460  5168 ?        S    06:45   0:00  \_ dovecot/imap
dovenull 1640607  0.0  0.6   8472  6544 ?        S    06:45   0:00  \_ dovecot/imap-login
vmail    1640608  0.0  0.4   6444  4980 ?        S    06:45   0:00  \_ dovecot/imap
dovenull 1640609  0.0  0.6   8472  6764 ?        S    06:45   0:00  \_ dovecot/imap-login
vmail    1640610  0.0  0.5   7072  5900 ?        S    06:45   0:00  \_ dovecot/imap
dovenull 1640613  0.0  0.6   8472  6620 ?        S    06:45   0:00  \_ dovecot/imap-login
vmail    1640614  0.0  0.5   6460  5312 ?        S    06:45   0:00  \_ dovecot/imap
dovenull 1640615  0.0  0.6   8472  6716 ?        S    06:45   0:00  \_ dovecot/imap-login
vmail    1640616  0.0  0.5   6444  5080 ?        S    06:45   0:00  \_ dovecot/imap
dovenull 1640617  0.0  0.6   8472  6752 ?        S    06:45   0:00  \_ dovecot/imap-login
vmail    1640618  0.0  0.5   7864  5512 ?        S    06:45   0:00  \_ dovecot/imap
[T] jeff@nantes-m1:~ $

On a hunch based on your suggested test, I installed mailx and did the following two tests.  The first triggers the error message, the second does not:

[T] jeff@nantes-m1:~ $ echo test | mailx -s 'test 1' jeff
[T] jeff@nantes-m1:~ $ echo test | mailx -s 'test 1' jeff@p27.eu

This suggests to me that some cron job was trying to mail me and failing to get its mail delivered.

So one fix (but maybe not the correct fix) is to add this line to /etc/postfix/virtual (despite the error coming from dovecot):

jeff    jeff@p27.eu

Jeff Abrahamson
+33 6 24 40 01 57
+44 7920 594 255

http://p27.eu/jeff/
http://mobilitains.fr/