path: root/doc/wiki/Design.Events.txt

Events (v2.3+)
==============

Dovecot v2.3 introduces "events", which improves both logging and statistics.
See <Events.txt> 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:

 * Categories, such as "storage", "mailbox" or "auth".
 * Fields, such as 'user=foo@example.com' or 'service=imap'.
 * Creation timestamp with microsecond precision.
 * Source code file and line number location when sending the event.
 * It may have an easy human-readable name. This is important for events that
   are expected to be used for statistics, so they can be easily referred to.
 * "Forced debug"-flag. Debug logging is enabled for this event regardless of
   the global debug log filters. A child event will inherit this flag.

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:

 * _connected (for connections)
 * _disconnected (for connections)
 * _finished (when some operation finishes, e.g. IMAP command or HTTP request)
    * e.g. http_request_finished, dns_request_finished, imap_command_finished
    * This should be used regardless of whether the operation succeeded or
      failed. The details would be in fields.
 * _retried (if an operation is internally retried one or more times before
   it's finished)

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:

 * strings
 * numbers (intmax_t = signed 64bit usually)
 * timestamp (struct timeval)

The fields can be used for various purposes:

 * Filtering events with field_name=value matching
 * Counting fields in statistics (most commonly number fields)
 * They can include metadata that are internally used by the code. For example
   passing data from one plugin to others.
 * Later on these fields can be used by the logging system.

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:

 * The name should consist of only [a-z], [0-9] and '_' characters.
 * Timestamps should have "_time" suffix
 * Durations should have "_usecs" suffix and be in microseconds.
    * Try to avoid adding extra duration fields for most events. There's the
      automatic "duration" field already that contains how long the event has
      existed. So usually the event lifetime should be the same as the wanted
      duration field.
 * Incoming TCP/IP connections should have "remote_ip", "remote_port",
   "local_ip" and "local_port" fields
 * Outgoing TCP/IP connections should have "ip" and "port" for the remote side.

    * For local side "client_ip" and "client_port" may optionally be used
    * NOTE: These are all different from incoming connection's IP/port fields.
      This is because often everything starts from an incoming connection,
      which will be used as the root event. So we may want to filter e.g.
      outgoing HTTP events going to port 80 which were initiated from IMAP
      clients that connected to port 993 (port=80 local_port=993)
 * Connection reads/writes should be counted in "bytes_in" and "bytes_out"
   fields
    * These fields were chosen over e.g. network_in/out because a lot of code
      is rather generic and can work over TCP/IP or UNIX sockets, or maybe even
      any other kind of iostreams. Using a generic bytes_in/out makes it
      simpler to count these. If further differentiation is wanted on
      statistics side, networking events can be filtered out with "ip".
    * These fields are usually easiest updated with 'event_add_int(event,
      "bytes_in", istream->v_offset)' and 'event_add_int(event, "bytes_out",
      ostream->offset)'. If iostreams aren't used, 'event_inc_int()' maybe be
      easier.
 * (Local) disk reads should have "disk_read" and "disk_write" fields
    * With remote filesystems like NFS it may be difficult to differentiate
      between disk IO and network IO. Generally the disk_read/write should be
      used for POSIX read() and write() calls from filesystem.
    * Counting only read()s and write()s doesn't necessarily translate to
      actual disk IO since it may only be accessing the kernel page cache.
      Still, this may be useful.
    * There is a lot of disk IO performed all over the code, so Dovecot will
      likely never include events for all disk reads/writes.
 * error=<value> : The operation failed. The <value> may be simply "y" or
   contain more details. This field shouldn't exist at all for successful
   operations.
 * error_code=<value> : Machine-readable error code for a failed operation. If
   set, the "error" field must also be set.

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.

(This file was created from the wiki on 2019-06-19 12:42)