"auth_cache_verify_password_with_worker = yes" does not work with proxy

Theo Pannen pannen at 1blu.de
Thu Apr 2 14:06:39 EEST 2020 

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

More information about the dovecot mailing list