Re: Dovecot 2.4 authentication

22 May 2026

      Looks like attachments don't work here.  I've appended to the text.

Hello,
Attached are three files in a tar archive:
debug-grep.log: Dovecot debug log filtered for specific SMTP user.
debug-mail.log: Same events filtered from mail.log.
postconf.txt
The separate authentication events are using differing methods in
Thunderbird but appear to all be using sasl_method=PLAIN.  Note that
there were some changes to doveconf since my original post.  But
authentication succeeded in these tests every time.  Is it even trying
encrypted passwords?  Makes me wonder if it is falling back to PLAIN
where other clients just fail on encrypted passwords.
Regards,
David Koski
dkoski@sutinen.com
On 5/13/26 10:34 PM, Aki Tuomi wrote:
...
...
On 14/05/2026 02:11 EEST David Koski via dovecot
<dovecot@dovecot.org> wrote:
Hello,
I just put a new Postfix with Dovecot 2.4 server on line migrating the
email from Dovecot 2.3.  I have discovered a number of clients (all
copiers so far) that no longer authenticate SMTP.  Mechanisms configured:
auth_mechanisms = plain login gssapi cram-md5 digest-md5
I found that if I disable all encrypted password methods (some copiers
list them separately with a checkbox) and leave only plain/login on the
client side, then it succeeds.  But sometimes it is not necessary.  It's
almost as if it only tries once and gives up if it fails.  I'm not sure
how it is actually supposed to work.  But it worked with Dovecot 2.3.  I
did test one account with an encrypted password like "{CRAM-MD5}6e3..."
successfully.  But other accounts failed.  It almost looks like the
encryption method must be specified on the client side to match the
server before it will work consistently.  I know that password
encryption is unnecessary with STARTTLS but I have to live with it now.
I have noticed that Thunderbird configured with encryption silently
falls back to plain/login so I didn't notice a problem.
Regards,
David Koski
dkoski@sutinen.com
Hi!
Can you send doveconf and logs with log_debug=category=auth please?
Aki
May 21 13:37:32 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
sql: Performing passdb lookup
May 21 13:37:32 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [57]: Debug: sql: Performing passdb lookup
May 21 13:37:32 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [57]: Debug: sql: query: CALL
password_query('scanner@bogus.relay', '<super.secret>')
May 21 13:37:32 auth-worker(272356): Debug:
mysql(/var/run/mysqld/mysqld.sock): Finished query 'CALL
password_query('scanner@bogus.relay', '<super.secret>')' in 1 msecs
May 21 13:37:32 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [57]: Debug: sql: Finished passdb lookup
May 21 13:37:32 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
sql: Finished passdb lookup
May 21 13:37:32 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
Auth request finished
May 21 13:37:32 auth: Debug: conn unix:auth (pid=272474,uid=121) [236]:
client passdb out: OK    1    user=scanner@bogus.relay
May 21 13:38:39 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
sql: Performing passdb lookup
May 21 13:38:39 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [72]: Debug: sql: Performing passdb lookup
May 21 13:38:39 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [72]: Debug: sql: query: CALL
password_query('scanner@bogus.relay', '<super.secret>')
May 21 13:38:39 auth-worker(272356): Debug:
mysql(/var/run/mysqld/mysqld.sock): Finished query 'CALL
password_query('scanner@bogus.relay', '<super.secret>')' in 1 msecs
May 21 13:38:39 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [72]: Debug: sql: Finished passdb lookup
May 21 13:38:39 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
sql: Finished passdb lookup
May 21 13:38:39 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
Auth request finished
May 21 13:38:39 auth: Debug: conn unix:auth (pid=272474,uid=121) [236]:
client passdb out: OK    2    user=scanner@bogus.relay
May 21 13:43:02 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
sql: Performing passdb lookup
May 21 13:43:02 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [122]: Debug: sql: Performing passdb lookup
May 21 13:43:02 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [122]: Debug: sql: query: CALL
password_query('scanner@bogus.relay', '<super.secret>')
May 21 13:43:02 auth-worker(272356): Debug:
mysql(/var/run/mysqld/mysqld.sock): Finished query 'CALL
password_query('scanner@bogus.relay', '<super.secret>')' in 1 msecs
May 21 13:43:02 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [122]: Debug: sql: Finished passdb lookup
May 21 13:43:02 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
sql: Finished passdb lookup
May 21 13:43:02 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
Auth request finished
May 21 13:43:02 auth: Debug: conn unix:auth (pid=272670,uid=121) [263]:
client passdb out: OK    2    user=scanner@bogus.relay
May 21 13:44:33 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
sql: Performing passdb lookup
May 21 13:44:33 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [142]: Debug: sql: Performing passdb lookup
May 21 13:44:33 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [142]: Debug: sql: query: CALL
password_query('scanner@bogus.relay', '<super.secret>')
May 21 13:44:33 auth-worker(272356): Debug:
mysql(/var/run/mysqld/mysqld.sock): Finished query 'CALL
password_query('scanner@bogus.relay', '<super.secret>')' in 1 msecs
May 21 13:44:33 auth-worker(scanner@bogus.relay,1.2.3.4)<272356>:
request [142]: Debug: sql: Finished passdb lookup
May 21 13:44:33 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
sql: Finished passdb lookup
May 21 13:44:33 auth(scanner@bogus.relay,1.2.3.4,sasl:plain): Debug:
Auth request finished
May 21 13:44:33 auth: Debug: conn unix:auth (pid=272670,uid=121) [263]:
client passdb out: OK    4    user=scanner@bogus.relay
2026-05-21T13:37:32.531697-07:00 B914839
postfix/submission/smtpd[272474]: 81C5C60429: client=unknown[1.2.3.4],
sasl_method=PLAIN, sasl_username=scanner@bogus.relay
2026-05-21T13:38:39.842635-07:00 B914839
postfix/submission/smtpd[272474]: CDAEC60429: client=unknown[1.2.3.4],
sasl_method=PLAIN, sasl_username=scanner@bogus.relay
2026-05-21T13:43:02.410975-07:00 B914839
postfix/submission/smtpd[272670]: 644C360429: client=unknown[1.2.3.4],
sasl_method=PLAIN, sasl_username=scanner@bogus.relay
2026-05-21T13:44:33.790632-07:00 B914839
postfix/submission/smtpd[272670]: C0FB860429: client=unknown[1.2.3.4],
sasl_method=PLAIN, sasl_username=scanner@bogus.relay
2.4.1-4 (7d8c0e5759): /etc/dovecot/dovecot.conf
Pigeonhole version 2.4.1-4 (0a86619f)
OS: Linux 6.12.69+deb13-amd64 x86_64 Debian 13.5
Hostname: B914839.online-server.cloud
4 default setting changes since version 2.4.0
dovecot_config_version = 2.4.0
auth_debug = yes
auth_debug_passwords = yes
auth_mechanisms = plain login gssapi cram-md5 digest-md5
debug_log_path = /var/log/dovecot/debug.log
default_vsz_limit = 512M
dovecot_storage_version = 2.4.0
fts_autoindex = yes
fts_autoindex_max_recent_msgs = 999
fts_search_add_missing = yes
info_log_path = /var/log/dovecot/info.log
lda_mailbox_autocreate = yes
lda_mailbox_autosubscribe = yes
log_debug = category=auth
log_path = /var/log/dovecot/dovecot.log
mail_driver = maildir
mail_plugins {
quota = yes
}
mailbox_directory_name_legacy = no
protocols {
imap = yes
lmtp = yes
sieve = yes
}
quota_exceeded_message = User %{user} has exceeded the storage volume. /
User %{user} has exhausted allowed storage space.
sieve_plugins {
sieve_imapsieve = yes
sieve_extprograms = yes
}
sql_driver = mysql
ssl = required
namespace inbox {
inbox = yes
prefix =
separator = .
type = private
mailbox Drafts {
auto = subscribe
special_use = "\\Drafts"
}
mailbox Outbox {
special_use = "\\Drafts"
}
mailbox Junk {
auto = subscribe
special_use = "\\Junk"
}
mailbox "Junk Email" {
auto = no
special_use = "\\Junk"
}
mailbox "Junk E-mail" {
auto = no
special_use = "\\Junk"
}
mailbox Trash {
auto = subscribe
special_use = "\\Trash"
}
mailbox "Deleted Items" {
auto = no
special_use = "\\Trash"
}
mailbox Spam {
auto = no
special_use = "\\Junk"
}
mailbox Archives {
auto = no
special_use = "\\Archive"
}
mailbox Sent {
auto = subscribe
special_use = "\\Sent"
}
mailbox "Sent Items" {
auto = no
special_use = "\\Sent"
}
mailbox "Sent Messages" {
auto = no
special_use = "\\Sent"
}
}
service imap-login {
inet_listener imap {
}
inet_listener imaps {
}
}
service pop3-login {
inet_listener pop3 {
}
inet_listener pop3s {
}
}
service submission-login {
inet_listener submission {
}
inet_listener submissions {
}
}
service lmtp {
unix_listener /var/spool/postfix/private/dovecot-lmtp {
group = postfix
mode = 0600
user = postfix
}
}
service imap {
}
service pop3 {
}
service submission {
}
service auth {
unix_listener auth-userdb {
group = postfix
}
unix_listener /var/spool/postfix/private/auth {
group = postfix
mode = 0660
user = postfix
}
}
service auth-worker {
}
service dict {
unix_listener dict {
}
}
ssl_server {
cert_file = /etc/letsencrypt/live/mail.sutinen.com/fullchain.pem
key_file = /etc/letsencrypt/live/mail.sutinen.com/privkey.pem
}
protocol lda {
mail_plugins {
sieve = yes
quota = yes
}
}
protocol imap {
mail_plugins {
imap_sieve = yes
}
}
protocol lmtp {
mail_plugins {
quota = yes
sieve = yes
notify = yes
push_notification = yes
}
postmaster_address = postmaster@sutinen.com
}
service managesieve-login {
inet_listener sieve {
port = 4190
}
inet_listener sieve_deprecated {
port = 2000
}
}
service managesieve {
}
sieve_script personal {
active_path = /var/vmail/sieve/%{user | domain }/%{user | username
}/active-script.sieve
driver = file
path = /var/vmail/sieve/%{user | domain }/%{user | username }/scripts
type = personal
}
sieve_script spam-global {
path = /var/vmail/sieve/global/spam-global.sieve
type = before
}
mailbox Spam {
sieve_script spam {
cause = copy
path = /var/vmail/sieve/global/learn-spam.sieve
type = before
}
}
imapsieve_from Spam {
sieve_script ham {
cause = copy
path = /var/vmail/sieve/global/learn-ham.sieve
type = before
}
}
mysql /var/run/mysqld/mysqld.sock {
dbname = vmail
password = # hidden, use -P to show it
user = vmail
}
passdb sql {
driver = sql
query = CALL password_query('%{user}', '%{password}')
}
userdb sql {
driver = sql
query = CALL user_query_dovecot('%{user | username}', '%{user | domain}')
}