Dovecot 2.1 and 2.2 had a relatively straightforward statistics system (which I believe may still be supported in 2.3 for now, although you have to rename settings in your configuration). In v2.3, Dovecot introduced a new, more flexible system based around the idea of events, which can be used to generate either or both of statistics or log messages. Today I'm going to talk about log messages, because they're simpler.

As an illustrative example, suppose that you want to emit a log message with the mailbox name (and sundry other details) any time someone SELECTs or EXAMINEs a mailbox other than the default IMAP INBOX, so that you can know what mailboxes your users are using (note that there are privacy implications here). First, we need a event exporter, which is the bit that will actually log things:

event_exporter log_tab {
   format = tab-text
   transport = log
   format_args = time-rfc3339
}

This is fairly straightforward and there is nothing hard to follow about it in the documentation. The 'tab-text' format produces a log line composed of tab-separated 'name=value' fields, instead of JSON, and it's what you probably want to use unless you already have a robust system for handling JSON payloads in syslog messages. However this somewhat depends on how you consume these log messages. If you access them directly through the systemd journal on Linux systems, the tabs will be actual tabs; if you get them through syslog on some systems, the tabs will be recorded as '#11', which is more ambiguous and harder to deal with.

(Dovecot may get additional format options in the future, and perhaps additional log options, such as logging to a file.)

To create specific log messages that will be logged through our exporter, you define a 'metric' (a statistic) and tell Dovecot it should also be logged as an event through your exporter. This looks like this:

metric imap/log/select {
  filter = event=imap_command_finished AND \
           tagged_reply_state=OK AND \
           (cmd_name = "SELECT" OR cmd_name = "EXAMINE") \
           AND NOT mailbox = "INBOX"

  fields = user cmd_name \
           mailbox duration \
           bytes_in bytes_out session remote_ip

  exporter = log_tab
  exporter_include = timestamps fields
}

Having Dovecot include 'timestamps' in the exporter data gives you both the start time and the end time of the event, with high precision. The 'fields' setting covers what data from the event you want to be logged. What data is available has to be researched from the Events documentation. You'll often want the IMAP command finished, IMAP command, and IMAP client documentation. The 'filter' statement narrows down what we log to just what we care about, as covered in Event Filtering.

I've given this 'metric' such an odd name because that name causes it to be excluded from the OpenMetrics format exporter for statistics, if you set one up. If you're exporting metrics to Prometheus (which can happily scrape Dovecot's OpenMetrics format), you probably don't want metrics for things you only set up for logging purposes. Giving your logging 'metrics' illegal OpenMetrics names keeps them out naturally. The statistics generated from these logging 'metrics' can (and will) still be listed out manually with 'doveadm stats dump' and the like.

It may be useful for experimentation to log absolutely every event that you can, which is handy to see what events exist in practice for sessions and what useful data they have. In that case, you want to select all events and not restrict what the event logs, so that it implicitly logs everything.

metric log/all {
  filter = event=* \
           AND NOT event=mail_cache_lookup_finished
  exporter = log_tab
}

(There's no point in restricting what's included in the log message. If you're searching through events, you want everything except perhaps the local hostname.)

I've excluded the mail cache lookup event here because it's really noisy if you include them, making it hard to pick out other event types that are useful to log. You may find you want to exclude other event types as well for this sort of exploration, and you certainly don't want to run this in production unless you enjoy having your logs explode.

If you go through this exercise, you'll find out some interesting and disappointing things. For example, in the current Dovecot 2.3.16 that's in Ubuntu 22.04, there is no event emitted for the end of an IMAP session, although Dovecot will log its own summary line for the session. There is an event for the end of POP3 connections, if you (still) care about them (we do for reasons outside the scope of this entry).

(To save me from ever having to look it up, the POP3 disconnection event is 'server_connection_disconnected' with the category 'service:pop3'.)