This documentation is for Dovecot v2.x, see wiki1 for v1.x documentation.

Events (v2.3+)

Dovecot v2.3 introduces "events", which improves both logging and statistics. See Events for list of all events.

Each logging call can be attached to a specific event, which can provide more metadata and context than just the log message string. This will eventually allow implementing things like machine-parseable (e.g. JSON) log lines containing key=value pairs, while still keeping the human readable text available. Each logging event can also be captured and sent to stats, even if it's not actually logged. Commonly statistics-related events are logged with debug level.

Events have:

Events are hierarchical, so they can have parent events. The events always inherit all of their parents' categories and fields. A child event can replace a parent's field, and it can also remove a parent's field with event_field_clear(). Ideally most events would have a parent hierarchy that reaches the top event that was created for the current user/session. This allows statistics to track which events happened due to which users. In some cases this may not really be possible, such as an HTTP connection that is shared across multiple users in the same process. Generic libraries should take the parent event in function parameters or in a settings struct or similar.

An event's lifetime is usually the same as the "object" it attaches to. For example an IMAP client connection should have a single event created at the beginning of the connection and destroyed at disconnection. The IMAP client connection event could be used for logging things like "Client connected" and "Client disconnected" and perhaps some other connection-specific events. However, most of the logging should be done by new events that have the IMAP client connection event as their parent. For example IMAP command event should exist during the execution of the IMAP command, and its parent should be the IMAP client connection event. Note that there's an automatic "duration" statistics field that is calculated from the creation of the event to the (last) sending of the event, so for it to make sense the event lifetime and its logging also needs to make sense. So for example if the IMAP client connection event was used for logging many things throughout the session, the "duration" field would make little sense for most of those events.

Events are "sent" by logging it. Any e_debug(), e_info(), e_warning() or e_error() call will also send the event, which may be redirected to the stats process. Often events that are intended for statistics are sent using the e_debug() call. The event can be sent to statistics even if it's not actually logged. Avoid sending events excessively. For example an e_debug() call every time connection reads or writes something will likely result in a huge amount of unnecessary debug logging.

Event names

Events that are expected to be used in statistics should have a name. Be consistent when naming the events. The name's prefix should be the subsystem that is logging the event. Usually this would be the primary category of the event. For example imap related events should begin with "imap_" and mailbox related events begin with "mailbox_".

The name should consist of only [a-z], [0-9] and '_' characters.

Current naming conventions for name suffixes:

Categories

The event categories are hierarchical. For example "mail" category has parent "mailbox", which has parent "storage". If an event filter contains "category:storage", it will match the "mail" and "mailbox" child categories as well.

Note that a category isn't the same as a service/process name. So for example imap process has an "imap" category for its IMAP-related events, such as IMAP client connection and IMAP command related events. Because most events would be child events under these IMAP events, they would all inherit the "imap" category. So it would appear that using "category:imap" filter would match most of the logging from imap process. However, there would likely be some events that wouldn't have the IMAP client as their parent event, so these wouldn't match the imap category.

The same category name must not be duplicated within the process. This is because event handling is optimized and performs category checking by comparing the categories' pointers, not names' strings. (Then again, if the struct event_category variable names were consistent, you'd get duplicate symbol errors from linker as well.)

Be careful naming events that go through client and server boundaries. For example if both lib-dns and dns service use "dns" as their category and also have identically named "dns_lookup" event, there's no easy way to differentiate in event filters between these two. So a statistics filter could end up counting each DNS lookup twice. Since it's more difficult to remember to check for event naming conflicts, it would be safer to use different category names entirely.

The category name should consist of only [a-z], [0-9] and '_' characters.

Fields

Each event can have any number of key=value fields. Parent event's fields are inherited by the child event.

There are 3 types of fields:

The fields can be used for various purposes:

Field names should be consistent across the code. Besides making it easier for admins to configure the events, this allows statistics code to sum up fields from different unrelated events. For example if all the networking events include "ip", "bytes_in" and "bytes_out" fields, statistics can globally track how much network traffic Dovecot is doing from its own point of view, regardless of whether it's HTTP traffic or IMAP traffic or something else.

Current naming conventions:

Note that events shouldn't be sent every time when receiving/sending network traffic. Instead, the bytes_in/out fields should be updated internally so that whenever the next event is sent it will have an updated traffic number.

Generally it's not useful for events to be counting operations. Rather each operation should be a separate event, and the statistics code should be the one counting them. This way statistics can only be counting e.g. operations with duration > 1 sec. If the statistics code was seeing only bulk operation counts this wouldn't be possible. The bytes_in/out and such fields are more of an exception, because it would be too inefficient to send individual events each time those were updated.

Note that even though internally updating a field for an event's parent will be immediately visible to its children, the update won't be automatically sent to the stats process. We may need to fix this if it becomes a problem.

Field inheritance may become problematic also when multiple nested ioloops are used. For example an outgoing imapc connection could receive a reply, which synchronously triggers an outgoing quota SQL connection. The quota SQL connection's parent event likely shouldn't be the imapc connection's event, because otherwise they could be mixing the IP/port fields and perhaps others. This isn't necessarily a problem though, but this is why when connection.c performs outgoing UNIX socket connection it clears the IP/port fields to make sure they don't exist for the connection event due to inheritance from a parent event.

Passthrough events

Passthrough events' main purpose is to make it easier to create temporary events as part of the event parameter in e_error(), e_warning(), e_info() or e_debug(). These passthrough events are automatically freed when the e_*() call is finished. Because this makes the freeing less obvious, it should be avoided outside e_*()'s event parameter.

A passthrough event's creation timestamp is the same as the parent event's timestamp, because its intention is to only complement it with additional fields. This way the generated event "duration" field is preserved properly.

The passthrough events also change the API to be more convenient towards being used in a parameter. Instead of having to use e.g.

event_add_str(event_set_name(event_create(parent), "name"), "key", "value")

The event_passthrough API can be a bit more readable as:

event_create_passthrough(parent)->set_name("name")->add_str("key", "value")->event().

The passthrough event is converted to a normal event at the end with the event() call. Note that this API works by modifying the last created passthrough event, so it's not possible to have multiple passthrough events created in parallel.

Log prefixes

Events allow replacing the current log prefix or appending to it. This way for example opening a mailbox can add a "Mailbox <name>: " prefix and then use e_debug(box->event, ...) without having to specify the mailbox name in every log message.

Global events

Sometimes there's not really any specific event that a log message would belong to, or it would be difficult to transfer the event there. In these cases the old i_debug(), i_info(), i_error(), etc. logging calls can still be used. These will be using the global event and its logging prefix.

The global events are pushed/popped in a stack. For example with IMAP the initial global event is the user's event. During IMAP command execution the global event is the IMAP command event.

Design/Events (last edited 2018-08-30 11:58:35 by TimoSirainen)