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