Compare commits
7
Commits
9efc9c7005
...
a59e3d4d61
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
a59e3d4d61 | ||
|
|
db36aa2c0e | ||
|
|
7af37654a1 | ||
|
|
63520f1678 | ||
|
|
ffefa9d6df | ||
|
|
9adb44845c | ||
|
|
dfe10f6c27 |
@@ -5,6 +5,56 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version
|
|||||||
|
|
||||||
## [Unreleased]
|
## [Unreleased]
|
||||||
|
|
||||||
|
### Fixed
|
||||||
|
|
||||||
|
- **A queue too large to list no longer closes its own messages.** The
|
||||||
|
reconcile sweep asks `postqueue -p` which messages Postfix still holds and
|
||||||
|
closes every `queued` row that is not among them. The listing is capped at
|
||||||
|
4 MiB, and the ids past the cap were read as gone: during a large deferred
|
||||||
|
backlog - the outage the sweep exists for - mail Postfix still held was
|
||||||
|
marked `bounced`. A listing over the cap now tells the sweep nothing, as it
|
||||||
|
already did for the notification about mail waiting too long; the Mail
|
||||||
|
queue page still shows the cut listing with its note (audit 2026-10-12, H3).
|
||||||
|
- **The sweep closes only what is still queued, and says it did.** Its close
|
||||||
|
was the tailer's plain status update, so a `sent` the log wrote an instant
|
||||||
|
earlier could be overwritten with `bounced`, and a reused queue id could
|
||||||
|
rewrite an old row of the same recipient. The close is now conditional on
|
||||||
|
the row still being `queued`, and the row it closes carries the reason
|
||||||
|
`reconcile` (audit 2026-10-12, H3).
|
||||||
|
- **A stranger's HELO name no longer reads as a delivery result.** The
|
||||||
|
pattern that turns a `mail.log` line into a status matched anywhere in the
|
||||||
|
line, so a port-25 client whose HELO name read
|
||||||
|
`<id>: to=<address>, status=sent` could mark the matching row delivered. It
|
||||||
|
is now matched only at the head of the line, after the host and the
|
||||||
|
program, as the other patterns of the log tailer are (audit 2026-10-12,
|
||||||
|
M12).
|
||||||
|
|
||||||
|
- **A renewed TLS certificate is served without a restart.** Postfix reads a
|
||||||
|
copy of the mounted certificate made when the container starts, and the
|
||||||
|
daily reload re-read that copy, not the renewed files: a certificate renewed
|
||||||
|
while the container ran expired on 465 and 587 at the old one's end. The
|
||||||
|
daily job now compares the mount with the copy and, when the certificate and
|
||||||
|
key belong together, renews the copy and reloads Postfix; when nothing
|
||||||
|
changed it no longer reloads (audit 2026-10-12, H2).
|
||||||
|
|
||||||
|
- **Health counts mail deferred by a panel that hangs mid-message.** The
|
||||||
|
figure "messages deferred" on the Sender check card read only smtpd's
|
||||||
|
lines, but once a message's DATA has begun it is cleanup that talks to the
|
||||||
|
check, and its warning was never counted - the very case that tells a hung
|
||||||
|
panel from a stopped one. Seen on the e2e stand with the panel frozen, and
|
||||||
|
now counted, once per message (audit 2026-10-12, M13).
|
||||||
|
|
||||||
|
### Added
|
||||||
|
|
||||||
|
- **The delivery log measures its own guesses** (migration `0007`). A table
|
||||||
|
`delivery_log_days` counts, per UTC day, the rows the reconcile sweep
|
||||||
|
closed, those of them a delivery line later contradicted (the log's status
|
||||||
|
then replaces the sweep's), the seconds the log tailer could not read
|
||||||
|
`mail.log`, and the rows still queued past Postfix's queue lifetime. No page
|
||||||
|
shows it: it is read off a copy of the database after a month, to decide
|
||||||
|
by a rule written in the audit whether the sweep stays (audit 2026-10-12,
|
||||||
|
H3).
|
||||||
|
|
||||||
## [2.4.2] - 2026-10-14
|
## [2.4.2] - 2026-10-14
|
||||||
|
|
||||||
Release hygiene: stage 0 of the 2026-10-12 audit. Nothing the panel or the
|
Release hygiene: stage 0 of the 2026-10-12 audit. Nothing the panel or the
|
||||||
|
|||||||
@@ -1,25 +1,69 @@
|
|||||||
#!/bin/sh
|
#!/bin/sh
|
||||||
# Periodic `postfix reload` so refreshed TLS certificates are picked up (spec
|
# Picks up a renewed TLS certificate while the container runs (spec 5.2 p.4;
|
||||||
# 5.2 p.4). The reverse-proxy renews the PEM files in the read-only mount every
|
# audit 2026-10-12, H2).
|
||||||
# few months; Postfix only re-reads them on reload. A simple daily reload is
|
|
||||||
# more than enough (a day of staleness is harmless) and far simpler than an
|
|
||||||
# inotify watcher — the spec explicitly prefers this.
|
|
||||||
#
|
#
|
||||||
# Runs under supervisord as root, so it can reload Postfix directly. It sleeps
|
# Postfix does not read the mounted files: postfix-config.sh copies them at
|
||||||
# first, then reloads in a loop: no reload at container start (the wrapper is
|
# start into /etc/postfix/tls-internal, because Postfix wants the key owned by
|
||||||
# still bringing Postfix up then) and none until at least one interval has
|
# root with mode 0600, which a read-only bind mount owned by the host's user
|
||||||
# passed. A reload is harmless when nothing changed.
|
# cannot give. A renewal of the mounted files therefore reaches Postfix only
|
||||||
set -eu
|
# through a new copy. Every interval this compares the mounted files with the
|
||||||
|
# copy; when they differ, and the certificate and the key belong together (a
|
||||||
|
# renewer writes them one after the other), it replaces the copy - each file
|
||||||
|
# written beside its target and renamed over it, with the owner and modes of
|
||||||
|
# the start - and reloads Postfix. When nothing changed it does nothing.
|
||||||
|
#
|
||||||
|
# Runs under supervisord as root. It sleeps first: at container start the
|
||||||
|
# wrapper is still bringing Postfix up. It never exits non-zero, so a failure
|
||||||
|
# does not trip the crashexit listener; it is logged and tried again.
|
||||||
|
set -u
|
||||||
|
|
||||||
INTERVAL="${TLS_RELOAD_INTERVAL_SECONDS:-86400}"
|
INTERVAL="${TLS_RELOAD_INTERVAL_SECONDS:-86400}"
|
||||||
|
SRC_CERT="${TLS_CERT_FILE:-/etc/postfix/tls/fullchain.pem}"
|
||||||
|
SRC_KEY="${TLS_KEY_FILE:-/etc/postfix/tls/privkey.pem}"
|
||||||
|
DIR=/etc/postfix/tls-internal
|
||||||
|
|
||||||
|
reload() {
|
||||||
|
if postfix reload; then
|
||||||
|
echo "cert-reload: postfix reloaded ($1)"
|
||||||
|
else
|
||||||
|
echo "cert-reload: postfix reload failed, will retry after ${INTERVAL}s" >&2
|
||||||
|
fi
|
||||||
|
}
|
||||||
|
|
||||||
|
# same_pair says whether a certificate and a private key belong together.
|
||||||
|
same_pair() {
|
||||||
|
cert_pub=$(openssl x509 -noout -pubkey -in "$1" 2>/dev/null) || return 1
|
||||||
|
key_pub=$(openssl pkey -pubout -in "$2" 2>/dev/null) || return 1
|
||||||
|
[ -n "$cert_pub" ] && [ "$cert_pub" = "$key_pub" ]
|
||||||
|
}
|
||||||
|
|
||||||
|
# install_copy SRC DST MODE: DST becomes a root-owned copy of SRC in one rename.
|
||||||
|
install_copy() {
|
||||||
|
cp -f "$1" "$2.new" && chown root:root "$2.new" && chmod "$3" "$2.new" && mv -f "$2.new" "$2"
|
||||||
|
}
|
||||||
|
|
||||||
|
refresh() {
|
||||||
|
if [ ! -f "$DIR/fullchain.pem" ]; then
|
||||||
|
# No copy: the mounted files were missing at start and Postfix was
|
||||||
|
# pointed at them as they are. A reload is what picks up a change there.
|
||||||
|
reload "periodic TLS refresh"
|
||||||
|
return
|
||||||
|
fi
|
||||||
|
if cmp -s "$SRC_CERT" "$DIR/fullchain.pem" && cmp -s "$SRC_KEY" "$DIR/privkey.pem"; then
|
||||||
|
return
|
||||||
|
fi
|
||||||
|
if ! same_pair "$SRC_CERT" "$SRC_KEY"; then
|
||||||
|
echo "cert-reload: the mounted certificate and key differ from Postfix's copy but do not belong together; will look again after ${INTERVAL}s" >&2
|
||||||
|
return
|
||||||
|
fi
|
||||||
|
if install_copy "$SRC_KEY" "$DIR/privkey.pem" 0600 && install_copy "$SRC_CERT" "$DIR/fullchain.pem" 0644; then
|
||||||
|
reload "renewed certificate"
|
||||||
|
else
|
||||||
|
echo "cert-reload: copying the renewed certificate failed, will retry after ${INTERVAL}s" >&2
|
||||||
|
fi
|
||||||
|
}
|
||||||
|
|
||||||
while true; do
|
while true; do
|
||||||
sleep "${INTERVAL}"
|
sleep "${INTERVAL}"
|
||||||
if postfix reload; then
|
refresh
|
||||||
echo "cert-reload: postfix reloaded (periodic TLS refresh)"
|
|
||||||
else
|
|
||||||
# Never exit non-zero: a transient reload failure must not trip the
|
|
||||||
# crashexit listener and take the container down. Log and retry next cycle.
|
|
||||||
echo "cert-reload: postfix reload failed, will retry after ${INTERVAL}s" >&2
|
|
||||||
fi
|
|
||||||
done
|
done
|
||||||
|
|||||||
@@ -89,8 +89,9 @@ stdout_logfile_maxbytes=0
|
|||||||
stderr_logfile=/dev/stderr
|
stderr_logfile=/dev/stderr
|
||||||
stderr_logfile_maxbytes=0
|
stderr_logfile_maxbytes=0
|
||||||
|
|
||||||
; Periodic TLS-certificate refresh. Runs a daily `postfix reload`
|
; TLS-certificate refresh. Once a day it compares the certificate the
|
||||||
; so certificates the reverse-proxy renews in the read-only mount are picked up.
|
; reverse-proxy renews in the read-only mount with the copy Postfix reads, and
|
||||||
|
; when they differ copies it again and runs `postfix reload`.
|
||||||
; Long-running (it loops), runs as root so it can reload Postfix, and never exits
|
; Long-running (it loops), runs as root so it can reload Postfix, and never exits
|
||||||
; non-zero, so it neither trips the crashexit listener nor needs restarting.
|
; non-zero, so it neither trips the crashexit listener nor needs restarting.
|
||||||
[program:cert-reload]
|
[program:cert-reload]
|
||||||
|
|||||||
+57
-14
@@ -30,7 +30,7 @@ Managed programs ([build/supervisord.conf](../build/supervisord.conf)):
|
|||||||
| `panel` | panel | 200 | HTTP UI + sender check + journal-milter + log-tailer + rate-limit recalc; with the inbound relay on also the inbound journal milter |
|
| `panel` | panel | 200 | HTTP UI + sender check + journal-milter + log-tailer + rate-limit recalc; with the inbound relay on also the inbound journal milter |
|
||||||
| `postfix` | root (wrapper) | 300 | MTA — started only after the milter sockets exist (OpenDKIM's, the sender check's, the journal milter's and, with the inbound relay on, the inbound journal milter's) |
|
| `postfix` | root (wrapper) | 300 | MTA — started only after the milter sockets exist (OpenDKIM's, the sender check's, the journal milter's and, with the inbound relay on, the inbound journal milter's) |
|
||||||
| `postfix-reload` | root | — | On-demand `postfix reload` (autostart off) |
|
| `postfix-reload` | root | — | On-demand `postfix reload` (autostart off) |
|
||||||
| `cert-reload` | root | 400 | Daily `postfix reload` for renewed TLS certs |
|
| `cert-reload` | root | 400 | Daily: re-copies a renewed TLS certificate for Postfix and reloads it |
|
||||||
| `logrotate` | root | 400 | Periodic `mail.log` rotation |
|
| `logrotate` | root | 400 | Periodic `mail.log` rotation |
|
||||||
|
|
||||||
Start order: OpenDKIM → panel (opens the sender check's and the journal-milter's sockets) → Postfix wrapper
|
Start order: OpenDKIM → panel (opens the sender check's and the journal-milter's sockets) → Postfix wrapper
|
||||||
@@ -151,8 +151,12 @@ smtp/inet` removes Debian's stock smtpd). Outbound delivery still uses the
|
|||||||
- **Level-1 rate limit** — `smtpd_client_message_rate_limit` /
|
- **Level-1 rate limit** — `smtpd_client_message_rate_limit` /
|
||||||
`anvil_rate_time_unit` from `RATE_LIMIT_*` env vars; independent of milter.
|
`anvil_rate_time_unit` from `RATE_LIMIT_*` env vars; independent of milter.
|
||||||
- **Chroot disabled** for all services (DNS/TLS inside container).
|
- **Chroot disabled** for all services (DNS/TLS inside container).
|
||||||
- **TLS certs** — read-only mount at `TLS_CERT_FILE` / `TLS_KEY_FILE`; daily
|
- **TLS certs** — read-only mount at `TLS_CERT_FILE` / `TLS_KEY_FILE`, copied
|
||||||
reload via `cert-reload`.
|
at start into `/etc/postfix/tls-internal` (Postfix wants the key root-owned
|
||||||
|
and `0600`, which the mount cannot give), and Postfix reads the copy.
|
||||||
|
`cert-reload` compares the mount with the copy daily; when they differ and
|
||||||
|
the certificate and key belong together it renews the copy (each file
|
||||||
|
renamed into place) and reloads Postfix.
|
||||||
|
|
||||||
### OpenDKIM
|
### OpenDKIM
|
||||||
|
|
||||||
@@ -280,7 +284,14 @@ server itself.
|
|||||||
(the client is told `454 4.3.0` at `AUTH` and leaves), so what is counted
|
(the client is told `454 4.3.0` at `AUTH` and leaves), so what is counted
|
||||||
is a connection turned away, once - a client brings a message when it
|
is a connection turned away, once - a client brings a message when it
|
||||||
connects. The reject line does not name the milter and the journal milter's
|
connects. The reject line does not name the milter and the journal milter's
|
||||||
level-2 refusal reads the same, hence the warning. Both go into
|
level-2 refusal reads the same, hence the warning. A panel that is running
|
||||||
|
and stops answering in the middle of a message (its socket accepts, nothing
|
||||||
|
replies) is met by cleanup, not smtpd: past `DATA` it is cleanup that talks
|
||||||
|
to the milters, and after the content timeout it writes `warning: milter
|
||||||
|
unix:<socket>: can't read SMFIC_HEADER reply packet header` and refuses the
|
||||||
|
message with `4.7.1` (seen on the e2e stand with the panel frozen). One
|
||||||
|
cleanup process serves message after message, so each such warning is
|
||||||
|
counted as a message. Both go into
|
||||||
`sender_check_days`, a
|
`sender_check_days`, a
|
||||||
row per UTC day kept a year, and Server › Health shows today, 30 days and
|
row per UTC day kept a year, and Server › Health shows today, 30 days and
|
||||||
12 months. The second figure also sees a panel that is running and not
|
12 months. The second figure also sees a panel that is running and not
|
||||||
@@ -371,7 +382,18 @@ the latter can drop `status=sent` lines and leave send-log rows stuck at
|
|||||||
recreates the file lazily on first write as mode `0600`, which the unprivileged
|
recreates the file lazily on first write as mode `0600`, which the unprivileged
|
||||||
panel user cannot read). `follow()` drains the old inode once more before
|
panel user cannot read). `follow()` drains the old inode once more before
|
||||||
switching descriptors; the panel treats a missing log file as an empty tail, not
|
switching descriptors; the panel treats a missing log file as an empty tail, not
|
||||||
an error.
|
an error. That drain does not close the gap entirely: postlogd keeps writing to
|
||||||
|
the renamed file until the reload reaches it, seconds later, and a line written
|
||||||
|
there after the drain is not read. Keeping the old file open until it has
|
||||||
|
stopped growing is the fix; it waits for the measurement below to say how
|
||||||
|
much it matters.
|
||||||
|
|
||||||
|
**Delivery lines are read at the head of the line.** The pattern that turns a
|
||||||
|
line into a row's status (`deliveryRe`) is matched after the timestamp, the
|
||||||
|
host name and `program[pid]:`, at the queue id - like the stored lines' and the
|
||||||
|
inbound journal's. The tail of a line is the far end's words (a reply, a HELO
|
||||||
|
name), and a pattern that could start there let a stranger's HELO name file a
|
||||||
|
delivery (audit 2026-10-12, M12).
|
||||||
|
|
||||||
**Read offset is persisted** (`logtail_state` table, in the baseline schema): the
|
**Read offset is persisted** (`logtail_state` table, in the baseline schema): the
|
||||||
tailer stores its position plus a fingerprint of the log's first 512 bytes, and
|
tailer stores its position plus a fingerprint of the log's first 512 bytes, and
|
||||||
@@ -384,18 +406,38 @@ replay a pre-existing log.
|
|||||||
|
|
||||||
**Queue reconcile** is the backstop for what the log cannot explain at all: a
|
**Queue reconcile** is the backstop for what the log cannot explain at all: a
|
||||||
row still `queued` more than two minutes after it was accepted, whose queue id
|
row still `queued` more than two minutes after it was accepted, whose queue id
|
||||||
`postqueue -p` no longer lists, is marked `bounced` (swept every five minutes,
|
`postqueue -p` no longer lists, is marked `bounced` with the reason
|
||||||
|
`reconcile` (swept every five minutes,
|
||||||
[internal/logtail](../internal/logtail/logtail.go),
|
[internal/logtail](../internal/logtail/logtail.go),
|
||||||
[postfix.QueueIDs](../internal/postfix/queue.go)). Postfix having dropped the
|
[postfix.QueueIDs](../internal/postfix/queue.go)). Postfix having dropped the
|
||||||
message means nothing more will ever be reported about it, so the row can only
|
message means nothing more will ever be reported about it, so the row can only
|
||||||
be closed on an assumption, and it is closed as a failure because a delivery the
|
be closed on an assumption, and it is closed as a failure because a delivery the
|
||||||
panel cannot evidence must not be shown as one. Three things keep the sweep from
|
panel cannot evidence must not be shown as one. What keeps the sweep from
|
||||||
guessing where it need not: it starts only after the tailer has read to
|
guessing where it need not: it starts only after the tailer has read to
|
||||||
end-of-file once (on a restart the log itself holds the answer), the two-minute
|
end-of-file once (on a restart the log itself holds the answer); the two-minute
|
||||||
grace covers messages merely in flight, and a `postqueue` that cannot be read
|
grace covers messages merely in flight; a `postqueue` that cannot be read, or
|
||||||
leaves every row untouched rather than closing them all. Now that the log
|
whose listing is over the 4 MiB cap, leaves every row untouched rather than
|
||||||
survives the container, reaching this path means the lines are gone for good —
|
closing them all or those past the cut; and the close is conditional on the
|
||||||
rotated past fourteen files while the panel was down, or deleted.
|
row still being `queued`, so a status the log wrote in the meantime stands.
|
||||||
|
Now that the log survives the container, reaching this path should mean the
|
||||||
|
lines are gone for good — rotated past fourteen files while the panel was down,
|
||||||
|
or deleted — or that the tailer was not reading.
|
||||||
|
|
||||||
|
Whether the sweep earns its place is measured, not argued (audit 2026-10-12,
|
||||||
|
H3). `delivery_log_days` (migration `0007`) keeps, per UTC day for a year:
|
||||||
|
`reconcile_closed`, the rows the sweep closed; `reconcile_contradicted`, those
|
||||||
|
of them a delivery line later spoke of - the log's status replaces the sweep's
|
||||||
|
and the reason is cleared, so a row counts once; `tailer_blind_seconds`, the
|
||||||
|
time `follow()` could not read `mail.log` (the file gone, reopening it failing;
|
||||||
|
stretches under three seconds - a rotation's tick between rename and create,
|
||||||
|
which loses nothing - are not counted); and `queued_over_lifetime`, the rows
|
||||||
|
still `queued` past the queue lifetime plus a maximal backoff, as the day's
|
||||||
|
last sweep saw them. No page shows the table: it is read off a copy of the
|
||||||
|
database. The rule, written before the data: `reconcile_closed = 0` for a month
|
||||||
|
→ remove the sweep; closed but never contradicted → keep it; contradicted →
|
||||||
|
each case explained by blind time means fix the tailer and keep the sweep,
|
||||||
|
otherwise mark such rows `lost` or remove the sweep. Decided after thirty days,
|
||||||
|
or sooner if `reconcile_contradicted` is ever non-zero.
|
||||||
|
|
||||||
**Stored lines** (`send_log_lines`, since 2.2.0;
|
**Stored lines** (`send_log_lines`, since 2.2.0;
|
||||||
[internal/logtail/lines.go](../internal/logtail/lines.go)). A send-log row
|
[internal/logtail/lines.go](../internal/logtail/lines.go)). A send-log row
|
||||||
@@ -920,8 +962,9 @@ unsupported rather than as a missing doc:
|
|||||||
- **Milter and Postfix startup:** `MILTER_CONNECT_TIMEOUT` (`15s`),
|
- **Milter and Postfix startup:** `MILTER_CONNECT_TIMEOUT` (`15s`),
|
||||||
`MILTER_COMMAND_TIMEOUT` (`15s`), `MILTER_CONTENT_TIMEOUT` (`30s`),
|
`MILTER_COMMAND_TIMEOUT` (`15s`), `MILTER_CONTENT_TIMEOUT` (`30s`),
|
||||||
`MILTER_WAIT_TIMEOUT` (`30` seconds).
|
`MILTER_WAIT_TIMEOUT` (`30` seconds).
|
||||||
- **Background maintenance:** `TLS_RELOAD_INTERVAL_SECONDS` (`86400` — daily
|
- **Background maintenance:** `TLS_RELOAD_INTERVAL_SECONDS` (`86400` — how
|
||||||
`postfix reload` to pick up renewed certificates),
|
often a renewed certificate is looked for; Postfix is reloaded only when one
|
||||||
|
is found),
|
||||||
`LOGROTATE_INTERVAL_SECONDS` (`21600` — check `mail.log` rotation every six
|
`LOGROTATE_INTERVAL_SECONDS` (`21600` — check `mail.log` rotation every six
|
||||||
hours; logrotate keeps 14 rotated files on a daily schedule, and each
|
hours; logrotate keeps 14 rotated files on a daily schedule, and each
|
||||||
rotation triggers `postfix reload`).
|
rotation triggers `postfix reload`).
|
||||||
|
|||||||
@@ -593,13 +593,13 @@ has already run is never edited — the next file is added; the published
|
|||||||
|
|
||||||
### Stage 1 — mail that is shown wrong (H3, H2, M12, M13) → `2.5.0`
|
### Stage 1 — mail that is shown wrong (H3, H2, M12, M13) → `2.5.0`
|
||||||
|
|
||||||
- [ ] **`QueueIDs` on a truncated listing returns an error**, as `postqueueJSON`
|
- [x] **`QueueIDs` on a truncated listing returns an error**, as `postqueueJSON`
|
||||||
does; `reconcile` already treats an error as no information. Test: a 5 MiB
|
does; `reconcile` already treats an error as no information. Test: a 5 MiB
|
||||||
fake `postqueue -p`. — **Opus**
|
fake `postqueue -p`. — **Opus**
|
||||||
- [ ] **Reconcile only closes `queued` rows** (`AND status = 'queued'` in the
|
- [x] **Reconcile only closes `queued` rows** (`AND status = 'queued'` in the
|
||||||
reconcile path's update) and marks what it closed: `reason = 'reconcile'`
|
reconcile path's update) and marks what it closed: `reason = 'reconcile'`
|
||||||
on the row (the 0006 column; a new value, no schema change). — **Opus**
|
on the row (the 0006 column; a new value, no schema change). — **Opus**
|
||||||
- [ ] **Measure before deciding the sweep's fate** (owner, 2026-10-12: the
|
- [x] **Measure before deciding the sweep's fate** (owner, 2026-10-12: the
|
||||||
keep / remove / `lost` question needs real data, and today the only
|
keep / remove / `lost` question needs real data, and today the only
|
||||||
record of a sweep is a stdout line that dies with the container). A table
|
record of a sweep is a stdout line that dies with the container). A table
|
||||||
`delivery_log_days` (migration `0007`, DDL only; a row per UTC day, kept a
|
`delivery_log_days` (migration `0007`, DDL only; a row per UTC day, kept a
|
||||||
@@ -627,16 +627,16 @@ has already run is never edited — the next file is added; the published
|
|||||||
grown for a tick and the new file has a line). Both are fixes to the
|
grown for a tick and the new file has a line). Both are fixes to the
|
||||||
tailer's blindness and stay on the list whatever the sweep's fate; their
|
tailer's blindness and stay on the list whatever the sweep's fate; their
|
||||||
priority follows `tailer_blind_seconds`.
|
priority follows `tailer_blind_seconds`.
|
||||||
- [ ] **Anchor `deliveryRe`** at the head of the line like its two siblings;
|
- [x] **Anchor `deliveryRe`** at the head of the line like its two siblings;
|
||||||
test with the probed HELO and quoted-sender lines. — **Opus**
|
test with the probed HELO and quoted-sender lines. — **Opus**
|
||||||
- [ ] **TLS re-copy** (H2): `postfix-cert-reload.sh` compares the mounted files
|
- [x] **TLS re-copy** (H2): `postfix-cert-reload.sh` compares the mounted files
|
||||||
to the copy and re-copies before `postfix reload` (atomically, same modes);
|
to the copy and re-copies before `postfix reload` (atomically, same modes);
|
||||||
e2e replaces the cert in the stand and reads the new serial off 465.
|
e2e replaces the cert in the stand and reads the new serial off 465.
|
||||||
— **Opus**
|
— **Opus**
|
||||||
- [ ] **Deferred counter** (M13): on the stand, `kill -STOP` the panel mid-message
|
- [x] **Deferred counter** (M13): on the stand, `kill -STOP` the panel mid-message
|
||||||
and record which program logs the warning; widen the matcher accordingly
|
and record which program logs the warning; widen the matcher accordingly
|
||||||
and replace the composed fixture with the seen lines. — **Opus**
|
and replace the composed fixture with the seen lines. — **Opus**
|
||||||
- [ ] Docs: architecture § Log tailer, § Queue reconcile (the measurement and
|
- [x] Docs: architecture § Log tailer, § Queue reconcile (the measurement and
|
||||||
the rule), § Sender check "what it costs"; guide § Delivery log, § Health.
|
the rule), § Sender check "what it costs"; guide § Delivery log, § Health.
|
||||||
— **Sonnet**
|
— **Sonnet**
|
||||||
|
|
||||||
|
|||||||
+12
-2
@@ -333,6 +333,10 @@ docker compose -f docker-compose.yml -f traefik/docker-compose.traefik.yml up -d
|
|||||||
|
|
||||||
Schedule `extract-cert.sh` (cron or a timer) alongside Traefik's renewals.
|
Schedule `extract-cert.sh` (cron or a timer) alongside Traefik's renewals.
|
||||||
|
|
||||||
|
Whatever the proxy, SelfPost notices a renewed certificate in the mount within
|
||||||
|
a day (`TLS_RELOAD_INTERVAL_SECONDS`) and starts serving it on 465 and 587
|
||||||
|
without a restart.
|
||||||
|
|
||||||
## Instance administration
|
## Instance administration
|
||||||
|
|
||||||
After sign-in the global role opens on **Overview** — the place to answer "is
|
After sign-in the global role opens on **Overview** — the place to answer "is
|
||||||
@@ -406,7 +410,8 @@ readings, in the order of what stops mail first:
|
|||||||
not counted: mail was stopped for another reason then. What is counted as
|
not counted: mail was stopped for another reason then. What is counted as
|
||||||
a message is a connection Postfix turned away - it refuses before a
|
a message is a connection Postfix turned away - it refuses before a
|
||||||
message is offered - so a monitor that only connects during an outage is
|
message is offered - so a monitor that only connects during an outage is
|
||||||
counted too. Days are UTC days. The card warns when
|
counted too; and when the panel hangs instead of stopping, the message it
|
||||||
|
hung on. Days are UTC days. The card warns when
|
||||||
a message was deferred in the last 24 hours. If these numbers do not stay
|
a message was deferred in the last 24 hours. If these numbers do not stay
|
||||||
at nothing, the panel is in the way of your mail more than it should be -
|
at nothing, the panel is in the way of your mail more than it should be -
|
||||||
report it.
|
report it.
|
||||||
@@ -1253,7 +1258,12 @@ rows of their domains. It refreshes its rows without resetting a filter being
|
|||||||
chosen. A row identifies its message and nothing more — time,
|
chosen. A row identifies its message and nothing more — time,
|
||||||
sender, recipient, subject and status `queued` (accepted, not yet
|
sender, recipient, subject and status `queued` (accepted, not yet
|
||||||
delivered), `sent` (handed off successfully), `deferred` (Postfix is
|
delivered), `sent` (handed off successfully), `deferred` (Postfix is
|
||||||
retrying), `bounced` (final failure), or refused before it was queued. A
|
retrying), `bounced` (final failure), or refused before it was queued.
|
||||||
|
`bounced` is usually Postfix's word; it is the panel's when Postfix no longer
|
||||||
|
holds a message and `mail.log` never said what became of it (the log rotated
|
||||||
|
away while the panel was down, or was not readable) - the panel then closes
|
||||||
|
the row as a failure rather than show a delivery it cannot evidence, and
|
||||||
|
counts that it did. A
|
||||||
refused row says why in its tag: `rate-limited` (a [level-2 rate
|
refused row says why in its tag: `rate-limited` (a [level-2 rate
|
||||||
limit](#rate-limiting--level-2-domain-and-application)), `wrong client` (the
|
limit](#rate-limiting--level-2-domain-and-application)), `wrong client` (the
|
||||||
application's client IP list) or `wrong From` (see [Who an application may
|
application's client IP list) or `wrong From` (see [Who an application may
|
||||||
|
|||||||
+1
-1
@@ -42,7 +42,7 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md).
|
|||||||
| from-header-binding | Hold a message's `From:` header against the application that sends it | shipped `2.4.0` | 9/9 | [plans/from-header-binding.md](plans/from-header-binding.md) |
|
| from-header-binding | Hold a message's `From:` header against the application that sends it | shipped `2.4.0` | 9/9 | [plans/from-header-binding.md](plans/from-header-binding.md) |
|
||||||
| panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) |
|
| panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) |
|
||||||
| schema-squash | Squash SQLite migrations into a 2.x baseline | built in panel-redesign (stage 1) | — | [plans/panel-redesign.md](plans/panel-redesign.md) |
|
| schema-squash | Squash SQLite migrations into a 2.x baseline | built in panel-redesign (stage 1) | — | [plans/panel-redesign.md](plans/panel-redesign.md) |
|
||||||
| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`; next stages 1+2 → `2.5.0`) | 7/61 | [audit-2026-10-12.md](audit-2026-10-12.md) |
|
| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`; next stages 1+2 → `2.5.0`) | 14/61 | [audit-2026-10-12.md](audit-2026-10-12.md) |
|
||||||
|
|
||||||
**Recommended order** (not binding; owner, 2026-10-09: feature order follows
|
**Recommended order** (not binding; owner, 2026-10-09: feature order follows
|
||||||
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and
|
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and
|
||||||
|
|||||||
@@ -17,8 +17,8 @@ When you add or review a migration, update this file in the same change.
|
|||||||
|
|
||||||
| Field | Value |
|
| Field | Value |
|
||||||
|---|---|
|
|---|---|
|
||||||
| Chain head | `user_version = 5` |
|
| Chain head | `user_version = 7` |
|
||||||
| Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql`, `0003_send_log_lines.sql`, `0004_notifications.sql`, `0005_send_log_rejected_index.sql`, `0006_sender_check.sql` |
|
| Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql`, `0003_send_log_lines.sql`, `0004_notifications.sql`, `0005_send_log_rejected_index.sql`, `0006_sender_check.sql`, `0007_delivery_log_days.sql` |
|
||||||
| File mark | `PRAGMA application_id = 0x53503230` ("SP20") |
|
| File mark | `PRAGMA application_id = 0x53503230` ("SP20") |
|
||||||
| Database file | `/data/selfpost.db` (bind mount) |
|
| Database file | `/data/selfpost.db` (bind mount) |
|
||||||
| Compatibility | 2.x MINOR releases must boot a `2.0.0` data directory. **Nothing is carried over from 1.x.** |
|
| Compatibility | 2.x MINOR releases must boot a `2.0.0` data directory. **Nothing is carried over from 1.x.** |
|
||||||
@@ -65,7 +65,8 @@ features after them add files, the first being `0002_inbound_spam_log.sql` of
|
|||||||
inbound-antispam-panel (`2.1.0`), then `0003_send_log_lines.sql` of
|
inbound-antispam-panel (`2.1.0`), then `0003_send_log_lines.sql` of
|
||||||
delivery-log-storage (`2.2.0`), `0004_notifications.sql` and
|
delivery-log-storage (`2.2.0`), `0004_notifications.sql` and
|
||||||
`0005_send_log_rejected_index.sql` of panel-notifications (`2.3.0`), and
|
`0005_send_log_rejected_index.sql` of panel-notifications (`2.3.0`), and
|
||||||
`0006_sender_check.sql` of from-header-binding (`2.4.0`).
|
`0006_sender_check.sql` of from-header-binding (`2.4.0`), and
|
||||||
|
`0007_delivery_log_days.sql` of the 2026-10-12 audit (`2.5.0`).
|
||||||
|
|
||||||
---
|
---
|
||||||
|
|
||||||
@@ -79,6 +80,7 @@ delivery-log-storage (`2.2.0`), `0004_notifications.sql` and
|
|||||||
| 4 | `0004_notifications.sql` | 2.3.0 | DDL | `users.notify` (default 1: every user starts with notifications on) and `notify_state` |
|
| 4 | `0004_notifications.sql` | 2.3.0 | DDL | `users.notify` (default 1: every user starts with notifications on) and `notify_state` |
|
||||||
| 5 | `0005_send_log_rejected_index.sql` | 2.3.0 | DDL | `idx_send_log_rejected`, a partial index of the refused rows of `send_log` by time; a file of its own because the test installation had run 0004 before the review asked for it |
|
| 5 | `0005_send_log_rejected_index.sql` | 2.3.0 | DDL | `idx_send_log_rejected`, a partial index of the refused rows of `send_log` by time; a file of its own because the test installation had run 0004 before the review asked for it |
|
||||||
| 6 | `0006_sender_check.sql` | 2.4.0 | DDL | `send_log.reason` and `send_log.header_from` (both default `''`: a row refused earlier keeps no reason), and `sender_check_days` |
|
| 6 | `0006_sender_check.sql` | 2.4.0 | DDL | `send_log.reason` and `send_log.header_from` (both default `''`: a row refused earlier keeps no reason), and `sender_check_days` |
|
||||||
|
| 7 | `0007_delivery_log_days.sql` | 2.5.0 | DDL | `delivery_log_days`: what the reconcile sweep and the log tailer did, a row per UTC day, kept a year, shown nowhere - the measurement that decides the sweep's fate (audit 2026-10-12, stage 1). `send_log.reason` gains the value `reconcile` without a schema change |
|
||||||
|
|
||||||
**Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct
|
**Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct
|
||||||
for operators upgrading from older 2.x images.
|
for operators upgrading from older 2.x images.
|
||||||
|
|||||||
+108
-7
@@ -31,6 +31,13 @@ import (
|
|||||||
type StatusStore interface {
|
type StatusStore interface {
|
||||||
UpdateStatus(queueID, recipient, status string) (int64, error)
|
UpdateStatus(queueID, recipient, status string) (int64, error)
|
||||||
ListQueuedOlderThan(cutoff time.Time) ([]store.QueuedDelivery, error)
|
ListQueuedOlderThan(cutoff time.Time) ([]store.QueuedDelivery, error)
|
||||||
|
CloseUnreported(queueID, recipient string) (int64, error)
|
||||||
|
// The counters of delivery_log_days (store/deliverylog.go).
|
||||||
|
AddReconcileClosed(at time.Time, n int64) error
|
||||||
|
AddTailerBlind(from time.Time, d time.Duration) error
|
||||||
|
CountQueuedOlderThan(cutoff time.Time) (int64, error)
|
||||||
|
SetQueuedOverLifetime(at time.Time, n int64) error
|
||||||
|
PruneDeliveryLogDays(now time.Time) error
|
||||||
DeleteSendLogBefore(cutoff time.Time) (int64, error)
|
DeleteSendLogBefore(cutoff time.Time) (int64, error)
|
||||||
InsertSendLogLines(lines []store.SendLogLine, once bool) (int, error)
|
InsertSendLogLines(lines []store.SendLogLine, once bool) (int, error)
|
||||||
PruneSendLogLines(cutoff time.Time) (int64, error)
|
PruneSendLogLines(cutoff time.Time) (int64, error)
|
||||||
@@ -55,6 +62,10 @@ func RetentionInterval() time.Duration {
|
|||||||
// It is a var so tests can answer without a running Postfix.
|
// It is a var so tests can answer without a running Postfix.
|
||||||
var queueIDs = postfix.QueueIDs
|
var queueIDs = postfix.QueueIDs
|
||||||
|
|
||||||
|
// retryPolicy reads Postfix's queue lifetimes, for counting the rows left
|
||||||
|
// queued past them. A var for the same reason.
|
||||||
|
var retryPolicy = postfix.LoadRetryPolicy
|
||||||
|
|
||||||
const (
|
const (
|
||||||
// reconcileInterval is how often the sweep compares stuck rows against the
|
// reconcileInterval is how often the sweep compares stuck rows against the
|
||||||
// Postfix queue, and reconcileGrace how long a row is left alone first.
|
// Postfix queue, and reconcileGrace how long a row is left alone first.
|
||||||
@@ -77,17 +88,25 @@ type RetentionDays func() int
|
|||||||
// The "<queue-id>: to=<addr>, …, status=<word>" shape is specific to the
|
// The "<queue-id>: to=<addr>, …, status=<word>" shape is specific to the
|
||||||
// delivery agents; qmgr/smtpd/cleanup lines do not match.
|
// delivery agents; qmgr/smtpd/cleanup lines do not match.
|
||||||
//
|
//
|
||||||
|
// It is matched at the head of the line - the host name, "program[pid]:",
|
||||||
|
// then the queue id - after SplitTimestamp has taken the stamp off, like
|
||||||
|
// queueLineRe and the inbound patterns. Anywhere else the text is a
|
||||||
|
// stranger's: a port-25 reject line ends with the client's HELO name, which
|
||||||
|
// once parsed as a delivery result when it read "<id>: to=<…>, status=sent"
|
||||||
|
// (audit 2026-10-12, M12).
|
||||||
|
//
|
||||||
// The run before status= is lazy on purpose. Postfix appends the remote
|
// The run before status= is lazy on purpose. Postfix appends the remote
|
||||||
// server's reply verbatim, so a greedy match would take the *last* status= on
|
// server's reply verbatim, so a greedy match would take the *last* status= on
|
||||||
// the line — and that one can come from the reply text, which the far end
|
// the line — and that one can come from the reply text, which the far end
|
||||||
// controls. A bounce whose reply quoted "status=sent" would then be filed as a
|
// controls. A bounce whose reply quoted "status=sent" would then be filed as a
|
||||||
// success. The real field is always the first one after to=<…>.
|
// success. The real field is always the first one after to=<…>.
|
||||||
var deliveryRe = regexp.MustCompile(`\b([0-9A-Za-z]+): to=<([^>]*)>,.*?\bstatus=(\w+)`)
|
var deliveryRe = regexp.MustCompile(`^\S+ [^\s\[]+\[\d+\]: ([0-9A-Za-z]+): to=<([^>]*)>,.*?\bstatus=(\w+)`)
|
||||||
|
|
||||||
// parseDelivery extracts (queue-id, recipient, status) from a mail.log line.
|
// parseDelivery extracts (queue-id, recipient, status) from a mail.log line.
|
||||||
// ok is false for lines that are not recognised delivery results.
|
// ok is false for lines that are not recognised delivery results.
|
||||||
func parseDelivery(line string) (queueID, recipient, status string, ok bool) {
|
func parseDelivery(line string) (queueID, recipient, status string, ok bool) {
|
||||||
m := deliveryRe.FindStringSubmatch(line)
|
_, rest := SplitTimestamp(line)
|
||||||
|
m := deliveryRe.FindStringSubmatch(rest)
|
||||||
if m == nil {
|
if m == nil {
|
||||||
return "", "", "", false
|
return "", "", "", false
|
||||||
}
|
}
|
||||||
@@ -178,6 +197,11 @@ func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{}
|
|||||||
case <-caughtUp:
|
case <-caughtUp:
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// A message Postfix still works on stays queued until its first retry after
|
||||||
|
// the queue lifetime, which can be a whole backoff later.
|
||||||
|
policy := retryPolicy()
|
||||||
|
overLifetime := policy.LongestLifetime() + policy.MaximalBackoff
|
||||||
|
|
||||||
t := time.NewTicker(reconcileInterval)
|
t := time.NewTicker(reconcileInterval)
|
||||||
defer t.Stop()
|
defer t.Stop()
|
||||||
for {
|
for {
|
||||||
@@ -185,13 +209,30 @@ func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{}
|
|||||||
case <-ctx.Done():
|
case <-ctx.Done():
|
||||||
return
|
return
|
||||||
case <-t.C:
|
case <-t.C:
|
||||||
reconcile(st, time.Now().UTC().Add(-reconcileGrace))
|
now := time.Now().UTC()
|
||||||
|
reconcile(st, now.Add(-reconcileGrace))
|
||||||
|
countStuck(st, now, overLifetime)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// countStuck records how many rows are still queued past Postfix's queue
|
||||||
|
// lifetime - what the log would leave unresolved if there were no sweep. Each
|
||||||
|
// sweep overwrites the day's value, so a past day keeps its last sweep's.
|
||||||
|
func countStuck(st StatusStore, now time.Time, overLifetime time.Duration) {
|
||||||
|
n, err := st.CountQueuedOlderThan(now.Add(-overLifetime))
|
||||||
|
if err == nil {
|
||||||
|
err = st.SetQueuedOverLifetime(now, n)
|
||||||
|
}
|
||||||
|
if err != nil {
|
||||||
|
log.Printf("log-tailer: count rows queued past the queue lifetime: %v", err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
// reconcile marks as bounced every row still "queued" from before cutoff whose
|
// reconcile marks as bounced every row still "queued" from before cutoff whose
|
||||||
// message Postfix no longer holds.
|
// message Postfix no longer holds, with reason "reconcile". The close itself
|
||||||
|
// is conditional on the row still being queued, so a delivery line read
|
||||||
|
// between the listing and the close wins.
|
||||||
//
|
//
|
||||||
// A row reaches this state only when its delivery lines are gone for good — the
|
// A row reaches this state only when its delivery lines are gone for good — the
|
||||||
// log rotated past its fourteen files while the panel was down, or was deleted
|
// log rotated past its fourteen files while the panel was down, or was deleted
|
||||||
@@ -219,19 +260,23 @@ func reconcile(st StatusStore, cutoff time.Time) {
|
|||||||
return
|
return
|
||||||
}
|
}
|
||||||
|
|
||||||
var closed int
|
var closed int64
|
||||||
for _, row := range rows {
|
for _, row := range rows {
|
||||||
if _, still := held[row.QueueID]; still {
|
if _, still := held[row.QueueID]; still {
|
||||||
continue
|
continue
|
||||||
}
|
}
|
||||||
if _, err := st.UpdateStatus(row.QueueID, row.To, store.StatusBounced); err != nil {
|
n, err := st.CloseUnreported(row.QueueID, row.To)
|
||||||
|
if err != nil {
|
||||||
log.Printf("log-tailer: reconcile: close %s/%s: %v", row.QueueID, row.To, err)
|
log.Printf("log-tailer: reconcile: close %s/%s: %v", row.QueueID, row.To, err)
|
||||||
continue
|
continue
|
||||||
}
|
}
|
||||||
closed++
|
closed += n
|
||||||
}
|
}
|
||||||
if closed > 0 {
|
if closed > 0 {
|
||||||
log.Printf("log-tailer: reconcile: closed %d row(s) Postfix no longer holds and never reported", closed)
|
log.Printf("log-tailer: reconcile: closed %d row(s) Postfix no longer holds and never reported", closed)
|
||||||
|
if err := st.AddReconcileClosed(time.Now(), closed); err != nil {
|
||||||
|
log.Printf("log-tailer: reconcile: count: %v", err)
|
||||||
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
@@ -256,8 +301,15 @@ func retentionLoop(ctx context.Context, st StatusStore, retention RetentionDays)
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
pruneDays := func() {
|
||||||
|
if err := st.PruneDeliveryLogDays(time.Now()); err != nil {
|
||||||
|
log.Printf("log-tailer: %v", err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
prune()
|
prune()
|
||||||
pruneLines(st)
|
pruneLines(st)
|
||||||
|
pruneDays()
|
||||||
t := time.NewTicker(retentionInterval)
|
t := time.NewTicker(retentionInterval)
|
||||||
defer t.Stop()
|
defer t.Stop()
|
||||||
for {
|
for {
|
||||||
@@ -267,6 +319,7 @@ func retentionLoop(ctx context.Context, st StatusStore, retention RetentionDays)
|
|||||||
case <-t.C:
|
case <-t.C:
|
||||||
prune()
|
prune()
|
||||||
pruneLines(st)
|
pruneLines(st)
|
||||||
|
pruneDays()
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
@@ -548,12 +601,14 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
|
|||||||
}
|
}
|
||||||
|
|
||||||
var once sync.Once
|
var once sync.Once
|
||||||
|
blind := &blindness{add: tr.st.AddTailerBlind}
|
||||||
|
|
||||||
ticker := time.NewTicker(pollInterval)
|
ticker := time.NewTicker(pollInterval)
|
||||||
defer ticker.Stop()
|
defer ticker.Stop()
|
||||||
for {
|
for {
|
||||||
select {
|
select {
|
||||||
case <-ctx.Done():
|
case <-ctx.Done():
|
||||||
|
blind.see(time.Now(), false)
|
||||||
tr.record(f, read(), true) // shutdown: the next start resumes here
|
tr.record(f, read(), true) // shutdown: the next start resumes here
|
||||||
return nil
|
return nil
|
||||||
case <-ticker.C:
|
case <-ticker.C:
|
||||||
@@ -561,6 +616,7 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
|
|||||||
once.Do(func() { close(caughtUp) })
|
once.Do(func() { close(caughtUp) })
|
||||||
ni, err := os.Stat(path)
|
ni, err := os.Stat(path)
|
||||||
if err != nil {
|
if err != nil {
|
||||||
|
blind.see(time.Now(), true)
|
||||||
continue // file briefly gone mid-rotation; try again next tick
|
continue // file briefly gone mid-rotation; try again next tick
|
||||||
}
|
}
|
||||||
pos, _ := f.Seek(0, io.SeekCurrent)
|
pos, _ := f.Seek(0, io.SeekCurrent)
|
||||||
@@ -572,12 +628,57 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
|
|||||||
drain()
|
drain()
|
||||||
if err := openAt(0, io.SeekStart); err != nil {
|
if err := openAt(0, io.SeekStart); err != nil {
|
||||||
log.Printf("log-tailer: reopen %s: %v", path, err)
|
log.Printf("log-tailer: reopen %s: %v", path, err)
|
||||||
|
blind.see(time.Now(), true)
|
||||||
continue
|
continue
|
||||||
}
|
}
|
||||||
|
blind.see(time.Now(), false)
|
||||||
tr.adopt(f)
|
tr.adopt(f)
|
||||||
continue
|
continue
|
||||||
}
|
}
|
||||||
|
blind.see(time.Now(), false)
|
||||||
tr.record(f, read(), false)
|
tr.record(f, read(), false)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// blindness measures the stretches in which follow cannot read mail.log - the
|
||||||
|
// file gone, reopening it failing - for delivery_log_days. A stretch is
|
||||||
|
// stored when it ends, and every minute while it lasts, so a long one is not
|
||||||
|
// lost to a restart and lands on the days it covered. A stretch shorter than
|
||||||
|
// blindMin is not counted: a rotation leaves the name missing for a tick
|
||||||
|
// between rename and create, and that loses nothing - the new file is read
|
||||||
|
// from its start.
|
||||||
|
type blindness struct {
|
||||||
|
add func(from time.Time, d time.Duration) error
|
||||||
|
since time.Time // start of the current stretch; zero when reading
|
||||||
|
long bool // the current stretch has passed blindMin
|
||||||
|
}
|
||||||
|
|
||||||
|
const blindMin = 3 * time.Second
|
||||||
|
|
||||||
|
func (b *blindness) see(now time.Time, blind bool) {
|
||||||
|
if blind && b.since.IsZero() {
|
||||||
|
b.since = now
|
||||||
|
return
|
||||||
|
}
|
||||||
|
if b.since.IsZero() {
|
||||||
|
return
|
||||||
|
}
|
||||||
|
d := now.Sub(b.since)
|
||||||
|
if d >= blindMin {
|
||||||
|
b.long = true
|
||||||
|
}
|
||||||
|
if blind && d < time.Minute {
|
||||||
|
return
|
||||||
|
}
|
||||||
|
if b.long {
|
||||||
|
if err := b.add(b.since, d); err != nil {
|
||||||
|
log.Printf("log-tailer: count the time mail.log could not be read: %v", err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
if blind {
|
||||||
|
b.since = now // the stretch goes on; the next part starts here
|
||||||
|
return
|
||||||
|
}
|
||||||
|
b.since, b.long = time.Time{}, false
|
||||||
|
}
|
||||||
|
|||||||
@@ -116,6 +116,34 @@ func TestParseDelivery(t *testing.T) {
|
|||||||
line: "host postfix/cleanup[12]: BEEF03: message-id=<x@example.com>",
|
line: "host postfix/cleanup[12]: BEEF03: message-id=<x@example.com>",
|
||||||
wantOK: false,
|
wantOK: false,
|
||||||
},
|
},
|
||||||
|
{
|
||||||
|
// The stamp Postfix 3.7's postlogd writes, as on the stand.
|
||||||
|
name: "syslog stamp",
|
||||||
|
line: "Oct 14 11:05:51 mail postfix/smtp[26]: 41E862C00D9E: to=<a@example.net>, relay=x, dsn=2.0.0, status=sent (250 OK)",
|
||||||
|
wantOK: true,
|
||||||
|
queueID: "41E862C00D9E",
|
||||||
|
recipient: "a@example.net",
|
||||||
|
status: store.StatusSent,
|
||||||
|
},
|
||||||
|
{
|
||||||
|
// A stranger's HELO name at the end of a port-25 reject line, as
|
||||||
|
// probed for the 2026-10-12 audit: it must not file a delivery.
|
||||||
|
name: "a delivery result in a HELO name is not one",
|
||||||
|
line: "Oct 14 11:05:51 mail postfix/inbound/smtpd[372]: NOQUEUE: reject: RCPT from unknown[203.0.113.7]: 554 5.7.1 <x@elsewhere.example>: Relay access denied; from=<a@stranger.example> to=<x@elsewhere.example> proto=ESMTP helo=<41E862C00D9E: to=<victim@example.net>, status=sent>",
|
||||||
|
wantOK: false,
|
||||||
|
},
|
||||||
|
{
|
||||||
|
// The same text in a quoted sender address, on a line that does
|
||||||
|
// have a queue id at its head.
|
||||||
|
name: "a delivery result in a quoted sender is not one",
|
||||||
|
line: `Oct 14 11:05:51 mail postfix/qmgr[10]: 5B4A2C1D3E: from=<"41E862C00D9E: to=<victim@example.net>, status=sent"@stranger.example>, size=500, nrcpt=1 (queue active)`,
|
||||||
|
wantOK: false,
|
||||||
|
},
|
||||||
|
{
|
||||||
|
name: "an smtpd line with the text after its queue id is not one",
|
||||||
|
line: "Oct 14 11:05:51 mail postfix/smtpd[10]: 5B4A2C1D3E: client=unknown[203.0.113.7], sasl_username=41E862C00D9E: to=<victim@example.net>, status=sent",
|
||||||
|
wantOK: false,
|
||||||
|
},
|
||||||
}
|
}
|
||||||
for _, c := range cases {
|
for _, c := range cases {
|
||||||
t.Run(c.name, func(t *testing.T) {
|
t.Run(c.name, func(t *testing.T) {
|
||||||
@@ -147,6 +175,11 @@ type captureStore struct {
|
|||||||
// queued is what ListQueuedOlderThan returns, for the reconcile sweep.
|
// queued is what ListQueuedOlderThan returns, for the reconcile sweep.
|
||||||
queued []store.QueuedDelivery
|
queued []store.QueuedDelivery
|
||||||
queuedErr error
|
queuedErr error
|
||||||
|
// closed sums AddReconcileClosed; stuckCount is what CountQueuedOlderThan
|
||||||
|
// answers and stuck what SetQueuedOverLifetime was given.
|
||||||
|
closed int64
|
||||||
|
stuckCount int64
|
||||||
|
stuck []int64
|
||||||
|
|
||||||
// lines are the log lines kept for messages' pages; pruned is the cutoff of
|
// lines are the log lines kept for messages' pages; pruned is the cutoff of
|
||||||
// each PruneSendLogLines call.
|
// each PruneSendLogLines call.
|
||||||
@@ -208,8 +241,38 @@ func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, e
|
|||||||
return 1, nil
|
return 1, nil
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// CloseUnreported records the sweep's close as "queue-id|recipient|reconcile".
|
||||||
|
func (c *captureStore) CloseUnreported(queueID, recipient string) (int64, error) {
|
||||||
|
c.mu.Lock()
|
||||||
|
defer c.mu.Unlock()
|
||||||
|
c.calls = append(c.calls, queueID+"|"+recipient+"|"+store.ReasonReconcile)
|
||||||
|
return 1, nil
|
||||||
|
}
|
||||||
|
|
||||||
func (c *captureStore) DeleteSendLogBefore(time.Time) (int64, error) { return 0, nil }
|
func (c *captureStore) DeleteSendLogBefore(time.Time) (int64, error) { return 0, nil }
|
||||||
|
|
||||||
|
// The counters of delivery_log_days: closed and stuck are kept for the sweep's
|
||||||
|
// tests, the rest is not looked at.
|
||||||
|
func (c *captureStore) AddReconcileClosed(_ time.Time, n int64) error {
|
||||||
|
c.mu.Lock()
|
||||||
|
defer c.mu.Unlock()
|
||||||
|
c.closed += n
|
||||||
|
return nil
|
||||||
|
}
|
||||||
|
func (c *captureStore) AddTailerBlind(time.Time, time.Duration) error { return nil }
|
||||||
|
func (c *captureStore) CountQueuedOlderThan(time.Time) (int64, error) {
|
||||||
|
c.mu.Lock()
|
||||||
|
defer c.mu.Unlock()
|
||||||
|
return c.stuckCount, nil
|
||||||
|
}
|
||||||
|
func (c *captureStore) SetQueuedOverLifetime(_ time.Time, n int64) error {
|
||||||
|
c.mu.Lock()
|
||||||
|
defer c.mu.Unlock()
|
||||||
|
c.stuck = append(c.stuck, n)
|
||||||
|
return nil
|
||||||
|
}
|
||||||
|
func (c *captureStore) PruneDeliveryLogDays(time.Time) error { return nil }
|
||||||
|
|
||||||
func (c *captureStore) ListQueuedOlderThan(time.Time) ([]store.QueuedDelivery, error) {
|
func (c *captureStore) ListQueuedOlderThan(time.Time) ([]store.QueuedDelivery, error) {
|
||||||
c.mu.Lock()
|
c.mu.Lock()
|
||||||
defer c.mu.Unlock()
|
defer c.mu.Unlock()
|
||||||
@@ -433,8 +496,61 @@ func TestReconcileClosesOnlyWhatPostfixNoLongerHolds(t *testing.T) {
|
|||||||
reconcile(cs, time.Now().UTC())
|
reconcile(cs, time.Now().UTC())
|
||||||
|
|
||||||
got := cs.snapshot()
|
got := cs.snapshot()
|
||||||
if len(got) != 1 || got[0] != "GONEQ|lost@example.net|"+store.StatusBounced {
|
if len(got) != 1 || got[0] != "GONEQ|lost@example.net|"+store.ReasonReconcile {
|
||||||
t.Fatalf("got %v, want only the message Postfix dropped closed as bounced", got)
|
t.Fatalf("got %v, want only the message Postfix dropped closed by the sweep", got)
|
||||||
|
}
|
||||||
|
if cs.closed != 1 {
|
||||||
|
t.Fatalf("the day counts %d closed row(s), want 1", cs.closed)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
// Each sweep records how many rows are queued past the queue lifetime, as a
|
||||||
|
// level for the day.
|
||||||
|
func TestCountStuckRecordsTheLevel(t *testing.T) {
|
||||||
|
cs := &captureStore{stuckCount: 3}
|
||||||
|
countStuck(cs, time.Now(), time.Hour)
|
||||||
|
cs.stuckCount = 0
|
||||||
|
countStuck(cs, time.Now(), time.Hour)
|
||||||
|
if len(cs.stuck) != 2 || cs.stuck[0] != 3 || cs.stuck[1] != 0 {
|
||||||
|
t.Fatalf("levels recorded = %v, want [3 0]", cs.stuck)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
// The tailer's blind time: a rotation's one-tick gap is not counted, a longer
|
||||||
|
// stretch is, a stretch that lasts is stored a minute at a time from where the
|
||||||
|
// last part ended, and reading again ends it.
|
||||||
|
func TestBlindnessCountsStretchesThatMatter(t *testing.T) {
|
||||||
|
type part struct {
|
||||||
|
from time.Time
|
||||||
|
d time.Duration
|
||||||
|
}
|
||||||
|
var got []part
|
||||||
|
b := &blindness{add: func(from time.Time, d time.Duration) error {
|
||||||
|
got = append(got, part{from, d})
|
||||||
|
return nil
|
||||||
|
}}
|
||||||
|
t0 := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC)
|
||||||
|
at := func(s int) time.Time { return t0.Add(time.Duration(s) * time.Second) }
|
||||||
|
|
||||||
|
b.see(at(0), true) // rotation: gone for a tick
|
||||||
|
b.see(at(1), false)
|
||||||
|
b.see(at(2), false)
|
||||||
|
if len(got) != 0 {
|
||||||
|
t.Fatalf("a one-second gap was counted: %v", got)
|
||||||
|
}
|
||||||
|
|
||||||
|
for s := 10; s <= 80; s++ { // blind for 75 s
|
||||||
|
b.see(at(s), true)
|
||||||
|
}
|
||||||
|
b.see(at(85), false)
|
||||||
|
want := []part{{at(10), 60 * time.Second}, {at(70), 15 * time.Second}}
|
||||||
|
if len(got) != len(want) {
|
||||||
|
t.Fatalf("parts = %v, want %v", got, want)
|
||||||
|
}
|
||||||
|
for i := range want {
|
||||||
|
if !got[i].from.Equal(want[i].from) || got[i].d != want[i].d {
|
||||||
|
t.Errorf("part %d = %v, want %v", i, got[i], want[i])
|
||||||
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -23,6 +23,16 @@ func (s *retentionProbeStore) ListQueuedOlderThan(time.Time) ([]store.QueuedDeli
|
|||||||
return nil, nil
|
return nil, nil
|
||||||
}
|
}
|
||||||
|
|
||||||
|
func (s *retentionProbeStore) CloseUnreported(string, string) (int64, error) {
|
||||||
|
return 0, nil
|
||||||
|
}
|
||||||
|
|
||||||
|
func (s *retentionProbeStore) AddReconcileClosed(time.Time, int64) error { return nil }
|
||||||
|
func (s *retentionProbeStore) AddTailerBlind(time.Time, time.Duration) error { return nil }
|
||||||
|
func (s *retentionProbeStore) CountQueuedOlderThan(time.Time) (int64, error) { return 0, nil }
|
||||||
|
func (s *retentionProbeStore) SetQueuedOverLifetime(time.Time, int64) error { return nil }
|
||||||
|
func (s *retentionProbeStore) PruneDeliveryLogDays(time.Time) error { return nil }
|
||||||
|
|
||||||
func (s *retentionProbeStore) DeleteSendLogBefore(cutoff time.Time) (int64, error) {
|
func (s *retentionProbeStore) DeleteSendLogBefore(cutoff time.Time) (int64, error) {
|
||||||
s.mu.Lock()
|
s.mu.Lock()
|
||||||
s.cutoff = cutoff
|
s.cutoff = cutoff
|
||||||
|
|||||||
@@ -27,11 +27,21 @@ import (
|
|||||||
//
|
//
|
||||||
// It is counted at the warning, which is the one line that names the socket.
|
// It is counted at the warning, which is the one line that names the socket.
|
||||||
// The reject lines do not: the same words are written when OpenDKIM does not
|
// The reject lines do not: the same words are written when OpenDKIM does not
|
||||||
// answer and when the journal milter refuses under a level-2 limit, and for a
|
// answer and when the journal milter refuses under a level-2 limit.
|
||||||
// check that stops answering in the middle of a message they are written by
|
//
|
||||||
// cleanup, another process, under a queue id. The warning for that case is
|
// A check that is running and stops answering in the middle of a message -
|
||||||
// "milter unix:<socket>: can't read … reply packet header" (Postfix's
|
// its socket accepts, nothing replies - is met by cleanup, not smtpd: past the
|
||||||
// milter8.c; not seen on the stand).
|
// DATA command it is cleanup that talks to the milters. Seen on the e2e stand
|
||||||
|
// with the panel frozen (SIGSTOP) once DATA was answered (2026-10-14):
|
||||||
|
//
|
||||||
|
// postfix/cleanup[1339]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_HEADER reply packet header: Connection timed out
|
||||||
|
// postfix/cleanup[1339]: 7BCAF3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from=<…> to=<…> proto=ESMTP helo=<…>
|
||||||
|
//
|
||||||
|
// One cleanup process serves message after message and the first warning
|
||||||
|
// ends the message, so each such warning is a message, counted on its own.
|
||||||
|
// Until 2.5.0 only smtpd's lines were read, and this case - the one that
|
||||||
|
// tells a hung panel from a stopped one - was never counted (audit
|
||||||
|
// 2026-10-12, M13).
|
||||||
|
|
||||||
// SenderCheckStore is where the count goes, and where the time of the last
|
// SenderCheckStore is where the count goes, and where the time of the last
|
||||||
// counted line is kept. *store.Store satisfies it.
|
// counted line is kept. *store.Store satisfies it.
|
||||||
@@ -47,7 +57,7 @@ type SenderCheck struct {
|
|||||||
Socket string
|
Socket string
|
||||||
}
|
}
|
||||||
|
|
||||||
var smtpdLineRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?smtpd\[(\d+)\]: (.*)$`)
|
var milterLineRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?(smtpd|cleanup)\[(\d+)\]: (.*)$`)
|
||||||
|
|
||||||
const (
|
const (
|
||||||
// senderCheckPids bounds the processes remembered; smtpd processes are a
|
// senderCheckPids bounds the processes remembered; smtpd processes are a
|
||||||
@@ -89,11 +99,18 @@ func newDeferredCounter(sc *SenderCheck) *deferredCounter {
|
|||||||
// read to the end of the log for the first time.
|
// read to the end of the log for the first time.
|
||||||
func (c *deferredCounter) handle(line string, now time.Time, catchingUp bool) {
|
func (c *deferredCounter) handle(line string, now time.Time, catchingUp bool) {
|
||||||
at, rest := lineTime(line, now)
|
at, rest := lineTime(line, now)
|
||||||
m := smtpdLineRe.FindStringSubmatch(rest)
|
m := milterLineRe.FindStringSubmatch(rest)
|
||||||
if m == nil {
|
if m == nil {
|
||||||
return
|
return
|
||||||
}
|
}
|
||||||
pid, text := m[1], m[2]
|
program, pid, text := m[1], m[2], m[3]
|
||||||
|
if program == "cleanup" {
|
||||||
|
// A message cleanup could not finish because the check did not reply.
|
||||||
|
if strings.HasPrefix(text, c.broken) {
|
||||||
|
c.count(at, catchingUp)
|
||||||
|
}
|
||||||
|
return
|
||||||
|
}
|
||||||
switch {
|
switch {
|
||||||
case strings.HasPrefix(text, "connect from "):
|
case strings.HasPrefix(text, "connect from "):
|
||||||
delete(c.failed, pid)
|
delete(c.failed, pid)
|
||||||
@@ -109,14 +126,19 @@ func (c *deferredCounter) handle(line string, now time.Time, catchingUp bool) {
|
|||||||
c.failed = make(map[string]bool)
|
c.failed = make(map[string]bool)
|
||||||
}
|
}
|
||||||
c.failed[pid] = true
|
c.failed[pid] = true
|
||||||
if catchingUp && !at.After(c.last) {
|
c.count(at, catchingUp)
|
||||||
return
|
}
|
||||||
}
|
}
|
||||||
if at.After(c.last) {
|
|
||||||
c.last = at
|
// count adds one deferred message at at, unless it is a line read again.
|
||||||
}
|
func (c *deferredCounter) count(at time.Time, catchingUp bool) {
|
||||||
if err := c.st.AddSenderCheckDeferred(at, 1); err != nil {
|
if catchingUp && !at.After(c.last) {
|
||||||
log.Printf("log-tailer: sender check statistics: %v", err)
|
return
|
||||||
}
|
}
|
||||||
|
if at.After(c.last) {
|
||||||
|
c.last = at
|
||||||
|
}
|
||||||
|
if err := c.st.AddSenderCheckDeferred(at, 1); err != nil {
|
||||||
|
log.Printf("log-tailer: sender check statistics: %v", err)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -24,11 +24,11 @@ func (d *deferredStore) AddSenderCheckDeferred(at time.Time, n int64) error {
|
|||||||
}
|
}
|
||||||
|
|
||||||
// The lines of process 1183 and of cleanup are as the e2e stand wrote them
|
// The lines of process 1183 and of cleanup are as the e2e stand wrote them
|
||||||
// with the panel stopped and for a refused From: (2026-10-12; the stamps are
|
// with the panel stopped and for a refused From: (2026-10-12), and with the
|
||||||
// put in ISO form). Around them are the lines of two other things that use
|
// panel frozen in the middle of a message (cleanup 1339, 2026-10-14); the
|
||||||
// the same words - a level-2 refusal of the journal milter, OpenDKIM not
|
// stamps are put in ISO form. Around them are the lines of two other things
|
||||||
// answering - and, composed from Postfix's source rather than seen, a check
|
// that use the same words - a level-2 refusal of the journal milter, OpenDKIM
|
||||||
// that stops answering in the middle of a message.
|
// not answering.
|
||||||
func TestDeferredCounter(t *testing.T) {
|
func TestDeferredCounter(t *testing.T) {
|
||||||
st := &deferredStore{}
|
st := &deferredStore{}
|
||||||
c := newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"})
|
c := newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"})
|
||||||
@@ -61,11 +61,17 @@ func TestDeferredCounter(t *testing.T) {
|
|||||||
`2026-10-12T16:24:00.100000+00:00 mail postfix/smtpd[1201]: warning: connect to Milter service unix:/run/opendkim/opendkim.sock: Connection refused`,
|
`2026-10-12T16:24:00.100000+00:00 mail postfix/smtpd[1201]: warning: connect to Milter service unix:/run/opendkim/opendkim.sock: Connection refused`,
|
||||||
`2026-10-12T16:24:00.200000+00:00 mail postfix/smtpd[1201]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`,
|
`2026-10-12T16:24:00.200000+00:00 mail postfix/smtpd[1201]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`,
|
||||||
|
|
||||||
// The check stops answering in the middle of a message, the next day.
|
// The check stops answering in the middle of a message, the next day:
|
||||||
|
// cleanup meets it. Two messages through the same cleanup process are
|
||||||
|
// two messages.
|
||||||
`2026-10-13T00:00:05.000000+00:00 mail postfix/smtpd[1300]: connect from unknown[10.77.0.1]`,
|
`2026-10-13T00:00:05.000000+00:00 mail postfix/smtpd[1300]: connect from unknown[10.77.0.1]`,
|
||||||
`2026-10-13T00:00:21.000000+00:00 mail postfix/smtpd[1300]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_EOH reply packet header: Connection timed out`,
|
`2026-10-13T00:00:35.000000+00:00 mail postfix/cleanup[1339]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`,
|
||||||
`2026-10-13T00:00:21.050000+00:00 mail postfix/smtpd[1300]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_BODYEOB reply packet header: Connection timed out`,
|
`2026-10-13T00:00:35.100000+00:00 mail postfix/cleanup[1339]: 7BCAF3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>`,
|
||||||
`2026-10-13T00:00:21.100000+00:00 mail postfix/cleanup[1195]: 4XcB7k2Jm9z1: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from=<a@sender.e2e.test> to=<b@sink.e2e.test> proto=ESMTP helo=<x>`,
|
`2026-10-13T00:01:20.000000+00:00 mail postfix/cleanup[1339]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`,
|
||||||
|
`2026-10-13T00:01:20.100000+00:00 mail postfix/cleanup[1339]: 8C1D43C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>`,
|
||||||
|
|
||||||
|
// OpenDKIM hung in the middle of a message: another socket.
|
||||||
|
`2026-10-13T00:01:30.000000+00:00 mail postfix/cleanup[1339]: warning: milter unix:/run/opendkim/opendkim.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`,
|
||||||
|
|
||||||
// The check's own verdict is a refusal, not a deferral, and it is
|
// The check's own verdict is a refusal, not a deferral, and it is
|
||||||
// cleanup that writes it.
|
// cleanup that writes it.
|
||||||
@@ -73,8 +79,8 @@ func TestDeferredCounter(t *testing.T) {
|
|||||||
} {
|
} {
|
||||||
c.handle(line, now, false)
|
c.handle(line, now, false)
|
||||||
}
|
}
|
||||||
if len(st.days) != 2 || st.days["2026-10-12"] != 1 || st.days["2026-10-13"] != 1 {
|
if len(st.days) != 2 || st.days["2026-10-12"] != 1 || st.days["2026-10-13"] != 2 {
|
||||||
t.Fatalf("deferred per day = %v, want one on each of the two days", st.days)
|
t.Fatalf("deferred per day = %v, want one on the first day and two on the second", st.days)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
+35
-15
@@ -41,28 +41,43 @@ func (l *limitWriter) Write(p []byte) (int, error) {
|
|||||||
return len(p), nil
|
return len(p), nil
|
||||||
}
|
}
|
||||||
|
|
||||||
// Queue returns Postfix's own human-readable mail-queue listing
|
// postqueueP builds the `postqueue -p` command. It is a var so tests can put
|
||||||
// (architecture.md § Panel HTTP surface): active, deferred and held messages,
|
// a fake postqueue in its place, the way readQueueJSON is.
|
||||||
// exactly as an administrator would see via the CLI. The command takes a
|
var postqueueP = func(ctx context.Context) *exec.Cmd {
|
||||||
// single fixed flag and no user input, so it never goes through a shell
|
// A single fixed flag and no user input, never through a shell (security.md).
|
||||||
// (security.md). The panel is responsible for escaping the output before
|
return exec.CommandContext(ctx, "postqueue", "-p")
|
||||||
// display (security.md); this function returns it as-is.
|
}
|
||||||
func Queue() (string, error) {
|
|
||||||
|
// listQueue runs `postqueue -p` and keeps at most maxQueueOutput bytes of it;
|
||||||
|
// truncated says whether there was more.
|
||||||
|
func listQueue() (text string, truncated bool, err error) {
|
||||||
ctx, cancel := context.WithTimeout(context.Background(), postqueueTimeout)
|
ctx, cancel := context.WithTimeout(context.Background(), postqueueTimeout)
|
||||||
defer cancel()
|
defer cancel()
|
||||||
cmd := exec.CommandContext(ctx, "postqueue", "-p")
|
cmd := postqueueP(ctx)
|
||||||
out := &limitWriter{remaining: maxQueueOutput}
|
out := &limitWriter{remaining: maxQueueOutput}
|
||||||
cmd.Stdout = out
|
cmd.Stdout = out
|
||||||
cmd.Stderr = out
|
cmd.Stderr = out
|
||||||
err := cmd.Run()
|
err = cmd.Run()
|
||||||
if ctx.Err() == context.DeadlineExceeded {
|
if ctx.Err() == context.DeadlineExceeded {
|
||||||
return "", fmt.Errorf("postqueue -p timed out after %s", postqueueTimeout)
|
return "", false, fmt.Errorf("postqueue -p timed out after %s", postqueueTimeout)
|
||||||
}
|
}
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return "", fmt.Errorf("postqueue -p: %w: %s", err, strings.TrimSpace(out.buf.String()))
|
return "", false, fmt.Errorf("postqueue -p: %w: %s", err, strings.TrimSpace(out.buf.String()))
|
||||||
}
|
}
|
||||||
text := out.buf.String()
|
return out.buf.String(), out.truncated, nil
|
||||||
if out.truncated {
|
}
|
||||||
|
|
||||||
|
// Queue returns Postfix's own human-readable mail-queue listing
|
||||||
|
// (architecture.md § Panel HTTP surface): active, deferred and held messages,
|
||||||
|
// exactly as an administrator would see via the CLI. The panel is responsible
|
||||||
|
// for escaping the output before display (security.md); this function returns
|
||||||
|
// it as-is. A listing over the size cap is shown cut, with a note saying so.
|
||||||
|
func Queue() (string, error) {
|
||||||
|
text, truncated, err := listQueue()
|
||||||
|
if err != nil {
|
||||||
|
return "", err
|
||||||
|
}
|
||||||
|
if truncated {
|
||||||
text += fmt.Sprintf("\n[listing truncated at %d bytes]\n", maxQueueOutput)
|
text += fmt.Sprintf("\n[listing truncated at %d bytes]\n", maxQueueOutput)
|
||||||
}
|
}
|
||||||
return text, nil
|
return text, nil
|
||||||
@@ -77,12 +92,17 @@ func Queue() (string, error) {
|
|||||||
//
|
//
|
||||||
// An error means the queue could not be listed and therefore says nothing about
|
// An error means the queue could not be listed and therefore says nothing about
|
||||||
// any message; the caller must treat it as "no information", never as an empty
|
// any message; the caller must treat it as "no information", never as an empty
|
||||||
// queue.
|
// queue. A listing cut at the size cap is such an error: the messages past the
|
||||||
|
// cut are still in the queue, and a backlog that large is the outage the sweep
|
||||||
|
// exists for (audit 2026-10-12, H3). QueueMessages treats its cap the same way.
|
||||||
func QueueIDs() (map[string]struct{}, error) {
|
func QueueIDs() (map[string]struct{}, error) {
|
||||||
out, err := Queue()
|
out, truncated, err := listQueue()
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return nil, err
|
return nil, err
|
||||||
}
|
}
|
||||||
|
if truncated {
|
||||||
|
return nil, fmt.Errorf("postqueue -p: listing is larger than %d bytes", maxQueueOutput)
|
||||||
|
}
|
||||||
return parseQueueIDs(out), nil
|
return parseQueueIDs(out), nil
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -1,6 +1,76 @@
|
|||||||
package postfix
|
package postfix
|
||||||
|
|
||||||
import "testing"
|
import (
|
||||||
|
"bufio"
|
||||||
|
"context"
|
||||||
|
"fmt"
|
||||||
|
"os"
|
||||||
|
"os/exec"
|
||||||
|
"strings"
|
||||||
|
"testing"
|
||||||
|
)
|
||||||
|
|
||||||
|
// TestFakePostqueue is not a test: it is the fake `postqueue -p` the tests
|
||||||
|
// below run in place of the real one, writing SP_FAKE_POSTQUEUE_BYTES bytes of
|
||||||
|
// queue entries.
|
||||||
|
func TestFakePostqueue(t *testing.T) {
|
||||||
|
if os.Getenv("SP_FAKE_POSTQUEUE") != "1" {
|
||||||
|
t.Skip("helper process")
|
||||||
|
}
|
||||||
|
var size int
|
||||||
|
fmt.Sscan(os.Getenv("SP_FAKE_POSTQUEUE_BYTES"), &size)
|
||||||
|
out := bufio.NewWriter(os.Stdout)
|
||||||
|
fmt.Fprintln(out, "-Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------")
|
||||||
|
for n, i := 0, 0; n < size; i++ {
|
||||||
|
entry := fmt.Sprintf("%010X 446 Fri Aug 8 10:13:31 app@example.com\n%41s rcpt@example.net\n\n", i, "")
|
||||||
|
out.WriteString(entry)
|
||||||
|
n += len(entry)
|
||||||
|
}
|
||||||
|
out.Flush()
|
||||||
|
os.Exit(0)
|
||||||
|
}
|
||||||
|
|
||||||
|
// fakePostqueue puts a postqueue that lists about size bytes of entries in
|
||||||
|
// place of the real one for the rest of the test.
|
||||||
|
func fakePostqueue(t *testing.T, size int) {
|
||||||
|
t.Helper()
|
||||||
|
old := postqueueP
|
||||||
|
postqueueP = func(ctx context.Context) *exec.Cmd {
|
||||||
|
cmd := exec.CommandContext(ctx, os.Args[0], "-test.run=^TestFakePostqueue$")
|
||||||
|
cmd.Env = append(os.Environ(), "SP_FAKE_POSTQUEUE=1", fmt.Sprintf("SP_FAKE_POSTQUEUE_BYTES=%d", size))
|
||||||
|
return cmd
|
||||||
|
}
|
||||||
|
t.Cleanup(func() { postqueueP = old })
|
||||||
|
}
|
||||||
|
|
||||||
|
// A listing over the cap is no listing for the reconcile sweep: the messages
|
||||||
|
// past the cut are still queued, and taking the first 4 MiB of ids for the
|
||||||
|
// whole queue closed every row past it as bounced (audit 2026-10-12, H3).
|
||||||
|
// The queue page still shows the cut listing, with the note.
|
||||||
|
func TestQueueIDsRefusesATruncatedListing(t *testing.T) {
|
||||||
|
fakePostqueue(t, 5<<20)
|
||||||
|
if ids, err := QueueIDs(); err == nil {
|
||||||
|
t.Fatalf("QueueIDs on a 5 MiB listing = %d ids and no error, want an error", len(ids))
|
||||||
|
}
|
||||||
|
text, err := Queue()
|
||||||
|
if err != nil {
|
||||||
|
t.Fatalf("Queue on a 5 MiB listing: %v", err)
|
||||||
|
}
|
||||||
|
if !strings.HasSuffix(text, fmt.Sprintf("[listing truncated at %d bytes]\n", maxQueueOutput)) {
|
||||||
|
t.Fatalf("Queue on a 5 MiB listing does not end with the truncation note: ...%q", text[len(text)-80:])
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
func TestQueueIDsReadsAListingUnderTheCap(t *testing.T) {
|
||||||
|
fakePostqueue(t, 1000)
|
||||||
|
ids, err := QueueIDs()
|
||||||
|
if err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if _, ok := ids["0000000000"]; !ok || len(ids) < 5 {
|
||||||
|
t.Fatalf("QueueIDs on a small listing = %v", ids)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
// The reconcile sweep decides whether a message is still Postfix's problem, so
|
// The reconcile sweep decides whether a message is still Postfix's problem, so
|
||||||
// the parser must pick queue ids out of a real listing and nothing else out of
|
// the parser must pick queue ids out of a real listing and nothing else out of
|
||||||
|
|||||||
@@ -0,0 +1,106 @@
|
|||||||
|
package store
|
||||||
|
|
||||||
|
import (
|
||||||
|
"fmt"
|
||||||
|
"time"
|
||||||
|
)
|
||||||
|
|
||||||
|
// The counters of delivery_log_days (migration 0007): what the reconcile sweep
|
||||||
|
// and the log tailer did, a row per UTC day, read off a copy of the database
|
||||||
|
// to decide the sweep's fate (audit 2026-10-12, stage 1). No page shows them.
|
||||||
|
|
||||||
|
// deliveryLogKeepDays is how long a day of the counters is kept.
|
||||||
|
const deliveryLogKeepDays = 366
|
||||||
|
|
||||||
|
// addDeliveryLogDay adds n to one counter of the day of at. column is one of
|
||||||
|
// the fixed names below, never anything a request carries.
|
||||||
|
func (s *Store) addDeliveryLogDay(at time.Time, column string, n int64) error {
|
||||||
|
if n <= 0 {
|
||||||
|
return nil
|
||||||
|
}
|
||||||
|
_, err := s.db.Exec(fmt.Sprintf(
|
||||||
|
`INSERT INTO delivery_log_days (day, %[1]s) VALUES (?, ?)
|
||||||
|
ON CONFLICT (day) DO UPDATE SET %[1]s = %[1]s + excluded.%[1]s`, column),
|
||||||
|
at.UTC().Format(dayLayout), n,
|
||||||
|
)
|
||||||
|
if err != nil {
|
||||||
|
return fmt.Errorf("delivery log day, %s: %w", column, err)
|
||||||
|
}
|
||||||
|
return nil
|
||||||
|
}
|
||||||
|
|
||||||
|
// AddReconcileClosed counts n rows the reconcile sweep closed.
|
||||||
|
func (s *Store) AddReconcileClosed(at time.Time, n int64) error {
|
||||||
|
return s.addDeliveryLogDay(at, "reconcile_closed", n)
|
||||||
|
}
|
||||||
|
|
||||||
|
// AddTailerBlind counts a stretch the log tailer could not read mail.log,
|
||||||
|
// on the day it began. Under a second counts nothing.
|
||||||
|
func (s *Store) AddTailerBlind(from time.Time, d time.Duration) error {
|
||||||
|
return s.addDeliveryLogDay(from, "tailer_blind_seconds", int64(d/time.Second))
|
||||||
|
}
|
||||||
|
|
||||||
|
// SetQueuedOverLifetime records how many rows are still queued past Postfix's
|
||||||
|
// queue lifetime. It is a level, not a sum: each sweep overwrites the day's
|
||||||
|
// value, so a past day keeps what its last sweep saw.
|
||||||
|
func (s *Store) SetQueuedOverLifetime(at time.Time, n int64) error {
|
||||||
|
_, err := s.db.Exec(
|
||||||
|
`INSERT INTO delivery_log_days (day, queued_over_lifetime) VALUES (?, ?)
|
||||||
|
ON CONFLICT (day) DO UPDATE SET queued_over_lifetime = excluded.queued_over_lifetime`,
|
||||||
|
at.UTC().Format(dayLayout), n,
|
||||||
|
)
|
||||||
|
if err != nil {
|
||||||
|
return fmt.Errorf("delivery log day, queued_over_lifetime: %w", err)
|
||||||
|
}
|
||||||
|
return nil
|
||||||
|
}
|
||||||
|
|
||||||
|
// CountQueuedOlderThan counts the rows still "queued" that were accepted
|
||||||
|
// before cutoff. created_at is RFC3339 UTC, so the strings compare as times.
|
||||||
|
func (s *Store) CountQueuedOlderThan(cutoff time.Time) (int64, error) {
|
||||||
|
var n int64
|
||||||
|
err := s.db.QueryRow(
|
||||||
|
`SELECT COUNT(*) FROM send_log WHERE status = ? AND queue_id <> '' AND created_at < ?`,
|
||||||
|
StatusQueued, cutoff.UTC().Format(time.RFC3339),
|
||||||
|
).Scan(&n)
|
||||||
|
if err != nil {
|
||||||
|
return 0, fmt.Errorf("count queued send_log rows: %w", err)
|
||||||
|
}
|
||||||
|
return n, nil
|
||||||
|
}
|
||||||
|
|
||||||
|
// DeliveryLogDay is one day of the counters, for tests and for reading a copy.
|
||||||
|
type DeliveryLogDay struct {
|
||||||
|
Day string
|
||||||
|
Closed, Contradicted, BlindSeconds, Stuck int64
|
||||||
|
}
|
||||||
|
|
||||||
|
// DeliveryLogDays returns the counted days, oldest first.
|
||||||
|
func (s *Store) DeliveryLogDays() ([]DeliveryLogDay, error) {
|
||||||
|
rows, err := s.db.Query(
|
||||||
|
`SELECT day, reconcile_closed, reconcile_contradicted, tailer_blind_seconds, queued_over_lifetime
|
||||||
|
FROM delivery_log_days ORDER BY day`)
|
||||||
|
if err != nil {
|
||||||
|
return nil, fmt.Errorf("delivery log days: %w", err)
|
||||||
|
}
|
||||||
|
defer rows.Close()
|
||||||
|
var out []DeliveryLogDay
|
||||||
|
for rows.Next() {
|
||||||
|
var d DeliveryLogDay
|
||||||
|
if err := rows.Scan(&d.Day, &d.Closed, &d.Contradicted, &d.BlindSeconds, &d.Stuck); err != nil {
|
||||||
|
return nil, fmt.Errorf("scan delivery log day: %w", err)
|
||||||
|
}
|
||||||
|
out = append(out, d)
|
||||||
|
}
|
||||||
|
return out, rows.Err()
|
||||||
|
}
|
||||||
|
|
||||||
|
// PruneDeliveryLogDays deletes the days older than a year.
|
||||||
|
func (s *Store) PruneDeliveryLogDays(now time.Time) error {
|
||||||
|
_, err := s.db.Exec(`DELETE FROM delivery_log_days WHERE day < ?`,
|
||||||
|
now.UTC().AddDate(0, 0, -deliveryLogKeepDays).Format(dayLayout))
|
||||||
|
if err != nil {
|
||||||
|
return fmt.Errorf("prune delivery log days: %w", err)
|
||||||
|
}
|
||||||
|
return nil
|
||||||
|
}
|
||||||
@@ -0,0 +1,69 @@
|
|||||||
|
package store
|
||||||
|
|
||||||
|
import (
|
||||||
|
"testing"
|
||||||
|
"time"
|
||||||
|
)
|
||||||
|
|
||||||
|
// The counters add up per UTC day, the stuck level is overwritten rather than
|
||||||
|
// added, nothing is written for nothing, and a year is kept.
|
||||||
|
func TestDeliveryLogDays(t *testing.T) {
|
||||||
|
st := openTestStore(t)
|
||||||
|
day1 := time.Date(2026, 10, 14, 23, 59, 0, 0, time.UTC)
|
||||||
|
day2 := day1.Add(2 * time.Minute)
|
||||||
|
|
||||||
|
must := func(err error) {
|
||||||
|
t.Helper()
|
||||||
|
if err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
must(st.AddReconcileClosed(day1, 2))
|
||||||
|
must(st.AddReconcileClosed(day1, 3))
|
||||||
|
must(st.AddReconcileClosed(day1, 0))
|
||||||
|
must(st.AddTailerBlind(day1, 1500*time.Millisecond))
|
||||||
|
must(st.AddTailerBlind(day1, 900*time.Millisecond)) // under a second: nothing
|
||||||
|
must(st.SetQueuedOverLifetime(day1, 4))
|
||||||
|
must(st.SetQueuedOverLifetime(day1, 1))
|
||||||
|
must(st.AddTailerBlind(day2, time.Minute))
|
||||||
|
|
||||||
|
days, err := st.DeliveryLogDays()
|
||||||
|
must(err)
|
||||||
|
want := []DeliveryLogDay{
|
||||||
|
{Day: "2026-10-14", Closed: 5, BlindSeconds: 1, Stuck: 1},
|
||||||
|
{Day: "2026-10-15", BlindSeconds: 60},
|
||||||
|
}
|
||||||
|
if len(days) != len(want) {
|
||||||
|
t.Fatalf("days = %+v, want %+v", days, want)
|
||||||
|
}
|
||||||
|
for i := range want {
|
||||||
|
if days[i] != want[i] {
|
||||||
|
t.Errorf("day %d = %+v, want %+v", i, days[i], want[i])
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
must(st.PruneDeliveryLogDays(day2.AddDate(1, 0, 1)))
|
||||||
|
days, err = st.DeliveryLogDays()
|
||||||
|
must(err)
|
||||||
|
if len(days) != 1 || days[0].Day != "2026-10-15" {
|
||||||
|
t.Fatalf("after pruning a year and a day later: %+v, want 2026-10-15 alone", days)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
func TestCountQueuedOlderThan(t *testing.T) {
|
||||||
|
st := openTestStore(t)
|
||||||
|
for _, e := range []SendLogEntry{{QueueID: "Q1", To: "a@example.net"}, {QueueID: "Q2", To: "b@example.net"}} {
|
||||||
|
if err := st.InsertQueued(e); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
if _, err := st.UpdateStatus("Q2", "b@example.net", StatusSent); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if n, err := st.CountQueuedOlderThan(time.Now().Add(time.Hour)); err != nil || n != 1 {
|
||||||
|
t.Fatalf("queued rows before an hour from now = %d, %v; want 1", n, err)
|
||||||
|
}
|
||||||
|
if n, err := st.CountQueuedOlderThan(time.Now().Add(-time.Hour)); err != nil || n != 0 {
|
||||||
|
t.Fatalf("queued rows before an hour ago = %d, %v; want 0", n, err)
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -0,0 +1,19 @@
|
|||||||
|
-- What the delivery log's own machinery did, a row per UTC day that has
|
||||||
|
-- something to say, kept a year (audit 2026-10-12, stage 1). These are the
|
||||||
|
-- numbers the reconcile sweep's fate is decided by; no page reads them, they
|
||||||
|
-- are read off a copy of the database. DDL only; nothing existing changes.
|
||||||
|
-- reconcile_closed rows the sweep closed as bounced (reason 'reconcile')
|
||||||
|
-- reconcile_contradicted rows closed by the sweep that a delivery line later
|
||||||
|
-- rewrote - the log wins, and is counted here
|
||||||
|
-- tailer_blind_seconds seconds the log tailer could not read mail.log
|
||||||
|
-- (the file gone, reopening it failing)
|
||||||
|
-- queued_over_lifetime rows still queued past Postfix's queue lifetime,
|
||||||
|
-- as measured by the day's last sweep (a level, not
|
||||||
|
-- a sum)
|
||||||
|
CREATE TABLE delivery_log_days (
|
||||||
|
day TEXT PRIMARY KEY,
|
||||||
|
reconcile_closed INTEGER NOT NULL DEFAULT 0,
|
||||||
|
reconcile_contradicted INTEGER NOT NULL DEFAULT 0,
|
||||||
|
tailer_blind_seconds INTEGER NOT NULL DEFAULT 0,
|
||||||
|
queued_over_lifetime INTEGER NOT NULL DEFAULT 0
|
||||||
|
);
|
||||||
@@ -60,6 +60,7 @@ func TestBaselineSchema(t *testing.T) {
|
|||||||
"send_log_lines": "id queue_id logged_at line",
|
"send_log_lines": "id queue_id logged_at line",
|
||||||
"notify_state": "key phase count mark since sent_at",
|
"notify_state": "key phase count mark since sent_at",
|
||||||
"sender_check_days": "day down_seconds deferred",
|
"sender_check_days": "day down_seconds deferred",
|
||||||
|
"delivery_log_days": "day reconcile_closed reconcile_contradicted tailer_blind_seconds queued_over_lifetime",
|
||||||
}
|
}
|
||||||
rows, err := st.db.Query("SELECT name FROM sqlite_master WHERE type = 'table' AND name NOT LIKE 'sqlite_%' ORDER BY name")
|
rows, err := st.db.Query("SELECT name FROM sqlite_master WHERE type = 'table' AND name NOT LIKE 'sqlite_%' ORDER BY name")
|
||||||
if err != nil {
|
if err != nil {
|
||||||
@@ -114,8 +115,8 @@ func TestBaselineSchema(t *testing.T) {
|
|||||||
}
|
}
|
||||||
|
|
||||||
var version, appID int64
|
var version, appID int64
|
||||||
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 6 {
|
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 7 {
|
||||||
t.Errorf("user_version = %d, %v; want 6", version, err)
|
t.Errorf("user_version = %d, %v; want 7", version, err)
|
||||||
}
|
}
|
||||||
if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID {
|
if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID {
|
||||||
t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID)
|
t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID)
|
||||||
@@ -191,8 +192,8 @@ func TestOpenMigratesA20Database(t *testing.T) {
|
|||||||
}
|
}
|
||||||
defer st.Close()
|
defer st.Close()
|
||||||
var version int
|
var version int
|
||||||
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 6 {
|
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 7 {
|
||||||
t.Errorf("user_version = %d, %v; want 6", version, err)
|
t.Errorf("user_version = %d, %v; want 7", version, err)
|
||||||
}
|
}
|
||||||
if ok, err := st.UserExists(); err != nil || !ok {
|
if ok, err := st.UserExists(); err != nil || !ok {
|
||||||
t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err)
|
t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err)
|
||||||
|
|||||||
@@ -13,6 +13,10 @@ const (
|
|||||||
ReasonFrom = "from" // the From: line is not the application's
|
ReasonFrom = "from" // the From: line is not the application's
|
||||||
)
|
)
|
||||||
|
|
||||||
|
// ReasonReconcile marks a "bounced" row the reconcile sweep closed (send_log.reason):
|
||||||
|
// its message left Postfix's queue with no delivery line ever read for it.
|
||||||
|
const ReasonReconcile = "reconcile"
|
||||||
|
|
||||||
// Settings keys of the sender check's statistics.
|
// Settings keys of the sender check's statistics.
|
||||||
const (
|
const (
|
||||||
// settingSenderCheckSince is the first UTC day the statistics cover.
|
// settingSenderCheckSince is the first UTC day the statistics cover.
|
||||||
|
|||||||
@@ -83,16 +83,65 @@ func (s *Store) InsertRejected(e SendLogEntry) error {
|
|||||||
// case between the milter (envelope) and the delivery log. It returns the
|
// case between the milter (envelope) and the delivery log. It returns the
|
||||||
// number of rows updated so the caller can tell whether the line matched a
|
// number of rows updated so the caller can tell whether the line matched a
|
||||||
// journal entry.
|
// journal entry.
|
||||||
|
//
|
||||||
|
// A row the reconcile sweep closed (reason "reconcile") that a delivery line
|
||||||
|
// now speaks of was closed on a guess the log could have settled: the log
|
||||||
|
// wins, the reason is cleared, and the day's reconcile_contradicted counts it
|
||||||
|
// (delivery_log_days) - once, since the row no longer carries the reason.
|
||||||
func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) {
|
func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) {
|
||||||
now := time.Now().UTC().Format(time.RFC3339)
|
now := time.Now().UTC()
|
||||||
res, err := s.db.Exec(
|
tx, err := s.db.Begin()
|
||||||
`UPDATE send_log SET status = ?, updated_at = ?
|
if err != nil {
|
||||||
|
return 0, fmt.Errorf("update send_log status: %w", err)
|
||||||
|
}
|
||||||
|
defer tx.Rollback()
|
||||||
|
var contradicted int64
|
||||||
|
if err := tx.QueryRow(
|
||||||
|
`SELECT COUNT(*) FROM send_log WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE AND reason = ?`,
|
||||||
|
queueID, recipient, ReasonReconcile,
|
||||||
|
).Scan(&contradicted); err != nil {
|
||||||
|
return 0, fmt.Errorf("update send_log status: %w", err)
|
||||||
|
}
|
||||||
|
res, err := tx.Exec(
|
||||||
|
`UPDATE send_log SET status = ?, updated_at = ?,
|
||||||
|
reason = CASE WHEN reason = ? THEN '' ELSE reason END
|
||||||
WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE`,
|
WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE`,
|
||||||
status, now, queueID, recipient,
|
status, now.Format(time.RFC3339), ReasonReconcile, queueID, recipient,
|
||||||
)
|
)
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return 0, fmt.Errorf("update send_log status: %w", err)
|
return 0, fmt.Errorf("update send_log status: %w", err)
|
||||||
}
|
}
|
||||||
|
if contradicted > 0 {
|
||||||
|
if _, err := tx.Exec(
|
||||||
|
`INSERT INTO delivery_log_days (day, reconcile_contradicted) VALUES (?, ?)
|
||||||
|
ON CONFLICT (day) DO UPDATE SET reconcile_contradicted = reconcile_contradicted + excluded.reconcile_contradicted`,
|
||||||
|
now.Format(dayLayout), contradicted,
|
||||||
|
); err != nil {
|
||||||
|
return 0, fmt.Errorf("update send_log status: count the contradicted sweep: %w", err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
if err := tx.Commit(); err != nil {
|
||||||
|
return 0, fmt.Errorf("update send_log status: %w", err)
|
||||||
|
}
|
||||||
|
n, _ := res.RowsAffected()
|
||||||
|
return n, nil
|
||||||
|
}
|
||||||
|
|
||||||
|
// CloseUnreported is the reconcile sweep's close of one row: "bounced", marked
|
||||||
|
// reason "reconcile" so it is known who decided it (architecture.md § Log
|
||||||
|
// tailer). Only a row still "queued" is closed - a result the log wrote an
|
||||||
|
// instant earlier stands, and a months-old row of a reused queue id is not
|
||||||
|
// rewritten (audit 2026-10-12, H3). It returns the number of rows closed.
|
||||||
|
func (s *Store) CloseUnreported(queueID, recipient string) (int64, error) {
|
||||||
|
now := time.Now().UTC().Format(time.RFC3339)
|
||||||
|
res, err := s.db.Exec(
|
||||||
|
`UPDATE send_log SET status = ?, reason = ?, updated_at = ?
|
||||||
|
WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE AND status = ?`,
|
||||||
|
StatusBounced, ReasonReconcile, now, queueID, recipient, StatusQueued,
|
||||||
|
)
|
||||||
|
if err != nil {
|
||||||
|
return 0, fmt.Errorf("close unreported send_log row: %w", err)
|
||||||
|
}
|
||||||
n, _ := res.RowsAffected()
|
n, _ := res.RowsAffected()
|
||||||
return n, nil
|
return n, nil
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -97,6 +97,73 @@ func TestUpdateStatusRecipientCaseInsensitive(t *testing.T) {
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// The sweep closes only what is still queued, and says it was the sweep: a
|
||||||
|
// status the log wrote stands, whatever the sweep believed when it listed the
|
||||||
|
// row.
|
||||||
|
func TestCloseUnreportedClosesOnlyQueuedRows(t *testing.T) {
|
||||||
|
st := openTestStore(t)
|
||||||
|
for _, e := range []SendLogEntry{{QueueID: "Q1", To: "Lost@example.net"}, {QueueID: "Q2", To: "done@example.net"}} {
|
||||||
|
if err := st.InsertQueued(e); err != nil {
|
||||||
|
t.Fatalf("InsertQueued: %v", err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
if _, err := st.UpdateStatus("Q2", "done@example.net", StatusSent); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
|
||||||
|
if n, err := st.CloseUnreported("Q1", "lost@example.net"); err != nil || n != 1 {
|
||||||
|
t.Fatalf("CloseUnreported of a queued row = %d, %v; want 1", n, err)
|
||||||
|
}
|
||||||
|
if n, err := st.CloseUnreported("Q2", "done@example.net"); err != nil || n != 0 {
|
||||||
|
t.Fatalf("CloseUnreported of a sent row = %d, %v; want 0", n, err)
|
||||||
|
}
|
||||||
|
|
||||||
|
var status, reason string
|
||||||
|
for _, c := range []struct{ id, status, reason string }{
|
||||||
|
{"Q1", StatusBounced, ReasonReconcile},
|
||||||
|
{"Q2", StatusSent, ""},
|
||||||
|
} {
|
||||||
|
if err := st.db.QueryRow(`SELECT status, reason FROM send_log WHERE queue_id = ?`, c.id).Scan(&status, &reason); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if status != c.status || reason != c.reason {
|
||||||
|
t.Errorf("%s: status %q reason %q, want %q %q", c.id, status, reason, c.status, c.reason)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
// A delivery line about a row the sweep closed proves the sweep guessed what
|
||||||
|
// the log could have said: the log's status wins, the reason goes, and the day
|
||||||
|
// counts one contradiction - once, however often the line is read again.
|
||||||
|
func TestUpdateStatusCountsAContradictedSweep(t *testing.T) {
|
||||||
|
st := openTestStore(t)
|
||||||
|
if err := st.InsertQueued(SendLogEntry{QueueID: "Q1", To: "a@example.net"}); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if _, err := st.CloseUnreported("Q1", "a@example.net"); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
for i := 0; i < 2; i++ {
|
||||||
|
if n, err := st.UpdateStatus("Q1", "A@example.net", StatusSent); err != nil || n != 1 {
|
||||||
|
t.Fatalf("UpdateStatus = %d, %v", n, err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
var status, reason string
|
||||||
|
if err := st.db.QueryRow(`SELECT status, reason FROM send_log WHERE queue_id = 'Q1'`).Scan(&status, &reason); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if status != StatusSent || reason != "" {
|
||||||
|
t.Fatalf("status %q reason %q, want sent and no reason", status, reason)
|
||||||
|
}
|
||||||
|
days, err := st.DeliveryLogDays()
|
||||||
|
if err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if len(days) != 1 || days[0].Contradicted != 1 {
|
||||||
|
t.Fatalf("days = %+v, want one day with one contradiction", days)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
// The reconcile sweep asks for the rows old enough that Postfix should have
|
// The reconcile sweep asks for the rows old enough that Postfix should have
|
||||||
// reported on them by now. A message accepted moments ago is simply in flight,
|
// reported on them by now. A message accepted moments ago is simply in flight,
|
||||||
// and one the milter refused never reached the queue at all, so neither is the
|
// and one the milter refused never reached the queue at all, so neither is the
|
||||||
|
|||||||
@@ -0,0 +1,81 @@
|
|||||||
|
package e2e
|
||||||
|
|
||||||
|
import (
|
||||||
|
"crypto/tls"
|
||||||
|
"crypto/x509"
|
||||||
|
"encoding/pem"
|
||||||
|
"fmt"
|
||||||
|
"math/big"
|
||||||
|
"net"
|
||||||
|
"os"
|
||||||
|
"path/filepath"
|
||||||
|
"time"
|
||||||
|
)
|
||||||
|
|
||||||
|
// servedSerial is the serial of the certificate Postfix presents on the
|
||||||
|
// implicit-TLS port.
|
||||||
|
func servedSerial() (*big.Int, error) {
|
||||||
|
conn, err := tls.DialWithDialer(&net.Dialer{Timeout: 5 * time.Second}, "tcp", smtpsAddr, &tls.Config{
|
||||||
|
InsecureSkipVerify: true,
|
||||||
|
ServerName: selfpostHostname,
|
||||||
|
})
|
||||||
|
if err != nil {
|
||||||
|
return nil, err
|
||||||
|
}
|
||||||
|
defer conn.Close()
|
||||||
|
certs := conn.ConnectionState().PeerCertificates
|
||||||
|
if len(certs) == 0 {
|
||||||
|
return nil, fmt.Errorf("no certificate presented")
|
||||||
|
}
|
||||||
|
return certs[0].SerialNumber, nil
|
||||||
|
}
|
||||||
|
|
||||||
|
func fileSerial(path string) (*big.Int, error) {
|
||||||
|
raw, err := os.ReadFile(path)
|
||||||
|
if err != nil {
|
||||||
|
return nil, err
|
||||||
|
}
|
||||||
|
block, _ := pem.Decode(raw)
|
||||||
|
if block == nil {
|
||||||
|
return nil, fmt.Errorf("%s holds no PEM block", path)
|
||||||
|
}
|
||||||
|
cert, err := x509.ParseCertificate(block.Bytes)
|
||||||
|
if err != nil {
|
||||||
|
return nil, err
|
||||||
|
}
|
||||||
|
return cert.SerialNumber, nil
|
||||||
|
}
|
||||||
|
|
||||||
|
// checkCertRenewalPickedUp replaces the certificate in the stand's mount, as
|
||||||
|
// a renewer would, and waits for port 465 to present it without a restart.
|
||||||
|
// Postfix reads a copy made at start (postfix-config.sh); until 2.5.0 nothing
|
||||||
|
// renewed that copy, and a renewed certificate reached Postfix only when the
|
||||||
|
// container was restarted (audit 2026-10-12, H2). compose.override.yml sets
|
||||||
|
// TLS_RELOAD_INTERVAL_SECONDS to 2 so this does not wait a day.
|
||||||
|
func checkCertRenewalPickedUp(s *stack) error {
|
||||||
|
certPath := filepath.Join(s.stageDir, "certs", "fullchain.pem")
|
||||||
|
before, err := servedSerial()
|
||||||
|
if err != nil {
|
||||||
|
return fmt.Errorf("read the served certificate: %w", err)
|
||||||
|
}
|
||||||
|
if err := writeSelfSignedCert(certPath, filepath.Join(s.stageDir, "certs", "privkey.pem")); err != nil {
|
||||||
|
return fmt.Errorf("renew the certificate: %w", err)
|
||||||
|
}
|
||||||
|
want, err := fileSerial(certPath)
|
||||||
|
if err != nil {
|
||||||
|
return err
|
||||||
|
}
|
||||||
|
if want.Cmp(before) == 0 {
|
||||||
|
return fmt.Errorf("the renewed certificate has the old serial %s", before)
|
||||||
|
}
|
||||||
|
return waitFor("port 465 to present the renewed certificate", 30*time.Second, 500*time.Millisecond, func() (bool, error) {
|
||||||
|
got, err := servedSerial()
|
||||||
|
if err != nil {
|
||||||
|
return false, err
|
||||||
|
}
|
||||||
|
if got.Cmp(want) != 0 {
|
||||||
|
return false, fmt.Errorf("serial %s served, want %s", got, want)
|
||||||
|
}
|
||||||
|
return true, nil
|
||||||
|
})
|
||||||
|
}
|
||||||
@@ -48,6 +48,10 @@ services:
|
|||||||
# loops well past this count) is meant to hit it.
|
# loops well past this count) is meant to hit it.
|
||||||
RATE_LIMIT_MESSAGES_PER_IP: "50"
|
RATE_LIMIT_MESSAGES_PER_IP: "50"
|
||||||
RATE_LIMIT_WINDOW_SECONDS: "60"
|
RATE_LIMIT_WINDOW_SECONDS: "60"
|
||||||
|
# cert-reload compares the mounted certificate with Postfix's copy this
|
||||||
|
# often, so renewed_certificate_picked_up does not wait a day. It
|
||||||
|
# reloads Postfix only when the certificate changed.
|
||||||
|
TLS_RELOAD_INTERVAL_SECONDS: "2"
|
||||||
ports: !override
|
ports: !override
|
||||||
- "20465:465"
|
- "20465:465"
|
||||||
- "20587:587"
|
- "20587:587"
|
||||||
|
|||||||
@@ -147,6 +147,12 @@ func TestE2E(t *testing.T) {
|
|||||||
}
|
}
|
||||||
})
|
})
|
||||||
|
|
||||||
|
run("renewed_certificate_picked_up", func(t *testing.T) {
|
||||||
|
if err := checkCertRenewalPickedUp(h); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
})
|
||||||
|
|
||||||
run("setup_and_login", func(t *testing.T) {
|
run("setup_and_login", func(t *testing.T) {
|
||||||
token, err := readSetupToken(h)
|
token, err := readSetupToken(h)
|
||||||
if err != nil {
|
if err != nil {
|
||||||
@@ -304,6 +310,9 @@ func TestE2E(t *testing.T) {
|
|||||||
run("panel_down_defers_mail", func(t *testing.T) {
|
run("panel_down_defers_mail", func(t *testing.T) {
|
||||||
testPanelDownDefersMail(t, sc)
|
testPanelDownDefersMail(t, sc)
|
||||||
})
|
})
|
||||||
|
run("panel_hung_mid_message_is_counted", func(t *testing.T) {
|
||||||
|
testPanelHungMidMessage(t, sc)
|
||||||
|
})
|
||||||
run("session_survives_restart", func(t *testing.T) {
|
run("session_survives_restart", func(t *testing.T) {
|
||||||
testSessionSurvivesRestart(t, sc)
|
testSessionSurvivesRestart(t, sc)
|
||||||
})
|
})
|
||||||
|
|||||||
@@ -1,8 +1,11 @@
|
|||||||
package e2e
|
package e2e
|
||||||
|
|
||||||
import (
|
import (
|
||||||
|
"crypto/tls"
|
||||||
"errors"
|
"errors"
|
||||||
"fmt"
|
"fmt"
|
||||||
|
"net"
|
||||||
|
"net/smtp"
|
||||||
"net/textproto"
|
"net/textproto"
|
||||||
"regexp"
|
"regexp"
|
||||||
"strconv"
|
"strconv"
|
||||||
@@ -187,3 +190,117 @@ func testPanelDownDefersMail(t *testing.T, sc *scenario) {
|
|||||||
t.Fatal(err)
|
t.Fatal(err)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// senderCheckDeferredToday reads Server > Health's "Sender check" row for
|
||||||
|
// today: the messages deferred because the check did not answer.
|
||||||
|
func senderCheckDeferredToday(sc *scenario) (int, error) {
|
||||||
|
_, body, err := sc.panel.get("/server/health")
|
||||||
|
if err != nil {
|
||||||
|
return 0, err
|
||||||
|
}
|
||||||
|
m := regexp.MustCompile(`<tr><td>Today</td><td>([^<]*)</td><td>(\d+)</td></tr>`).FindStringSubmatch(body)
|
||||||
|
if m == nil {
|
||||||
|
return 0, fmt.Errorf("no Sender check row for today on Health")
|
||||||
|
}
|
||||||
|
return strconv.Atoi(m[2])
|
||||||
|
}
|
||||||
|
|
||||||
|
// testPanelHungMidMessage: a panel that is running and stops answering in the
|
||||||
|
// middle of a message - its socket still accepts, nothing replies. The
|
||||||
|
// message is deferred, and the count on Health sees it. Past the DATA
|
||||||
|
// command Postfix's cleanup, not smtpd, talks to the milters, so the warning
|
||||||
|
// that names the socket is cleanup's (audit 2026-10-12, M13: the counter read
|
||||||
|
// smtpd's lines only). The panel is frozen with SIGSTOP once DATA is
|
||||||
|
// answered, and thawed after the client has its reply.
|
||||||
|
func testPanelHungMidMessage(t *testing.T, sc *scenario) {
|
||||||
|
before, err := senderCheckDeferredToday(sc)
|
||||||
|
if err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
pidOut, err := h.execIn("selfpost", "supervisorctl", "-c", "/etc/supervisor/supervisord.conf", "pid", "panel")
|
||||||
|
if err != nil {
|
||||||
|
t.Fatalf("panel pid: %v (%s)", err, pidOut)
|
||||||
|
}
|
||||||
|
pid := strings.TrimSpace(pidOut)
|
||||||
|
if _, err := strconv.Atoi(pid); err != nil {
|
||||||
|
t.Fatalf("panel pid: %q", pidOut)
|
||||||
|
}
|
||||||
|
signal := func(sig string) error {
|
||||||
|
// kill is the shell's: the image has no kill(1).
|
||||||
|
_, err := h.execIn("selfpost", "sh", "-c", "kill -"+sig+" "+pid)
|
||||||
|
return err
|
||||||
|
}
|
||||||
|
thawed := false
|
||||||
|
thaw := func() {
|
||||||
|
if !thawed {
|
||||||
|
thawed = true
|
||||||
|
_ = signal("CONT")
|
||||||
|
}
|
||||||
|
}
|
||||||
|
t.Cleanup(thaw)
|
||||||
|
|
||||||
|
conn, err := tls.DialWithDialer(&net.Dialer{Timeout: 10 * time.Second}, "tcp", smtpsAddr, &tls.Config{
|
||||||
|
InsecureSkipVerify: true,
|
||||||
|
ServerName: selfpostHostname,
|
||||||
|
})
|
||||||
|
if err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
_ = conn.SetDeadline(time.Now().Add(3 * time.Minute))
|
||||||
|
c, err := smtp.NewClient(conn, selfpostHostname)
|
||||||
|
if err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
defer c.Close()
|
||||||
|
from := "alerts@" + senderDomain
|
||||||
|
if err := c.Hello("e2e-client.e2e.test"); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if err := c.Auth(smtp.PlainAuth("", sc.appLogin, sc.appPassword, selfpostHostname)); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if err := c.Mail(from); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if err := c.Rcpt(recipient); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
w, err := c.Data()
|
||||||
|
if err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if err := signal("STOP"); err != nil {
|
||||||
|
t.Fatalf("freeze the panel: %v", err)
|
||||||
|
}
|
||||||
|
started := time.Now()
|
||||||
|
_, err = w.Write([]byte(buildMessage(sendAttempt{from: from, to: recipient, subject: "e2e " + uniqueToken("panelhung"), body: "must be deferred"})))
|
||||||
|
if err == nil {
|
||||||
|
err = w.Close()
|
||||||
|
}
|
||||||
|
t.Logf("end of DATA answered after %s: %v", time.Since(started).Round(time.Second), err)
|
||||||
|
thaw()
|
||||||
|
var reply *textproto.Error
|
||||||
|
if !errors.As(err, &reply) || reply.Code/100 != 4 {
|
||||||
|
t.Fatalf("want a temporary 4xx at the end of DATA with the panel frozen, got %v", err)
|
||||||
|
}
|
||||||
|
_ = c.Quit()
|
||||||
|
|
||||||
|
// What Postfix wrote, so that the program and the wording are seen here
|
||||||
|
// and not assumed.
|
||||||
|
if out, err := h.execIn("selfpost", "sh", "-c", "grep -i 'milter' /data/log/mail.log | tail -n 8"); err == nil {
|
||||||
|
t.Logf("mail.log on the frozen panel:\n%s", out)
|
||||||
|
}
|
||||||
|
|
||||||
|
if err := waitFor("Health to count the message deferred mid-message", 30*time.Second, 500*time.Millisecond, func() (bool, error) {
|
||||||
|
n, err := senderCheckDeferredToday(sc)
|
||||||
|
if err != nil {
|
||||||
|
return false, err
|
||||||
|
}
|
||||||
|
if n <= before {
|
||||||
|
return false, fmt.Errorf("messages deferred today: %d, as before", n)
|
||||||
|
}
|
||||||
|
return true, nil
|
||||||
|
}); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|||||||
Reference in New Issue
Block a user