Hi,
Dovecot v2.3.11.3 (502c39af9)
auth_passdb_request_finished appears to fire twice for an IMAP login using a Redis passdb. auth_request_finished only fires once.
In the debug log below, the line "Finished passdb lookup" appears to be logged twice (once by "auth" and once by "auth-worker"). However, the actual passdb lookup against Redis is only performed once. This is confirmed by monitoring queries made against Redis.
Configuration:
metric auth_passdb_request_finished { event_name = auth_passdb_request_finished }
auth_debug = yes passdb { auth_verbose = yes override_fields = proxy=y name = redis driver = dict args = /etc/dovecot/dovecot-redis.conf.ext }
With the above configuration, I am seeing the auth_passdb_request_finished metric being incremented twice for every successful login:
/ # doveadm stats dump metric_name field count sum min max avg median stddev %95 auth_passdb_request_finished duration 0 0 0 0 0.00 0 0.00 0 / # curl imap://localhost -u foo:bar -XNOOP / # doveadm stats dump metric_name field count sum min max avg median stddev %95 auth_passdb_request_finished duration 2 20327 6240 14087 10163.50 10163 3923.50 14087
This is the (anonymized) debug output emitted for the above commands:
Sep 19 15:03:32 auth: Debug: client in: AUTH 1 PLAIN service=imap secured session=msC166uvOL0K9HPG lip=127.0.0.1 rip=127.0.0.1 lport=143 rport=48440 resp=<hidden> Sep 19 15:03:32 auth: Debug: redis(foo,127.0.0.1,<msC166uvOL0K9HPG>): Performing passdb lookup Sep 19 15:03:32 auth-worker(76): Debug: conn unix:auth-worker (pid=30,uid=90): auth-worker<3>: Handling PASSV request Sep 19 15:03:32 auth-worker(76): Debug: redis(foo,127.0.0.1,<msC166uvOL0K9HPG>): Performing passdb lookup Sep 19 15:03:32 auth-worker(76): Debug: redis(foo,127.0.0.1,<msC166uvOL0K9HPG>): Lookup: shared/users/foo = {"user":"foo","password":"{SHA256-CRYPT}[...]","host":"other_host","uid":1000,"home":"\/mail\/foo"} Sep 19 15:03:32 auth-worker(76): Debug: redis(foo,127.0.0.1,<msC166uvOL0K9HPG>): Finished passdb lookup Sep 19 15:03:32 auth-worker(76): Debug: conn unix:auth-worker (pid=30,uid=90): auth-worker<3>: Finished Sep 19 15:03:32 auth: Debug: redis(foo,127.0.0.1,<msC166uvOL0K9HPG>): Finished passdb lookup Sep 19 15:03:32 auth: Debug: auth(foo,127.0.0.1,<msC166uvOL0K9HPG>): Auth request finished Sep 19 15:03:32 auth: Debug: client passdb out: OK 1 user=foo proxy host=other_host uid=1000 home=/mail/foo hostip=127.0.0.2 pass=<hidden>
Best regards, Eirik
Eirik