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
