Previously, we would compare only the names of the pools when
updating the round robin source selection state.
That meant that if you change the composition of a pool by changing
either the number of the definition of its constituent sources,
that change may not take effect until the corresponding queues
had aged out.
This commit resolves this by comparing both the name and the
composition of the pool when deciding to rebuild the source
selection state.
I noticed while testing the throttle serialization commit
that precedes this one that my directly-in-the-lua-file config
changes weren't being picked up when the config epoch changed.
This commit revises the pooling logic to also check the epoch
in addition to the age of the pooled entries.
Prior to exposing max_burst in the throttle string parser, we
couldn't guarantee to represent any arbitrary throttle as a string,
so we serialized as the underlying struct fields.
That's a bit unwieldy to read, so let's switch to the string
representation.
This commit makes the string repr infallible (previously it could fail
if you had specified max_burst), then tackles the fanout from that.
Apparently none of our snapshot tests include any of these throttles,
so I manually spot checked it with `kcli inspect-sched-q` to observe
the `max_message_rate`.
This was always present, it just wasn't something we provided a syntax
to specify.
max_burst allows you to control how quickly your throttle budget will
be consumed over the throttle time period.
The default max_burst is equal to the limit you specify, allowing
the full budget to be instantaneously consumed.
refs: https://github.com/KumoCorp/kumomta/issues/326
We've been trying to run down an issue where a subset of messages
can get stuck in the scheduled queue. This has only occured in
a single deployment as far as we know; that deployment makes
use of the `requeue_message` event handler.
The identifying characteristics of the bad state are:
* `kcli inspect-sched-q` returns information about messages where
the due time is less than the `now` field in the inspect result.
* The scheduled queue depth for that queue is flat
I've been scratching my head over this, but I *think* the issue
is a race condition during insertion. The potential race was:
* [thread a] insert message to SINGLETON_WHEEL that is due immediately
* [wheel maintainer thread] pop due message from SINGLETON_WHEEL
* [wheel maintainer thread] verify that message is tracked by
queue-local hash <fail>
* [thread a] add message to queue-local hash, bump scheduled queue
counters
Those immediately due messages would sit there until a rebind forces
them to be reconsidered, or until kumod was restarted (with the same
overall effect).
The race condition could only trigger when:
* The message(s) being inserted are immediately due
* It is some multiple of 3 seconds since the singleton wheel was
started; that is how often it awakes to process the scheduled
queue timer wheel.
This commit re-orders things such that the queue-local hash is updated
prior to inserting into SINGLETON_WHEEL. The ordering is enforced
by the containing mutex.
We had a few too many "bland" NotConnected errors showing up in
transient failure logs; while it may have been technically
correct, it was lacking in context.
This commit replaces NotConnected in the read/write error paths
with Read/Write error variants that include the error message,
partial read (for Read errors) and the associated command/stage.
For pipelining errors, we can now dup this same state into each
of the command slots when considering the pipelining error as
well; previously we couldn't clone the error type because of
the (unused!) ssl error variant.
The CI flakes I've been running down are due to this:
```json
{"type":"TransientFailure","queue":"maildir","response":{"code":400,"enhanced_code":null,
"content":"failed to write to maildir: creating dirs for maildir /tmp/.tmpBi1p8H/maildir in queue maildir: File exists (os error 17)"}
```
which sounds like a race condition when multiple threads are trying
to create that maildir directory structure from scratch at the same
time.
This commit adds some error handling to catch and deal with this
appropriately.
It's more acceptable for the client to go nuts with its own memory usage
than it is for the server side to waste memory on trace data, so let's
allow it to buffer indefinitely while it is busy formatting the output.
When we output just a single line of data, there is no need
to also emit another line with its length. This was a side effect
of adding terse mode to the client side.
Now that we're doing the terse processing server side, the
non-Abbreviated cases are never actually terse-processing eligible
on the client (assuming that the client and server version match),
so having the byte length summary presented there is especially
noticeable.
We can simply elide it by trimming off trailing whitespace.
Previously we'd simply drop the connection. With this behavior we now
emit an error to the journal (once per tracer session) and emit a
diagnost to the client (each time) whenever some number of events
were dropped by the internal broadcast channel.
This adds a way for the lower level dispatcher impl to communicate
back up to the higher level that the session is done and can be
closed out without treating it as a connection failure.
For SMTP the criteria for this is that, if we ever got as far
as MAIL FROM, then we consider that the connection was established
OK and that means that if we subsequently reach a point where we need to
connect again, then it must be due to an earlier policy issue that was
already recorded as a transient failure.
In that circumstance, if we have not more hosts to connect to, we
will indicate that we terminated "OK".
This works because the upper level checks for this state before
asking the session to connect again.
If there are more addresses that could be tried, we will report a
connection failure for the next message picked up by the session;
this commit only changes the behavior for the case where there
are no more addresses left in the current connection plan.
A customer reported a really long log record like:
```
KumoMTA internal: failed to connect to any candidate hosts: TLS
handshake failed: tls handshake eof, will re-connect in the clear
because opportunistic_tls_reconnect_on_failed_handshake=true, TLS
handshake failed: tls handshake eof ...
```
the site in question had just a single address in its connection plan.
I don't see how we could loop like this unless the cache that is
used to indicate that TLS is broken is being thrashed and the value
that we write to it in response to this event triggering is
never actually sticking in the cache.
This commit introduces a per-session variable to flag that TLS
is broken for this particular site, so that we don't have to rely
on the cached value when we're about to loop and retry.
I'm investigating an issue where a block of messages appear to be stuck
in a scheduled state. In looking at the math here, I'm wondering if it
is possible for some overflow to happen when converting from chrono
to std time types, so adjust the logic to be less prone to such a thing,
if it is occurring.
This controls what we do in an smtp session when we experience a
disconnect during message sending; do we give up on the session,
continue with the connection plan, or try to connect to the same
host again and continue sending any additional messages there?
In the smtp client we internally map IO and timeout errors into
a NotConnected state and break its internal socket, prevent it
from trying to talk to a broken session.
In the dispatcher layer that sits above it, when we consider
whether we need to open a connection, we look only to see if
we have a connection open or not.
If that connection is in a broken state we would keep trying to
use it, because we didn't consider that it might have such
an internal broken state.
This commit fixes up that logic so that we realize that it is
broken, and allow us to move to the next host in the connection
plan.
For the read code paths: if we experience an IO error or timeout,
ensure that we break the socket so that we don't try to reuse it
in the future, like we do for (most of) the write code paths.
For the write code paths, there were a couple of missing spots
where we didn't guarantee to break the socket, so ensure that
we do by centralizing all writes through a newly factored function
for that purpose.
Ensure that we log a diagnostic to the tracer for IO and timeout errors.
Generate a Closed event for the tracer whenever we break the socket.
Remove ClientError::Io, as we want to standardize on NotConnected
for the IO error case. This highlighted that flushing the socket
could also generate an IO error, so add the same sort of diagnostic
trace, socket break and error code mapping there for that as well.
This is to avoid always running into a postfix load shedding
strategy where it categorizes RSET as a junk command and will
reject the transaction.
https://www.postfix.org/STRESS_README.html
Previously, when using pipelining, we'd still send the individual
commands one by one, resulting in potentially multiple packets over the
wire, then we'd read the command responses back.
This was really only taking advantage of half of what pipelining offers,
by avoiding the read stalls between each of the pipelined commands.
What this commit does is to pre-format those writes into a single buffer
so that we have a single logical send which stands a good chance of
being transmitted as a single packet on the wire. (TLS may complicate
this in practice).
This should make a marginal improvement in latency, but it may also help
to address some flakiness in the integration tests that we part of
df8bb0f3ae, where we sometimes see the
disconnect without reading the 421 response back. My theory for those
is that, due to noisy neighbors on the CI system, we stand a good chance
of hitting a write error when writing out the later commands in the
pipeline, after the one that triggered a 421 in the peer, if that has
had time to propagate the shutdown back to us already.
98a5479ce9 changed the logic around
pipelining error handling in a subtle way: it switched from sequentially
considering both the transport and protocol errors for each of the
pipelined commands to eager consideration of transport errors, before
considering any transport errors.
In a situation where the remote host issues a 421 response to the MAIL
FROM that is part of our pipeline of (RSET, MAIL FROM, RCPT TO, DATA),
rather than reporting a 421 response to MAIl FROM, we'd end up bubbling
up the NotConnected error from RCPT TO, leading to the miscategorization
and so on that was improved in caadc0e7e8
This commit fixes up this situation by:
* Ensuring that we pad out the number of results from pipeline_commands
to match the number of commands, synthesizing NotConnected errors
for the remaining slots if we experience a transport error.
* Check for any transport error and adjust the logic to essentially
prefer handling a protocol error from an earlier stage, rather
than taking the transport error. This allows the transport-success
(eg: peer didn't disconnect) case to continue to defer acting upon
any protocol errors until we have the full set of protocol responses
back, so that we can handle the obscure but important DATA case that
was the original intent behind the changes in
98a5479ce9
Previously, we'd just drop the socket without a care about any
pending data that might be buffered up inside it.
The next commit depends on seeing the 421 from the integration test,
but because of the drop, we'd just see a rustls error about the peer
disconnecting without sending close-notify.
This commit adds a graceful shutdown to the 421 rejection case.
The logic in this part of the ready_queue is to loop while we have
messages, and work through the connection plan.
There are a few cases in the lower level smtp_dispatcher that don't
directly manipulate the disposition of a message if something goes
wrong. The logic at that layer will bubble up an error with the
expectation that the ready_queue looping logic will try again
on another connection.
What actually happened was that the error propagated up and the
message would get "silently" re-queued (with the recent Delay
logging, we'd get a DispatcherDrop record for the context).
This isn't desirable because the visibility into what happened
is low, and also because the action being taken isn't necessarily
in alignment with what smtp_dispatcher thinks is happening.
What this commit does is to catch the error case (instead of
letting it propagate) and log a transient failure.
This handles the visibility side of this issue.
We'll tackle the mismatched expectations in a follow-on commit.
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.
Only the first would take effect because the rule_hash we
computed included all of the actions, so each individual
action would appear to be a duplicate of the first.
This commit ensures that we vary the hash per-action
to avoid this, and augments the integration test
to explicitly verify the result.
The changes in e4b743cb8f to improve
memoize performance could cause the error message above because
the __newindex method wasn't actually writing the new value to
the unshared table, it was returning the existing value!
Most of this commit is really plumbing to support calling through the
cache layers in the same way that the listener would use, but in the
context of the unit tests in the lua file.
A nice side effect of this plumbing is that it is now possible
to iterate (via pairs) and index fields of the main config
objects that are returned by the most common `kumo.make_xxx`
functions.
Wez Furlong
ncai
Nathalie Caiandncai
Mike Hillyer