Compare commits

..
7 Commits
Author SHA1 Message Date
mixandClaude Opus 5.5 a59e3d4d61 docs: stage 1 of the audit - log tailer, reconcile, sender check, guide
test / test (push) Canceled after 0s
architecture.md
- § Log tailer: the rotation drain does not close the gap entirely
  (postlogd writes to the renamed file until the reload reaches it); the fix
  waits for the measurement. Delivery lines read at the head of the line
  (M12).
- § Queue reconcile: reason "reconcile", the 4 MiB cap, the conditional
  close; the measurement (delivery_log_days, its four counters) and the
  decision rule written before the data.
- § Sender check, what it costs: cleanup meets a check that hangs mid-message,
  with the warning seen on the stand; counted once per message.

guide.md
- § Outbound log: `bounced` is the panel's word when Postfix no longer holds
  a message and the log never said; it is counted.
- § Overview and Health, Sender check: the message a hung panel deferred is
  counted too.

Audit plan line ticked, roadmap 14/61. Stage 1's code items are done
(the two deferred tailer fixes wait for the data, as planned).

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 14:42:02 +03:00
mixandClaude Opus 5.5 db36aa2c0e logtail: count the message a hung sender check defers in cleanup (audit M13)
Seen on the e2e stand, the panel frozen with SIGSTOP once DATA was
answered: the client gets 451 4.7.1 after 30 s, and the warning that names
the socket is cleanup's, not smtpd's:

  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 ...
    4.7.1 Service unavailable - try again later; ...

The counter read smtpd lines only, so Health's "messages deferred" missed
the one case that tells a hung panel from a stopped one. milterLineRe now
takes smtpd and cleanup; cleanup's "milter unix:<socket>:" warning counts a
message each time (one cleanup process serves message after message, and the
first warning ends the message); smtpd keeps once per connection. The
composed fixture is replaced by the seen lines, with two messages through one
cleanup process and OpenDKIM hung in cleanup (not counted).

e2e panel_hung_mid_message_is_counted: freezes the panel after DATA's 354,
wants a 4xx at the end of DATA, logs what mail.log says, and waits for
Health's today count to grow. kill through sh -c: the image has no kill(1).

CHANGELOG [Unreleased], audit plan line ticked, roadmap 13/61.
Evidence on the test server for this tree (with the next commit's docs):
go vet clean, go test ./... 23 packages ok, make e2e exit 0 -
renewed_certificate_picked_up 1.2 s, panel_hung_mid_message_is_counted
31.7 s.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 14:42:01 +03:00
mixandClaude Opus 5.5 7af37654a1 cert-reload: renew Postfix's copy of a renewed certificate (audit H2)
postfix-config.sh copies the mounted certificate and key into
/etc/postfix/tls-internal at start (root-owned, key 0600) and Postfix reads
the copy; cert-reload only ran `postfix reload` daily, which re-read the
stale copy, so a certificate renewed while the container ran expired on
465/587 with the old one.

postfix-cert-reload.sh now, every TLS_RELOAD_INTERVAL_SECONDS: compares the
mount with the copy (cmp); when they differ and the certificate and key
belong together (openssl public keys equal - a renewer writes them one
after the other), writes each file beside its target, root-owned with the
start's modes, renames it over the target, and reloads Postfix. Nothing
changed - no reload. No copy (files missing at start) - the old periodic
reload. Never exits non-zero.

e2e renewed_certificate_picked_up: writes a new certificate into the
stand's mount and waits (30 s) for port 465 to present its serial;
compose.override.yml sets TLS_RELOAD_INTERVAL_SECONDS=2.
supervisord.conf comment, architecture.md (process table, § Postfix TLS
certs, the env knob), guide (after the proxies: picked up within a day).
CHANGELOG [Unreleased], audit plan line ticked, roadmap 12/61.

Evidence: GOOS=linux go vet in test/e2e clean; the server run of the stage
follows before the push.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 14:25:20 +03:00
mixandClaude Opus 5.5 63520f1678 logtail: deliveryRe anchored at the head of the line (audit M12)
The pattern that writes a row's status matched anywhere in a line: a
port-25 reject line ending helo=<ID: to=<victim@...>, status=sent> parsed
as (ID, victim, sent). parseDelivery now takes the stamp off with
SplitTimestamp and matches `^host program[pid]: <id>: to=<...>, ...
status=`, as queueLineRe and the inbound patterns do.

Tests: the probed HELO line, the same text in a quoted sender on a qmgr
line, the text after an smtpd line's queue id - none parse; a syslog-stamped
line as Postfix 3.7 writes it parses. The existing cases unchanged.

CHANGELOG [Unreleased], audit plan line ticked, roadmap 11/61.
Evidence: go test ./internal/logtail ok but for TestFollowTailsAndRotates
(Windows); the server run of the stage follows before the push.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 14:22:03 +03:00
mixandClaude Opus 5.5 ffefa9d6df delivery log: measure the sweep before deciding its fate (audit H3, 0007)
Migration 0007 (DDL only): delivery_log_days, a row per UTC day, kept a
year, shown nowhere - read off a copy of the database after a month by the
decision rule written in the audit plan.

- reconcile_closed: the sweep adds the rows it actually closed.
- reconcile_contradicted: store.UpdateStatus, in one transaction, counts the
  rows with reason "reconcile" a delivery line now speaks of, writes the
  log's status and clears the reason - so a re-read line counts once.
- tailer_blind_seconds: follow() tracks stretches in which the file is gone
  or reopening fails (logtail.blindness); stored when a stretch ends and
  every minute while it lasts; under 3 s not counted (the rotation's tick
  between rename and create loses nothing).
- queued_over_lifetime: every sweep overwrites the day's level with the rows
  queued past LongestLifetime + MaximalBackoff (a message Postfix still
  works on stays queued until its first retry after the lifetime).
- retentionLoop prunes days older than a year.

Tests: store (sums per day, the level overwritten, under a second nothing,
prune; a contradicted sweep counted once and its reason cleared; count of
queued rows); logtail (the sweep counts what it closed; countStuck records
the level; blindness - a one-tick gap not counted, 75 s stored as 60 + 15
from where the last part ended). Schema tests at user_version 7.

schema-migrations.md: chain head 7 (it still said 5 since 2.4.0), row 7.
CHANGELOG [Unreleased], audit plan line ticked, roadmap 10/61.
Evidence: go vet ./... clean; go test ./internal/store ok, ./internal/logtail
ok but for TestFollowTailsAndRotates (Windows); the server run of the stage
follows before the push.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 14:20:44 +03:00
mixandClaude Opus 5.5 9adb44845c logtail: the sweep closes only queued rows, with reason "reconcile" (audit H3)
reconcile() closed a row through UpdateStatus (WHERE queue_id AND to_addr),
which could overwrite a "sent" the tailer wrote between the listing and the
close, and rewrite an old row of a reused queue id. store.CloseUnreported
sets status bounced and reason "reconcile" (store.ReasonReconcile; the
0006 column, no schema change) WHERE ... AND status = 'queued'; the sweep
counts rows actually closed.

Tests: store - a queued row is closed with the reason, a sent row is left
alone (0 rows); logtail - the sweep's close goes through CloseUnreported.

CHANGELOG [Unreleased], audit plan line ticked, roadmap 9/61.
Evidence: go vet ./... clean; go test ./internal/store ok, ./internal/logtail
ok but for TestFollowTailsAndRotates (Windows rename of an open file, fails
here always); the server run of the stage follows before the push.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 14:16:26 +03:00
mixandClaude Opus 5.5 dfe10f6c27 postfix: a truncated postqueue -p listing is no listing for the sweep (audit H3)
QueueIDs parsed Queue()'s text, which caps postqueue -p at 4 MiB and
appends a note, and returned the ids before the cut with no error: the
reconcile sweep then closed every queued row past the cut as bounced while
Postfix still held the mail. listQueue() now returns the text and whether
it was cut; QueueIDs refuses a cut listing with an error (reconcile already
treats an error as no information), the way postqueueJSON does for the
notifier. Queue() keeps showing the cut listing with its note.

postqueueP is a var so tests run a fake postqueue (the test binary as a
helper process): 5 MiB -> QueueIDs errors, Queue ends with the note; 1000
bytes -> ids read.

CHANGELOG [Unreleased], audit plan line ticked, roadmap 8/61.
Evidence: go test ./internal/postfix ok (Windows); the server run of the
stage follows before the push.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 14:13:34 +03:00
26 changed files with 1128 additions and 107 deletions
+50
View File
@@ -5,6 +5,56 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version
## [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
Release hygiene: stage 0 of the 2026-10-12 audit. Nothing the panel or the
+61 -17
View File
@@ -1,25 +1,69 @@
#!/bin/sh
# Periodic `postfix reload` so refreshed TLS certificates are picked up (spec
# 5.2 p.4). The reverse-proxy renews the PEM files in the read-only mount every
# 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.
# Picks up a renewed TLS certificate while the container runs (spec 5.2 p.4;
# audit 2026-10-12, H2).
#
# Runs under supervisord as root, so it can reload Postfix directly. It sleeps
# first, then reloads in a loop: no reload at container start (the wrapper is
# still bringing Postfix up then) and none until at least one interval has
# passed. A reload is harmless when nothing changed.
set -eu
# Postfix does not read the mounted files: postfix-config.sh copies them at
# start into /etc/postfix/tls-internal, because Postfix wants the key owned by
# root with mode 0600, which a read-only bind mount owned by the host's user
# cannot give. A renewal of the mounted files therefore reaches Postfix only
# 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}"
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
sleep "${INTERVAL}"
if postfix reload; then
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
refresh
done
+3 -2
View File
@@ -89,8 +89,9 @@ stdout_logfile_maxbytes=0
stderr_logfile=/dev/stderr
stderr_logfile_maxbytes=0
; Periodic TLS-certificate refresh. Runs a daily `postfix reload`
; so certificates the reverse-proxy renews in the read-only mount are picked up.
; TLS-certificate refresh. Once a day it compares the certificate the
; 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
; non-zero, so it neither trips the crashexit listener nor needs restarting.
[program:cert-reload]
+57 -14
View File
@@ -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 |
| `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) |
| `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 |
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` /
`anvil_rate_time_unit` from `RATE_LIMIT_*` env vars; independent of milter.
- **Chroot disabled** for all services (DNS/TLS inside container).
- **TLS certs** — read-only mount at `TLS_CERT_FILE` / `TLS_KEY_FILE`; daily
reload via `cert-reload`.
- **TLS certs** — read-only mount at `TLS_CERT_FILE` / `TLS_KEY_FILE`, copied
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
@@ -280,7 +284,14 @@ server itself.
(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
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
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
@@ -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
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
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
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
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),
[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
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
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
leaves every row untouched rather than closing them all. Now that the log
survives the container, reaching this path means the lines are gone for good —
rotated past fourteen files while the panel was down, or deleted.
end-of-file once (on a restart the log itself holds the answer); the two-minute
grace covers messages merely in flight; a `postqueue` that cannot be read, or
whose listing is over the 4 MiB cap, leaves every row untouched rather than
closing them all or those past the cut; and the close is conditional on the
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;
[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_COMMAND_TIMEOUT` (`15s`), `MILTER_CONTENT_TIMEOUT` (`30s`),
`MILTER_WAIT_TIMEOUT` (`30` seconds).
- **Background maintenance:** `TLS_RELOAD_INTERVAL_SECONDS` (`86400` — daily
`postfix reload` to pick up renewed certificates),
- **Background maintenance:** `TLS_RELOAD_INTERVAL_SECONDS` (`86400` — how
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
hours; logrotate keeps 14 rotated files on a daily schedule, and each
rotation triggers `postfix reload`).
+7 -7
View File
@@ -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`
- [ ] **`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
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'`
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
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
@@ -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
tailer's blindness and stay on the list whatever the sweep's fate; their
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**
- [ ] **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);
e2e replaces the cert in the stand and reads the new serial off 465.
— **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 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.
— **Sonnet**
+12 -2
View File
@@ -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.
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
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
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
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
at nothing, the panel is in the way of your mail more than it should be -
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,
sender, recipient, subject and status `queued` (accepted, not yet
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
limit](#rate-limiting--level-2-domain-and-application)), `wrong client` (the
application's client IP list) or `wrong From` (see [Who an application may
+1 -1
View File
@@ -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) |
| 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) |
| 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
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and
+5 -3
View File
@@ -17,8 +17,8 @@ When you add or review a migration, update this file in the same change.
| Field | Value |
|---|---|
| Chain head | `user_version = 5` |
| 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` |
| 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`, `0007_delivery_log_days.sql` |
| File mark | `PRAGMA application_id = 0x53503230` ("SP20") |
| 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.** |
@@ -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
delivery-log-storage (`2.2.0`), `0004_notifications.sql` 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` |
| 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` |
| 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
for operators upgrading from older 2.x images.
+108 -7
View File
@@ -31,6 +31,13 @@ import (
type StatusStore interface {
UpdateStatus(queueID, recipient, status string) (int64, 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)
InsertSendLogLines(lines []store.SendLogLine, once bool) (int, 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.
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 (
// reconcileInterval is how often the sweep compares stuck rows against the
// 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
// 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
// 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
// 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=<…>.
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.
// ok is false for lines that are not recognised delivery results.
func parseDelivery(line string) (queueID, recipient, status string, ok bool) {
m := deliveryRe.FindStringSubmatch(line)
_, rest := SplitTimestamp(line)
m := deliveryRe.FindStringSubmatch(rest)
if m == nil {
return "", "", "", false
}
@@ -178,6 +197,11 @@ func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{}
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)
defer t.Stop()
for {
@@ -185,13 +209,30 @@ func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{}
case <-ctx.Done():
return
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
// 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
// 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
}
var closed int
var closed int64
for _, row := range rows {
if _, still := held[row.QueueID]; still {
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)
continue
}
closed++
closed += n
}
if closed > 0 {
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()
pruneLines(st)
pruneDays()
t := time.NewTicker(retentionInterval)
defer t.Stop()
for {
@@ -267,6 +319,7 @@ func retentionLoop(ctx context.Context, st StatusStore, retention RetentionDays)
case <-t.C:
prune()
pruneLines(st)
pruneDays()
}
}
}
@@ -548,12 +601,14 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
}
var once sync.Once
blind := &blindness{add: tr.st.AddTailerBlind}
ticker := time.NewTicker(pollInterval)
defer ticker.Stop()
for {
select {
case <-ctx.Done():
blind.see(time.Now(), false)
tr.record(f, read(), true) // shutdown: the next start resumes here
return nil
case <-ticker.C:
@@ -561,6 +616,7 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
once.Do(func() { close(caughtUp) })
ni, err := os.Stat(path)
if err != nil {
blind.see(time.Now(), true)
continue // file briefly gone mid-rotation; try again next tick
}
pos, _ := f.Seek(0, io.SeekCurrent)
@@ -572,12 +628,57 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
drain()
if err := openAt(0, io.SeekStart); err != nil {
log.Printf("log-tailer: reopen %s: %v", path, err)
blind.see(time.Now(), true)
continue
}
blind.see(time.Now(), false)
tr.adopt(f)
continue
}
blind.see(time.Now(), 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
}
+118 -2
View File
@@ -116,6 +116,34 @@ func TestParseDelivery(t *testing.T) {
line: "host postfix/cleanup[12]: BEEF03: message-id=<x@example.com>",
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 {
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 []store.QueuedDelivery
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
// each PruneSendLogLines call.
@@ -208,8 +241,38 @@ func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, e
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 }
// 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) {
c.mu.Lock()
defer c.mu.Unlock()
@@ -433,8 +496,61 @@ func TestReconcileClosesOnlyWhatPostfixNoLongerHolds(t *testing.T) {
reconcile(cs, time.Now().UTC())
got := cs.snapshot()
if len(got) != 1 || got[0] != "GONEQ|lost@example.net|"+store.StatusBounced {
t.Fatalf("got %v, want only the message Postfix dropped closed as bounced", got)
if len(got) != 1 || got[0] != "GONEQ|lost@example.net|"+store.ReasonReconcile {
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])
}
}
}
+10
View File
@@ -23,6 +23,16 @@ func (s *retentionProbeStore) ListQueuedOlderThan(time.Time) ([]store.QueuedDeli
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) {
s.mu.Lock()
s.cutoff = cutoff
+39 -17
View File
@@ -27,11 +27,21 @@ import (
//
// 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
// answer and when the journal milter refuses under a level-2 limit, and for a
// 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
// "milter unix:<socket>: can't read … reply packet header" (Postfix's
// milter8.c; not seen on the stand).
// answer and when the journal milter refuses under a level-2 limit.
//
// A check that is running and stops answering in the middle of a message -
// its socket accepts, nothing replies - is met by cleanup, not smtpd: past the
// 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
// counted line is kept. *store.Store satisfies it.
@@ -47,7 +57,7 @@ type SenderCheck struct {
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 (
// 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.
func (c *deferredCounter) handle(line string, now time.Time, catchingUp bool) {
at, rest := lineTime(line, now)
m := smtpdLineRe.FindStringSubmatch(rest)
m := milterLineRe.FindStringSubmatch(rest)
if m == nil {
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 {
case strings.HasPrefix(text, "connect from "):
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[pid] = true
if catchingUp && !at.After(c.last) {
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)
}
c.count(at, catchingUp)
}
}
// count adds one deferred message at at, unless it is a line read again.
func (c *deferredCounter) count(at time.Time, catchingUp bool) {
if catchingUp && !at.After(c.last) {
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)
}
}
+17 -11
View File
@@ -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
// with the panel stopped and for a refused From: (2026-10-12; the stamps are
// put in ISO form). Around them are the lines of two other things that use
// the same words - a level-2 refusal of the journal milter, OpenDKIM not
// answering - and, composed from Postfix's source rather than seen, a check
// that stops answering in the middle of a message.
// with the panel stopped and for a refused From: (2026-10-12), and with the
// panel frozen in the middle of a message (cleanup 1339, 2026-10-14); the
// stamps are put in ISO form. Around them are the lines of two other things
// that use the same words - a level-2 refusal of the journal milter, OpenDKIM
// not answering.
func TestDeferredCounter(t *testing.T) {
st := &deferredStore{}
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.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: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: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: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: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: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: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
// cleanup that writes it.
@@ -73,8 +79,8 @@ func TestDeferredCounter(t *testing.T) {
} {
c.handle(line, now, false)
}
if len(st.days) != 2 || st.days["2026-10-12"] != 1 || st.days["2026-10-13"] != 1 {
t.Fatalf("deferred per day = %v, want one on each of the two days", st.days)
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 the first day and two on the second", st.days)
}
}
+35 -15
View File
@@ -41,28 +41,43 @@ func (l *limitWriter) Write(p []byte) (int, error) {
return len(p), nil
}
// 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 command takes a
// single fixed flag and no user input, so it never goes through a shell
// (security.md). The panel is responsible for escaping the output before
// display (security.md); this function returns it as-is.
func Queue() (string, error) {
// postqueueP builds the `postqueue -p` command. It is a var so tests can put
// a fake postqueue in its place, the way readQueueJSON is.
var postqueueP = func(ctx context.Context) *exec.Cmd {
// A single fixed flag and no user input, never through a shell (security.md).
return exec.CommandContext(ctx, "postqueue", "-p")
}
// 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)
defer cancel()
cmd := exec.CommandContext(ctx, "postqueue", "-p")
cmd := postqueueP(ctx)
out := &limitWriter{remaining: maxQueueOutput}
cmd.Stdout = out
cmd.Stderr = out
err := cmd.Run()
err = cmd.Run()
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 {
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()
if out.truncated {
return out.buf.String(), out.truncated, nil
}
// 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)
}
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
// 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) {
out, err := Queue()
out, truncated, err := listQueue()
if err != nil {
return nil, err
}
if truncated {
return nil, fmt.Errorf("postqueue -p: listing is larger than %d bytes", maxQueueOutput)
}
return parseQueueIDs(out), nil
}
+71 -1
View File
@@ -1,6 +1,76 @@
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 parser must pick queue ids out of a real listing and nothing else out of
+106
View File
@@ -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
}
+69
View File
@@ -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
);
+5 -4
View File
@@ -60,6 +60,7 @@ func TestBaselineSchema(t *testing.T) {
"send_log_lines": "id queue_id logged_at line",
"notify_state": "key phase count mark since sent_at",
"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")
if err != nil {
@@ -114,8 +115,8 @@ func TestBaselineSchema(t *testing.T) {
}
var version, appID int64
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 6 {
t.Errorf("user_version = %d, %v; want 6", version, err)
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 7 {
t.Errorf("user_version = %d, %v; want 7", version, err)
}
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)
@@ -191,8 +192,8 @@ func TestOpenMigratesA20Database(t *testing.T) {
}
defer st.Close()
var version int
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 6 {
t.Errorf("user_version = %d, %v; want 6", version, err)
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 7 {
t.Errorf("user_version = %d, %v; want 7", version, err)
}
if ok, err := st.UserExists(); err != nil || !ok {
t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err)
+4
View File
@@ -13,6 +13,10 @@ const (
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.
const (
// settingSenderCheckSince is the first UTC day the statistics cover.
+53 -4
View File
@@ -83,16 +83,65 @@ func (s *Store) InsertRejected(e SendLogEntry) error {
// 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
// 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) {
now := time.Now().UTC().Format(time.RFC3339)
res, err := s.db.Exec(
`UPDATE send_log SET status = ?, updated_at = ?
now := time.Now().UTC()
tx, err := s.db.Begin()
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`,
status, now, queueID, recipient,
status, now.Format(time.RFC3339), ReasonReconcile, queueID, recipient,
)
if err != nil {
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()
return n, nil
}
+67
View File
@@ -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
// 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
+81
View File
@@ -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
})
}
+4
View File
@@ -48,6 +48,10 @@ services:
# loops well past this count) is meant to hit it.
RATE_LIMIT_MESSAGES_PER_IP: "50"
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
- "20465:465"
- "20587:587"
+9
View File
@@ -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) {
token, err := readSetupToken(h)
if err != nil {
@@ -304,6 +310,9 @@ func TestE2E(t *testing.T) {
run("panel_down_defers_mail", func(t *testing.T) {
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) {
testSessionSurvivesRestart(t, sc)
})
+117
View File
@@ -1,8 +1,11 @@
package e2e
import (
"crypto/tls"
"errors"
"fmt"
"net"
"net/smtp"
"net/textproto"
"regexp"
"strconv"
@@ -187,3 +190,117 @@ func testPanelDownDefersMail(t *testing.T, sc *scenario) {
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)
}
}