Unable to authenticate on Dovecot - auth-userdb issue?
Mark ADAMS
MADAMS9 at msn.com
Fri Jan 3 04:27:30 EET 2020
Some general information:
Mageia Linux 5.4.6-desktop-2.mga7
2.3.7.2 (3c910f64b)
postfix + dovecot + mysql
192.168.1.105 (shuttle) the email server machine
192.168.1.103 (pvr) the mail client machine
I am unable to authenticate to send email. I've looked at postfix but I can't get past dovecot's authentication. Here is what I'm seeing in logs:
Jan 02 18:46:47 shuttle sshd[6660]: Connection closed by 192.168.1.100 port 48506 [preauth]
Jan 02 18:47:05 shuttle postfix/smtpd[6352]: connect from pvr[192.168.1.103]
Jan 02 18:47:16 shuttle postfix/smtpd[6352]: lost connection after CONNECT from pvr[192.168.1.103]
Jan 02 18:47:16 shuttle postfix/smtpd[6352]: disconnect from pvr[192.168.1.103] commands=0/0
Jan 02 18:47:36 shuttle postfix/smtpd[6352]: connect from pvr[192.168.1.103]
Jan 02 18:47:36 shuttle postfix/smtpd[6352]: 6345D4A4A97: client=pvr[192.168.1.103]
Jan 02 18:47:37 shuttle postfix/cleanup[6500]: 6345D4A4A97: message-id=<>
Jan 02 18:47:37 shuttle postfix/qmgr[1385]: 6345D4A4A97: from=<madams at pvr>, size=485, nrcpt=1 (queue active)
Jan 02 18:47:37 shuttle postfix/smtpd[6352]: disconnect from pvr[192.168.1.103] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jan 02 18:47:37 shuttle dovecot[6744]: lda(root at shuttle)<6744><>: Error: auth-master: userdb lookup(root at shuttle): connect(/run/dovecot/auth-userdb) failed: Permission denied (euid=8(mail) egid=12(mail) missing +r perm: /run/dovecot/auth-userdb, dir owned by 0:0 mode=0755)
Jan 02 18:47:37 shuttle dovecot[6744]: lda: Fatal: Internal error occurred. Refer to server log for more information.
Jan 02 18:47:37 shuttle postfix/pipe[6743]: 6345D4A4A97: to=<root at shuttle>, relay=dovecot, delay=1.1, delays=1.1/0.01/0/0.06, dsn=4.3.0, status=deferred (temporary failure. Command output: lda(root at shuttle): Error: net_connect_unix(/run/dovecot/stats-writer) failed: Permission denied )
^C
Note: this error references "/run/dovecot/auth-userdb". That isn't even supposed to be the location of that file. I have no idea why that location shows up. The correct location should be "/etc/dovecot/auth-userdb". The file does exist at that location.
There is no "base_dir" configured in /etc/dovecot/dovecot.conf. When I do try an point the configuration at the correct base_dir, I get this when I try to restart dovecot:
-- The unit dovecot.service has entered the 'failed' state with result 'exit-code'.
Jan 02 18:51:50 shuttle dovecot[7226]: master: Error: service(aggregator): unlink(/etc/dovecot/replication-notify-fifo) failed: Read-only file system
Jan 02 18:51:50 shuttle dovecot[7226]: master: Error: service(pop3): unlink(/etc/dovecot/login/pop3) failed: Read-only file system
Jan 02 18:51:50 shuttle dovecot[7226]: master: Error: service(old-stats): unlink(/etc/dovecot/old-stats) failed: Read-only file system
Jan 02 18:51:50 shuttle dovecot[7226]: master: Error: service(old-stats): unlink(/etc/dovecot/old-stats-mail) failed: Read-only file system
Jan 02 18:51:50 shuttle dovecot[7226]: master: Error: service(old-stats): unlink(/etc/dovecot/old-stats-user) failed: Read-only file system
Jan 02 18:51:50 shuttle dovecot[7226]: master: Error: service(log): unlink(/etc/dovecot/log-errors) failed: Read-only file system
Jan 02 18:51:50 shuttle dovecot[7226]: master: Error: service(lmtp): unlink(/etc/dovecot/lmtp) failed: Read-only file system
Jan 02 18:51:50 shuttle dovecot[7226]: master: Error: service(ipc): unlink(/etc/dovecot/ipc) failed: Read-only file system
Jan 02 18:51:50 shuttle dovecot[7226]: master: Error: service(ipc): unlink(/etc/dovecot/login/ipc-proxy) failed: Read-only file system
Jan 02 18:51:50 shuttle dovecot[7226]: master: Error: service(indexer-worker): unlink(/etc/dovecot/indexer-worker) failed: Read-only file system
And there are about 30 lines of "read-only file system" errors. I haven't been able to track down the cause of that.
Once the line "base_dir = /etc/dovecot" is commented out in /etc/dovecot/dovecot.conf, I can start dovecot:
# systemctl status dovecot
● dovecot.service - Dovecot IMAP/POP3 email server
Loaded: loaded (/usr/lib/systemd/system/dovecot.service; enabled; vendor preset: disabled)
Active: active (running) since Thu 2020-01-02 18:54:15 MST; 5s ago
Docs: man:dovecot(1)
http://wiki2.dovecot.org/
Main PID: 7550 (dovecot)
Memory: 3.8M
CGroup: /system.slice/dovecot.service
├─7550 /usr/sbin/dovecot -F
├─7554 dovecot/anvil
├─7555 dovecot/log
└─7556 dovecot/config
Jan 02 18:54:15 shuttle systemd[1]: Started Dovecot IMAP/POP3 email server.
Jan 02 18:54:15 shuttle dovecot[7550]: master: Dovecot v2.3.7.2 (3c910f64b) starting up for imap, pop3, lmtp
Jan 02 18:54:15 shuttle dovecot[7550]: master: Error: t_readlink(/etc/dovecot/dovecot.conf) failed: readlink() failed: Invalid argument
I have no idea what's up with the t_readlink error. Might be related to the errors above. I can't really find out much about it.
Trying to send email shows no apparent errors:
[madams at pvr ~]$ mail root at shuttle
Subject: testing
test
.
EOT
[madams at pvr ~]$
Trying to send mail in detail looks like this:
$ openssl s_client -connect shuttle:25 -starttls smtp
CONNECTED(00000003)
depth=0 C = US, ST = NM, O = Personal, OU = Private
verify error:num=18:self signed certificate
verify return:1
depth=0 C = US, ST = NM, O = Personal, OU = Private
verify return:1
---
Certificate chain
0 s:/C=US/ST=NM/O=Personal/OU=Private
i:/C=US/ST=NM/O=Personal/OU=Private
---
Server certificate
<It produces all the right certificate information>
-----END CERTIFICATE-----
subject=/C=US/ST=NM/O=Personal/OU=Private
issuer=/C=US/ST=NM/O=Personal/OU=Private
---
No client certificate CA names sent
Peer signing digest: SHA512
Server Temp Key: ECDH, P-256, 256 bits
---
SSL handshake has read 1764 bytes and written 467 bytes
---
New, TLSv1/SSLv3, Cipher is ECDHE-RSA-AES256-GCM-SHA384
Server public key is 2048 bit
Secure Renegotiation IS supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
<and all the SSL information is good>
Start Time: 1578016729
Timeout : 300 (sec)
Verify return code: 18 (self signed certificate)
---
250 CHUNKING
ehlo shuttle
250-shuttle
250-PIPELINING
250-SIZE 10240000
250-VRFY
250-ETRN
250-AUTH PLAIN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250-DSN
250-SMTPUTF8
250 CHUNKING
mail from: madams at pvr
250 2.1.0 Ok
rcpt to: root at shuttle
250 2.1.5 Ok
data
354 End data with <CR><LF>.<CR><LF>
subject: testing
test
.
250 2.0.0 Ok: queued as A73A84A4AE4
quit
221 2.0.0 Bye
closed
That transaction produces this in journalctl:
an 02 19:04:15 shuttle postfix/smtpd[8856]: connect from pvr[192.168.1.103]
Jan 02 19:04:15 shuttle dovecot[7555]: auth: Debug: Loading modules from directory: /usr/lib64/dovecot/modules/auth
Jan 02 19:04:15 shuttle dovecot[7555]: auth: Debug: Module loaded: /usr/lib64/dovecot/modules/auth/lib20_auth_var_expand_crypt.so
Jan 02 19:04:15 shuttle dovecot[7555]: auth: Debug: Read auth token secret from /run/dovecot/auth-token-secret.dat
Jan 02 19:04:15 shuttle dovecot[7555]: auth: Debug: auth client connected (pid=0)
Jan 02 19:04:31 shuttle postfix/smtpd[8856]: B621F4A4B0F: client=pvr[192.168.1.103]
Jan 02 19:04:39 shuttle postfix/cleanup[8914]: B621F4A4B0F: message-id=<>
Jan 02 19:04:40 shuttle postfix/qmgr[1385]: B621F4A4B0F: from=<madams at pvr>, size=184, nrcpt=1 (queue active)
Jan 02 19:04:40 shuttle dovecot[8947]: lda(root at shuttle)<8947><>: Error: auth-master: userdb lookup(root at shuttle): connect(/run/dovecot/auth-userdb) failed: Permission denied (euid=8(mail) egid=12(mail) missing +r perm: /run/dovecot/auth-userdb, dir owned by 0:0 mode=0755)
Jan 02 19:04:40 shuttle dovecot[8947]: lda: Fatal: Internal error occurred. Refer to server log for more information.
Jan 02 19:04:40 shuttle postfix/pipe[8946]: B621F4A4B0F: to=<root at shuttle>, relay=dovecot, delay=13, delays=13/0.01/0/0.06, dsn=4.3.0, status=deferred (temporary failure. Command output: lda(root at shuttle): Error: net_connect_unix(/run/dovecot/stats-writer) failed: Permission denied )
Jan 02 19:04:43 shuttle postfix/smtpd[8856]: disconnect from pvr[192.168.1.103] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Jan 02 19:04:48 shuttle sshd[8962]: Connection closed by 192.168.1.100 port 48596 [preauth]
I've experimented with ownership and permissions on run/dovecot/auth-userdb. It's running as vmail:dovecot, but the permissions I set on it are not persistent - they keep reverting to srw----- whenever I restart dovecot. This is correct given the configuration in dovecot.conf, but should those permissions be set to 0600? Also, that shouldn't be happening in /run/dovcot, it should all be happening in /etc/dovcot.
Attempting to test authentication over TLS isn't working and I'm so confused at this point I'm not even sure I should be doing it.
250 CHUNKING
ehlo shuttle
250-shuttle
250-PIPELINING
250-SIZE 10240000
250-VRFY
250-ETRN
250-AUTH PLAIN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250-DSN
250-SMTPUTF8
250 CHUNKING
auth login
535 5.7.8 Error: authentication failed: Invalid authentication mechanism
auth login bWFkYW1z bm9uZQ==
501 5.5.4 Syntax: AUTH mechanism
auth plain bWFkYW1z bm9uZQ==
501 5.5.4 Syntax: AUTH mechanism
And those are base64 encoded credentials (bWFkYW1z bm9uZQ==).
Here is my config. All I want to do is run from machines on my lan to Thunderbird on my desktop so I can get notices about events and system health from my other servers. Should this be so hard? Is this Postfix's fault? Can anybody help with this?
Thanks.
And now that config:
# dovecot -n
# 2.3.7.2 (3c910f64b): /etc/dovecot/dovecot.conf
# OS: Linux 5.4.6-desktop-2.mga7 x86_64 Mageia 7
# Hostname: shuttle
auth_debug_passwords = yes
auth_username_format = %Ln
disable_plaintext_auth = no
first_valid_uid = 0
last_valid_uid = 10001
mail_gid = 10001
mail_location = mbox:~/mail:INBOX=/var/mail/%u
mail_privileged_group = mail
mail_uid = 10001
namespace inbox {
inbox = yes
location =
mailbox Drafts {
special_use = \Drafts
}
mailbox Junk {
special_use = \Junk
}
mailbox Sent {
special_use = \Sent
}
mailbox "Sent Messages" {
special_use = \Sent
}
mailbox Trash {
special_use = \Trash
}
prefix =
}
passdb {
args = %s
driver = pam
}
plugin {
sieve = file:~/sieve;active=~/.dovecot.sieve
}
service auth-worker {
user = vmail
}
service auth {
unix_listener /var/spool/postfix/private/auth {
group = postfix
mode = 0666
user = postfix
}
unix_listener auth-userdb {
group = dovecot
mode = 0600
user = vmail
}
user = dovecot
}
service imap-login {
inet_listener imap {
port = 143
}
}
service lmtp {
unix_listener /var/spool/postfix/private/dovecot-lmtp {
group = postfix
mode = 0600
user = postfix
}
}
service pop3-login {
inet_listener pop3s {
port = 995
ssl = yes
}
}
ssl = required
ssl_cert = </etc/pki/tls/certs/fullchain.cer
ssl_dh = # hidden, use -P to show it
ssl_key = # hidden, use -P to show it
protocol lmtp {
hostname = shuttle
postmaster_address = postmaster at shuttle
}
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://dovecot.org/pipermail/dovecot/attachments/20200103/05358343/attachment-0001.html>
More information about the dovecot
mailing list