thr3ads.net - dovecot - "auth_cache_verify_password_with_worker = yes" does not work with proxy [Apr 2020]

If this information is useful, please help other people find it:
Share via:
Theo Pannen
2020-Apr-02 11:06 UTC
"auth_cache_verify_password_with_worker = yes" does not work with proxy

Hello,

i use a proxy only configuration with version 2.2.22 (Ubuntu 16.04) and have now
transferred it to version 2.3.10. This works as before.

But as soon as i use "auth_cache_verify_password_with_worker = yes",
it does not work anymore.
The first login still works, but from the second one, where the answer comes
from the cache, there is an error. The login is still accepted but dovecot
searches the mailbox locally.

The configuration for cache and proxy (from dovecot -n):

auth_cache_verify_password_with_worker = yes
auth_cache_negative_ttl = 0
auth_cache_size = 64 M

passdb {
  args = /etc/dovecot/dovecot-sql.conf.ext
  driver = sql
}

The sql from /etc/dovecot/dovecot-sql.conf.ext:

password_query = SELECT pwdCrypt AS password, \
                        NULL AS nopassword, \
                        'MyMasterUser' AS master, \
                        'MyMasterPass' AS pass, \
                        ipv4address AS host, \
                        '%u' AS destuser, \
                        'Y' AS proxy \
                  FROM mailbox \
                  WHERE user = '%u' AND activeFlg = '1' LIMIT 1


The logfile extracts with "auth_cache_verify_password_with_worker =
yes":

- First Login from mail.log (work's)

Apr  2 12:27:11 mf-19 dovecot: auth: Debug: client in:
AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=6fZiPkyiWHJSZMhl#011lip=178.254.4.122#011rip=93.200.174.28#011lport=143#011rport=29272#011local_name=mf-19.1blu.de#011ssl_cipher=TLS_AES_128_GCM_SHA256#011ssl_cipher_bits=128#011ssl_pfs=KxANY#011ssl_protocol=TLSv1.3
Apr  2 12:27:11 mf-19 dovecot: auth: Debug: client passdb out: CONT#0111
Apr  2 12:27:11 mf-19 dovecot: auth: Debug: client in: CONT<hidden>
Apr  2 12:27:11 mf-19 dovecot: auth: Debug:
sql(testuser,93.200.174.28,<6fZiPkyiWHJSZMhl>): Performing passdb lookup
Apr  2 12:27:11 mf-19 dovecot: auth: Debug:
sql(testuser,93.200.174.28,<6fZiPkyiWHJSZMhl>): cache miss
Apr  2 12:27:11 mf-19 dovecot: auth-worker(18978): Debug: Loading modules from
directory: /usr/lib/dovecot/modules/auth
Apr  2 12:27:11 mf-19 dovecot: auth-worker(18978): Debug: Module loaded:
/usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so
Apr  2 12:27:11 mf-19 dovecot: auth-worker(18978): Debug: Module loaded:
/usr/lib/dovecot/modules/auth/libdriver_mysql.so
Apr  2 12:27:11 mf-19 dovecot: auth-worker(18978): Debug: conn unix:auth-worker
(pid=18976,uid=109): Server accepted connection (fd=16)
Apr  2 12:27:11 mf-19 dovecot: auth-worker(18978): Debug: conn unix:auth-worker
(pid=18976,uid=109): Sending version handshake
Apr  2 12:27:11 mf-19 dovecot: auth-worker(18978): Debug: conn unix:auth-worker
(pid=18976,uid=109): auth-worker<1>: Handling PASSV request
Apr  2 12:27:11 mf-19 dovecot: auth-worker(18978): Debug:
sql(testuser,93.200.174.28,<6fZiPkyiWHJSZMhl>): Performing passdb lookup
Apr  2 12:27:11 mf-19 dovecot: auth-worker(18978): Debug:
sql(testuser,93.200.174.28,<6fZiPkyiWHJSZMhl>): query: SELECT pwdCrypt AS
password, NULL AS nopassword, 'MyMasterUser' AS master,
'MyMasterPass' AS pass, ipv4address AS host, 'testuser' AS
destuser, 'Y' AS proxy FROM    mailbox WHERE user = 'testuser'
AND activeFlg = '1' LIMIT 1
Apr  2 12:27:11 mf-19 dovecot: auth-worker(18978): Debug:
sql(testuser,93.200.174.28,<6fZiPkyiWHJSZMhl>): Finished passdb lookup
Apr  2 12:27:11 mf-19 dovecot: auth-worker(18978): Debug: conn unix:auth-worker
(pid=18976,uid=109): auth-worker<1>: Finished
Apr  2 12:27:11 mf-19 dovecot: auth: Debug:
sql(testuser,93.200.174.28,<6fZiPkyiWHJSZMhl>): Finished passdb lookup
Apr  2 12:27:11 mf-19 dovecot: auth: Debug:
auth(testuser,93.200.174.28,<6fZiPkyiWHJSZMhl>): Auth request finished
Apr  2 12:27:11 mf-19 dovecot: auth: Debug: client passdb out:
OK#0111#011user=testuser#011master=MyMasterUser#011pass=<hidden>#011host=10.1.2.3#011destuser=testuser#011proxy
Apr  2 12:27:11 mf-19 dovecot: imap-login: proxy(testuser): started proxying to
10.1.2.3:143 (master MyMasterUser): user=<testuser>, method=PLAIN,
rip=93.200.174.28, lip=178.254.4.122, TLS, session=<6fZiPkyiWHJSZMhl>


- Further logins from mail.log (searches locally):

Apr  2 12:27:18 mf-19 dovecot: auth: Debug: client in:
AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=L4PQPkyi7plSZMhl#011lip=178.254.4.122#011rip=93.200.174.28#011lport=143#011rport=39406#011local_name=mf-19.1blu.de#011ssl_cipher=TLS_AES_128_GCM_SHA256#011ssl_cipher_bits=128#011ssl_pfs=KxANY#011ssl_protocol=TLSv1.3
Apr  2 12:27:18 mf-19 dovecot: auth: Debug: client passdb out: CONT#0111
Apr  2 12:27:18 mf-19 dovecot: auth: Debug: client in: CONT<hidden>
Apr  2 12:27:18 mf-19 dovecot: auth: Debug:
sql(testuser,93.200.174.28,<L4PQPkyi7plSZMhl>): Performing passdb lookup
Apr  2 12:27:18 mf-19 dovecot: auth: Debug:
sql(testuser,93.200.174.28,<L4PQPkyi7plSZMhl>): cache hit:
<hidden>#011master=MyMasterUser#011pass=MyMasterPass#011host=10.1.2.3#011destuser=testuser#011proxy=Y
Apr  2 12:27:18 mf-19 dovecot: auth: Debug:
sql(testuser,93.200.174.28,<L4PQPkyi7plSZMhl>): cache: validating password
on worker
Apr  2 12:27:18 mf-19 dovecot: auth-worker(18978): Debug: conn unix:auth-worker
(pid=18976,uid=109): auth-worker<2>: Handling PASSW request
Apr  2 12:27:18 mf-19 dovecot: auth-worker(18978): Debug: conn unix:auth-worker
(pid=18976,uid=109): auth-worker<2>: Finished
Apr  2 12:27:18 mf-19 dovecot: auth: Debug:
sql(testuser,93.200.174.28,<L4PQPkyi7plSZMhl>): Finished passdb lookup
Apr  2 12:27:18 mf-19 dovecot: auth: Debug:
auth(testuser,93.200.174.28,<L4PQPkyi7plSZMhl>): Auth request finished
Apr  2 12:27:18 mf-19 dovecot: auth: Debug: client passdb out:
OK#0111#011user=testuser
Apr  2 12:27:18 mf-19 dovecot: auth: Debug: master in:
REQUEST#011219414529#01118975#0111#011f78b3499f7157a5daf7eb2050cd79e60#011session_pid=18980#011request_auth_token
Apr  2 12:27:18 mf-19 dovecot: auth: Debug:
static(testuser,93.200.174.28,<L4PQPkyi7plSZMhl>): Performing userdb
lookup
Apr  2 12:27:18 mf-19 dovecot: auth: Debug:
static(testuser,93.200.174.28,<L4PQPkyi7plSZMhl>): Finished userdb lookup
Apr  2 12:27:18 mf-19 dovecot: auth: Debug: master userdb out:
USER#011219414529#011testuser#011#011auth_mech=PLAIN#011auth_token=e6819f7eac20f6520440abd937322ff13618741f
Apr  2 12:27:18 mf-19 dovecot: imap-login: Login: user=<testuser>,
method=PLAIN, rip=93.200.174.28, lip=178.254.4.122, mpid=18980, TLS,
session=<L4PQPkyi7plSZMhl>
Apr  2 12:27:18 mf-19 dovecot:
imap(testuser)<18980><L4PQPkyi7plSZMhl>: Debug: Added userdb
setting: plugin/=yes

Because it is pure proxy there is no userdb configuration and no local user.
mail.err therefore contains the error message:

Apr  2 12:27:18 mf-19 dovecot:
imap(testuser)<18980><L4PQPkyi7plSZMhl>: Error: Couldn't drop
privileges: User is missing UID (see mail_uid setting)


- Further logins without "auth_cache_verify_password_with_worker =
yes" works as expected:

Apr  2 12:31:46 mf-19 dovecot: auth: Debug: client in:
AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=9cvDTkyi7XxSZMhl#011lip=178.254.4.122#011rip=93.200.174.28#011lport=143#011rport=31981#011local_name=mf-19.1blu.de#011ssl_cipher=TLS_AES_128_GCM_SHA256#011ssl_cipher_bits=128#011ssl_pfs=KxANY#011ssl_protocol=TLSv1.3
Apr  2 12:31:46 mf-19 dovecot: auth: Debug: client passdb out: CONT#0111
Apr  2 12:31:46 mf-19 dovecot: auth: Debug: client in: CONT<hidden>
Apr  2 12:31:46 mf-19 dovecot: auth: Debug:
sql(testuser,93.200.174.28,<9cvDTkyi7XxSZMhl>): Performing passdb lookup
Apr  2 12:31:46 mf-19 dovecot: auth: Debug:
sql(testuser,93.200.174.28,<9cvDTkyi7XxSZMhl>): cache hit:
<hidden>#011master=MyMasterUser#011pass=MyMasterPass#011host=10.1.2.3#011destuser=testuser#011proxy=Y
Apr  2 12:31:46 mf-19 dovecot: auth: Debug:
sql(testuser,93.200.174.28,<9cvDTkyi7XxSZMhl>): Finished passdb lookup
Apr  2 12:31:46 mf-19 dovecot: auth: Debug:
auth(testuser,93.200.174.28,<9cvDTkyi7XxSZMhl>): Auth request finished
Apr  2 12:31:46 mf-19 dovecot: auth: Debug: client passdb out:
OK#0111#011user=testuser#011master=MyMasterUser#011pass=<hidden>#011host=10.1.2.3#011destuser=testuser#011proxy
Apr  2 12:31:46 mf-19 dovecot: imap-login: proxy(testuser): started proxying to
10.1.2.3:143 (master MyMasterUser): user=<testuser>, method=PLAIN,
rip=93.200.174.28, lip=178.254.4.122, TLS, session=<9cvDTkyi7XxSZMhl>
Apr  2 12:32:37 mf-19 dovecot: auth-worker(19036): Debug: conn unix:auth-worker
(pid=19032,uid=109): Disconnected: Connection closed (fd=-1)


Did I forget something in the configuration or is this a bug?

Thanks
Theo
Apparently Analagous Threads

Search for more maybe matching threads
dovecot - Apr 2020 - "auth_cache_verify_password_with_worker = yes" does not work with proxy

"auth_cache_verify_password_with_worker = yes" does not work with proxy

Apparently Analagous Threads

Wisdom of the Ancients
