Adding upstream version 1:2.3.19.1+dfsg1.upstream/1%2.3.19.1+dfsg1upstream

Signed-off-by: Daniel Baumann <daniel.baumann@progress-linux.org>

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)