dovecot - Sep 2020 - auth_passdb_request_finished request fires twice on IMAP login

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

> On 19/09/2020 18:14 Eirik Rye <rye at trojka.no> wrote:
> 
>  
> 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:
<snip/>
> 
> Best regards,
> Eirik
You can add 

category = service:auth 

to your metric to make it fire only once.

Aki