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

On 12/05/2022 01:15 Sylvain Robitaille wrote:

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>: 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= May 11 16:58:50 lust dovecot: imap(syl)<26573>: 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@encs.concordia.ca

Hi! Can you provide us with the configuration you attempted? AKi