diff options
Diffstat (limited to '')
| -rw-r--r-- | doc/wiki/Design.Events.txt | 264 |
1 files changed, 264 insertions, 0 deletions
diff --git a/doc/wiki/Design.Events.txt b/doc/wiki/Design.Events.txt new file mode 100644 index 0000000..c6df740 --- /dev/null +++ b/doc/wiki/Design.Events.txt @@ -0,0 +1,264 @@ +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) |