diff --git a/CHANGELOG.md b/CHANGELOG.md index 432a14e..940ecb8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -32,6 +32,33 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version ### Fixed +- **A message Postfix gave up on no longer stays "deferred" for ever.** + Postfix records the end of a message's queue lifetime in one line for the + whole message, without the recipients; the panel waited for a line per + recipient that Postfix never writes, and the reconcile sweep closed only + `queued` rows, so such rows said `deferred` until they were pruned. The + log tailer now reads that line and closes the message's rows as + `bounced`; the sweep also closes a `deferred` row whose message Postfix no + longer holds (which covers the rows left so far, and `postsuper -d`); a + message forced to expire (`postsuper -e`, `#` in the queue listing) is + still counted as held (audit 2026-10-12, stage 2c; assumptions A-8, + B-PQ1). +- **Postfix's time values are read as Postfix reads them.** A bare number + took seconds, so `maximal_queue_lifetime = 3` was three seconds to the + panel and three days to Postfix; `1h7m` was 67 minutes to the panel and + one hour to Postfix. A value now takes the parameter's own default unit + and one unit only; `$name` references are expanded; a + `bounce_queue_lifetime` longer than `maximal_queue_lifetime` is cut to it, + as Postfix's queue manager does (assumptions B-PQ10, B-PQ11). +- **A refusal's line goes on the right application's row.** Postfix's line + about a refusal at `MAIL FROM` was matched to its row by client address, + sender and time; two applications behind one address sending as one + sender could take each other's line. The line carries the login after + all, and the match now uses it. A login read from smtpd's `client=` line + no longer keeps a trailing comma when the client also gave `AUTH=` on + `MAIL FROM`. A refusal written from `mail.log` after a restart says that + Postfix's line names the last recipient only (assumptions A-15, A-21, + A-23). - **A bounce is judged by the filter lists as the panel counts it.** rspamd's sender rules took a bounce's `From:` header when the envelope sender was empty, so a bounce could be refused or allowed by an entry the diff --git a/docs/architecture.md b/docs/architecture.md index 178a0b1..a94e13d 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -186,10 +186,15 @@ domain is added or deleted. One process, five roles (six with the inbound relay on): 1. **HTTP server** — `:8080` (`PANEL_HTTP_ADDR`); HTTPS terminated by reverse - proxy only. On start it runs `postconf -h` once for the deferred-mail retry + proxy only. On start it runs `postconf -h -x` once for the deferred-mail retry parameters (`queue_run_delay`, `minimal_backoff_time`, `maximal_backoff_time`, `maximal_queue_lifetime`, `bounce_queue_lifetime`, - `delay_warning_time`) and caches the snapshot on the handlers config. The + `delay_warning_time`), reads each as Postfix does - one number and one + unit, the parameter's own default unit when there is none (`5d` for the + lifetimes, so a bare `3` is three days), `bounce_queue_lifetime` capped at + `maximal_queue_lifetime` as qmgr caps it (Postfix 3.7.11, + `src/global/conv_time.c`, `src/qmgr/qmgr.c`) - and caches the snapshot on + the handlers config. The Outbound queue box and a delivery's `deferred` / `bounced` history print those numbers; they never call `postconf` per request. If `postconf` is missing, the panel logs a warning and uses Postfix 3.x compiled-in defaults @@ -432,8 +437,11 @@ judged); the sender check writes it on the row, and the message's page shows the lines stored under it - only those of the minutes around the refusal, since Postfix frees the id at once. A message the journal milter refused at `MAIL FROM` has none: the tailer reads smtpd's `NOQUEUE: milter-reject: MAIL -from [
]: …; from=<…>` - it names no login - and puts it on -the newest refused row of that client address and sender within two minutes +from [
]: …; from=<…> … sasl_username=` - the login is +Postfix's last field on an authenticated session (Postfix 3.7.11, +`src/smtpd/smtpd.c`, `smtpd_whatsup()`), and a line without one is no +application's - and puts it on the nearest refused row of that client +address, login and sender within two minutes (`send_log.refusal_line`; the milter writes `send_log.client_ip`), retrying for 30 s when the row is not written yet; a line already on a row goes on no other. The sender check writes its @@ -441,13 +449,23 @@ row through a buffer after answering 550; a panel stopped in between wrote none. The tailer remembers each queue id's login from smtpd's `client=` line, and 30 s after cleanup's `milter-reject: END-OF-MESSAGE … 5.7.1 From:` line it writes the row from the line if no refused row of that id exists -(`send_log.recovered`, shown on the page). It reads from its saved offset, so +(`send_log.recovered`, shown on the page). cleanup's line names one +recipient, the message's last (`src/cleanup/cleanup_milter.c`), so a row +written from it has that one, which its page says. It reads from its saved offset, so a kill is covered as well as a clean stop. +**Expiry.** A message Postfix gives up on at the end of its queue lifetime has +no line per recipient: qmgr writes one line for the message, `: +from=<...>, status=expired, returned to sender` (`force-expired` after +`postsuper -e`; Postfix 3.7.11, `src/qmgr/qmgr_active.c`, +`qmgr_active_done_25_generic()`), and the recipients' last lines say +`deferred`. The tailer reads that line and closes the message's open rows - +each recipient's newest, `queued` or `deferred` - as `bounced`. + **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` with the reason -`reconcile` (swept every five minutes, +row still open - `queued`, or `deferred` and waiting - more than two minutes +after it was accepted, whose queue id `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 @@ -458,8 +476,12 @@ 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, 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 +conditional on the row still being open, so a final status the log wrote in +the meantime stands. A deferred row is the sweep's too because Postfix can +drop a deferred message without a final line for its recipients: at expiry +before `2.5.2` read that line, and with `postsuper -d`, which logs only +`removed`. The listing's `#` - a message forced to expire - is read as part +of the id's flags (`src/postqueue/showq_compat.c`, `showq_message()`). 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 @@ -471,16 +493,18 @@ 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_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 +them whose final line - sent, bounced, or the message's expiry - 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; a deferred line is not one, a deferred row has it by definition); `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 +are not counted); and `queued_over_lifetime`, the rows still open (`queued` +or `deferred`; `queued` only before `2.5.2`) 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 @@ -529,8 +553,8 @@ reads them: - **Which lines are a row's.** Postfix reuses a queue id once the message has left the queue, and a row outlives that by months. `SendLogLines` gives a row the lines of its queue id dated from one hour before the row was written to - the queue lifetime (the larger of `maximal_queue_lifetime` and - `bounce_queue_lifetime`) plus a day after it. That limits a chance reuse of + the queue lifetime (`maximal_queue_lifetime`, which `bounce_queue_lifetime` + cannot exceed) plus a day after it. That limits a chance reuse of the id to those days; it does not exclude it. A message with several recipients is several rows under one id, and each row's page shows all of the message's lines. diff --git a/docs/guide.md b/docs/guide.md index 89f7ec6..c6ff763 100644 --- a/docs/guide.md +++ b/docs/guide.md @@ -1268,8 +1268,10 @@ 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. -`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 +`bounced` is usually Postfix's word - a message it gave up on at the end of +its queue lifetime is `bounced` too, since Postfix returns it to the sender; +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 diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index ae13e0a..a0e4253 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -30,13 +30,14 @@ import ( // far into mail.log it has read. *store.Store satisfies it. type StatusStore interface { UpdateStatus(queueID, recipient, status string) (int64, error) - ListQueuedOlderThan(cutoff time.Time) ([]store.QueuedDelivery, error) + ExpireMessage(queueID string) (int64, error) + ListOpenOlderThan(cutoff time.Time) ([]store.QueuedDelivery, 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) + CountOpenOlderThan(cutoff time.Time) (int64, error) SetQueuedOverLifetime(at time.Time, n int64) error PruneDeliveryLogDays(now time.Time) error RefusalStore @@ -132,15 +133,35 @@ func parseDelivery(line string) (queueID, recipient, status string, ok bool) { status = store.StatusDeferred case "bounced": status = store.StatusBounced - case "expired": - // Postfix gave up after the queue lifetime; a final failure for us. - status = store.StatusBounced default: return "", "", "", false } return m[1], m[2], status, true } +// expiryRe matches qmgr's line for a message it gave up on: +// +// postfix/qmgr[93]: 41E862C00D9E: from=, status=expired, returned to sender +// +// Postfix 3.7.11, src/qmgr/qmgr_active.c, qmgr_active_done_25_generic(): +// msg_info("%s: from=<%s>, status=%s, returned to sender") with "expired" +// once the queue lifetime has passed, "force-expired" after postsuper -e. +// It is the only line about the expiry, one per message, and no recipient is +// named (assumptions A-8). The line must end there: the sender is the +// client's text, and only qmgr writes this shape. +var expiryRe = regexp.MustCompile(`^\S+ \S*/qmgr\[\d+\]: ([0-9A-Za-z]+): from=<.*>, status=(?:force-)?expired, returned to sender\s*$`) + +// parseExpiry returns the queue id of a message Postfix gave up on, from its +// expiry line; ok is false for any other line. +func parseExpiry(line string) (queueID string, ok bool) { + _, rest := SplitTimestamp(line) + m := expiryRe.FindStringSubmatch(rest) + if m == nil { + return "", false + } + return m[1], true +} + // Run follows path and updates send-log statuses until ctx is cancelled, while // a background sweep prunes rows older than retention(). Reading resumes at // the offset the previous run persisted, so a restart parses the delivery lines @@ -199,6 +220,11 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa refusals.handle(line, now, Place{FP: tr.line.FP, End: tr.lineStart}) queueID, recipient, status, ok := parseDelivery(line) if !ok { + if queueID, ok := parseExpiry(line); ok { + if _, err := st.ExpireMessage(queueID); err != nil { + log.Printf("log-tailer: expire %s: %v", queueID, err) + } + } return } if _, err := st.UpdateStatus(queueID, recipient, status); err != nil { @@ -243,11 +269,11 @@ func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{} } } -// countStuck records how many rows are still queued past Postfix's queue +// countStuck records how many rows are still open 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)) + n, err := st.CountOpenOlderThan(now.Add(-overLifetime)) if err == nil { err = st.SetQueuedOverLifetime(now, n) } @@ -256,10 +282,10 @@ func countStuck(st StatusStore, now time.Time, overLifetime time.Duration) { } } -// reconcile marks as bounced every row still "queued" from before cutoff whose -// 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. +// reconcile marks as bounced every row still open ("queued" or "deferred") +// from before cutoff whose message Postfix no longer holds, with reason +// "reconcile". The close itself is conditional on the row still being open, +// so a final 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 @@ -279,9 +305,9 @@ func countStuck(st StatusStore, now time.Time, overLifetime time.Duration) { // 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) + rows, err := st.ListOpenOlderThan(cutoff) if err != nil { - log.Printf("log-tailer: reconcile: list queued rows: %v", err) + log.Printf("log-tailer: reconcile: list open rows: %v", err) return } if len(rows) == 0 { @@ -307,7 +333,7 @@ func reconcile(st StatusStore, cutoff time.Time, path string) { continue } closed += n - if n > 0 && deliveryInLog(path, row) { + if n > 0 && resultInLog(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++ } @@ -323,13 +349,15 @@ func reconcile(st StatusStore, cutoff time.Time, path string) { } } -// 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. +// resultInLog says whether the current log or the one rotated last holds a +// final result for row - a delivery line that says sent or bounced, or the +// message's expiry line. A deferred line is not one: a deferred row has one +// by definition. Rows reach the sweep minutes after they were written, so +// the end of those two files is where such a line would be. // logrotate 3.21.0, logrotate.c, prerotateSingleLog(): the first rotated // name is ".1", without the compression suffix under delaycompress // (build/logrotate-mail.conf). -func deliveryInLog(path string, row store.QueuedDelivery) bool { +func resultInLog(path string, row store.QueuedDelivery) bool { if path == "" { return false } @@ -339,7 +367,10 @@ func deliveryInLog(path string, row store.QueuedDelivery) bool { continue } for _, line := range lines { - if q, r, _, ok := parseDelivery(line); ok && q == row.QueueID && strings.EqualFold(r, row.To) { + if q, r, s, ok := parseDelivery(line); ok && q == row.QueueID && strings.EqualFold(r, row.To) && s != store.StatusDeferred { + return true + } + if q, ok := parseExpiry(line); ok && q == row.QueueID { return true } } diff --git a/internal/logtail/logtail_test.go b/internal/logtail/logtail_test.go index 9606ed7..7ef37a2 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -17,10 +17,69 @@ import ( // The mail.log lines in this file are composed by hand, after the formats the // code cites (Postfix 3.7.11, src/global/log_adhoc.c and the others), unless a // comment says where one was seen. Some are shapes Postfix does not write: -// "to=..., status=expired" (qmgr logs expiry once per message as "from=<..>, -// status=expired, returned to sender" - assumptions A-8), ISO stamps -// (msg_logger.c writes "%b %d %H:%M:%S" - A-12), and opendkim lines in -// mail.log (build/opendkim.conf has Syslog no). +// ISO stamps (msg_logger.c writes "%b %d %H:%M:%S" - A-12), and opendkim +// lines in mail.log (build/opendkim.conf has Syslog no). +// qmgr's expiry line, as Postfix 3.7.11 writes it (src/qmgr/qmgr_active.c, +// qmgr_active_done_25_generic(): "%s: from=<%s>, status=%s, returned to +// sender"); composed by hand after that format. The sender is the client's +// text, so a line only resembles one when it ends as qmgr's does. +func TestParseExpiry(t *testing.T) { + for _, c := range []struct { + line string + id string + }{ + {"Oct 14 09:01:02 relay postfix/qmgr[93]: 41E862C00D9E: from=, status=expired, returned to sender", "41E862C00D9E"}, + {"Oct 14 09:01:02 relay postfix/qmgr[93]: 3Fq1Lw0bZ8z9tN: from=<>, status=force-expired, returned to sender", "3Fq1Lw0bZ8z9tN"}, + // Not qmgr. + {"Oct 14 09:01:02 relay postfix/smtp[26]: 41E862C00D9E: from=, status=expired, returned to sender", ""}, + // qmgr's ordinary from= line, whose sender carries the text. + {"Oct 14 09:01:02 relay postfix/qmgr[93]: 41E862C00D9E: from=, status=expired, returned to sender>, size=500, nrcpt=1 (queue active)", ""}, + {"Oct 14 09:01:02 relay postfix/qmgr[93]: 41E862C00D9E: removed", ""}, + } { + id, ok := parseExpiry(c.line) + if ok != (c.id != "") || id != c.id { + t.Errorf("parseExpiry(%q) = %q, %v; want %q", c.line, id, ok, c.id) + } + } +} + +// The tailer closes an expired message's rows when it reads qmgr's line. +func TestExpiryLineClosesTheMessage(t *testing.T) { + path := filepath.Join(t.TempDir(), "mail.log") + if err := os.WriteFile(path, nil, 0o644); err != nil { + t.Fatal(err) + } + cs := &captureStore{} + stop := startRun(t, path, cs) + defer stop() + appendLine(t, path, "Oct 14 09:01:00 relay postfix/smtp[26]: 41E862C00D9E: to=, relay=none, delay=9, dsn=4.4.1, status=deferred (connect timed out)") + appendLine(t, path, "Oct 14 09:01:02 relay postfix/qmgr[93]: 41E862C00D9E: from=, status=expired, returned to sender") + waitFor(t, func() bool { return contains(cs.snapshot(), "41E862C00D9E|*|expired") }) + if !contains(cs.snapshot(), "41E862C00D9E|a@example.net|"+store.StatusDeferred) { + t.Fatalf("calls = %v, want the deferral before the expiry", cs.snapshot()) + } +} + +// A deferred row the sweep closes is not "missed" for its deferred line - it +// has one by definition - but is for its message's expiry line. +func TestReconcileMissedCountsOnlyFinalLines(t *testing.T) { + stubQueue(t, nil) + path := filepath.Join(t.TempDir(), "mail.log") + if err := os.WriteFile(path, []byte( + "Oct 14 10:59:58 mail postfix/smtp[26]: DEFQ: to=, relay=none, delay=9, dsn=4.4.1, status=deferred (connect timed out)\n"+ + "Oct 14 10:59:59 mail postfix/qmgr[10]: EXPQ: from=, status=expired, returned to sender\n"), 0o644); err != nil { + t.Fatal(err) + } + cs := &captureStore{queued: []store.QueuedDelivery{ + {ID: 1, QueueID: "DEFQ", To: "late@example.net"}, + {ID: 2, QueueID: "EXPQ", To: "gone@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) + } +} + func TestParseDelivery(t *testing.T) { cases := []struct { name string @@ -53,12 +112,11 @@ func TestParseDelivery(t *testing.T) { status: store.StatusBounced, }, { - name: "expired maps to bounced", - line: "host postfix/smtp[26]: DEF: to=, relay=none, status=expired (delivery temporarily suspended)", - wantOK: true, - queueID: "DEF", - recipient: "slow@example.net", - status: store.StatusBounced, + // Expiry is not a delivery line (TestParseExpiry); qmgr's line + // for it names no recipient. + name: "qmgr expiry line ignored", + line: "host postfix/qmgr[10]: DEF: from=, status=expired, returned to sender", + wantOK: false, }, { name: "qmgr from-line ignored", @@ -189,10 +247,10 @@ type captureStore struct { haveState bool stateErr error - // queued is what ListQueuedOlderThan returns, for the reconcile sweep. + // queued is what ListOpenOlderThan returns, for the reconcile sweep. queued []store.QueuedDelivery queuedErr error - // closed sums AddReconcileClosed; stuckCount is what CountQueuedOlderThan + // closed sums AddReconcileClosed; stuckCount is what CountOpenOlderThan // answers and stuck what SetQueuedOverLifetime was given. closed int64 missed int64 @@ -259,6 +317,14 @@ func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, e return 1, nil } +// ExpireMessage records an expiry line's close as "queue-id|*|expired". +func (c *captureStore) ExpireMessage(queueID string) (int64, error) { + c.mu.Lock() + defer c.mu.Unlock() + c.calls = append(c.calls, queueID+"|*|expired") + return 1, nil +} + // 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) { @@ -290,11 +356,11 @@ func (c *captureStore) AddReconcileMissed(_ time.Time, n int64) error { return nil } func (c *captureStore) AddTailerBlind(time.Time, time.Duration) error { return nil } -func (c *captureStore) AttachRefusalLine(string, string, time.Time, string) (bool, error) { +func (c *captureStore) AttachRefusalLine(string, string, string, time.Time, string) (bool, error) { return true, nil } func (c *captureStore) RecoverRefusal(store.SendLogEntry, time.Time) (bool, error) { return false, nil } -func (c *captureStore) CountQueuedOlderThan(time.Time) (int64, error) { +func (c *captureStore) CountOpenOlderThan(time.Time) (int64, error) { c.mu.Lock() defer c.mu.Unlock() return c.stuckCount, nil @@ -307,7 +373,7 @@ func (c *captureStore) SetQueuedOverLifetime(_ time.Time, n int64) error { } func (c *captureStore) PruneDeliveryLogDays(time.Time) error { return nil } -func (c *captureStore) ListQueuedOlderThan(time.Time) ([]store.QueuedDelivery, error) { +func (c *captureStore) ListOpenOlderThan(time.Time) ([]store.QueuedDelivery, error) { c.mu.Lock() defer c.mu.Unlock() return c.queued, c.queuedErr diff --git a/internal/logtail/refusals.go b/internal/logtail/refusals.go index 822e1cd..c49280c 100644 --- a/internal/logtail/refusals.go +++ b/internal/logtail/refusals.go @@ -14,20 +14,24 @@ import ( // level-2 limit, a client address off the application's list - is put on the // row the milter wrote, so the message's page shows it (audit 2026-10-12, // stage 2b). The refusal has no queue id; it is matched to its row by client -// address, sender and time. As the stand writes it (e2e stand, date not -// recorded): +// address, login, sender and time: // -// postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo= +// postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo= sasl_username= // // Postfix 3.7.11, src/smtpd/smtpd.c, check_milter_reply(): "%s: %s: %s from // %s: %s;%s" with "NOQUEUE" before the queue file is opened, and -// smtpd_whatsup() for the rest - " from=<..>" first. smtpd_whatsup() also -// ends the line with " sasl_username=" on an authenticated session, -// which the quote above lacks and the regexp does not use (assumptions A-20, -// A-21). +// smtpd_whatsup() for the rest: " from=<..>", " to=<..>", " proto=..", +// " helo=<..>", then " sasl_username=<..>" when the session authenticated +// (assumptions A-20, A-21). The login is read at the end of the line, where +// Postfix puts it last; a line without one is no application's refusal - the +// journal milter refuses at MAIL FROM only an authenticated session +// (milter/ratelimit.go). The HELO name before it is the client's text and can +// end in what looks like the field, but only in a session that has no login, +// and so no refused row to take the line; a row must also be of the line's +// client address and sender, within minutes. // // Port 25's smtpd (postfix/inbound/smtpd) is a stranger's and has no such row. -var refusalLineRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: NOQUEUE: milter-reject: MAIL from [^\[\s]*\[([^\]]+)\]: [45]\d\d .*?; from=<([^>]*)>`) +var refusalLineRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: NOQUEUE: milter-reject: MAIL from [^\[\s]*\[([^\]]+)\]: [45]\d\d .*?; from=<([^>]*)>(?:.* sasl_username=<([^<>]*)>|.*)$`) // refusalLineWait is how long a line waits for its row: the milter writes the // row when it refuses, which can be read a moment after the line. @@ -35,7 +39,7 @@ const refusalLineWait = 30 * time.Second // RefusalStore is where the lines go. *store.Store satisfies it. type RefusalStore interface { - AttachRefusalLine(clientIP, from string, at time.Time, line string) (bool, error) + AttachRefusalLine(clientIP, login, from string, at time.Time, line string) (bool, error) RecoverRefusal(e store.SendLogEntry, at time.Time) (bool, error) } @@ -56,18 +60,19 @@ var fromRefusalRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?cleanup\[\d // clientLoginRe is smtpd's line naming the login a queue id was submitted // under: ": client=host[addr], sasl_method=PLAIN, sasl_username=". -// Postfix 3.7.11, src/smtpd/smtpd.c, mail_open_stream(): ", sasl_sender=<..>" -// follows when the client gave AUTH= on MAIL FROM, and "\S+" then takes -// "login," with the comma (assumptions A-23). -var clientLoginRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: ([0-9A-Za-z]+): client=.*?, sasl_username=(\S+)`) +// Postfix 3.7.11, src/smtpd/smtpd.c, mail_open_stream(): ", sasl_sender=.." +// follows when the client gave AUTH= on MAIL FROM, then ", orig_queue_id=.." +// and ", orig_client=.." for XFORWARD; the login ends at the comma (a login +// holds none - internal/postfix assertMapSafe; assumptions A-23). +var clientLoginRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: ([0-9A-Za-z]+): client=.*?, sasl_username=([^,\s]+)`) // refusalLogins bounds the queue ids whose login is remembered. const refusalLogins = 4096 type pendingRefusal struct { - clientIP, from, line string - at, until time.Time - start Place // where the line starts in the log + clientIP, login, from, line string + at, until time.Time + start Place // where the line starts in the log } // pendingRecovery is a From: refusal whose row is looked for once the panel @@ -139,14 +144,17 @@ func (r *refusalLines) handle(line string, now time.Time, start Place) { return } m := refusalLineRe.FindStringSubmatch(rest) - if m == nil || m[1] == "inbound" { + if m == nil || m[1] == "inbound" || m[4] == "" { return } - ip := net.ParseIP(strings.TrimPrefix(m[2], "IPv6:")) + // The address in "name[addr]" is smtpd's state->addr, which has no + // "IPv6:" (Postfix 3.7.11, src/smtpd/smtpd_peer.c, smtpd_peer_init(); + // assumptions A-24). + ip := net.ParseIP(m[2]) if ip == nil { return } - p := pendingRefusal{clientIP: ip.String(), from: m[3], line: line, at: at, until: now.Add(refusalLineWait), start: start} + p := pendingRefusal{clientIP: ip.String(), login: m[4], from: m[3], line: line, at: at, until: now.Add(refusalLineWait), start: start} if !r.attach(p) { r.pending = append(r.pending, p) } @@ -206,7 +214,7 @@ func domainOf(addr string) string { } func (r *refusalLines) attach(p pendingRefusal) bool { - ok, err := r.st.AttachRefusalLine(p.clientIP, p.from, p.at, p.line) + ok, err := r.st.AttachRefusalLine(p.clientIP, p.login, p.from, p.at, p.line) if err != nil { log.Printf("log-tailer: refusal line: %v", err) return true // not retried: the store said no for its own reason diff --git a/internal/logtail/refusals_test.go b/internal/logtail/refusals_test.go index 542d714..10b044f 100644 --- a/internal/logtail/refusals_test.go +++ b/internal/logtail/refusals_test.go @@ -19,13 +19,13 @@ func (r *refusalProbe) RecoverRefusal(e store.SendLogEntry, _ time.Time) (bool, return true, nil } -func (r *refusalProbe) AttachRefusalLine(clientIP, from string, _ time.Time, line string) (bool, error) { +func (r *refusalProbe) AttachRefusalLine(clientIP, login, from string, _ time.Time, line string) (bool, error) { if r.rows == 0 { return false, nil } r.rows-- r.lines = append(r.lines, line) - r.who = append(r.who, clientIP+"|"+from) + r.who = append(r.who, clientIP+"|"+login+"|"+from) return true, nil } @@ -46,6 +46,9 @@ func TestRefusalLines(t *testing.T) { `2026-10-14T12:00:00+00:00 mail postfix/inbound/smtpd[372]: NOQUEUE: milter-reject: MAIL from unknown[203.0.113.7]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, `2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`, `2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: NOQUEUE: reject: RCPT from unknown[10.77.0.1]: 553 5.7.1 : Sender address rejected: not owned by user app1; from= to= proto=ESMTP helo=`, + // No login: no application's refusal (the panel down refuses every + // session, an unauthenticated one too). + `2026-10-14T12:00:00+00:00 mail postfix/smtpd[12]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, } { r.handle(other, now, Place{}) } @@ -59,7 +62,7 @@ func TestRefusalLines(t *testing.T) { } st.rows = 1 // the milter's row is written r.retry(now.Add(time.Second)) - if len(r.pending) != 0 || len(st.lines) != 1 || st.who[0] != "10.77.0.1|billing@sender.e2e.test" { + if len(r.pending) != 0 || len(st.lines) != 1 || st.who[0] != "10.77.0.1|l2app|billing@sender.e2e.test" { t.Fatalf("after the retry: pending %d, attached %v", len(r.pending), st.who) } diff --git a/internal/logtail/retention_test.go b/internal/logtail/retention_test.go index 9b0e4ee..e88cbe6 100644 --- a/internal/logtail/retention_test.go +++ b/internal/logtail/retention_test.go @@ -19,10 +19,12 @@ func (s *retentionProbeStore) UpdateStatus(string, string, string) (int64, error return 0, nil } -func (s *retentionProbeStore) ListQueuedOlderThan(time.Time) ([]store.QueuedDelivery, error) { +func (s *retentionProbeStore) ListOpenOlderThan(time.Time) ([]store.QueuedDelivery, error) { return nil, nil } +func (s *retentionProbeStore) ExpireMessage(string) (int64, error) { return 0, nil } + func (s *retentionProbeStore) CloseUnreported(int64) (int64, error) { return 0, nil } @@ -30,7 +32,7 @@ func (s *retentionProbeStore) CloseUnreported(int64) (int64, error) { 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 } +func (s *retentionProbeStore) CountOpenOlderThan(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 } @@ -99,7 +101,7 @@ func TestRetentionLoopUsesUpdatedValue(t *testing.T) { t.Fatalf("second prune cutoff age %v, want about 7 days", age) } -func (s *retentionProbeStore) AttachRefusalLine(string, string, time.Time, string) (bool, error) { +func (s *retentionProbeStore) AttachRefusalLine(string, string, string, time.Time, string) (bool, error) { return true, nil } diff --git a/internal/postfix/duration.go b/internal/postfix/duration.go index 286b282..147c0ef 100644 --- a/internal/postfix/duration.go +++ b/internal/postfix/duration.go @@ -2,85 +2,80 @@ package postfix import ( "fmt" + "math" "strconv" "strings" "time" - "unicode" ) -// ParseDuration converts a Postfix time value to a duration. Units are those -// postconf prints and accepts: s, m, h, d, w. A bare number is seconds. Values -// may concatenate units (`1h7m`), matching Postfix's own conv_time. -func ParseDuration(s string) (time.Duration, error) { - s = strings.TrimSpace(s) +// ParseTime reads a Postfix time value as Postfix 3.7.11 reads it: +// src/global/conv_time.c, conv_time(), called by get_mail_conf_time() in +// src/global/mail_conf_time.c. One number - strtol(), so leading blanks and a +// "+" are taken, a negative number or one past an int is invalid - followed +// by one unit, w d h m or s in lower case; with no unit, defUnit, which +// Postfix takes from the parameter's default value (get_def_time_unit(): "5d" +// gives d, "300s" s, "0h" h). Whatever follows the unit is ignored, so "1h7m" +// is one hour (assumptions B-PQ10, B-PQ11). A string with no digits is read as +// 0 of the unit it starts with, as strtol() leaves it there. +func ParseTime(s string, defUnit byte) (time.Duration, error) { if s == "" { return 0, fmt.Errorf("postfix: empty time value") } - var total time.Duration i := 0 - for i < len(s) { - for i < len(s) && unicode.IsSpace(rune(s[i])) { - i++ - } - if i >= len(s) { - break - } - if s[i] == '-' { - return 0, fmt.Errorf("postfix: negative time value %q", s) - } - if s[i] == '+' { - i++ - } - start := i - for i < len(s) && s[i] >= '0' && s[i] <= '9' { - i++ - } - if i == start { - return 0, fmt.Errorf("postfix: invalid time value %q", s) - } - n, err := strconv.ParseInt(s[start:i], 10, 64) - if err != nil { - return 0, fmt.Errorf("postfix: invalid time value %q", s) - } - unit := byte('s') - if i < len(s) && isTimeUnit(s[i]) { - unit = s[i] | 0x20 // ASCII fold to lowercase - i++ - } - part, err := durationForUnit(n, unit) - if err != nil { - return 0, err - } - total += part + for i < len(s) && isCSpace(s[i]) { + i++ } - return total, nil -} - -func isTimeUnit(c byte) bool { - switch c | 0x20 { - case 's', 'm', 'h', 'd', 'w': - return true + neg := false + if i < len(s) && (s[i] == '+' || s[i] == '-') { + neg = s[i] == '-' + i++ } - return false -} - -func durationForUnit(n int64, unit byte) (time.Duration, error) { - var unitDur time.Duration + start := i + var n int64 + for i < len(s) && s[i] >= '0' && s[i] <= '9' { + n = n*10 + int64(s[i]-'0') + if n > math.MaxInt32 { + return 0, fmt.Errorf("postfix: time value %q out of range", s) + } + i++ + } + end := i + if i == start { + // strtol() converted nothing: the end is the start of the string. + end, n, neg = 0, 0, false + } + if neg && n > 0 { + return 0, fmt.Errorf("postfix: negative time value %q", s) + } + unit := defUnit + if end < len(s) { + unit = s[end] + } + var per int64 switch unit { - case 's': - unitDur = time.Second - case 'm': - unitDur = time.Minute - case 'h': - unitDur = time.Hour - case 'd': - unitDur = 24 * time.Hour case 'w': - unitDur = 7 * 24 * time.Hour + per = 7 * 24 * 3600 + case 'd': + per = 24 * 3600 + case 'h': + per = 3600 + case 'm': + per = 60 + case 's': + per = 1 default: - return 0, fmt.Errorf("postfix: unknown time unit %q", string(unit)) + return 0, fmt.Errorf("postfix: invalid time value %q", s) } - return time.Duration(n) * unitDur, nil + // conv_time(): "if (intval < INT_MAX / WEEK)" and the like. + if per > 1 && n >= math.MaxInt32/per { + return 0, fmt.Errorf("postfix: time value %q out of range", s) + } + return time.Duration(n*per) * time.Second, nil +} + +// isCSpace is C's isspace() in the "C" locale, which strtol() skips. +func isCSpace(c byte) bool { + return c == ' ' || c == '\t' || c == '\n' || c == '\v' || c == '\f' || c == '\r' } // FormatDuration renders a Postfix interval the way the Mail queue card and diff --git a/internal/postfix/duration_test.go b/internal/postfix/duration_test.go index f65579f..8ca4067 100644 --- a/internal/postfix/duration_test.go +++ b/internal/postfix/duration_test.go @@ -5,39 +5,47 @@ import ( "time" ) -func TestParseDuration(t *testing.T) { +// Postfix 3.7.11, src/global/conv_time.c, conv_time(): one number, one +// lower-case unit, the default unit when there is none, the rest ignored. +func TestParseTime(t *testing.T) { cases := []struct { in string + unit byte want time.Duration }{ - {"5d", 5 * 24 * time.Hour}, - {"300s", 300 * time.Second}, - {"4000s", 4000 * time.Second}, - {"1h", time.Hour}, - {"0", 0}, - {"0s", 0}, - {"300", 300 * time.Second}, - {" 300s ", 300 * time.Second}, - {"1h7m", time.Hour + 7*time.Minute}, - {"1w", 7 * 24 * time.Hour}, - {"2m", 2 * time.Minute}, + {"5d", 's', 5 * 24 * time.Hour}, + {"300s", 'd', 300 * time.Second}, + {"4000s", 's', 4000 * time.Second}, + {"1h", 's', time.Hour}, + {"0", 's', 0}, + {"0s", 's', 0}, + {"300", 's', 300 * time.Second}, + {"3", 'd', 3 * 24 * time.Hour}, // maximal_queue_lifetime = 3 + {"2", 'h', 2 * time.Hour}, // delay_warning_time = 2 + {" 300s ", 's', 300 * time.Second}, + {"+5m", 's', 5 * time.Minute}, + {"1h7m", 's', time.Hour}, // what follows the unit is ignored + {"1h 5x", 's', time.Hour}, + {"1w", 's', 7 * 24 * time.Hour}, + {"2m", 's', 2 * time.Minute}, + {"s", 'd', 0}, // strtol() reads nothing and stops at the "s" } for _, tc := range cases { - got, err := ParseDuration(tc.in) + got, err := ParseTime(tc.in, tc.unit) if err != nil { - t.Errorf("ParseDuration(%q): %v", tc.in, err) + t.Errorf("ParseTime(%q, %c): %v", tc.in, tc.unit, err) continue } if got != tc.want { - t.Errorf("ParseDuration(%q) = %v, want %v", tc.in, got, tc.want) + t.Errorf("ParseTime(%q, %c) = %v, want %v", tc.in, tc.unit, got, tc.want) } } } -func TestParseDurationRejectsInvalid(t *testing.T) { - for _, in := range []string{"", "foo", "5x", "-300s", "s", "1h 5x"} { - if _, err := ParseDuration(in); err == nil { - t.Errorf("ParseDuration(%q) = nil, want error", in) +func TestParseTimeRejectsInvalid(t *testing.T) { + for _, in := range []string{"", "foo", "5x", "-300s", "5D", "1H", " s", "99999999999s", "400000w"} { + if _, err := ParseTime(in, 's'); err == nil { + t.Errorf("ParseTime(%q) = nil, want error", in) } } } diff --git a/internal/postfix/queue.go b/internal/postfix/queue.go index c0d2f19..89ea0a2 100644 --- a/internal/postfix/queue.go +++ b/internal/postfix/queue.go @@ -125,12 +125,15 @@ func QueueIDs() (map[string]struct{}, error) { // 3C5B04E6C1* 446 Thu Aug 7 10:12:31 app@example.com // // The id is at the start of the line, optionally flagged '*' (in the active -// queue) or '!' (on hold), and is followed by the message size. Requiring the +// queue) or '!' (on hold), then '#' when the message was forced to expire +// (Postfix 3.7.11, src/postqueue/showq_compat.c, showq_message(): the flags +// are appended to the id in that order; assumptions B-PQ1), and is followed +// by the message size. Requiring the // size is what separates an entry from the listing's other left-margin lines: // the '-Queue ID-' header, the '-- 5 Kbytes in 2 Requests.' trailer, a deferred // entry's '(connect timed out)' reason, and 'Mail queue is empty'. Recipient // lines are indented and never match. -var queueEntryRe = regexp.MustCompile(`^([0-9A-Za-z]+)[*!]?\s+\d+\s`) +var queueEntryRe = regexp.MustCompile(`^([0-9A-Za-z]+)[*!]?#?\s+\d+\s`) func parseQueueIDs(listing string) map[string]struct{} { ids := make(map[string]struct{}) diff --git a/internal/postfix/queue_test.go b/internal/postfix/queue_test.go index bed52ae..a51be99 100644 --- a/internal/postfix/queue_test.go +++ b/internal/postfix/queue_test.go @@ -92,10 +92,16 @@ func TestParseQueueIDs(t *testing.T) { A1B2C3D4E5F! 891 Fri Aug 8 10:14:31 app@example.com held@example.net --- 1 Kbytes in 3 Requests. +6D7E8F9A0B*# 512 Fri Aug 8 10:15:31 app@example.com + expiring@example.net + +7E8F9A0B1C# 512 Fri Aug 8 10:16:31 app@example.com + expiring2@example.net + +-- 2 Kbytes in 5 Requests. ` ids := parseQueueIDs(listing) - want := []string{"3C5B04E6C1", "5B4A2C1D3E", "A1B2C3D4E5F"} + want := []string{"3C5B04E6C1", "5B4A2C1D3E", "A1B2C3D4E5F", "6D7E8F9A0B", "7E8F9A0B1C"} for _, id := range want { if _, ok := ids[id]; !ok { t.Errorf("queue id %s not found in %v", id, ids) diff --git a/internal/postfix/retry.go b/internal/postfix/retry.go index fa7d14b..b2f106c 100644 --- a/internal/postfix/retry.go +++ b/internal/postfix/retry.go @@ -55,6 +55,13 @@ var retryConfKeys = []string{ "delay_warning_time", } +// retryConfUnits is each key's default unit: the last letter of its default +// value (Postfix 3.7.11, src/global/mail_params.h, DEF_QUEUE_RUN_DELAY +// "300s", DEF_MIN_BACKOFF_TIME, DEF_MAX_BACKOFF_TIME "4000s", +// DEF_MAX_QUEUE_TIME "5d", DEF_DSN_QUEUE_TIME "5d", DEF_DELAY_WARN_TIME +// "0h"; src/global/mail_conf_time.c, get_def_time_unit()). +var retryConfUnits = []byte{'s', 's', 's', 'd', 'd', 'h'} + // readRetryConf runs `postconf -h` for the retry-policy keys. Tests replace it // the same way logtail stubs queueIDs. var readRetryConf = postconfRetryValues @@ -63,8 +70,9 @@ func postconfRetryValues() ([]string, error) { // Fixed argv, no user input — same pattern as Queue (security.md). // Postfix 3.7.11, src/postconf/postconf_main.c, pcf_show_parameters(): // named parameters are printed in argument order, with -h one "%s\n" - // value each, as written in main.cf (not expanded without -x). - cmd := exec.Command("postconf", "-h", + // value each; -x expands "$name" as Postfix itself does when it reads + // the value (mail_conf_eval()). + cmd := exec.Command("postconf", "-h", "-x", "queue_run_delay", "minimal_backoff_time", "maximal_backoff_time", @@ -109,12 +117,18 @@ func parseRetryPolicy(lines []string) (RetryPolicy, error) { } var durs [6]time.Duration for i, line := range lines { - d, err := ParseDuration(line) + d, err := ParseTime(line, retryConfUnits[i]) if err != nil { return RetryPolicy{}, fmt.Errorf("%s: %w", retryConfKeys[i], err) } durs[i] = d } + // Postfix 3.7.11, src/qmgr/qmgr.c, qmgr_post_init(): "bounce_queue_lifetime + // is larger than maximal_queue_lifetime - adjusting" - qmgr uses the + // smaller. + if durs[4] > durs[3] { + durs[4] = durs[3] + } return RetryPolicy{ QueueRunDelay: durs[0], MinimalBackoff: durs[1], @@ -141,13 +155,11 @@ func (p RetryPolicy) BackoffCap() string { // sender, which an application may submit too. It bounds which stored log // lines can be about a send-log row (store.SendLogLines). // -// Postfix 3.7.11, src/qmgr/qmgr_active.c, qmgr_active_done(): a message -// expires after var_max_queue_time, or var_dsn_queue_time when its sender is -// null - whoever submitted it (qmgr.c caps the second at the first). +// Postfix 3.7.11, src/qmgr/qmgr_active.c, qmgr_active_done_25_generic(): a +// message expires after var_max_queue_time, or var_dsn_queue_time when its +// sender is null - whoever submitted it; qmgr.c caps the second at the +// first, and so does parseRetryPolicy, which leaves the first the longer. func (p RetryPolicy) LongestLifetime() time.Duration { - if p.BounceQueueLifetime > p.MaximalQueueLifetime { - return p.BounceQueueLifetime - } return p.MaximalQueueLifetime } diff --git a/internal/postfix/retry_test.go b/internal/postfix/retry_test.go index fc5f2e9..295b331 100644 --- a/internal/postfix/retry_test.go +++ b/internal/postfix/retry_test.go @@ -29,14 +29,29 @@ func TestLoadRetryPolicyUsesPostconfValues(t *testing.T) { if p.MaximalQueueLifetime != 2*24*time.Hour { t.Errorf("MaximalQueueLifetime = %v, want 2d", p.MaximalQueueLifetime) } - if p.BounceQueueLifetime != 5*24*time.Hour { - t.Errorf("BounceQueueLifetime = %v, want 5d", p.BounceQueueLifetime) + // 5d over a maximal 2d: qmgr uses 2d (Postfix 3.7.11, src/qmgr/qmgr.c, + // qmgr_post_init(), "adjusting bounce_queue_lifetime"). + if p.BounceQueueLifetime != 2*24*time.Hour { + t.Errorf("BounceQueueLifetime = %v, want 2d", p.BounceQueueLifetime) } if p.DelayWarningTime != 0 { t.Errorf("DelayWarningTime = %v, want 0", p.DelayWarningTime) } } +// A message lives at most maximal_queue_lifetime: qmgr caps +// bounce_queue_lifetime at it (Postfix 3.7.11, src/qmgr/qmgr.c, +// qmgr_post_init()), so a larger bounce lifetime does not lengthen it. +func TestLongestLifetimeIsTheQueueLifetime(t *testing.T) { + p, err := parseRetryPolicy([]string{"300s", "300s", "4000s", "1d", "5d", "0h"}) + if err != nil { + t.Fatal(err) + } + if p.LongestLifetime() != 24*time.Hour || p.BounceQueueLifetime != 24*time.Hour { + t.Fatalf("LongestLifetime %v, BounceQueueLifetime %v; want 24h both", p.LongestLifetime(), p.BounceQueueLifetime) + } +} + func TestLoadRetryPolicyFallsBackWhenPostconfFails(t *testing.T) { old := readRetryConf readRetryConf = func() ([]string, error) { diff --git a/internal/store/deliverylog.go b/internal/store/deliverylog.go index e5b530b..285f159 100644 --- a/internal/store/deliverylog.go +++ b/internal/store/deliverylog.go @@ -69,13 +69,14 @@ func (s *Store) SetQueuedOverLifetime(at time.Time, n int64) error { 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) { +// CountOpenOlderThan counts the rows still open - "queued" or "deferred" - +// that were accepted before cutoff. created_at is RFC3339 UTC, so the strings +// compare as times. +func (s *Store) CountOpenOlderThan(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), + `SELECT COUNT(*) FROM send_log WHERE status IN (?, ?) AND queue_id <> '' AND created_at < ?`, + StatusQueued, StatusDeferred, cutoff.UTC().Format(time.RFC3339), ).Scan(&n) if err != nil { return 0, fmt.Errorf("count queued send_log rows: %w", err) diff --git a/internal/store/deliverylog_test.go b/internal/store/deliverylog_test.go index 74dbafb..178ee58 100644 --- a/internal/store/deliverylog_test.go +++ b/internal/store/deliverylog_test.go @@ -59,7 +59,7 @@ func TestAddDeliveryLogDayRefusesAnotherColumn(t *testing.T) { } } -func TestCountQueuedOlderThan(t *testing.T) { +func TestCountOpenOlderThan(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 { @@ -69,10 +69,10 @@ func TestCountQueuedOlderThan(t *testing.T) { 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 { + if n, err := st.CountOpenOlderThan(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 { + if n, err := st.CountOpenOlderThan(time.Now().Add(-time.Hour)); err != nil || n != 0 { t.Fatalf("queued rows before an hour ago = %d, %v; want 0", n, err) } } diff --git a/internal/store/refusal_test.go b/internal/store/refusal_test.go index 66bc291..7034d8a 100644 --- a/internal/store/refusal_test.go +++ b/internal/store/refusal_test.go @@ -28,19 +28,23 @@ func TestAttachRefusalLine(t *testing.T) { } first := "Oct 14 12:00:00 mail postfix/smtpd[1]: NOQUEUE: milter-reject: MAIL from unknown[10.0.0.1]: 451 4.7.1 first" second := "Oct 14 12:00:00 mail postfix/smtpd[2]: NOQUEUE: milter-reject: MAIL from unknown[10.0.0.1]: 451 4.7.1 second" + // Another application at the same client, as the same sender: not its. + if ok, _ := st.AttachRefusalLine("10.0.0.1", "other", "billing@example.com", now, "another login"); ok { + t.Fatal("a line of another login took a row") + } for _, line := range []string{first, second} { - if ok, err := st.AttachRefusalLine("10.0.0.1", "Billing@example.com", now, line); err != nil || !ok { + if ok, err := st.AttachRefusalLine("10.0.0.1", "L2App", "Billing@example.com", now, line); err != nil || !ok { t.Fatalf("attach %q = %v, %v", line, ok, err) } } // Read again after a restart: no row takes it a second time. - if ok, _ := st.AttachRefusalLine("10.0.0.1", "billing@example.com", now, first); ok { + if ok, _ := st.AttachRefusalLine("10.0.0.1", "l2app", "billing@example.com", now, first); ok { t.Fatal("a line already on a row took another") } - if ok, _ := st.AttachRefusalLine("10.0.0.3", "billing@example.com", now, "a third"); ok { + if ok, _ := st.AttachRefusalLine("10.0.0.3", "l2app", "billing@example.com", now, "a third"); ok { t.Fatal("a line of another client took a row") } - if ok, _ := st.AttachRefusalLine("10.0.0.2", "billing@example.com", now.Add(-time.Hour), "an hour off"); ok { + if ok, _ := st.AttachRefusalLine("10.0.0.2", "other", "billing@example.com", now.Add(-time.Hour), "an hour off"); ok { t.Fatal("a line an hour off took a row") } lines := map[string]string{} diff --git a/internal/store/sendlog.go b/internal/store/sendlog.go index 1144feb..76c8d3d 100644 --- a/internal/store/sendlog.go +++ b/internal/store/sendlog.go @@ -162,14 +162,14 @@ func (s *Store) UpdateStatus(queueID, recipient, status 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. +// (architecture.md § Log tailer). Only a row still open - "queued" or +// "deferred" - is closed; a final 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 id = ? AND status = ?`, - StatusBounced, ReasonReconcile, now, id, StatusQueued, + `UPDATE send_log SET status = ?, reason = ?, updated_at = ? WHERE id = ? AND status IN (?, ?)`, + StatusBounced, ReasonReconcile, now, id, StatusQueued, StatusDeferred, ) if err != nil { return 0, fmt.Errorf("close unreported send_log row: %w", err) @@ -178,6 +178,30 @@ func (s *Store) CloseUnreported(id int64) (int64, error) { return n, nil } +// ExpireMessage closes the rows of a message Postfix gave up on at the end of +// its queue lifetime: each recipient's newest row with that queue id, if it +// is still open ("queued" or "deferred"), becomes "bounced" - Postfix returns +// the message to its sender. Postfix 3.7.11, src/qmgr/qmgr_active.c, +// qmgr_active_done_25_generic(), logs expiry once per message, ": +// from=<..>, status=expired, returned to sender", with no line per +// recipient: the recipients' last lines say "deferred" (assumptions A-8). It +// returns the number of rows closed. +func (s *Store) ExpireMessage(queueID string) (int64, error) { + now := time.Now().UTC().Format(time.RFC3339) + res, err := s.db.Exec( + `UPDATE send_log SET status = ?, updated_at = ? + WHERE status IN (?, ?) AND id IN ( + SELECT MAX(id) FROM send_log WHERE queue_id = ? AND status <> 'rejected' + GROUP BY to_addr COLLATE NOCASE)`, + StatusBounced, now, StatusQueued, StatusDeferred, queueID, + ) + if err != nil { + return 0, fmt.Errorf("expire send_log rows of %s: %w", queueID, err) + } + n, _ := res.RowsAffected() + return n, nil +} + // QueuedDelivery is a send-log row still waiting for a delivery result, // 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). @@ -187,22 +211,25 @@ type QueuedDelivery struct { To string } -// ListQueuedOlderThan returns the rows still marked "queued" that were accepted -// before cutoff — old enough that Postfix should long since have reported a -// result for them. Rows without a queue-id are skipped: the milter refused -// those before Postfix ever saw the message, so the queue has nothing to say -// about them. +// ListOpenOlderThan returns the rows still open - "queued", or "deferred" +// and waiting for the next attempt - that were accepted before cutoff, old +// enough that Postfix should long since have reported a result for them or +// still hold the message. Rows without a queue-id are skipped: the milter +// refused those before Postfix ever saw the message, so the queue has +// nothing to say about them. A deferred row is among them because Postfix +// can drop a deferred message without a line per recipient: at expiry (one +// line per message, ExpireMessage) and by postsuper -d (only "removed"). // // created_at is stored as RFC3339 UTC, so a lexical comparison against the same // format is chronologically correct. SQLite 3.53.4 compares TEXT with the // BINARY collation, memcmp() (https://sqlite.org/datatype3.html § 7), and // time.RFC3339 of a UTC time is fixed-width, YYYY-MM-DDTHH:MM:SSZ. -func (s *Store) ListQueuedOlderThan(cutoff time.Time) ([]QueuedDelivery, error) { +func (s *Store) ListOpenOlderThan(cutoff time.Time) ([]QueuedDelivery, error) { rows, err := s.db.Query( `SELECT id, queue_id, to_addr FROM send_log - WHERE status = ? AND queue_id <> '' AND created_at < ? + WHERE status IN (?, ?) AND queue_id <> '' AND created_at < ? ORDER BY id`, - StatusQueued, cutoff.UTC().Format(time.RFC3339), + StatusQueued, StatusDeferred, cutoff.UTC().Format(time.RFC3339), ) if err != nil { return nil, fmt.Errorf("list queued send_log rows: %w", err) @@ -253,8 +280,10 @@ type SendLogRow struct { // AttachRefusalLine puts Postfix's line about a refusal at MAIL FROM on the // row the journal milter wrote for it (audit 2026-10-12, stage 2b). Such a // refusal has no queue id, and the line names no login, so the row is found -// by what the line says: a refused row of that client and sender without a -// line yet, written within two minutes of the line's time; the nearest in +// by what the line says: a refused row of that client, login and sender +// without a line yet - the login is smtpd's sasl_username= on the line, so +// two applications behind one address sending as one sender are told apart +// (assumptions A-21) - written within two minutes of the line's time; the nearest in // time, the oldest of equals, when there are several - lines are read in the // order the rows were written, so two refusals of one second take one line // each in turn (review of stage 2b). A line already on a row - read again @@ -265,12 +294,13 @@ type SendLogRow struct { // reads YYYY-MM-DDTHH:MM:SSZ, the T and the Z included (lang_datefunc.html // § 2); NOCASE folds ASCII only (datatype3.html § 7.1); ?1 is bound once and // used twice (lang_expr.html § 4). -func (s *Store) AttachRefusalLine(clientIP, from string, at time.Time, line string) (bool, error) { +func (s *Store) AttachRefusalLine(clientIP, login, from string, at time.Time, line string) (bool, error) { res, err := s.db.Exec( `UPDATE send_log SET refusal_line = ?1 WHERE id = ( SELECT id FROM send_log WHERE status = ?2 AND queue_id = '' AND refusal_line = '' AND reason IN ('', ?3, ?4) AND from_addr = ?5 COLLATE NOCASE AND client_ip = ?6 + AND app_login = ?10 COLLATE NOCASE AND created_at BETWEEN ?7 AND ?8 ORDER BY ABS(julianday(created_at) - julianday(?9)), id LIMIT 1) @@ -279,6 +309,7 @@ func (s *Store) AttachRefusalLine(clientIP, from string, at time.Time, line stri at.Add(-refusalLineWindow).UTC().Format(time.RFC3339), at.Add(refusalLineWindow).UTC().Format(time.RFC3339), at.UTC().Format(time.RFC3339), + login, ) if err != nil { return false, fmt.Errorf("attach refusal line: %w", err) @@ -452,7 +483,7 @@ func sendLogWhere(f SendLogFilter) (string, []any) { // implementing the configurable retention window (architecture.md § // Persistence, SEND_LOG_RETENTION_DAYS). It returns the number of rows pruned. // created_at is stored as RFC3339 UTC, so a lexical comparison against the -// same format is chronologically correct (see ListQueuedOlderThan). +// same format is chronologically correct (see ListOpenOlderThan). func (s *Store) DeleteSendLogBefore(cutoff time.Time) (int64, error) { res, err := s.db.Exec( `DELETE FROM send_log WHERE created_at < ?`, diff --git a/internal/store/sendlog_test.go b/internal/store/sendlog_test.go index 5be0f22..fce6b43 100644 --- a/internal/store/sendlog_test.go +++ b/internal/store/sendlog_test.go @@ -142,6 +142,72 @@ func TestCloseUnreportedClosesOnlyQueuedRows(t *testing.T) { } } +// Postfix's expiry line closes the message's open rows - each recipient's +// newest, queued or deferred - and leaves a final result, a refusal and an +// older message that had the same queue id alone (assumptions A-8). +func TestExpireMessageClosesOnlyOpenRows(t *testing.T) { + st := openTestStore(t) + for _, e := range []SendLogEntry{ + {QueueID: "OLDQ", To: "a@example.net"}, // an earlier message, same id + {QueueID: "Q1", To: "a@example.net"}, + {QueueID: "Q1", To: "b@example.net"}, + {QueueID: "Q1", To: "c@example.net"}, + } { + if err := st.InsertQueued(e); err != nil { + t.Fatal(err) + } + } + if _, err := st.db.Exec(`UPDATE send_log SET queue_id = 'Q1' WHERE queue_id = 'OLDQ'`); err != nil { + t.Fatal(err) + } + if _, err := st.UpdateStatus("Q1", "a@example.net", StatusDeferred); err != nil { + t.Fatal(err) + } + if _, err := st.UpdateStatus("Q1", "c@example.net", StatusSent); err != nil { + t.Fatal(err) + } + if n, err := st.ExpireMessage("Q1"); err != nil || n != 2 { + t.Fatalf("ExpireMessage = %d, %v; want 2 (a deferred, b queued)", n, err) + } + rows, err := st.db.Query(`SELECT to_addr, status FROM send_log ORDER BY id`) + if err != nil { + t.Fatal(err) + } + defer rows.Close() + var got []string + for rows.Next() { + var to, status string + if err := rows.Scan(&to, &status); err != nil { + t.Fatal(err) + } + got = append(got, to+" "+status) + } + want := []string{ + "a@example.net " + StatusQueued, // the earlier message's row + "a@example.net " + StatusBounced, + "b@example.net " + StatusBounced, + "c@example.net " + StatusSent, + } + if strings.Join(got, "; ") != strings.Join(want, "; ") { + t.Fatalf("rows = %v, want %v", got, want) + } +} + +// The sweep closes a deferred row as it closes a queued one: Postfix can drop +// a deferred message without a line per recipient. +func TestCloseUnreportedClosesADeferredRow(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.UpdateStatus("Q1", "a@example.net", StatusDeferred); err != nil { + t.Fatal(err) + } + if n, err := st.CloseUnreported(rowID(t, st, "Q1")); err != nil || n != 1 { + t.Fatalf("CloseUnreported of a deferred row = %d, %v; want 1", n, err) + } +} + // 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 row is marked // reconcile-contradicted, and the day counts one contradiction - once, @@ -205,7 +271,7 @@ func TestUpdateStatusRewritesOnlyTheNewestRow(t *testing.T) { // 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 // sweep's business. -func TestListQueuedOlderThan(t *testing.T) { +func TestListOpenOlderThan(t *testing.T) { st := openTestStore(t) for _, e := range []SendLogEntry{ @@ -232,9 +298,9 @@ func TestListQueuedOlderThan(t *testing.T) { backdate(t, st, "OLD1", cutoff.Add(-time.Hour)) backdate(t, st, "DONE1", cutoff.Add(-time.Hour)) - got, err := st.ListQueuedOlderThan(cutoff) + got, err := st.ListOpenOlderThan(cutoff) if err != nil { - t.Fatalf("ListQueuedOlderThan: %v", err) + t.Fatalf("ListOpenOlderThan: %v", err) } 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/internal/store/sessions.go b/internal/store/sessions.go index 9ca96c1..08b609a 100644 --- a/internal/store/sessions.go +++ b/internal/store/sessions.go @@ -103,7 +103,7 @@ func (s *Store) DeleteUserSessions(userID int64) error { // forever. It piggybacks on session creation rather than running as its own // background loop. // expires_at is RFC3339 UTC text, so < compares moments (see -// ListQueuedOlderThan). +// ListOpenOlderThan). func (s *Store) DeleteExpiredSessions(now time.Time) (int64, error) { res, err := s.db.Exec(`DELETE FROM sessions WHERE expires_at < ?`, now.UTC().Format(time.RFC3339)) if err != nil { diff --git a/internal/web/handlers/handlers_users_test.go b/internal/web/handlers/handlers_users_test.go index f57db85..dc47d39 100644 --- a/internal/web/handlers/handlers_users_test.go +++ b/internal/web/handlers/handlers_users_test.go @@ -167,7 +167,7 @@ func TestARefusedMessageShowsPostfixsLine(t *testing.T) { } if subject == "with its line" { line := time.Now().UTC().Format("2006-01-02T15:04:05Z") + " mail postfix/smtpd[2131]: NOQUEUE: milter-reject: MAIL from unknown[198.51.100.7]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=" - if ok, err := st.AttachRefusalLine("198.51.100.7", "alerts@example.org", time.Now(), line); err != nil || !ok { + if ok, err := st.AttachRefusalLine("198.51.100.7", "alerts", "alerts@example.org", time.Now(), line); err != nil || !ok { t.Fatalf("attach = %v, %v", ok, err) } } diff --git a/internal/web/view/outbound_log.go b/internal/web/view/outbound_log.go index 7c36b84..d869a8b 100644 --- a/internal/web/view/outbound_log.go +++ b/internal/web/view/outbound_log.go @@ -262,7 +262,10 @@ func NewOutMessage(m Meta, in MessageInput) *OutMessage { history.Help = topicLink(HelpSenderCheck, "What an application may write in From:") } if in.Recovered { - facts = append(facts, Fact{Label: "Written", Value: Rich("from ", Code("mail.log"), " after a restart: the panel stopped before it wrote the refusal")}) + // cleanup's line names the message's last recipient only (Postfix + // 3.7.11, src/cleanup/cleanup_milter.c, cleanup_milter_apply(), + // " to=<%s>" of state->recip; assumptions A-15). + facts = append(facts, Fact{Label: "Written", Value: Rich("from ", Code("mail.log"), " after a restart: the panel stopped before it wrote the refusal. Postfix's line names the last recipient only")}) } if in.QueueID != "" { facts = append(facts, Fact{Label: "Queue id", Value: Rich(Mono(in.QueueID), " - given, the message was not queued")}) diff --git a/test/e2e/delivery_log_test.go b/test/e2e/delivery_log_test.go index d91fee2..1e4916a 100644 --- a/test/e2e/delivery_log_test.go +++ b/test/e2e/delivery_log_test.go @@ -78,3 +78,75 @@ func testDeliveryLogSurvivesRotation(t *testing.T, sc *scenario) { t.Fatalf("after mail.log was rotated: %v", err) } } + +// testExpiredMessageIsClosed: a message Postfix gives up on is closed as +// bounced. Postfix logs expiry once per message, ": from=<..>, +// status=expired, returned to sender" (here "force-expired"), and no line per +// recipient (Postfix 3.7.11, src/qmgr/qmgr_active.c, +// qmgr_active_done_25_generic(); assumptions A-8). The queue lifetime cannot +// be waited out, so the message is deferred by hand - defer_transports=smtp, +// under which qmgr hands the recipient to the retry service, "4.3.2 deferred +// transport" (src/qmgr/qmgr_message.c, qmgr_message_resolve()) - and then +// forced to expire: postsuper -e marks it, postqueue -i has qmgr look at it +// at once (man/man1/postsuper.1, postqueue.1). +func testExpiredMessageIsClosed(t *testing.T, sc *scenario) { + exec := func(args ...string) { + t.Helper() + if out, err := h.execIn("selfpost", args...); err != nil { + t.Fatalf("%s: %v\n%s", strings.Join(args, " "), err, out) + } + } + exec("postconf", "-e", "defer_transports=smtp") + exec("postfix", "reload") + defer func() { + // The bounce to the sender waits behind the same setting. + h.execIn("selfpost", "postconf", "-e", "defer_transports=") + h.execIn("selfpost", "postfix", "reload") + h.execIn("selfpost", "postqueue", "-f") + }() + + token := uniqueToken("expire") + if res := attemptSend(sendAttempt{ + authLogin: sc.appLogin, authPassword: sc.appPassword, + from: "alerts@" + senderDomain, headerFrom: "alerts@" + senderDomain, to: recipient, + subject: "e2e " + token, body: "deferred, then expired", + }); !res.ok() { + t.Fatalf("send: %v", res.firstErr()) + } + row := func() (string, error) { + return asPanel(`import sqlite3,sys +r=sqlite3.connect("/data/selfpost.db").execute("select queue_id, status from send_log where subject like ? order by id desc",("%"+sys.argv[1]+"%",)).fetchone() +print("" if r is None else r[0]+" "+r[1])`, token) + } + var queueID string + if err := waitFor("the row to be deferred", 30*time.Second, 500*time.Millisecond, func() (bool, error) { + out, err := row() + if err != nil { + return false, err + } + if f := strings.Fields(out); len(f) == 2 && f[1] == "deferred" { + queueID = f[0] + return true, nil + } + return false, fmt.Errorf("row %q", out) + }); err != nil { + t.Fatal(err) + } + + exec("postsuper", "-e", queueID) + exec("postqueue", "-i", queueID) + if err := waitFor("the expired message's row to be bounced", 30*time.Second, 500*time.Millisecond, func() (bool, error) { + out, err := row() + if err != nil { + return false, err + } + return out == queueID+" bounced", fmt.Errorf("row %q", out) + }); err != nil { + out, _ := h.execIn("selfpost", "grep", queueID, "/data/log/mail.log") + t.Fatalf("%v\nmail.log:\n%s", err, out) + } + out, err := h.execIn("selfpost", "grep", queueID+": from=, status=force-expired, returned to sender", "/data/log/mail.log") + if err != nil { + t.Fatalf("no expiry line in mail.log: %v\n%s", err, out) + } +} diff --git a/test/e2e/main_test.go b/test/e2e/main_test.go index 4c5a9bd..c2d0a34 100644 --- a/test/e2e/main_test.go +++ b/test/e2e/main_test.go @@ -345,6 +345,9 @@ func TestE2E(t *testing.T) { // From here on the installation is no longer the one the run started: it // is restored from its own backup, then switched to accept mail on port 25. + run("expired_message_is_closed", func(t *testing.T) { + testExpiredMessageIsClosed(t, sc) + }) run("full_backup_restore", func(t *testing.T) { testFullBackupRestore(t, sc) })