Doveadm auth test fails

[Ken Wright]

On Thu, 2022-01-06 at 03:44 +0100, John Fawcett wrote:
> On 06/01/2022 01:16, Ken Wright wrote:
> > I've been having trouble logging into my email server (postfix
> > 3.4.13, dovecot 2.3.7.2, postfixadmin 3.3.8).  I decided to try the
> > doveadm auth test, and got the following result:
> > 
> > kwright at grace:~$ sudo doveadm auth test me at mydomain.com
> > Password:
> > passdb: me at mydomain.com auth failed
> > extra fields:
> >    user=me at mydomain.com
> > 
> > I logged in to PostfixAdmin and made sure I was using the correct
> > password, but got exactly the same result afterward.  Should I have
> > restarted Dovecot after changing the password?  I'm totally confused
> > by this problem; any and all suggestions will be gratefully received!
> > 
> > Ken
> > 
> > 
> > 
> Ken
> 
> Dovecot does have credential caching, so potentially the info could be
> coming from the cache though dovecot uses some logic to understand
> when it should do a new query so normally its not necessary to flush
> the cache or restart dovecot after changing a password. If you're doing
> testing on a non live server in the process of being set up then you
> may want to take the cautious approach of restarting dovecot.
> 
> about why the command is failing. You may be able to find other 
> information in the log.
> 
> You may want to investigate turning on authentication and password 
> debugging to progress this problem.
> 
> auth_debug = yes
> 
> auth_debug_passwords = yes
> 
> (and restart dovecot)

Okay, I've done this.

> Then try an authentication test again or even a full login test
> 
> doveadm auth login username
> 
> Those settings will give you information in the log about what dovecot
> is doing internally in relation to lookup up the user info and password
> including information about password mismatches.

Here's the latest output of tail /var/log/mail.log:

Jan  5 22:09:28 grace dovecot: auth-worker(218040): Debug: conn
unix:auth-worker (pid=171742,uid=118): auth-worker<1590>: Handling
PASSV request
Jan  5 22:09:28 grace dovecot: auth-worker(218040): Debug:
sql(me at mydomain.com,192.168.1.1,<3VfPMuHUrpvAqAEB>): Performing passdb
lookup
Jan  5 22:09:28 grace dovecot: auth-worker(218040): Debug:
sql(me at mydomain.com,192.168.1.1,<3VfPMuHUrpvAqAEB>): query: SELECT
username AS user,password FROM mailbox WHERE username =
'me at mydomain.com' AND active='1'
Jan  5 22:09:28 grace dovecot: auth-worker(218040):
sql(me at mydomain.com,192.168.1.1,<3VfPMuHUrpvAqAEB>): Password mismatch
Jan  5 22:09:28 grace dovecot: auth-worker(218040): Debug:
sql(me at mydomain.com,192.168.1.1,<3VfPMuHUrpvAqAEB>): ARGON2I(password)
!= '$1$c9809462$ecGdXzPm2xqMK0TKngGkc.', try DES-CRYPT scheme instead
Jan  5 22:09:28 grace dovecot: auth-worker(218040): Debug:
sql(me at mydomain.com,192.168.1.1,<3VfPMuHUrpvAqAEB>): Finished passdb
lookup
Jan  5 22:09:28 grace dovecot: auth-worker(218040): Debug: conn
unix:auth-worker (pid=171742,uid=118): auth-worker<1590>: Finished
Jan  5 22:09:28 grace dovecot: auth: Debug:
sql(me at mydomain.com,192.168.1.1,<3VfPMuHUrpvAqAEB>): Finished passdb
lookup
Jan  5 22:09:28 grace dovecot: auth: Debug:
auth(me at mydomain.com,192.168.1.1,<3VfPMuHUrpvAqAEB>): Auth request
finished
Jan  5 22:09:30 grace dovecot: auth: Debug: client passdb out:
FAIL#0111#011user=me at mydomain.com

I know the password is correct, but it still fails.  I had some
problems getting this mailbox set up in PostfixAdmin; could it be the
database is faulty?

Ken