log tailer: expiry, Postfix's time values and refusal lines as Postfix writes them
test / test (push) Canceled after 0s

Expiry (assumptions A-8). Postfix 3.7.11 logs the end of a message's queue
lifetime once per message, "<id>: from=<..>, status=expired, returned to
sender" (src/qmgr/qmgr_active.c, qmgr_active_done_25_generic()), with no
line per recipient; the tailer waited for "to=..., status=expired", which
no Postfix writes, and the sweep closed only queued rows, so such rows
stayed deferred. The tailer now reads qmgr's line (ExpireMessage: each
recipient's newest open row of the id becomes bounced); the sweep closes a
deferred row too when Postfix no longer holds the message, and counts as
missed only a final line (sent, bounced, expiry). The queue listing's '#'
(forced expiry, showq_compat.c showq_message()) is read as a flag (B-PQ1).

Time values (B-PQ10, B-PQ11): conv_time() ported - one number, one
lower-case unit, the parameter's default unit when none (get_def_time_unit:
d for the lifetimes, h for delay_warning_time), the rest ignored; postconf
-h -x expands $name; bounce_queue_lifetime capped at maximal_queue_lifetime
as qmgr_post_init() caps it, so LongestLifetime is the queue lifetime.

Refusals (A-21, A-23, A-24, A-15): smtpd_whatsup() ends the NOQUEUE line
with sasl_username=<login> on an authenticated session; the line is now
matched to its row by client, login and sender, and a line without a login
is no application's. The client= line's login ends at the comma. The
"IPv6:" trim goes (namaddr is built from state->addr). A row recovered from
cleanup's line says that line names the last recipient only.

Stand (2026-10-14, make e2e, exit 0): new expired_message_is_closed -
defer_transports=smtp makes the retry service defer the message, postsuper
-e and postqueue -i force its expiry; mail.log has "<id>:
from=<alerts@sender.e2e.test>, status=force-expired, returned to sender"
and the row goes deferred -> bounced; refusals_show_postfixs_line passes
with the login match. go vet and go test ./... pass on the server.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
mix
2026-10-14 20:21:51 +03:00
co-authored by Claude Opus 5.5
parent 55aef6e721
commit 0ed03b2094
24 changed files with 594 additions and 212 deletions
+27
View File
@@ -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
+41 -17
View File
@@ -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 <client>[<address>]: …; from=<…>` - it names no login - and puts it on
the newest refused row of that client address and sender within two minutes
from <client>[<address>]: …; from=<…> … sasl_username=<login>` - 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, `<id>:
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.
+4 -2
View File
@@ -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
+50 -19
View File
@@ -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=<app@example.org>, 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 "<log>.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
}
}
+81 -15
View File
@@ -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=<app@example.org>, 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=<app@example.org>, 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=<x>, 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=<a@example.net>, 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=<app@example.org>, 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=<late@example.net>, 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=<app@example.org>, 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=<slow@example.net>, 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=<app@example.org>, 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
+26 -18
View File
@@ -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=<billing@sender.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>
// postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from=<billing@sender.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test> sasl_username=<l2app>
//
// 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=<login>" 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,16 +60,17 @@ 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: "<id>: client=host[addr], sasl_method=PLAIN, sasl_username=<login>".
// 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
clientIP, login, from, line string
at, until time.Time
start Place // where the line starts in the log
}
@@ -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
+6 -3
View File
@@ -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=<a@stranger.example> proto=ESMTP helo=<x>`,
`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 <a@x>: Sender address rejected: not owned by user app1; from=<a@x> to=<b@y> proto=ESMTP helo=<x>`,
// 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=<billing@sender.e2e.test> proto=ESMTP helo=<x>`,
} {
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)
}
+5 -3
View File
@@ -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
}
+49 -54
View File
@@ -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])) {
for i < len(s) && isCSpace(s[i]) {
i++
}
if i >= len(s) {
break
}
if s[i] == '-' {
return 0, fmt.Errorf("postfix: negative time value %q", s)
}
if s[i] == '+' {
neg := false
if i < len(s) && (s[i] == '+' || s[i] == '-') {
neg = s[i] == '-'
i++
}
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 {
return 0, fmt.Errorf("postfix: invalid time value %q", s)
// strtol() converted nothing: the end is the start of the string.
end, n, neg = 0, 0, false
}
n, err := strconv.ParseInt(s[start:i], 10, 64)
if err != nil {
return 0, fmt.Errorf("postfix: invalid time value %q", s)
if neg && n > 0 {
return 0, fmt.Errorf("postfix: negative time value %q", s)
}
unit := byte('s')
if i < len(s) && isTimeUnit(s[i]) {
unit = s[i] | 0x20 // ASCII fold to lowercase
i++
unit := defUnit
if end < len(s) {
unit = s[end]
}
part, err := durationForUnit(n, unit)
if err != nil {
return 0, err
}
total += part
}
return total, nil
}
func isTimeUnit(c byte) bool {
switch c | 0x20 {
case 's', 'm', 'h', 'd', 'w':
return true
}
return false
}
func durationForUnit(n int64, unit byte) (time.Duration, error) {
var unitDur time.Duration
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
+27 -19
View File
@@ -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)
}
}
}
+5 -2
View File
@@ -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{})
+8 -2
View File
@@ -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)
+21 -9
View File
@@ -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
}
+17 -2
View File
@@ -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) {
+6 -5
View File
@@ -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)
+3 -3
View File
@@ -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)
}
}
+8 -4
View File
@@ -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{}
+48 -17
View File
@@ -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, "<id>:
// 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 < ?`,
+69 -3
View File
@@ -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)
+1 -1
View File
@@ -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 {
+1 -1
View File
@@ -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=<alerts@example.org> proto=ESMTP helo=<app>"
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)
}
}
+4 -1
View File
@@ -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")})
+72
View File
@@ -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, "<id>: 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=<alerts@"+senderDomain+">, 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)
}
}
+3
View File
@@ -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)
})