"auth_cache_verify_password_with_worker = yes" funktioniert nicht mit proxy

Theo Pannen pannen at 1blu.de
Mi Apr 15 13:04:08 CEST 2020 

Hallo,

ich habe eine reine Proxy-Konfiguration von der Version 2.2.22 auf 2.3.10 übertragen. Das funktioniert wie bisher

Wenn ich aber "auth_cache_verify_password_with_worker = yes" setzte funktioniert es nicht mehr.

Das erste Login geht noch, aber ab dem zweiten, wenn die Antwort aus dem Cache kommt, gibt es einen Fehler. Das Login (Passwort) wird aktzeptiert, aber dovecot sucht die Mailbox lokal.


Die Konfiguration von cache und proxy (von 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
}

Das SQL von /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


Logfile-Ausug mit "auth_cache_verify_password_with_worker = yes":

- Erstes Login von mail.log (funktioniert)

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>


- Weitere logins von mail.log (sucht lokal):

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

Da es ein reiner proxy ist, gib es keine userdb Konfiguration und keine lokalen User.
mail.err enthält deshalb folgenden Eintrag:

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)


- Weitere Logins ohne "auth_cache_verify_password_with_worker = yes" funktionieren wie erwartet:

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)


Irgendeine Idee?

Danke
Theo

Mehr Informationen über die Mailingliste Dovecot