diff --git a/CHANGELOG.md b/CHANGELOG.md index 87e4a36..57e0f65 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,9 +18,14 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version - **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). + rewrite an old row of the same recipient. The sweep now closes a row by its + id and only while it is `queued`, and the row it closes carries the reason + `reconcile`; a delivery line updates only the newest row of its queue id + and recipient (audit 2026-10-12, H3). +- **A recipient with a quoted local part is followed to its delivery.** The + journal cut `"a b"@example.net` at its space, and the log tailer cut + `"a>b"@example.net` at its `>`: the row matched no delivery line and the + sweep closed it as bounced. Both now take the whole address. - **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 @@ -57,8 +62,10 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version - **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 + closed, those of them whose delivery line was in `mail.log` all along (the + log tailer missed it), those a delivery line read later contradicted (the + log's status then replaces the sweep's, and the row is marked + `reconcile-contradicted`), 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, diff --git a/build/postfix-cert-reload.sh b/build/postfix-cert-reload.sh index 543fb2b..6c91ab1 100644 --- a/build/postfix-cert-reload.sh +++ b/build/postfix-cert-reload.sh @@ -7,60 +7,76 @@ # 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. +# copy; when they differ it copies both beside their targets, checks that the +# copies - not the mounted files, which a renewer may be rewriting - are a +# certificate and the key that belongs to it, renames both over the targets +# 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 +umask 077 # the key's copy is never readable by others, not even for an instant 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 +CERT="$DIR/fullchain.pem" +KEY="$DIR/privkey.pem" +PENDING=0 # a copy was renewed and Postfix has not been reloaded since reload() { if postfix reload; then echo "cert-reload: postfix reloaded ($1)" + PENDING=0 else - echo "cert-reload: postfix reload failed, will retry after ${INTERVAL}s" >&2 + echo "cert-reload: postfix reload failed, will try again after ${INTERVAL}s" >&2 fi } -# same_pair says whether a certificate and a private key belong together. +# same_pair says whether a certificate file and a private key file 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. + if [ "$PENDING" = 1 ]; then + reload "renewed certificate, earlier reload had failed" + fi + if [ "$(postconf -h smtpd_tls_cert_file 2>/dev/null)" != "$CERT" ]; then + # Postfix reads the mounted files themselves (they were missing at + # start, so no copy was made): a reload is what picks up a change. reload "periodic TLS refresh" return fi - if cmp -s "$SRC_CERT" "$DIR/fullchain.pem" && cmp -s "$SRC_KEY" "$DIR/privkey.pem"; then + if [ ! -r "$SRC_CERT" ] || [ ! -r "$SRC_KEY" ]; then + echo "cert-reload: cannot read ${SRC_CERT} or ${SRC_KEY}; Postfix keeps the certificate it has" >&2 return fi - if ! same_pair "$SRC_CERT" "$SRC_KEY"; then + if cmp -s "$SRC_CERT" "$CERT" && cmp -s "$SRC_KEY" "$KEY"; then + return + fi + rm -f "$CERT.new" "$KEY.new" + if ! cp "$SRC_CERT" "$CERT.new" || ! cp "$SRC_KEY" "$KEY.new"; then + rm -f "$CERT.new" "$KEY.new" + echo "cert-reload: copying the renewed certificate failed, will try again after ${INTERVAL}s" >&2 + return + fi + if ! same_pair "$CERT.new" "$KEY.new"; then + rm -f "$CERT.new" "$KEY.new" 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 + chown root:root "$CERT.new" "$KEY.new" + chmod 0644 "$CERT.new" + chmod 0600 "$KEY.new" + mv -f "$KEY.new" "$KEY" && mv -f "$CERT.new" "$CERT" + PENDING=1 + reload "renewed certificate" } while true; do diff --git a/docs/architecture.md b/docs/architecture.md index 9eb5285..19b2a95 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -417,27 +417,41 @@ 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; 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. +closing them all or those past the cut; and the close, by the row's id, is +conditional on the row still being `queued`, so a status the log wrote in the +meantime stands. A delivery line updates only the newest row of its queue id +and recipient: Postfix reuses a short queue id once the message has left the +queue, and an old row must not be rewritten. `UpdateStatus`'s transaction +starts with a write, so a commit by the `dmarc-ingest` process in between +cannot fail it with `database is locked`. 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. +`reconcile_closed`, the rows the sweep closed; `reconcile_missed`, those of +them whose delivery line was in `mail.log` or `mail.log.1` when the sweep +closed them - the tailer did not read a line that was there, which is what a +lost line looks like (it is never read late); `reconcile_contradicted`, those +a delivery line read later gave a status - the log's status replaces the +sweep's and the row's reason becomes `reconcile-contradicted`, so a row counts +once and can be found; `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 - rows +stuck although the sweep runs (mail on hold, or a queue that could not be +listed). What removing the sweep would leave queued is closed − missed − +contradicted: the rows nothing in the log ever resolved. 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 +neither missed nor contradicted → keep it; missed or contradicted → the tailer +loses or delays lines - fix the tailer (the two deferred steps: the rotation +window, pausing the sweep while blind) and keep the sweep; if what remains +after that is never resolved by the log, mark such rows `lost` or remove the +sweep. Decided after thirty days, or sooner if `reconcile_missed` or +`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 diff --git a/docs/audit-2026-10-12.md b/docs/audit-2026-10-12.md index a0b9af7..599140e 100644 --- a/docs/audit-2026-10-12.md +++ b/docs/audit-2026-10-12.md @@ -584,7 +584,12 @@ has already run is never edited — the next file is added; the published from`. In the product this is a second or so after an application is saved in which its first message can get a permanent 553; not worth a change (an application is configured after it is created, not within the - second). The other cases are held to `451 4.7.1` (level 2, both MAIL FROM + second). *Measured 2026-10-14:* applications created and used after 0, + 10, 40 and 110 s of waiting (the first send two seconds after the save at + the soonest) were all served by an smtpd started after the reload; the + stale one only ever answered within the reload's own second. The e2e + waits for the map after each application it creates (`waitForSenderMap`), + after the main positive path failed on it once. The other cases are held to `451 4.7.1` (level 2, both MAIL FROM of one connection), `553` at RCPT (sender mismatch), `554 … Client host rejected` at RCPT (no AUTH, and the relay case, whose comment claimed `reject_unauth_destination` - on 465 the client restriction comes first; @@ -621,6 +626,15 @@ has already run is never edited — the next file is added; the published explained by `tailer_blind` means fix the tailer and keep the sweep, otherwise `lost` or remove. Decide after 30 days of data, or sooner if `contradicted` is ever non-zero. — **Opus** + *Changed by the reviews of stage 1 (2026-10-14):* a fifth counter, + `reconcile_missed` - a closed row whose delivery line was in `mail.log` or + `mail.log.1` when the sweep closed it; `contradicted` alone cannot see a + lost line, which is never read late. `queued_over_lifetime` cannot show + "what removing the sweep would leave visible" while the sweep runs (those + rows are closed by then); it counts rows stuck despite the sweep, and what + removing it would leave is `closed - missed - contradicted`. A + contradicted row keeps the mark `reconcile-contradicted`. The rule reads + accordingly in architecture.md § Log tailer. - *Deferred until the data is in* (not a step yet): pausing the sweep while the tailer is not reading (publish "healthy" from `follow`, skip the sweep otherwise), and the rotation window (keep draining the old inode until it has not @@ -747,6 +761,16 @@ order - each stands on the one before. sentence stays only for a row whose line was truly never written or is older than this change, and says that. Done when the e2e shows the stored line on the page of each of the three refusals. - **Opus** +- [ ] **A message the sweep closed does not say the receiving server refused + it** (review of stage 1, 2026-10-14). The history step of a `bounced` row + reads "the receiving server refused the message permanently, or Postfix + gave up ... The reason is in the delivery log below" + ([handlers_monitor.go](../internal/web/handlers/handlers_monitor.go)); for + a row with reason `reconcile` neither is known and the log has nothing. + Such a row gets its own step: Postfix no longer held the message and + `mail.log` never said what became of it, so the panel closed it as a + failure. Wording in the mockup `out-message` first (`design:` commit), + with the box of the step above. - **Sonnet** - [ ] **A refusal the panel did not get to write is written from `mail.log`** (owner, 2026-10-13, from the Not done list of from-header-binding; built on the step above). The check answers 550 and @@ -775,7 +799,13 @@ order - each stands on the one before. becomes *Connections turned away*. Postfix refuses from the connection on while the check does not answer, before any message is offered, so a client that connects three times with one message is three, and a monitor - that only connects is one; messages cannot be counted. The mockup `health` + that only connects is one; messages cannot be counted. *To ask the owner + when this step is reached (2026-10-14):* since the M13 fix the figure + also counts whole messages - one a panel that hangs mid-message makes + cleanup defer (one per message, with a queue id) - so "Connections turned + away" would be half true; my recommendation: "Turned away" with the help + saying it counts connections refused at the start and messages deferred + in the middle. The mockup `health` and help topic `sender-check` first (`design:` commit), then the page and `view/help.go`, word for word. - **Sonnet** - [ ] Docs: architecture § Log tailer (the rotated file, the saved place, a diff --git a/docs/roadmap.md b/docs/roadmap.md index 1e8548f..f104946 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -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`) | 15/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`) | 15/62 | [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 diff --git a/docs/schema-migrations.md b/docs/schema-migrations.md index f7dfac9..c32052d 100644 --- a/docs/schema-migrations.md +++ b/docs/schema-migrations.md @@ -17,8 +17,8 @@ When you add or review a migration, update this file in the same change. | Field | Value | |---|---| -| 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` | +| Chain head | `user_version = 8` | +| 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`, `0008_tenant_boundary.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.** | @@ -66,7 +66,8 @@ 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`), and -`0007_delivery_log_days.sql` of the 2026-10-12 audit (`2.5.0`). +`0007_delivery_log_days.sql` and `0008_tenant_boundary.sql` of the 2026-10-12 +audit (`2.5.0`). --- @@ -80,7 +81,8 @@ 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 | +| 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 values `reconcile` and `reconcile-contradicted` without a schema change | +| 8 | `0008_tenant_boundary.sql` | 2.5.0 | DDL | `idx_applications_login_nocase`: an application login is unique without regard to case (audit 2026-10-12, H4) | **Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct for operators upgrading from older 2.x images. diff --git a/internal/logtail/lines_test.go b/internal/logtail/lines_test.go index 325b56a..6a9ccfd 100644 --- a/internal/logtail/lines_test.go +++ b/internal/logtail/lines_test.go @@ -176,7 +176,7 @@ func TestRunKeepsQueueLinesOnce(t *testing.T) { const ( client = "host postfix/submission/smtpd[1]: 41E862C00D9E: client=unknown[203.0.113.7]" - sent = "host postfix/smtp[1]: 41E862C00D9E: to=, dsn=2.0.0, status=sent (ok)" + sent = "host postfix/smtp[1]: 41E862C00D9E: to=, relay=x, dsn=2.0.0, status=sent (ok)" later = "host postfix/qmgr[1]: 41E862C00D9E: removed" ) diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index f509bca..9c80e36 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -31,9 +31,10 @@ import ( type StatusStore interface { UpdateStatus(queueID, recipient, status string) (int64, error) ListQueuedOlderThan(cutoff time.Time) ([]store.QueuedDelivery, error) - CloseUnreported(queueID, recipient string) (int64, error) + CloseUnreported(id int64) (int64, error) // The counters of delivery_log_days (store/deliverylog.go). AddReconcileClosed(at time.Time, n int64) error + AddReconcileMissed(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 @@ -88,6 +89,10 @@ type RetentionDays func() int // The ": to=, …, status=" shape is specific to the // delivery agents; qmgr/smtpd/cleanup lines do not match. // +// The recipient runs to the ">, " that comes before relay= (and orig_to=, +// when there is one): a quoted local part may hold a ">", and a recipient cut +// there would match no row and leave it for the sweep (review of stage 1). +// // 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 @@ -100,7 +105,7 @@ type RetentionDays func() int // 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(`^\S+ [^\s\[]+\[\d+\]: ([0-9A-Za-z]+): to=<([^>]*)>,.*?\bstatus=(\w+)`) +var deliveryRe = regexp.MustCompile(`^\S+ [^\s\[]+\[\d+\]: ([0-9A-Za-z]+): to=<(.*?)>, (?:orig_to=<.*?>, )?relay=.*?\bstatus=(\w+)`) // parseDelivery extracts (queue-id, recipient, status) from a mail.log line. // ok is false for lines that are not recognised delivery results. @@ -149,7 +154,7 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa // the sweep would otherwise close. follow() closes this once it has read to // end-of-file for the first time. caughtUp := make(chan struct{}) - go reconcileLoop(ctx, st, caughtUp) + go reconcileLoop(ctx, st, caughtUp, path) var deferred *deferredCounter if sender != nil { @@ -190,7 +195,7 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa // up with the log, and then leaves the first sweep a full interval away, so a // restart resolves rows from the log — the accurate source — before the sweep // gets to guess at whatever the log could not explain. -func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{}) { +func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{}, path string) { select { case <-ctx.Done(): return @@ -210,7 +215,7 @@ func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{} return case <-t.C: now := time.Now().UTC() - reconcile(st, now.Add(-reconcileGrace)) + reconcile(st, now.Add(-reconcileGrace), path) countStuck(st, now, overLifetime) } } @@ -242,7 +247,12 @@ func countStuck(st StatusStore, now time.Time, overLifetime time.Duration) { // success because a delivery the panel cannot evidence must not be shown as // one. Rows whose message is still in the queue, and every row when the queue // cannot be listed at all, are left exactly as they are. -func reconcile(st StatusStore, cutoff time.Time) { +// +// A closed row whose delivery line is in mail.log or mail.log.1 after all is +// counted as missed: the line was there and the tailer did not read it. That +// is what tells a tailer that loses lines from a log that lost them, which +// reconcile_contradicted cannot - a lost line is never read late. +func reconcile(st StatusStore, cutoff time.Time, path string) { rows, err := st.ListQueuedOlderThan(cutoff) if err != nil { log.Printf("log-tailer: reconcile: list queued rows: %v", err) @@ -260,26 +270,54 @@ func reconcile(st StatusStore, cutoff time.Time) { return } - var closed int64 + var closed, missed int64 for _, row := range rows { if _, still := held[row.QueueID]; still { continue } - n, err := st.CloseUnreported(row.QueueID, row.To) + n, err := st.CloseUnreported(row.ID) if err != nil { log.Printf("log-tailer: reconcile: close %s/%s: %v", row.QueueID, row.To, err) continue } closed += n + if n > 0 && deliveryInLog(path, row) { + log.Printf("log-tailer: reconcile: %s/%s had a delivery line in the log the tailer did not read", row.QueueID, row.To) + missed++ + } } 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) } + if err := st.AddReconcileMissed(time.Now(), missed); err != nil { + log.Printf("log-tailer: reconcile: count: %v", err) + } } } +// deliveryInLog says whether the current log or the one rotated last holds a +// delivery line for row. Rows reach the sweep minutes after they were +// written, so the end of those two files is where such a line would be. +func deliveryInLog(path string, row store.QueuedDelivery) bool { + if path == "" { + return false + } + for _, p := range []string{path, path + ".1"} { + lines, err := QueueLines(p, row.QueueID, 256) + if err != nil { + continue + } + for _, line := range lines { + if q, r, _, ok := parseDelivery(line); ok && q == row.QueueID && strings.EqualFold(r, row.To) { + return true + } + } + } + return false +} + // retentionLoop prunes expired send-log rows immediately and then periodically, // and after each sweep the stored log lines no row carries the queue id of: // those the deleted rows leave behind, and those that never had a row diff --git a/internal/logtail/logtail_test.go b/internal/logtail/logtail_test.go index c9b514e..f03b02d 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -116,6 +116,16 @@ func TestParseDelivery(t *testing.T) { line: "host postfix/cleanup[12]: BEEF03: message-id=", wantOK: false, }, + { + // A quoted local part may hold ">": the recipient runs to the + // ">, " before relay=. + name: "a recipient with > in a quoted local part", + line: `host postfix/smtp[26]: C0FFEE: to=<"a>b"@example.net>, relay=mx[203.0.113.9]:25, dsn=2.0.0, status=sent (250 OK)`, + wantOK: true, + queueID: "C0FFEE", + recipient: `"a>b"@example.net`, + status: store.StatusSent, + }, { // The stamp Postfix 3.7's postlogd writes, as on the stand. name: "syslog stamp", @@ -178,6 +188,7 @@ type captureStore struct { // closed sums AddReconcileClosed; stuckCount is what CountQueuedOlderThan // answers and stuck what SetQueuedOverLifetime was given. closed int64 + missed int64 stuckCount int64 stuck []int64 @@ -241,12 +252,18 @@ 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) { +// CloseUnreported records the sweep's close as "queue-id|recipient|reconcile", +// finding the row by its id among queued. +func (c *captureStore) CloseUnreported(id int64) (int64, error) { c.mu.Lock() defer c.mu.Unlock() - c.calls = append(c.calls, queueID+"|"+recipient+"|"+store.ReasonReconcile) - return 1, nil + for _, q := range c.queued { + if q.ID == id { + c.calls = append(c.calls, q.QueueID+"|"+q.To+"|"+store.ReasonReconcile) + return 1, nil + } + } + return 0, nil } func (c *captureStore) DeleteSendLogBefore(time.Time) (int64, error) { return 0, nil } @@ -259,6 +276,12 @@ func (c *captureStore) AddReconcileClosed(_ time.Time, n int64) error { c.closed += n return nil } +func (c *captureStore) AddReconcileMissed(_ time.Time, n int64) error { + c.mu.Lock() + defer c.mu.Unlock() + c.missed += 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() @@ -332,7 +355,7 @@ func TestFollowTailsAndRotates(t *testing.T) { // Give follow() time to open at EOF (it seeks to end immediately on start, // so the seed line above is ignored), then append a delivery line. time.Sleep(50 * time.Millisecond) - appendLine(t, path, "host postfix/smtp[1]: Q1: to=, dsn=2.0.0, status=sent (ok)") + appendLine(t, path, "host postfix/smtp[1]: Q1: to=, relay=x, dsn=2.0.0, status=sent (ok)") waitFor(t, func() bool { return contains(cs.snapshot(), "Q1|a@example.net|sent") }) // Rotate: move the current file aside and create a fresh one (logrotate @@ -343,7 +366,7 @@ func TestFollowTailsAndRotates(t *testing.T) { if err := os.WriteFile(path, nil, 0o644); err != nil { t.Fatalf("recreate: %v", err) } - appendLine(t, path, "host postfix/smtp[1]: Q2: to=, dsn=5.1.1, status=bounced (nope)") + appendLine(t, path, "host postfix/smtp[1]: Q2: to=, relay=x, dsn=5.1.1, status=bounced (nope)") waitFor(t, func() bool { return contains(cs.snapshot(), "Q2|b@example.net|bounced") }) cancel() @@ -375,12 +398,12 @@ func TestFollowResumesAfterRestart(t *testing.T) { cs := &captureStore{} stop := startRun(t, path, cs) - appendLine(t, path, "host postfix/smtp[1]: Q1: to=, dsn=2.0.0, status=sent (ok)") + appendLine(t, path, "host postfix/smtp[1]: Q1: to=, relay=x, dsn=2.0.0, status=sent (ok)") waitFor(t, func() bool { return contains(cs.snapshot(), "Q1|a@example.net|sent") }) stop() // persists the offset past Q1 // Down: Postfix keeps delivering. - appendLine(t, path, "host postfix/smtp[1]: Q2: to=, dsn=2.0.0, status=sent (ok)") + appendLine(t, path, "host postfix/smtp[1]: Q2: to=, relay=x, dsn=2.0.0, status=sent (ok)") cs.reset() stop = startRun(t, path, cs) @@ -394,7 +417,7 @@ func TestFollowResumesAfterRestart(t *testing.T) { // The stored offset belongs to a file that no longer exists, so the new one // must be read from the start. if err := os.WriteFile(path, []byte(strings.Repeat("host postfix/qmgr[1]: fresh log after rotation\n", 20)+ - "host postfix/smtp[1]: Q3: to=, dsn=5.1.1, status=bounced (nope)\n"), 0o644); err != nil { + "host postfix/smtp[1]: Q3: to=, relay=x, dsn=5.1.1, status=bounced (nope)\n"), 0o644); err != nil { t.Fatalf("recreate log: %v", err) } @@ -490,17 +513,39 @@ func TestReconcileClosesOnlyWhatPostfixNoLongerHolds(t *testing.T) { stubQueue(t, nil, "STILLQ") cs := &captureStore{queued: []store.QueuedDelivery{ - {QueueID: "STILLQ", To: "inflight@example.net"}, - {QueueID: "GONEQ", To: "lost@example.net"}, + {ID: 1, QueueID: "STILLQ", To: "inflight@example.net"}, + {ID: 2, QueueID: "GONEQ", To: "lost@example.net"}, }} - reconcile(cs, time.Now().UTC()) + reconcile(cs, time.Now().UTC(), "") got := cs.snapshot() 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) + if cs.closed != 1 || cs.missed != 0 { + t.Fatalf("the day counts %d closed and %d missed, want 1 and 0", cs.closed, cs.missed) + } +} + +// A closed row whose delivery line is in the log after all - here in the file +// rotated last - is counted as missed: the tailer did not read it. +func TestReconcileCountsALineTheTailerMissed(t *testing.T) { + stubQueue(t, nil) + dir := t.TempDir() + path := filepath.Join(dir, "mail.log") + if err := os.WriteFile(path, []byte("Oct 14 11:00:00 mail postfix/qmgr[10]: OTHERQ: removed\n"), 0o644); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(path+".1", []byte("Oct 14 10:59:58 mail postfix/smtp[26]: SEENQ: to=, relay=mx[203.0.113.9]:25, dsn=2.0.0, status=sent (250 OK)\n"), 0o644); err != nil { + t.Fatal(err) + } + cs := &captureStore{queued: []store.QueuedDelivery{ + {ID: 1, QueueID: "SEENQ", To: "seen@example.net"}, + {ID: 2, QueueID: "GONEQ", To: "lost@example.net"}, + }} + reconcile(cs, time.Now().UTC(), path) + if cs.closed != 2 || cs.missed != 1 { + t.Fatalf("closed %d, missed %d; want 2 and 1", cs.closed, cs.missed) } } @@ -560,9 +605,9 @@ func TestReconcileLeavesRowsAloneWhenTheQueueCannotBeRead(t *testing.T) { stubQueue(t, errors.New("postqueue: Permission denied")) cs := &captureStore{queued: []store.QueuedDelivery{ - {QueueID: "GONEQ", To: "lost@example.net"}, + {ID: 1, QueueID: "GONEQ", To: "lost@example.net"}, }} - reconcile(cs, time.Now().UTC()) + reconcile(cs, time.Now().UTC(), "") if got := cs.snapshot(); len(got) != 0 { t.Fatalf("got %v, want no row touched", got) @@ -574,7 +619,7 @@ func TestReconcileLeavesRowsAloneWhenTheQueueCannotBeRead(t *testing.T) { func TestReconcileSkipsTheQueueWhenNoRowIsStuck(t *testing.T) { calls := stubQueue(t, nil) - reconcile(&captureStore{}, time.Now().UTC()) + reconcile(&captureStore{}, time.Now().UTC(), "") if *calls != 0 { t.Fatalf("queue listed %d time(s), want none", *calls) diff --git a/internal/logtail/retention_test.go b/internal/logtail/retention_test.go index cef26b9..e174bb9 100644 --- a/internal/logtail/retention_test.go +++ b/internal/logtail/retention_test.go @@ -23,10 +23,11 @@ func (s *retentionProbeStore) ListQueuedOlderThan(time.Time) ([]store.QueuedDeli return nil, nil } -func (s *retentionProbeStore) CloseUnreported(string, string) (int64, error) { +func (s *retentionProbeStore) CloseUnreported(int64) (int64, error) { return 0, nil } +func (s *retentionProbeStore) AddReconcileMissed(time.Time, int64) error { return 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 } diff --git a/internal/milter/address_test.go b/internal/milter/address_test.go new file mode 100644 index 0000000..666db7b --- /dev/null +++ b/internal/milter/address_test.go @@ -0,0 +1,23 @@ +package milter + +import "testing" + +// The journal row's recipient has to be the address Postfix later logs in +// to=<…>, or the delivery line matches no row and the sweep closes it as +// bounced. A quoted local part may hold a space or a ">". +func TestCleanAddress(t *testing.T) { + for _, c := range []struct{ in, want string }{ + {"", "a@example.net"}, + {" SIZE=100 BODY=8BITMIME", "a@example.net"}, + {"a@example.net", "a@example.net"}, + {"a@example.net SIZE=100", "a@example.net"}, + {"<>", ""}, + {`<"a b"@example.net>`, `"a b"@example.net`}, + {`<"a>b"@example.net> NOTIFY=SUCCESS`, `"a>b"@example.net`}, + {`<"a\"> b"@example.net>`, `"a\"> b"@example.net`}, + } { + if got := cleanAddress(c.in); got != c.want { + t.Errorf("cleanAddress(%q) = %q, want %q", c.in, got, c.want) + } + } +} diff --git a/internal/milter/milter.go b/internal/milter/milter.go index 202189a..44c8d39 100644 --- a/internal/milter/milter.go +++ b/internal/milter/milter.go @@ -203,9 +203,30 @@ func (s *session) record(queueID string) { } // cleanAddress strips the angle brackets and any ESMTP parameters Postfix may -// pass with an address, leaving the bare mailbox. +// pass with an address, leaving the bare mailbox. A bracketed address ends at +// the first ">" outside a quoted local part: a quoted local part may hold a +// space or a ">", and an address cut there matched no delivery line, so its +// row was left for the reconcile sweep to close as bounced (review of audit +// stage 1). func cleanAddress(a string) string { a = strings.TrimSpace(a) + if strings.HasPrefix(a, "<") { + quoted := false + for i := 1; i < len(a); i++ { + switch a[i] { + case '\\': + if quoted { + i++ // the escaped character is part of the local part + } + case '"': + quoted = !quoted + case '>': + if !quoted { + return a[1:i] + } + } + } + } if i := strings.IndexByte(a, ' '); i >= 0 { // drop "addr SIZE=… BODY=…" params a = a[:i] } diff --git a/internal/postfix/queue.go b/internal/postfix/queue.go index 4226241..7815996 100644 --- a/internal/postfix/queue.go +++ b/internal/postfix/queue.go @@ -62,7 +62,13 @@ func listQueue() (text string, truncated bool, err error) { return "", false, fmt.Errorf("postqueue -p timed out after %s", postqueueTimeout) } if err != nil { - return "", false, fmt.Errorf("postqueue -p: %w: %s", err, strings.TrimSpace(out.buf.String())) + // stdout and stderr share the buffer: the end of it says why, and up + // to 4 MiB of listing does not belong in an error. + why := strings.TrimSpace(out.buf.String()) + if len(why) > 512 { + why = "..." + why[len(why)-512:] + } + return "", false, fmt.Errorf("postqueue -p: %w: %s", err, why) } return out.buf.String(), out.truncated, nil } diff --git a/internal/postfix/queue_test.go b/internal/postfix/queue_test.go index e1f592c..d34b896 100644 --- a/internal/postfix/queue_test.go +++ b/internal/postfix/queue_test.go @@ -49,8 +49,8 @@ func fakePostqueue(t *testing.T, size int) { // 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)) + if ids, err := QueueIDs(); err == nil || !strings.Contains(err.Error(), "listing is larger than") { + t.Fatalf("QueueIDs on a 5 MiB listing = %d ids, %v; want the listing refused for its size", len(ids), err) } text, err := Queue() if err != nil { diff --git a/internal/store/deliverylog.go b/internal/store/deliverylog.go index 390a7f4..e5b530b 100644 --- a/internal/store/deliverylog.go +++ b/internal/store/deliverylog.go @@ -12,9 +12,17 @@ import ( // 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. +// deliveryLogCounters are the columns addDeliveryLogDay may add to: the +// name is put into the statement, so nothing else may reach it. +var deliveryLogCounters = map[string]bool{ + "reconcile_closed": true, "reconcile_missed": true, "tailer_blind_seconds": true, +} + +// addDeliveryLogDay adds n to one counter of the day of at. func (s *Store) addDeliveryLogDay(at time.Time, column string, n int64) error { + if !deliveryLogCounters[column] { + return fmt.Errorf("delivery log day: no counter %q", column) + } if n <= 0 { return nil } @@ -34,6 +42,12 @@ func (s *Store) AddReconcileClosed(at time.Time, n int64) error { return s.addDeliveryLogDay(at, "reconcile_closed", n) } +// AddReconcileMissed counts n rows the sweep closed whose delivery line was +// in mail.log all along: the tailer did not read it. +func (s *Store) AddReconcileMissed(at time.Time, n int64) error { + return s.addDeliveryLogDay(at, "reconcile_missed", 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 { @@ -71,14 +85,14 @@ func (s *Store) CountQueuedOlderThan(cutoff time.Time) (int64, error) { // DeliveryLogDay is one day of the counters, for tests and for reading a copy. type DeliveryLogDay struct { - Day string - Closed, Contradicted, BlindSeconds, Stuck int64 + Day string + Closed, Missed, 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 + `SELECT day, reconcile_closed, reconcile_missed, 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) @@ -87,7 +101,7 @@ func (s *Store) DeliveryLogDays() ([]DeliveryLogDay, error) { 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 { + if err := rows.Scan(&d.Day, &d.Closed, &d.Missed, &d.Contradicted, &d.BlindSeconds, &d.Stuck); err != nil { return nil, fmt.Errorf("scan delivery log day: %w", err) } out = append(out, d) diff --git a/internal/store/deliverylog_test.go b/internal/store/deliverylog_test.go index 4297960..1199f87 100644 --- a/internal/store/deliverylog_test.go +++ b/internal/store/deliverylog_test.go @@ -21,6 +21,7 @@ func TestDeliveryLogDays(t *testing.T) { must(st.AddReconcileClosed(day1, 2)) must(st.AddReconcileClosed(day1, 3)) must(st.AddReconcileClosed(day1, 0)) + must(st.AddReconcileMissed(day1, 2)) must(st.AddTailerBlind(day1, 1500*time.Millisecond)) must(st.AddTailerBlind(day1, 900*time.Millisecond)) // under a second: nothing must(st.SetQueuedOverLifetime(day1, 4)) @@ -30,7 +31,7 @@ func TestDeliveryLogDays(t *testing.T) { days, err := st.DeliveryLogDays() must(err) want := []DeliveryLogDay{ - {Day: "2026-10-14", Closed: 5, BlindSeconds: 1, Stuck: 1}, + {Day: "2026-10-14", Closed: 5, Missed: 2, BlindSeconds: 1, Stuck: 1}, {Day: "2026-10-15", BlindSeconds: 60}, } if len(days) != len(want) { @@ -50,6 +51,14 @@ func TestDeliveryLogDays(t *testing.T) { } } +// Only the counters may be added to by name. +func TestAddDeliveryLogDayRefusesAnotherColumn(t *testing.T) { + st := openTestStore(t) + if err := st.addDeliveryLogDay(time.Now(), "day", 1); err == nil { + t.Fatal("addDeliveryLogDay took the column day") + } +} + func TestCountQueuedOlderThan(t *testing.T) { st := openTestStore(t) for _, e := range []SendLogEntry{{QueueID: "Q1", To: "a@example.net"}, {QueueID: "Q2", To: "b@example.net"}} { diff --git a/internal/store/migrations/0007_delivery_log_days.sql b/internal/store/migrations/0007_delivery_log_days.sql index a17ab4f..236ba1a 100644 --- a/internal/store/migrations/0007_delivery_log_days.sql +++ b/internal/store/migrations/0007_delivery_log_days.sql @@ -3,16 +3,24 @@ -- 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 +-- reconcile_missed of those, rows whose delivery line was in mail.log +-- (or mail.log.1) when the sweep closed them: the +-- tailer had not read it +-- reconcile_contradicted rows closed by the sweep that a delivery line read +-- later gave a status (reason becomes +-- 'reconcile-contradicted'). closed - missed - +-- contradicted is what the log never resolved: what +-- removing the sweep would leave queued -- 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 +-- queued_over_lifetime rows still queued past Postfix's queue lifetime +-- and a backoff, as the day's last sweep saw them - +-- rows stuck although the sweep runs (a level, not -- a sum) CREATE TABLE delivery_log_days ( day TEXT PRIMARY KEY, reconcile_closed INTEGER NOT NULL DEFAULT 0, + reconcile_missed 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 diff --git a/internal/store/schema_test.go b/internal/store/schema_test.go index 6d9cfd8..2e634be 100644 --- a/internal/store/schema_test.go +++ b/internal/store/schema_test.go @@ -60,7 +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", + "delivery_log_days": "day reconcile_closed reconcile_missed 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 { diff --git a/internal/store/sendercheck.go b/internal/store/sendercheck.go index ff4759a..3861631 100644 --- a/internal/store/sendercheck.go +++ b/internal/store/sendercheck.go @@ -13,9 +13,15 @@ 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" +// Who decided a "bounced" row the log did not (send_log.reason). +const ( + // ReasonReconcile: the reconcile sweep closed the row - its message left + // Postfix's queue with no delivery line ever read for it. + ReasonReconcile = "reconcile" + // ReasonReconcileContradicted: the sweep closed it and a delivery line + // read afterwards gave the status the row now has. + ReasonReconcileContradicted = "reconcile-contradicted" +) // Settings keys of the sender check's statistics. const ( diff --git a/internal/store/sendlog.go b/internal/store/sendlog.go index 3e7ecc9..8b16727 100644 --- a/internal/store/sendlog.go +++ b/internal/store/sendlog.go @@ -84,10 +84,22 @@ func (s *Store) InsertRejected(e SendLogEntry) error { // number of rows updated so the caller can tell whether the line matched a // journal entry. // +// Only the newest row of the pair is updated. Postfix reuses a short queue id +// once the message has left the queue, and a row outlives that by months; a +// line about today's message must not rewrite an old one (audit 2026-10-12, +// review of stage 1). +// // 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. +// now speaks of was closed on a guess the log could have settled: the log's +// status wins, the reason becomes "reconcile-contradicted" - which row, and +// updated_at says when - and the day's reconcile_contradicted counts it +// (delivery_log_days), once, since the row no longer reads "reconcile". +// +// The transaction's first statement is a write. A transaction that reads +// first and then writes fails at once with "database is locked" when another +// connection - the dmarc-ingest process opens the same file - commits in +// between, and the line would be lost; a write first takes the write lock, +// and the busy timeout waits for it. func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) { now := time.Now().UTC() tx, err := s.db.Begin() @@ -95,18 +107,18 @@ func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) { 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 { + const newest = `id = (SELECT MAX(id) FROM send_log WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE)` + marked, err := tx.Exec( + `UPDATE send_log SET reason = ? WHERE `+newest+` AND reason = ?`, + ReasonReconcileContradicted, queueID, recipient, ReasonReconcile, + ) + if err != nil { return 0, fmt.Errorf("update send_log status: %w", err) } + contradicted, _ := marked.RowsAffected() 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.Format(time.RFC3339), ReasonReconcile, queueID, recipient, + `UPDATE send_log SET status = ?, updated_at = ? WHERE `+newest, + status, now.Format(time.RFC3339), queueID, recipient, ) if err != nil { return 0, fmt.Errorf("update send_log status: %w", err) @@ -127,17 +139,16 @@ func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) { 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) { +// CloseUnreported is the reconcile sweep's close of one row, by its id: +// "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 (audit 2026-10-12, H3). It +// returns the number of rows closed, 0 or 1. +func (s *Store) CloseUnreported(id int64) (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, + `UPDATE send_log SET status = ?, reason = ?, updated_at = ? WHERE id = ? AND status = ?`, + StatusBounced, ReasonReconcile, now, id, StatusQueued, ) if err != nil { return 0, fmt.Errorf("close unreported send_log row: %w", err) @@ -150,6 +161,7 @@ func (s *Store) CloseUnreported(queueID, recipient string) (int64, error) { // reduced to what the log-tailer's reconcile sweep needs to look it up in the // Postfix queue and, failing that, to close it (architecture.md § Log tailer). type QueuedDelivery struct { + ID int64 QueueID string To string } @@ -164,7 +176,7 @@ type QueuedDelivery struct { // format is chronologically correct. func (s *Store) ListQueuedOlderThan(cutoff time.Time) ([]QueuedDelivery, error) { rows, err := s.db.Query( - `SELECT queue_id, to_addr FROM send_log + `SELECT id, queue_id, to_addr FROM send_log WHERE status = ? AND queue_id <> '' AND created_at < ? ORDER BY id`, StatusQueued, cutoff.UTC().Format(time.RFC3339), @@ -177,7 +189,7 @@ func (s *Store) ListQueuedOlderThan(cutoff time.Time) ([]QueuedDelivery, error) var out []QueuedDelivery for rows.Next() { var d QueuedDelivery - if err := rows.Scan(&d.QueueID, &d.To); err != nil { + if err := rows.Scan(&d.ID, &d.QueueID, &d.To); err != nil { return nil, fmt.Errorf("scan queued send_log row: %w", err) } out = append(out, d) diff --git a/internal/store/sendlog_test.go b/internal/store/sendlog_test.go index 3c9aae1..e09c850 100644 --- a/internal/store/sendlog_test.go +++ b/internal/store/sendlog_test.go @@ -97,6 +97,16 @@ func TestUpdateStatusRecipientCaseInsensitive(t *testing.T) { } } +// rowID is the id of the newest send-log row of a queue id. +func rowID(t *testing.T, st *Store, queueID string) int64 { + t.Helper() + var id int64 + if err := st.db.QueryRow(`SELECT MAX(id) FROM send_log WHERE queue_id = ?`, queueID).Scan(&id); err != nil { + t.Fatal(err) + } + return id +} + // 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. @@ -111,10 +121,10 @@ func TestCloseUnreportedClosesOnlyQueuedRows(t *testing.T) { t.Fatal(err) } - if n, err := st.CloseUnreported("Q1", "lost@example.net"); err != nil || n != 1 { + if n, err := st.CloseUnreported(rowID(t, st, "Q1")); 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 { + if n, err := st.CloseUnreported(rowID(t, st, "Q2")); err != nil || n != 0 { t.Fatalf("CloseUnreported of a sent row = %d, %v; want 0", n, err) } @@ -133,14 +143,15 @@ func TestCloseUnreportedClosesOnlyQueuedRows(t *testing.T) { } // 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. +// the log could have said: the log's status wins, the row is marked +// reconcile-contradicted, 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 { + if _, err := st.CloseUnreported(rowID(t, st, "Q1")); err != nil { t.Fatal(err) } for i := 0; i < 2; i++ { @@ -152,8 +163,8 @@ func TestUpdateStatusCountsAContradictedSweep(t *testing.T) { 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) + if status != StatusSent || reason != ReasonReconcileContradicted { + t.Fatalf("status %q reason %q, want sent and %s", status, reason, ReasonReconcileContradicted) } days, err := st.DeliveryLogDays() if err != nil { @@ -164,6 +175,32 @@ func TestUpdateStatusCountsAContradictedSweep(t *testing.T) { } } +// Postfix reuses a short queue id once its message has left the queue; a +// line about the message of today rewrites today's row, not the months-old +// one of the same id and recipient. +func TestUpdateStatusRewritesOnlyTheNewestRow(t *testing.T) { + st := openTestStore(t) + for i := 0; i < 2; i++ { + if err := st.InsertQueued(SendLogEntry{QueueID: "REUSED", To: "a@example.net"}); err != nil { + t.Fatal(err) + } + } + old := rowID(t, st, "REUSED") - 1 + if _, err := st.db.Exec(`UPDATE send_log SET status = ? WHERE id = ?`, StatusSent, old); err != nil { + t.Fatal(err) + } + if n, err := st.UpdateStatus("REUSED", "a@example.net", StatusBounced); err != nil || n != 1 { + t.Fatalf("UpdateStatus = %d, %v; want 1 row", n, err) + } + var status string + if err := st.db.QueryRow(`SELECT status FROM send_log WHERE id = ?`, old).Scan(&status); err != nil { + t.Fatal(err) + } + if status != StatusSent { + t.Fatalf("the old row became %q, want it left sent", status) + } +} + // 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 @@ -199,7 +236,7 @@ func TestListQueuedOlderThan(t *testing.T) { if err != nil { t.Fatalf("ListQueuedOlderThan: %v", err) } - if len(got) != 1 || got[0] != (QueuedDelivery{QueueID: "OLD1", To: "stale@example.net"}) { + if len(got) != 1 || got[0] != (QueuedDelivery{ID: got[0].ID, QueueID: "OLD1", To: "stale@example.net"}) { t.Fatalf("got %+v, want only the stale queued row", got) } } diff --git a/test/e2e/cert_reload_check.go b/test/e2e/cert_reload_check.go index acf1371..069061f 100644 --- a/test/e2e/cert_reload_check.go +++ b/test/e2e/cert_reload_check.go @@ -9,6 +9,7 @@ import ( "net" "os" "path/filepath" + "strings" "time" ) @@ -68,7 +69,7 @@ func checkCertRenewalPickedUp(s *stack) error { 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) { + if err := 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 @@ -77,5 +78,19 @@ func checkCertRenewalPickedUp(s *stack) error { return false, fmt.Errorf("serial %s served, want %s", got, want) } return true, nil - }) + }); err != nil { + return err + } + // The path that was broken is the one taken: Postfix reads the copy, and + // the copy is the renewed file, the key private to root. + out, err := s.execIn("selfpost", "sh", "-c", + "postconf -h smtpd_tls_cert_file && cmp /etc/postfix/tls/fullchain.pem /etc/postfix/tls-internal/fullchain.pem && "+ + "cmp /etc/postfix/tls/privkey.pem /etc/postfix/tls-internal/privkey.pem && stat -c '%a %U' /etc/postfix/tls-internal/privkey.pem") + if err != nil { + return fmt.Errorf("Postfix's copy of the certificate: %v\n%s", err, out) + } + if !strings.Contains(out, "/etc/postfix/tls-internal/fullchain.pem\n") || !strings.Contains(out, "600 root") { + return fmt.Errorf("Postfix's copy of the certificate: %q, want Postfix reading it and the key 600 root", out) + } + return nil } diff --git a/test/e2e/main_test.go b/test/e2e/main_test.go index f0aa33e..4bfee50 100644 --- a/test/e2e/main_test.go +++ b/test/e2e/main_test.go @@ -241,6 +241,9 @@ func TestE2E(t *testing.T) { if err != nil { t.Fatalf("add application: %v", err) } + if err := waitForSenderMap(login, password, "alerts@"+senderDomain); err != nil { + t.Fatal(err) + } sc.appLogin, sc.appPassword = login, password }) diff --git a/test/e2e/negative_test.go b/test/e2e/negative_test.go index a527121..0348ba7 100644 --- a/test/e2e/negative_test.go +++ b/test/e2e/negative_test.go @@ -20,6 +20,9 @@ func testLevel2RateLimit(t *testing.T, sc *scenario) { if err != nil { t.Fatalf("add application: %v", err) } + if err := waitForSenderMap(login, password, "billing@"+senderDomain); err != nil { + t.Fatal(err) + } sc.l2AppLogin, sc.l2AppPassword = login, password appID, err := sc.panel.applicationID(sc.domainID, login) @@ -177,7 +180,8 @@ func testSessionSurvivesRestart(t *testing.T, sc *scenario) { // loop went through: the case once passed on "limit tripped on attempt 1/60" // when the connection was reset because Postfix was still starting - and, // held to anvil's reply, it turned out the first message had always been -// refused for another reason (below). +// refused for another reason: the new login was not yet in the sender map an +// smtpd from before the panel's reload held (waitForSenderMap). func testLevel1RateLimit(t *testing.T, sc *scenario) { login, password, err := sc.panel.addApplication(sc.domainID, "l1app", "wildcard", "") if err != nil { @@ -191,21 +195,11 @@ func testLevel1RateLimit(t *testing.T, sc *scenario) { }) } - // The panel writes sender_login_maps and reloads Postfix, but an smtpd - // process that was idle before the reload can still take the next - // connection with the old map and answer 553 for the new login (seen on - // the stand: the process that greeted waitForSMTPSReady). Wait for the map - // to take effect; any other refusal fails at once. - deadline := time.Now().Add(15 * time.Second) - for { - res := send() - if res.ok() { - break - } - if res.refusedAt("RCPT", 553, "not owned by user "+login) != nil || time.Now().After(deadline) { - t.Fatalf("the first message of %s, before any limit could trip: %v", login, res.firstErr()) - } - time.Sleep(300 * time.Millisecond) + if err := waitForSenderMap(login, password, "l1@"+senderDomain); err != nil { + t.Fatal(err) + } + if res := send(); !res.ok() { + t.Fatalf("the first message of %s, before any limit could trip: %v", login, res.firstErr()) } const maxAttempts = 60 diff --git a/test/e2e/sender_check_test.go b/test/e2e/sender_check_test.go index a4b14a7..de06ce3 100644 --- a/test/e2e/sender_check_test.go +++ b/test/e2e/sender_check_test.go @@ -28,6 +28,9 @@ func testSenderCheck(t *testing.T, sc *scenario) { t.Fatalf("add the second domain: %v", err) } listLogin, listPassword, err := sc.panel.addApplication(sc.domainID, "app-list", "list", "billing@"+senderDomain) + if err == nil { + err = waitForSenderMap(listLogin, listPassword, "billing@"+senderDomain) + } if err != nil { t.Fatalf("add the application with a list: %v", err) } diff --git a/test/e2e/smtp_client.go b/test/e2e/smtp_client.go index a86dedf..ed7a7bc 100644 --- a/test/e2e/smtp_client.go +++ b/test/e2e/smtp_client.go @@ -227,3 +227,59 @@ func mailTwiceOnOneConnection(login, password, from string) [2]error { _ = c.Quit() return out } + +// waitForSenderMap waits until Postfix lets login use from: an application +// the panel has just created is written into the sender map and Postfix is +// reloaded, and an smtpd that was idle from before the reload can still take +// a connection in the second that follows and answer 553 "not owned by user" +// (seen on the stand; two seconds after the save it no longer happened, at 0, +// 10, 40 or 110 s of waiting). It goes as far as RCPT and then RSET, so no +// message is sent and no row is written. Only that 553 is waited out, for 15 +// s at most; any other answer fails at once. +func waitForSenderMap(login, password, from string) error { + deadline := time.Now().Add(15 * time.Second) + for { + err := probeSender(login, password, from) + if err == nil { + return nil + } + if replyIs(err, 553, "not owned by user "+login) != nil || time.Now().After(deadline) { + return fmt.Errorf("Postfix does not yet let %s send as %s: %w", login, from, err) + } + time.Sleep(300 * time.Millisecond) + } +} + +// probeSender authenticates as login and offers MAIL FROM from and one RCPT, +// then resets. It returns the first refusal, or nil. +func probeSender(login, password, from string) error { + conn, err := tls.DialWithDialer(&net.Dialer{Timeout: 10 * time.Second}, "tcp", smtpsAddr, &tls.Config{ + InsecureSkipVerify: true, + ServerName: selfpostHostname, + }) + if err != nil { + return err + } + _ = conn.SetDeadline(time.Now().Add(30 * time.Second)) + c, err := smtp.NewClient(conn, selfpostHostname) + if err != nil { + _ = conn.Close() + return err + } + defer c.Close() + if err := c.Hello("e2e-client.e2e.test"); err != nil { + return err + } + if err := c.Auth(smtp.PlainAuth("", login, password, selfpostHostname)); err != nil { + return err + } + if err := c.Mail(from); err != nil { + return err + } + if err := c.Rcpt(recipient); err != nil { + return err + } + _ = c.Reset() + _ = c.Quit() + return nil +}