Hi My name is Keith Smith. I am a PHP developer and have been a
freelance PHP developer since 2006.
I have been working on a PHP web server in the hope of learning more
about Linux hosting server administration. Over the years I have had
the opportunity to create many PHP virtual hosts. I have not worked
with or configured BIND, Postfix, and Dovecot before about 3 weeks ago.
My home server is connected to the Internet via my home office business
cable account. No blocked ports and I am able run one or more servers.
I am running Ubuntu 20.04lts / Apache / MySql (or a clone) / PHP / BIND9
/ Postfix / Dovecot / Let's Encrypt SSL.
My server’s FQDN is : soho.keiththewebguy.com as is my reverse lookup
on my IP : 98.191.108.149.
The purpose is for learning. I intend to run one such configured server
out of my home office running one domain or more (virtual hosts) and
would like to configure Postfix/Dovecot to service one or more email
addresses per virtual hosting.
I have BIND working. At least enough that a simple web page can be
displayed. I've installed Postfix and Dovecot and am getting an
authentication issue that shows up in the logs.
I do not know all that you might need. Please let me know.
I admit I find Postfix difficult to understand. I am at the newbie
stage. I've scoured the Internet looking for answers.
After I configured Postfix and Dovecot I issued the commend : telnet
keiththewebguy.com 25 on my web server. It returned:
Trying 98.191.108.149...
Connected to keiththewebguy.com.
Escape character is '^]'.
220 soho.keiththewebguy.com ESMTP Postfix
I issued : ehlo soho.keiththewebguy.com
250-soho.keiththewebguy.com
250-PIPELINING
250-SIZE 10240000
250-VRFY
250-ETRN
250-STARTTLS
250-AUTH PLAIN LOGIN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250-DSN
250 CHUNKING
I issued : quit
221 2.0.0 Bye
Connection closed by foreign host.
---
I assume this means things are configured correctly.
I am looking at both logs:
1) /var/log/mail.err which contains no content.
2) /var/log/mail.log which is verbose.
To /etc/dovecot/dovecot.conf I added the following for debugging:
auth_verbose = yes
auth_verbose_passwords = no
auth_debug = yes
auth_debug_passwords = yes
mail_debug = yes
verbose_ssl = yes
I am trying to connect using Thunderbird.
Config:
IMAP port 993 / SSL/TLS / Normal Password / username :
ke...@keiththewebguy.com and password that is in
/etc/dovecot/dovecot-users
SMTP port 25 / STARTTLS / Normal Password / username :
ke...@keiththewebguy.com and password that is in
/etc/dovecot/dovecot-users
Thunderbird tests these configurations and reports them as found on the
server.
When I press the done button to create the email account I get a message
"Unable to log into the server. Probably wrong configuration,
username, or password.".
The output when trying to create the Thunderbird account:
/var/log/mail.log
===============
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x10, ret=1:
before SSL initialization
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: before SSL initialization
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2002,
ret=-1: before SSL initialization
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: before SSL initialization
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS read client hello
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS write server hello
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS write certificate
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS write key exchange
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS write server done
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2002,
ret=-1: SSLv3/TLS write server done
Jul 5 18:58:35 soho dovecot: message repeated 2 times: [ imap-login:
Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done]
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS write server done
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS read client key exchange
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS read change cipher spec
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS read finished
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS write session ticket
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS write change cipher spec
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2001,
ret=1: SSLv3/TLS write finished
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x20, ret=1:
SSL negotiation finished successfully
Jul 5 18:58:35 soho dovecot: imap-login: Debug: SSL: where=0x2002,
ret=1: SSL negotiation finished successfully
Jul 5 18:58:35 soho dovecot: auth: Debug: Loading modules from
directory: /usr/lib/dovecot/modules/auth
Jul 5 18:58:35 soho dovecot: auth: Debug: Module loaded:
/usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so
Jul 5 18:58:35 soho dovecot: auth: Debug: Read auth token secret from
/var/run/dovecot/auth-token-secret.dat
Jul 5 18:58:35 soho dovecot: auth: Debug: passwd-file
/etc/dovecot/dovecot-users: Read 1 users in 0 secs
Jul 5 18:58:35 soho dovecot: auth: Debug: auth client connected
(pid=2021)
Jul 5 18:58:35 soho dovecot: auth: Debug: client in:
AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=wVJ55GTGvspiv2yV#011lip=192.168.1.10#011rip=98.191.108.149#011lport=993#011rport=51902#011local_name=mail.keiththewebguy.com#011ssl_cipher=ECDHE-RSA-AES128-GCM-SHA256#011ssl_cipher_bits=128#011ssl_pfs=KxECDHE#011ssl_protocol=TLSv1.2
Jul 5 18:58:35 soho dovecot: auth: Debug: client passdb out:
CONT#0111#011
Jul 5 18:58:35 soho dovecot: auth: Debug: client in:
CONT#0111#011AGtlaXRoQGtlaXRodGhld2ViZ3V5LmNvbQBJY2VjcmVhbS1Db25lXjIx
(previous base64 data may contain sensitive data)
Jul 5 18:58:35 soho dovecot: auth: Debug:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
Performing passdb lookup
Jul 5 18:58:35 soho dovecot: auth: Debug:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
lookup: user=ke...@keiththewebguy.com file=/etc/dovecot/dovecot-users
Jul 5 18:58:35 soho dovecot: auth:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
unknown user
Jul 5 18:58:35 soho dovecot: auth: Debug:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
Finished passdb lookup
Jul 5 18:58:35 soho dovecot: auth: Debug:
auth(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): Auth
request finished
Jul 5 18:58:37 soho dovecot: auth: Debug: client passdb out:
FAIL#0111#011user=ke...@keiththewebguy.com
Jul 5 18:58:37 soho dovecot: auth: Debug: client in:
AUTH#0112#011LOGIN#011service=imap#011secured=tls#011session=wVJ55GTGvspiv2yV#011lip=192.168.1.10#011rip=98.191.108.149#011lport=993#011rport=51902#011local_name=mail.keiththewebguy.com#011ssl_cipher=ECDHE-RSA-AES128-GCM-SHA256#011ssl_cipher_bits=128#011ssl_pfs=KxECDHE#011ssl_protocol=TLSv1.2
Jul 5 18:58:41 soho dovecot: auth: Debug: client passdb out:
CONT#0112#011VXNlcm5hbWU6
Jul 5 18:58:41 soho dovecot: auth: Debug: client in:
CONT#0112#011a2VpdGhAa2VpdGh0aGV3ZWJndXkuY29t (previous base64 data may
contain sensitive data)
Jul 5 18:58:41 soho dovecot: auth: Debug: client passdb out:
CONT#0112#011UGFzc3dvcmQ6
Jul 5 18:58:41 soho dovecot: auth: Debug: client in:
CONT#0112#011SWNlY3JlYW0tQ29uZV4yMQ== (previous base64 data may contain
sensitive data)
Jul 5 18:58:41 soho dovecot: auth: Debug:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
Performing passdb lookup
Jul 5 18:58:41 soho dovecot: auth: Debug:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
lookup: user=ke...@keiththewebguy.com file=/etc/dovecot/dovecot-users
Jul 5 18:58:41 soho dovecot: auth:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
unknown user
Jul 5 18:58:41 soho dovecot: auth: Debug:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
Finished passdb lookup
Jul 5 18:58:41 soho dovecot: auth: Debug:
auth(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): Auth
request finished
Jul 5 18:58:43 soho dovecot: auth: Debug: client passdb out:
FAIL#0112#011user=ke...@keiththewebguy.com
Jul 5 18:58:43 soho dovecot: auth: Debug: client in:
AUTH#0113#011PLAIN#011service=imap#011secured=tls#011session=wVJ55GTGvspiv2yV#011lip=192.168.1.10#011rip=98.191.108.149#011lport=993#011rport=51902#011local_name=mail.keiththewebguy.com#011ssl_cipher=ECDHE-RSA-AES128-GCM-SHA256#011ssl_cipher_bits=128#011ssl_pfs=KxECDHE#011ssl_protocol=TLSv1.2#011resp=AGtlaXRoQGtlaXRodGhld2ViZ3V5LmNvbQBJY2VjcmVhbS1Db25lXjIx
(previous base64 data may contain sensitive data)
Jul 5 18:58:47 soho dovecot: auth: Debug:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
Performing passdb lookup
Jul 5 18:58:47 soho dovecot: auth: Debug:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
lookup: user=ke...@keiththewebguy.com file=/etc/dovecot/dovecot-users
Jul 5 18:58:47 soho dovecot: auth:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
unknown user
Jul 5 18:58:47 soho dovecot: auth: Debug:
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
Finished passdb lookup
Jul 5 18:58:47 soho dovecot: auth: Debug:
auth(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): Auth
request finished
Jul 5 18:58:49 soho dovecot: auth: Debug: client passdb out:
FAIL#0113#011user=ke...@keiththewebguy.com
Jul 5 18:58:49 soho dovecot: imap-login: Debug: SSL alert: close notify
Jul 5 18:58:49 soho dovecot: imap-login: Disconnected (auth failed, 3
attempts in 14 secs): user=<ke...@keiththewebguy.com>, method=PLAIN,
rip=98.191.108.149, lip=192.168.1.10, TLS, session=<wVJ55GTGvspiv2yV>
Jul 5 18:58:49 soho dovecot: imap-login: Debug: SSL alert: close notify
==================
I see the following lines:
passwd-file /etc/dovecot/dovecot-users: Read 1 users in 0 secs
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
Performing passdb lookup
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
lookup: user=ke...@keiththewebguy.com file=/etc/dovecot/dovecot-users
file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
unknown user
passwd-file(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>):
Finished passdb lookup
auth(ke...@keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): Auth
request finished
client passdb out: FAIL#0111#011user=ke...@keiththewebguy.com
---
It seems there is an issue with the user or the configuration of
/etc/dovecot/dovecot-users.
Any thoughts are most welcome!! Thanks in advance!!
