We were collecting the logs, printing them as we found them, and
then returning the sorted result.
That made it awkward for a human to review, so what we do now
is defer printing the logged records until after we have sorted
them.
For records with the same timestamp, we sort based on the message
id and the record type so that there is some additional consistency
and to make it easier to reason about.
Problem scenario: you have defined an automation rule with the
unanchored regex `detected an unusual rate` that triggers a suspension.
What happens: when the remote host initially responds and that
rule matches, a suspension will be created. When subsequent
messages are checked against that rule, the message will not
be attempted (good), but we will generate and log a transient failure
response of the form: `KumoMTA internal: suspended, rule: detected an
unusual rate`. When that response is presented to TSA, since the regex
is unanchored, the original rule will also match it, and that will
cause the duration to be reset, effectively perpetuating the suspension
until the combination of ingress and the retry window exceeds the
duration specified in the rule (bad).
You can explicity mark up your regex with an anchor to prevent
this sort of matching, but it is a PITA to do that for every
suspension rule.
This commit resolves this issue by recognizing that the default
should be to not match internally generated rules. The newly
introduced `match_internal` boolean defaults to false and controls
whether we should consider these internal messages, and allows
the matching to be turned on when needed. We use this in one
of the default shaping rules that is used to disable the use
of tls for broken hosts.
This commit addresses a couple of related issues around scheduled qeueue
suspensions:
1. There was no check in the ready queue logic to confirm that a
given message was not part of a suspension. Ideally, it wouldn't
land in the ready queue if it is suspended, but if you have a large
ready queue and one of the messages generates a suspension, then
the remainder would get attempted, oblivious to the new suspension.
The resolution here is to add a check for that case, log a transfail
and requeue the message.
2. We only checked whether the scheduled queue was suspended in the
case where a message was being newly inserted into the queuing
system. Importantly, messages being promoted from the scheduled
queue didn't use this code path. This commit fixes this up by
relocating the check to the appropriate location. In addition,
we now will log a transfail for this case and delay the message
according to its retry schedule.
3. Since we're in here changing the retry schedule for suspensions,
take the opportunity to take care of #293 which applies to the
more general logic around all sources being suspended.
The upshot of this is that we're now logging transfails in a number
of suspension cases where we weren't previously, and using the normal
retry schedule for those cases where we weren't previously doing
that either.
refs: https://github.com/KumoCorp/kumomta/issues/290
refs: https://github.com/KumoCorp/kumomta/issues/293
The reported behavior was that messages seemd to be retried much faster
than the retry schedule, and at a quick glance it looked like the
nxdomain code path didn't respest the backoff, but from hooking
up this test and making the durations longer, it really doesn't seem
like the issue was that simple:
refs: https://github.com/KumoCorp/kumomta/issues/271
This really is adding batching support to custom lua delivery
protocol handlers, but the main use case for these today is
to implement log hooks.
The way that it works is that you can specify a `batch_size`
as part of setting up the lua protocol handler.
Then, when it is time to send messages, if the batch_size is
the default of 1, the lua delivery logic will invoke the `send` method
on the connection object returned from the constructor. This
is the same as the behavior from before this commit.
However, if the batch_size is greater than 1, then the lua delivery
logic will instead attempt to collect up to batch_size messages
that are immediately available from the ready queue, and then pass
those to a new `send_batch` method.
The send_batch method accepts an array of messages; that array will
always have at least one message, and up to batch_size messages,
depending on the throughput and queue size.
If the send_batch method's return value applies equally to all
messages in the batch, so if it indicates that something failed,
that disposition will apply to all messages.
One of the reasons that I'd avoided implementing batching thus far
was that it makes it awkward to resolve persistent/recurring issues
that are due to a single message in that batch. If the batch is
always retried together then there is a good chance that it will
always fail together.
There's no explicit mitigation for that issue here, but it may
be probablistically mitigated by the jitter that is applied to
messages that transiently fail. If a batch transiently fails,
each message in that batch will be subject to its own random
jitter which should cause an offending message to be retried
with a different subset of messages next time around.
The integration test included here demonstrates the batching
working with an http log hook implementation.
I recently broke when adding the singleton maintainer task.
The nature of the issue is that the scheduled queue maintainers
are created and won't wake up to do any work for 1 day, or until
they get notified by an action like a rebind operation.
Why didn't the integration tests catch this obvious regression?
Because they didn't assert that we saw a specific number of attempts,
only that the mathmatical relationship between an arbitrary number
of records was correct.
As part of this, I found a similar sort of wakeup issue with the
skiplist queue, where adding the initial entry didn't wakeup
the queue because of the way that the Ord trait works on Option.
This commit addresses that as well.
As mentioned in a prior commit, when there are very large numbers
of scheduled queues (hundreds of thousands), the tokio timer/task
infrastructure becomes over-burdened and the system bogs down.
This commit introduces a SingletonTimerWheel strategy for the
scheduled queues. When this strategy is in use, each scheduled
queue maintains a local HashSet of Messages rather than an
individual wheel or skip list. The time ordering is instead
handled by a global singleton timerwheel that holds weak references
to the messages.
The definitive ownership of the Message belongs to the per-Queue
HashSet.
The global wheel ticks over once every 3 seconds for ALL queues
that have delayed messages, popping off the weak references
and attempting to upgrade them to a full Message reference.
From there, the message is resolved back to its containing queue,
and if it is found in the HashSet then it is reinserted into the
ready queue.
If either the upgrade or HashSet check fails then the message
has been either bounced or rebound and requires no further
processing.
This change makes the number of scheduled tasks for delayed
messages O(1), rather than O(number-of-queues), at the cost
of a small loss in precision of promoting the delayed messages
to the ready queue, and double the amount of Message handles;
previously it would be approx:
number-of-delayed-messages * sizeof(pointer)
now it is 2x that amount (~ + some misc overhead)
I don't plan to add a SingletonSkipList strategy: since the list is
global it can have potentially millions of delayed messages (the entire
server's delayed mail) so we really do want O(1) insertion for this
rather than the skip lists worse insertion complexity.
Since this change eliminates the maintainer task, we need an alternative
approach for processing configuration refreshes, so this commit moves
that out of the per-queue maintainer and into a separate task that wakes
up periodically to assess all scheduled queues to see if they are due
for a refresh (according to their individual refresh_intervals) and
perform the refresh.
This change makes the config refresh a sequential operation:
only the refresh task will zip through and perform the refreshes.
Previously, you could expect to see most/all of the qmaint threads
doing this.
Previously we were using only our timeq module, which is built on top of
hashed hierarchical timer wheels.
Timer wheels have O(1) insertion and removal which are excellent
properties for larger delayed queues.
However, they do not know how to answer the question "when is the
next item due", but only "what is due in the next tick".
The underlying timer wheel implementation assumes a 1ms granularity
which is a little bit at-odds with our pragmatic view of the scheduled
queue, which is "if it's in there, precision timing isn't important, and
it's generally fine to consider once per minute", requiring that we
either aggressively scheduled a maintainer task to wake up every 1ms per
scheduled queue (untenable!) or have it wake up no more than once per
second but ideally closer to once per minute to then tick however
milliseconds are necessary to advance the wheel to the current slot.
For small numbers of scheduled queues with sufficiently large retry
intervals this hasn't bubbled up as an issue so far, but it bothers
me that it isn't as efficient as it could be because we have to wake up
reasonably frequently to keep things ticking over, and that introduces
higher continual CPU utilization. It's small, but I worry about
the aggregate cost spread over very large numbers of scheduled queues.
What I really want here is a a timer wheel that I can tick with
arbitrary granularity and with that in mind I took a look at adapting
the handful of existing implementations and found that we're already
using the cleanest implementation, and it would take some effort that I
didn't really want to spend right now.
I opted for a reasonably simple alternative option, which is to adopt a
skiplist for the queue. This has O(log n) insertion to maintain ordering
with O(1) removal and can answer "when is the next item due". What this
means is that we pay a slightly higher insertion cost one-time in
exchange for being able to put the maintainer for the queue asleep until
we need it, and not have to keep waking up between times, which should
scale better.
What this means in practice is that we now wake up the maintainer either
when the next message is due, or once per minute to re-evaluate the
queue configuration hook, so we're slightly better off, but totally
where I'd like to be.
I've introduced a reap_interval (default 10 minutes) and a
refresh_interval (default 1 minute) as parameters in get_queue_config so
that you can increase that 1m interval for reloading.
What I'd like to do in a follow up commit is introduce a way to define
the refresh policy. For example, it would be neat to say "watch my
policy directory and refresh when it changes", which would make things
the most efficient for many users. For those that are loading their
config from a remote datasource, we'd need to consider some other
mechanism for this; maybe some kind of long-poll or pubsub, but will
obviously still be able to support the current interval based polling.
Now, with all of that said: I didn't want to switch the product
default over and hope for best, so what I did was add a strategy
option to allow this to be adopted on a per-queue basis.
Since I was in here adding some options, I also added an option
that allows explicitly setting the interval used for timerwheel
ticks, so you now have a lot more opportunities for tuning this
stuff.
We've been trying to run down a weird problem with the lapin
client where the system appears to get bogged down around lapin
and the submission rate goes through the floor. There no obvious
signs of a problem elsewhere in the system or in the logging,
so we're trying out an optional alternative client implementation.
This commit adds a "one-shot" publish function:
```
log_hooks:new {
name = 'amqp',
constructor = function(domain, tenant, campaign)
local sender = {}
local host, port = table.unpack(kumo.string.split(AMQP_HOST_PORT, ':'))
function sender:send(msg)
kumo.amqp.basic_publish {
routing_key = 'woot',
payload = msg:get_data(),
connection = {
host = host,
port = tonumber(port),
},
}
return '250 ok'
end
return sender
end,
}
```
behind the scenes we maintain a connection+channel pool for this.
This first pass doesn't support confirms, to the publish is
fire-and-forget; we assume that if there was no error while trying to
acquire the channel or returned immediately by the underlying
basic_publish function, that the server took the message and we're
done.
I was going to use mobc for the connection pooling here, since I just
implemented it for the recent redis client changes, but it triggered a
non-sensical panic around mobc's internal use of the metrics crate.
Upon further inspection, mobc appears to clobber certain metrics when
multiple Pools are in used, which makes it unsuitable for real world
use. That was the cause of the panic; I couldn't figure out the cause of
the panic. I switched to using the deadpool connection pooling crate
which has a similar API and doesn't panic. I will replace the use of
mobc in mod-redis with deadpool in a later commit.
I've introduced a place to stash the "global" tokio runtime that
is configured by `main` in `kumod` and `tsa-daemon`. That allows
us to bounce onto that runtime, rather than spawning an ad-hoc
single threaded runtime.
Since we're still preserving the existing client, this commit
introduces a new and slightly different integration test to
verify that publishing is operational from here.
Docs still need to be written up for this, but I want to put
this through its paces before doing that.
I'm expecting CI to not like this, as we're using the testcontainers
crate which spawns docker images to set up isolated server instances.
This is not directly compatible with our current CI environment.
So these tests are only enabled when KUMOD_TESTCONTAINERS=1 is
set in the environment.
The test sets up a rabbit instance, declares a queue, sets up simple log
hook in kumo, injects a message and then waits for it to process
through, then checks to receive a reception and delivery record.
To facilitate this, some adjustments needed to be made to the time
calculation in the maintainer because we previously didn't consider it
to be valid to have a retry_interval below 1 minute, but in order for
this integration test to be viable to run as part of the CI it needs to
run in significantly less time than 1 minute.
The approach taken here is to avoid considering 1 minute as the
baseline, but rather take 1/20th of the retry_interval. In the default
configuration, the numbers work out the same as previously, but they
will scale down as the retry_interval is reduced.
Care is taken to avoid a couple of borderline busy wait scenarios where
we might otherwise have woken up at unrealistically small intervals:
timeq can suggest 1ms in a few scenarios, and we just round those up to
the next second to avoid that.
It's worth noting that we do not consider the scheduled queue to be a
realtime, high granularity queue: anything that lands there is
considered to be bulk/batch and will be handled later: it isn't worth
prioritizing with high granularity because messages that land there are
generally not going to be delivered quickly.
As much as I'd love for tokio to be magic and figure everything
out, it doesn't and cannot do that.
In any complex system it is important to be able to control
and provision the various stages so that a certain QoS is met.
This commit expands the use of the various thread pools, and
adjusts them from always spawning num-cpus to a more balanced
set of sizes, so that not everything is competing with everything.
These sizes are configurable via env vars, but a preferably
configured during the `init` event via a handful of new lua
functions that must be called very early on.
More docs on these will appear in a later commit.
The default pool sizes are a function of the number of cores,
and are intended to balance receiving and sending functions
such that a throughput test should run without any significant
build up of the scheduled queue.
This commit also exposes the sizes of the thread pools and the
number of parked (idle) threads via prometheus.
When `log_arf` or `log_oob` are set to true with `relay_to=false`, we
now return a 550 error response for messages that are not ARF or OOB
reports. Previously, we would return a 250 response and silently drop
the message in this case, which gave the false impression that it was
accepted for relaying.
Expand integration test to explicitly assert that the right things
are allowed/denied/relayed/parsed.
We skip logging the 421 we generate while shutting down because
it feels a bit redundant; you'll see the server shutting down
in the journal anyway.
refs: https://github.com/KumoCorp/kumomta/issues/88
This commit connects the new websocket based suspension feed
up to shaping.lua. This allows ready-q suspensions to be
enacted in realtime, as well as sets things up to support
scheduled queue suspensions in a later commit.
refs: https://github.com/KumoCorp/kumomta/issues/113
As best as I can tell, this is a casualty of a last moment
code format/copy-pasta. All of the logic works correctly,
but the Reception log record didn't include the relay
disposition so the log_oob or log_arf flag didn't make it
to the logging layer.
This code isn't currently reachable (defaults to false), but allows
for a runtime selection between rustls and openssl-based tls.
refs: https://github.com/KumoCorp/kumomta/issues/8
This was a 2-in-1 issue really.
When a message line starts with a `.` we are required to encode it
by prefixing the line with an additional `.`, aka: "dot stuffing".
In our implementation of this we would unintentionally remap CRLF
to CR, and then fail to emit CRLF.CRLF at the end of the data
that we'd planned to send.
The result of this was that we're hang waiting for the remote host
to respond to our DATA, meanwhile, it was waiting for the end of
our data. We'd sit there until either side reached their respective
timeout for the data phase.
This commit fixes up both parts of this bug.
NOTE: macos is NOT a platform supported for production use!
This commit just enables basic build and test to facilitate
offline work when I'm travelling with a mac laptop.
There are important systems functions that are not implemented
in the macOS build.
Previously, you would do either:
`msg:set_meta('queue', 'smart.host.domain')`
or
`msg:set_meta('queue', '[10.0.0.1]')`
to override the effective domain for a message and cause it to be routed
to somewhere other than the recipient domain.
That was OK for basic smart hosting, but limiting when you wanted to use
multiple candidate hosts.
This commit expands the queue config `protocol` field to support
specifying an explicit list of MX hosts that should be used instead.
The integration tests have been migrated away from the old style to this
new style.
While adding plumbing for this, I uncovered an inconsistency between the
queue name generated for the ready queue and the name used by suspension
handling. The inconsistency was introduced in
0842a0fc8b and related work. This commit
resolves it.
These are two different groups of queues, so there are two different
sets of things to manage them.
kcli now has `suspend(-list|cancel)?` and
`suspend-ready-q(-list|cancel)?` subcommands for establishing a
suspension, listing the suspensions and cancelling a suspension
in the scheduled-q and ready-q namespaces respectively.
The names of the ready queues can be derived from the metrics API:
```console
$ curl -s 'http://localhost:8000/metrics.json' | jq .
...
"ready_count": {
"help": "number of messages in the ready queue",
"type": "gauge",
"value": {
"service": {
"smtp_client:source2->(in1-smtp|in2-smtp).messagingengine.com": 0.0
}
}
},
...
```
From the above, `source2->(in1-smtp|in2-smtp).messagingengine.com` is
the name of the underlying ready queue.
We can and probably should add something to `kcli` to make that slightly
easier to review and manage for the operator.
refs: https://github.com/KumoCorp/kumomta/issues/51
There were a few cases where client operations weren't wrapped
up in a timeout, which is a potential cause of hanging on shutdown:
if we're waiting an unbounded amount of time for a connection to
do something before we can shutdown, then we'll never finish.
The current timeouts struct really encodes the read timeout for
waiting for the result of a command.
What we also need is a duration to wait for sending data. We're
using the smaller of the per-command read timeout or 1 minute for
this.
Dirkjan Ochtman
Wez Furlong