Postfix / Dovecot Not Able to Authenticate

techlists at phpcoderusa.com techlists at phpcoderusa.com
Mon Jul 5 23:59:43 EEST 2021 

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 and Dovecot 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 : 
keith at keiththewebguy.com and password that is in 
/etc/dovecot/dovecot-users

SMTP port 25 / STARTTLS / Normal Password / username : 
keith at 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(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
Performing passdb lookup
Jul  5 18:58:35 soho dovecot: auth: Debug: 
passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
lookup: user=keith at keiththewebguy.com file=/etc/dovecot/dovecot-users
Jul  5 18:58:35 soho dovecot: auth: 
passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
unknown user
Jul  5 18:58:35 soho dovecot: auth: Debug: 
passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
Finished passdb lookup
Jul  5 18:58:35 soho dovecot: auth: Debug: 
auth(keith at 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=keith at 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(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
Performing passdb lookup
Jul  5 18:58:41 soho dovecot: auth: Debug: 
passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
lookup: user=keith at keiththewebguy.com file=/etc/dovecot/dovecot-users
Jul  5 18:58:41 soho dovecot: auth: 
passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
unknown user
Jul  5 18:58:41 soho dovecot: auth: Debug: 
passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
Finished passdb lookup
Jul  5 18:58:41 soho dovecot: auth: Debug: 
auth(keith at 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=keith at 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(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
Performing passdb lookup
Jul  5 18:58:47 soho dovecot: auth: Debug: 
passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
lookup: user=keith at keiththewebguy.com file=/etc/dovecot/dovecot-users
Jul  5 18:58:47 soho dovecot: auth: 
passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
unknown user
Jul  5 18:58:47 soho dovecot: auth: Debug: 
passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
Finished passdb lookup
Jul  5 18:58:47 soho dovecot: auth: Debug: 
auth(keith at 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=keith at 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=<keith at 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(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
Performing passdb lookup

passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
lookup: user=keith at keiththewebguy.com file=/etc/dovecot/dovecot-users

file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
unknown user

passwd-file(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): 
Finished passdb lookup

auth(keith at keiththewebguy.com,98.191.108.149,<wVJ55GTGvspiv2yV>): Auth 
request finished

client passdb out: FAIL#0111#011user=keith at keiththewebguy.com

- - - -

dovecot -n  :

# 2.3.7.2 (3c910f64b): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.7.2 ()
# OS: Linux 5.4.0-77-generic x86_64 Ubuntu 20.04.2 LTS ext4
# Hostname: soho.keiththewebguy.com
auth_debug = yes
auth_debug_passwords = yes
auth_mechanisms = plain login
auth_verbose = yes
mail_debug = yes
mail_location = maildir:/var/mail/vhosts/%d/%n
mail_privileged_group = mail
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 = scheme=PLAIN username_format=%u /etc/dovecot/dovecot-users
   driver = passwd-file
}
protocols = " imap lmtp pop3"
service auth {
   unix_listener /var/spool/postfix/private/auth {
     group = postfix
     mode = 0666
     user = postfix
   }
}
service imap-login {
   inet_listener imaps {
     port = 993
     ssl = yes
   }
}
service lmtp {
   unix_listener /var/spool/postfix/private/dovecot-lmtp {
     group = postfix
     mode = 0600
     user = postfix
   }
}
ssl = required
ssl_cert = </etc/letsencrypt/live/keiththewebguy.com/fullchain.pem
ssl_client_ca_dir = /etc/ssl/certs
ssl_dh = # hidden, use -P to show it
ssl_key = # hidden, use -P to show it
userdb {
   args = uid=vmail gid=vmail home=/var/mail/vhosts/%d/%n
   driver = static
}
verbose_ssl = yes
- - -

Any thoughts are most welcome!!  Thanks in advance!!

More information about the dovecot mailing list