TL;DR: you can easily halve your system performance by logging headers
vs. logging meta.
This is one of those things that is easy to overlook or forget,
but: whenever you need to operate on the message data, rather
than its metadata, the aggregate cost is high.
In this case, we were recently troubleshooting a system where
the CPU was bogged down and we traced it to the logging configuration: a
number of message headers were being logged in a configuration that
made heavy use of throttles and limits in its traffic shaping, and
thus had a large number of Delayed and TransientFailure events being
written to the logs.
When logging headers, each one of those events requires loading
the message from the spool and parsing out the headers. When the
average message size is ~100KB this imposes a notable overhead
on the CPU and IO utilization of the system.
What we recommend instead of logging headers directly is capturing
the information that you want to log into the message metadata
at the time that the message is received.
The message meta is usually already loaded, but is also typically
much smaller and easier to decode than the full message content
in the cases where it is not loaded.
As a result, it is much cheaper to log meta than to log headers.
This commit adds some warnings and cross links to help folks
be aware of this, and to generally navigate related meta and logging
topics more easily via tags.
The purpose of this record is to log additional context about why
a message might end up in the scheduled queue when it hasn't
logged a TransientFailure.
There are a few situations around handling throttles and limits
where we might put a message back into the scheduled queue, without also
logging a TransientFailure record. It's possible that we should
reconsider some of those, but for the moment, there is an observability
hole that needs to be filled.
What this commit does is introduce an `InsertContext` which can hold one
or more `InsertReason`s about why a message is being inserted into the
scheduled queue.
There are 3 primary reasons for insertion:
* Received - the message was just received/injected
* Enumerated - the message was discovered in spool enumeration
* DueTimeWasReached - the message is now due for delivery and is being
popped off the scheduled queue
The additional reasons can be added to the context to provide more
color about what happened.
When a message is added to the scheduled queue, the accumulation
in the InsertContext is examined, and if the context doesn't
indicate that the message was Enumerated and it wasn't also
already logged as a TransientFailure, a `Delay` record is
logged.
The `Delay` record includes in its `response.content` the ordered set of
InsertReasons as well as the delay duration and due time.
Logging Delay records might place undesirable pressure on the
logging storage, so you may wish to disable it via:
```lua
kumo.configure_local_logs {
per_record = {
Delay = {
-- Suppress Delay records
enable = false
}
}
}
```
or similar.
Change the field from a SocketAddr to a struct with distinct fields:
```json
// For SMTP delivery, the source address (and port) that was used.
// (*Since: Dev Builds Only*)
"source_address": {
// The source address. The port number may be unknown and reported
// as zero when using a proxy protocol.
"address": "10.0.0.1:53210",
// If a proxy protocol was used, this field will be
// set to its name. It may be null/not set for no proxy,
// "haproxy" or "socks5".
"protocol": "socks5",
// If a proxy protocol was used, this field will be
// set to the proxy server address. It will be null/not set
// when no proxy was used.
"server": "192.168.1.1:5000"
},
```
In #154, the request was to log configuration information here, but I
opted against this as there can be a number of different configuration
fields and the combinatorics for future changes make me uncomfortable
from a code maintainance perspective--it will already be heavy to
try to pass thu all of the existing config information, and as we
add more options in the future it will be awful not just to look at,
but also from a memory and storage overhead.
The approach taken here is to make a little struct that is flexible
enough to convey the desired information without it being too much of a
burden.
closes: #40closes: #154
Wez Furlong
Ryan Bonnell