How to use mail_user_session_finished? (was Re: [Dovecot-news] Dovecot v2.3.19 released)

[Sylvain Robitaille]

On Tue, 10 May 2022, Aki Tuomi via Dovecot-news wrote:

> + Added mail_user_session_finished event, which is emitted when the mail
>  user session is finished (e.g. imap, pop3, lmtp). It also includes
>  fields with some process statistics information.
>  See https://doc.dovecot.org/admin_manual/list_of_events/ for more
>  information.

We thought that this might give us some useful information in our logs,
especially when investigating user complaints (thanks, by the way, both
for Dovecot itself, and for the new logging functionality).  I added to
our 10-logging.conf file:

    --- .../10-logging.conf 2022-02-02 09:53:52.000000000 -0500
    +++ .../10-logging.conf 2022-05-11 16:40:48.116914000 -0400
    @@ -44,8 +44,13 @@ plugin {
       #mail_log_events = delete undelete expunge copy mailbox_delete
mailbox_rename
       #mail_log_events = mailbox_delete mailbox_rename
       # 2022-01-02 Anne Bennett: per RT#461889, log more
    -  mail_log_events = delete undelete expunge copy mailbox_delete
mailbox_rename append flag_change
    +  # 2022-05-11 Sylvain Robitaille: per RT#478860, log new
    +  #            mail_user_session_finished event
    +  mail_log_events = delete undelete expunge copy mailbox_delete
mailbox_rename append flag_change mail_user_session_finished
       # Available fields: uid, box, msgid, from, subject, size, vsize, flags
       # size and vsize are available only for expunge and copy events.
    -  mail_log_fields = uid box msgid size
    +  # mail_user_session_finished adds: utime, stime, minor_faults,
    +  #    major_faults, vol_cs, invol_cs, rss, vsz, rchar, wchar, syscr,
    +  #    syscw
    +  mail_log_fields = uid box msgid size rss vsz
     }

... and reloaded ("dovecot reload"), following which the log
informed me:

    May 11 16:56:45 lust dovecot: master: Warning: SIGHUP received - reloading configuration
    May 11 16:56:46 lust dovecot: imap(syl)<27995><X6CKJb/eMpSEzQLZ>: Disconnected: Server shutting down. in=20441 out=1721757 deleted=42
expunged=40 trashed=0 hdr_count=89 hdr_bytes=147223 body_count=81 body_bytes=1504010
    ...
    May 11 16:58:05 lust dovecot: imap-login: Login: user=<syl>, method=GSSAPI, rip=132.205.2.217, lip=132.205.96.89, mpid=26509, TLS, session=<td6lssLenKKEzQLZ>
    May 11 16:58:05 lust dovecot: imap(syl)<26509><td6lssLenKKEzQLZ>: Fatal: Unknown field in mail_log_fields: 'rss'

Hrmmm ... Ok, remove "rss" and reload:

    May 11 16:58:44 lust dovecot: master: Warning: SIGHUP received - reloading configuration
    May 11 16:58:50 lust dovecot: imap-login: Login: user=<syl>, method=GSSAPI, rip=132.205.2.217, lip=132.205.96.89, mpid=26573, TLS, session=<e/hRtcLepKKEzQLZ>
    May 11 16:58:50 lust dovecot: imap(syl)<26573><e/hRtcLepKKEzQLZ>: Fatal: Unknown field in mail_log_fields: 'vsz'

Not what I was expecting, of course, but can we at least see the
events logged?  remove "vsz" and reload again:

    May 11 16:59:02 lust dovecot: master: Warning: SIGHUP received - reloading configuration
    May 11 16:59:06 lust dovecot: imap-login: Login: user=<syl>, method=GSSAPI, rip=132.205.2.217, lip=132.205.96.89, mpid=26606, TLS, session=<BuVBtsLepqKEzQLZ>
    May 11 16:59:06 lust dovecot: imap(syl)<26606><BuVBtsLepqKEzQLZ>: Fatal: Unknown event in mail_log_events: 'mail_user_session_finished'

Alright, remove mail_user_session_finished and reload, and it's ok
again.  I *must* be doing something wrong here, but I can't figure
out what that it, and it seems that mail_user_session_finished has not
reached any of the documentation within the source tree.  Can someone
point me to documentation for how to use this?  Am I jumping the gun
here, or am I just doing it wrong?

-- 
----------------------------------------------------------------------
Sylvain Robitaille                               syl at encs.concordia.ca

Systems analyst / AITS                            Concordia University
Faculty of Engineering and Computer Science   Montreal, Quebec, Canada
----------------------------------------------------------------------