Compare commits

...
9 Commits
Author SHA1 Message Date
mixandClaude Opus 5.5 a990e7cc23 delivery-log-storage: findings of the technical and security reviews
test / test (push) Canceled after 0s
Neither review (read-only agents, Opus and Fable, over ae06d8b..815236a) has
a Critical or High finding. What they found and what was done:

- A stranger on port 25 could grow the table: every queue-id line of inbound
  mail was stored and pruned an hour or more later, his own message-id among
  them. The tailer now leaves out the lines of a queue id that
  postfix/inbound/smtpd opened, until qmgr removes the message or another
  listener opens one under the id; 4096 such ids are remembered.
- A commit, so a disk sync, per stored line on the connection the journal
  milter shares, and a backlog written line by line. Lines are now written in
  one transaction per pass over the log, 500 at most, before the read offset
  is saved (InsertSendLogLines; follow() calls the keeper's flush).
- The prune asked the send log once per line and ran hourly. It asks once per
  queue id and runs at start and with the six-hourly sweep; with port-25 mail
  left out there is little without a row to wait for.
- The 4096-byte cut could split a character; it keeps characters whole.
- security.md did not say that a backup now carries these lines, and the plan
  said the time window excludes a reused queue id where it only limits the
  chance to the row's queue lifetime. Both are corrected; the collision is
  recorded as an accepted risk with its trigger.
- Tests that did not prove their comments: the prune is now tested with the
  sweep, a rejected row next to the prune, batching and the change from
  catching up to following, port-25 mail left out and its id reused.

Left as found and written down in the plan: lines the tailer never reads
(a file rotated away while the panel was down), and a message in the queue
across the upgrade, which shows only its later lines.

On the test server, for this tree: go vet clean, go test ./... 22 packages
ok, make e2e ok.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:41:04 +03:00
mixandClaude Opus 5.5 815236a607 delivery-log-storage: e2e holds the page to its lines after a rotation
New step delivery_log_survives_rotation: the page of the first delivered
message must list the line that opened its queue id and its delivery line,
then mail.log is rotated with logrotate -f, the current file is checked to
hold no delivery line, and the page must list both lines still. Before this
feature the page searched the current file and would show none.

The step runs after negative_level1_ratelimit: placed right after the first
delivery it rotated away the "connect from" line the level-2 step reads from
the current log, and that step failed.

On the test server, for this tree: go vet clean, go test ./... 22 packages
ok, make e2e ok (126 s).

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:25:21 +03:00
mixandClaude Opus 5.5 a6845ae948 delivery-log-storage: architecture and guide
architecture.md § Log tailer gains "Stored lines": what is kept and why the
queue id is read from the head of a line, why the tailer does not check for a
row before writing, the one prune rule that is the table's retention, how a
row is given its lines when Postfix reuses queue ids, the write-once rule
while catching up, and the size. QueueLines is described as what it is now,
the fallback for rows without stored lines. guide.md: the message page keeps
its lines after rotation; retention also bounds the kept lines, which are in
a full backup.

Docs only.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:15:47 +03:00
mixandClaude Opus 5.5 1e6836b3c1 delivery-log-storage: a message's page reads its stored lines
The Delivery log box on a message's page was filled by searching the current
mail.log on every view; that file is rotated daily, so the box was empty for
anything not sent today. deliveryLog now asks the store for the row's lines -
its queue id, dated within the row's queue lifetime plus a day
(RetryPolicy.LongestLifetime) - and shows the latest 200, oldest first.

When nothing is stored the page still searches the current file, which is
what shows a message accepted before 2.2.0. When that finds nothing either,
the note no longer blames rotation for the ordinary case: it says lines are
kept with the row since 2.2.0. The Outbound log help topic in help.go follows
the mockup changed in fc184ec, word for word.

Checked on Windows: go vet clean; go test ./internal/web/... ./internal/postfix
./internal/store pass, the guards among them. New test: lines shown from the
table when mail.log holds none of them, without another queue id's lines and
without those of an earlier message under the same id.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:15:26 +03:00
mixandClaude Opus 5.5 fc184ecc01 design: the Outbound log help topic says the lines are kept
The topic said a message's lines are found in mail.log by queue id and that an
old message may show none, because that file is rotated. With
delivery-log-storage the lines are kept with the row: they stay on the page
for as long as the row does and go with it. A message accepted before 2.2.0
shows them only while they are in the current file.

Mockup source and its built page only; help.go follows with the page.
build.py: 35 pages; check.py: 32 screens, 52 sp- classes, 0 violations.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:12:10 +03:00
mixandClaude Opus 5.5 81df131217 delivery-log-storage: the tailer keeps the lines of queued messages
Every mail.log line headed by a queue id is written to send_log_lines as the
tailer reads it, dated by the line's own stamp. The id is taken from the head
of the line only - the tail is the far end's text - and has to look like one:
"NOQUEUE:" and "warning:" stand in the same place.

The tailer does not check for a send-log row first: a message's first lines
come before the journal milter writes it. Lines that never get a row are
removed by the prune, which deletes lines older than an hour whose queue id
no row carries. It runs at start, after each send-log sweep and hourly.

While the tailer catches up at start a line is written only if it is not
there already, as the inbound journal does: its place is saved every few
seconds, so an unclean stop means reading some lines twice.

Checked on Windows: go vet clean; go test ./internal/logtail passes except
TestFollowTailsAndRotates, which fails there on renaming an open file and
always did. New tests: which line heads are queue ids, a line dated by its
stamp, no second copy after a rewound offset, the prune cadence and cutoff.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:11:28 +03:00
mixandClaude Opus 5.5 3d17206063 delivery-log-storage: the table for a message's log lines
Migration 0003_send_log_lines.sql, DDL only: queue id, the line's own time,
the line. No reference to send_log, because a message's first lines are
logged before the journal milter writes its row and one queue id is several
rows.

Store methods: InsertSendLogLine; InsertSendLogLineOnce for lines the tailer
reads twice after an unclean stop; SendLogLines, which gives a row the lines
of its queue id dated from an hour before the row to the queue lifetime after
it, so a later message under a reused id is not shown; PruneSendLogLines,
which deletes lines whose queue id has no send-log row - the whole of the
table's retention. A line is cut to 4096 bytes.

Nothing writes or reads the table yet. Checked on Windows: go vet and
go test ./internal/store pass, with the schema test pinning the new table,
its index and user_version 3.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:08:56 +03:00
mixandClaude Opus 5.5 4468aa8dd7 delivery-log-storage: agreed, plan and checklist
The owner agreed the item on 2026-10-12 (option 1 of the roadmap entry: store
the lines). plans/delivery-log-storage.md records what that means in detail:
every mail.log line headed by a queue id goes into send_log_lines with the
line's own time; a line is a row's when the id matches and its time lies
within the row's queue lifetime, which is the bound against Postfix reusing
ids; a line whose id has no send-log row is deleted after an hour, which is
both the retention and the clean-up of inbound and bounce lines; the page
reads the table and falls back to the current file for rows older than it.
Eight checklist steps, cut 2.2.0.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:05:08 +03:00
mixandClaude Opus 5.5 977d63a2ea roadmap: inbound quarantine is an idea, not a candidate
The owner, 2026-10-12: take quarantine out of the main plan, it is an idea
to think about. Its index row and section leave roadmap.md; a new closing
section, "Ideas, not on the roadmap", keeps a paragraph and the link to the
notes in plans/inbound-quarantine.md. panel-notifications no longer lists
"mail is held in quarantine" among its events. The plans that called it a
candidate say what it is now. The drawn screens stay unbuilt, as they were.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:04:44 +03:00
29 changed files with 1381 additions and 96 deletions
+37
View File
@@ -5,6 +5,43 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version
## [Unreleased] ## [Unreleased]
### Added
- **Schema: `send_log_lines`** (migration `0003_send_log_lines.sql`, DDL only).
The table that will hold what Postfix wrote about a message for as long as
its send-log row lives, with the store methods to write a line, to write it
once, to read the lines of a row and to prune
([plans/delivery-log-storage.md](docs/plans/delivery-log-storage.md)).
- **The log tailer keeps what Postfix writes about queued messages.** A
`mail.log` line headed by a queue id is stored with the line's own time, one
transaction per pass over the log; after an unclean stop a line read twice
is stored once. Mail that came in on port 25 is left out: a stranger's
message never has a send-log row, and what he can make Postfix log is not
written to the database. Lines whose queue id has no send-log row - the row
was pruned, or the message never had one (bounces) - are deleted once they
are an hour old, at start and with every six-hourly send-log sweep.
### Changed
- **A message's page keeps its delivery log after `mail.log` rotates.** The
*Delivery log* box on Outbound › Log › a message was filled by searching
the current `mail.log`, which is rotated daily, so it was empty for anything
not sent today while the row itself lives for ninety days. The page now
reads the lines the tailer stored: they are there for as long as the row
is. Postfix reuses queue ids, so a row is given only the lines dated within
its own queue lifetime. A message accepted before this version shows its
lines only while they are still in the current file, as before; the note
shown when there are none and the *Outbound log* help topic say so.
### Security
- **A full backup now carries the log lines of messages in the send log** -
client addresses, SASL logins, message ids, receivers' replies - where
`mail.log` itself is not in a backup. Recorded in
[security.md](docs/security.md) with the accepted risk of a queue-id
collision showing one message's lines on another's page. Technical and
security reviews of 2026-10-12: no Critical or High finding.
## [2.1.0] - 2026-10-12 ## [2.1.0] - 2026-10-12
### Security ### Security
+61 -6
View File
@@ -184,6 +184,8 @@ One process, four roles:
3. **log-tailer** — follows `MAIL_LOG`, updates send-log delivery status by 3. **log-tailer** — follows `MAIL_LOG`, updates send-log delivery status by
queue-id. Send-log `queued → sent` transitions depend on this goroutine alone queue-id. Send-log `queued → sent` transitions depend on this goroutine alone
(`UpdateStatus` is only called from [internal/logtail](../internal/logtail/logtail.go)). (`UpdateStatus` is only called from [internal/logtail](../internal/logtail/logtail.go)).
It also keeps the lines Postfix writes under a queue id, for the message's
page (§ Log tailer, *Stored lines*).
4. **rate-limit recalc** — every six hours (and on demand from Domain settings and 4. **rate-limit recalc** — every six hours (and on demand from Domain settings and
the application form), recomputes level-2 **Auto** rate limits from send-log statistics. the application form), recomputes level-2 **Auto** rate limits from send-log statistics.
@@ -234,15 +236,66 @@ leaves every row untouched rather than closing them all. Now that the log
survives the container, reaching this path means the lines are gone for good — survives the container, reaching this path means the lines are gone for good —
rotated past fourteen files while the panel was down, or deleted. rotated past fourteen files while the panel was down, or deleted.
**Stored lines** (`send_log_lines`, since 2.2.0;
[internal/logtail/lines.go](../internal/logtail/lines.go)). A send-log row
lives for the retention window, ninety days by default, and `mail.log` for a
day before it is rotated; a message's page (`/outbound/log/{id}`) shows what
Postfix wrote about it, so the tailer keeps those lines in the database as it
reads them:
- **What is kept:** a line headed by a queue id — after the timestamp, the
host name and `program[pid]:` — with that id, the line's own time and the
line as written, cut to 4096 bytes. The id is read from the head of the line
only: the tail is the far end's text. `NOQUEUE` and `warning` stand in the
same place and are not ids; the pattern accepts Postfix's short form
(capital hexadecimal) and its long form (no vowels).
- **Port-25 mail is left out.** A queue id opened by `postfix/inbound/smtpd`
is a stranger's message and never gets a send-log row; none of its lines
are stored, up to qmgr's `removed` or until another listener opens a
message under the id (4096 such ids are remembered). What a stranger can
make Postfix log is therefore not written to the database at his rate.
- **No check for a row at write time.** A message's first lines (`client=`,
`message-id=`) are logged before the journal milter writes its row at
end-of-message, so the tailer cannot ask whether the id is in the send log.
Lines that never get a row — bounces Postfix generates, port-25 mail met in
mid-flight after a restart — are kept for a while.
- **Written per pass, not per line:** the lines of one pass over the log go
in one transaction (`InsertSendLogLines`), 500 at most, before the read
offset is saved. A commit per line would be a disk sync per line on the
connection the journal milter shares.
- **Retention is one rule:** a line older than an hour whose queue id no
send-log row carries is deleted (`PruneSendLogLines`), at start and after
every six-hourly send-log sweep. That removes the lines of rows the sweep
deleted and the lines that never had a row. The send log is asked once per
queue id; the statement still walks the table, about a second per million
lines, with the connection taken meanwhile.
- **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 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.
- **Read twice, stored once.** The read offset is saved every few seconds, so
after an unclean stop some lines are read again; while the tailer is
catching up at start it writes a line only if the same line is not there.
- **Not stored:** what the tailer never read — the tail of a file rotated away
while the panel was down.
- **Size:** six to ten lines of about 200 bytes per message — more than the row
itself. The table is in the database and therefore in a full backup, which
`log/` is not ([security.md](security.md) § Backup and domain export).
**Two one-shot reads** sit beside the follow loop and are unrelated to it, both **Two one-shot reads** sit beside the follow loop and are unrelated to it, both
serving panel pages on request: `TailLines` (the last *n* lines, for serving panel pages on request: `TailLines` (the last *n* lines, for
`/server/log`) and `QueueLines` (the lines carrying one queue-id, for `/server/log`) and `QueueLines` (the lines carrying one queue-id). `QueueLines`
`/outbound/log/{id}`). `QueueLines` scans a bounded tail of the current file — is what a message's page falls back to when no lines are stored for its row —
a message accepted before 2.2.0. It scans a bounded tail of the current file —
finding a message's lines means reading rather than seeking — and matches the id finding a message's lines means reading rather than seeking — and matches the id
anchored on the character before it, since queue ids are hexadecimal runs and a anchored on the character before it, since queue ids are hexadecimal runs and a
shorter one is regularly the tail of a longer one. Send-log rows outlive the log shorter one is regularly the tail of a longer one. For such a message an empty
(retention 90 days, rotation 14 files), so an empty result is the expected end result is the expected end state once the log has rotated, and the page reports
state for an older message and the page reports it as such, not as a failure. it as such, not as a failure.
--- ---
@@ -617,6 +670,7 @@ The tables that carry the panel's model:
(send-log retention). Nothing that belongs to a user. (send-log retention). Nothing that belongs to a user.
- `applications` (with `auth_ip_restrict` / `auth_allowed_ips`), - `applications` (with `auth_ip_restrict` / `auth_allowed_ips`),
`application_addresses`, `rate_limits` (no `allowed_ips` column), `send_log`, `application_addresses`, `rate_limits` (no `allowed_ips` column), `send_log`,
`send_log_lines` (what Postfix logged under a queue id — § Log tailer),
`logtail_state`, `inbound_domains`, `inbound_transports`, `logtail_state`, `inbound_domains`, `inbound_transports`,
`inbound_recipients`, `dmarc_reports`, `dmarc_report_records`. `inbound_recipients`, `dmarc_reports`, `dmarc_report_records`.
@@ -624,7 +678,8 @@ The panel is the only writer; SQLite runs in WAL mode on one connection (see
[Panel binary](#panel-binary-cmdpanel)), which is why a full backup snapshots [Panel binary](#panel-binary-cmdpanel)), which is why a full backup snapshots
with `VACUUM INTO` instead of copying the file. with `VACUUM INTO` instead of copying the file.
**Rotation:** send-log retention `SEND_LOG_RETENTION_DAYS` (default 90); **Rotation:** send-log retention `SEND_LOG_RETENTION_DAYS` (default 90), which
the stored log lines follow;
`mail.log` via logrotate (14 rotated files, check every 6h, rename + `mail.log` via logrotate (14 rotated files, check every 6h, rename +
`postfix reload` in `postrotate` — see § Log tailer above). `postfix reload` in `postrotate` — see § Log tailer above).
+1 -1
View File
@@ -124,7 +124,7 @@
<div class="sp-help-topic" id="dns"><h3>DNS records</h3><p>DKIM proves the message was signed by this relay, SPF lists the addresses allowed to send for the domain, DMARC tells receivers what to do when both fail and where to report. Publish all three exactly as shown; merge SPF into an existing record rather than adding a second one. A domain's status is the worst of its three records, and results are cached for a few minutes, so use Re-check DNS after publishing. The SPF check is shallow: it looks for this server's address in the record itself and does not follow <code>include:</code> or <code>redirect=</code>, so a record that relies on them is reported as a warning, not a failure. <code>p=none</code> does not affect delivery; tighten to <code>quarantine</code>, then <code>reject</code>, once the reports look clean. A domain's report address is set in its Domain settings.</p></div> <div class="sp-help-topic" id="dns"><h3>DNS records</h3><p>DKIM proves the message was signed by this relay, SPF lists the addresses allowed to send for the domain, DMARC tells receivers what to do when both fail and where to report. Publish all three exactly as shown; merge SPF into an existing record rather than adding a second one. A domain's status is the worst of its three records, and results are cached for a few minutes, so use Re-check DNS after publishing. The SPF check is shallow: it looks for this server's address in the record itself and does not follow <code>include:</code> or <code>redirect=</code>, so a record that relies on them is reported as a warning, not a failure. <code>p=none</code> does not affect delivery; tighten to <code>quarantine</code>, then <code>reject</code>, once the reports look clean. A domain's report address is set in its Domain settings.</p></div>
<div class="sp-help-topic" id="apps"><h3>Applications</h3><p>An application is one SASL login, unique across all domains. It may send as any address of its domain or only as listed addresses, and, with a list of client IPs set, only from those addresses. The password is shown once at creation or regeneration and is not stored in readable form.</p></div> <div class="sp-help-topic" id="apps"><h3>Applications</h3><p>An application is one SASL login, unique across all domains. It may send as any address of its domain or only as listed addresses, and, with a list of client IPs set, only from those addresses. The password is shown once at creation or regeneration and is not stored in readable form.</p></div>
<div class="sp-help-topic" id="limits"><h3>Rate limits</h3><p>Level 1 is a per-IP ceiling set in <code>.env</code>. Level 2 is optional, per domain and per application, entered by hand or computed from the last 30 days of sending, and can never exceed level 1. An application's own limit replaces its domain's.</p></div> <div class="sp-help-topic" id="limits"><h3>Rate limits</h3><p>Level 1 is a per-IP ceiling set in <code>.env</code>. Level 2 is optional, per domain and per application, entered by hand or computed from the last 30 days of sending, and can never exceed level 1. An application's own limit replaces its domain's.</p></div>
<div class="sp-help-topic" id="log"><h3>Outbound log</h3><p>One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out) and rejected (refused before queueing under a level-2 rate limit, so it never reached Postfix). A message's page lists these steps and the lines Postfix wrote about it in <code>mail.log</code>, found by queue id; that file is rotated daily and about two weeks are kept, so an old message may show none. Rows are deleted after the retention set in Server › Settings, 90 days by default. A domain administrator sees only the rows of their own domains.</p></div> <div class="sp-help-topic" id="log"><h3>Outbound log</h3><p>One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out) and rejected (refused before queueing under a level-2 rate limit, so it never reached Postfix). A message's page lists these steps and the lines Postfix wrote about it in <code>mail.log</code>, found by queue id. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains.</p></div>
<div class="sp-help-topic" id="queue"><h3>Queue and retries</h3><p>The page lists, as <code>postqueue -p</code> prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged.</p></div> <div class="sp-help-topic" id="queue"><h3>Queue and retries</h3><p>The page lists, as <code>postqueue -p</code> prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged.</p></div>
<div class="sp-help-topic" id="dmarc"><h3>DMARC reports</h3><p>An aggregate report is the summary a receiving provider sends, usually daily, to the <code>rua=</code> address of your DMARC record: which servers sent mail as your domain and whether SPF or DKIM passed for it. A domain's report address is one of three choices, set in its Domain settings: no reports (the default for a new domain), the SelfPost hosted address (an address on this server whose reports are parsed and shown under DMARC reports; offered only while hosted reports are enabled on the server), or an address typed for the domain (an ordinary mailbox that receives the raw XML; a button fills in your own profile e-mail). When the typed address is on another domain than the one sending, that domain must publish a report-authorization record, or providers will not send; the domain's page shows it with the other DNS records and checks it. In the tables pass means SPF or DKIM passed and aligned, fail means neither did, and your own server shows as <em>this relay</em>. A fail from any other source is someone else sending as your domain — a forwarder, an application you forgot, or abuse — so do not tighten <code>p=</code> until that sender is fixed or removed. A domain administrator reads the reports of their own domains.</p></div> <div class="sp-help-topic" id="dmarc"><h3>DMARC reports</h3><p>An aggregate report is the summary a receiving provider sends, usually daily, to the <code>rua=</code> address of your DMARC record: which servers sent mail as your domain and whether SPF or DKIM passed for it. A domain's report address is one of three choices, set in its Domain settings: no reports (the default for a new domain), the SelfPost hosted address (an address on this server whose reports are parsed and shown under DMARC reports; offered only while hosted reports are enabled on the server), or an address typed for the domain (an ordinary mailbox that receives the raw XML; a button fills in your own profile e-mail). When the typed address is on another domain than the one sending, that domain must publish a report-authorization record, or providers will not send; the domain's page shows it with the other DNS records and checks it. In the tables pass means SPF or DKIM passed and aligned, fail means neither did, and your own server shows as <em>this relay</em>. A fail from any other source is someone else sending as your domain — a forwarder, an application you forgot, or abuse — so do not tighten <code>p=</code> until that sender is fixed or removed. A domain administrator reads the reports of their own domains.</p></div>
</div> </div>
@@ -58,7 +58,7 @@
<div class="sp-help-topic" id="dns"><h3>DNS records</h3><p>DKIM proves the message was signed by this relay, SPF lists the addresses allowed to send for the domain, DMARC tells receivers what to do when both fail and where to report. Publish all three exactly as shown; merge SPF into an existing record rather than adding a second one. A domain's status is the worst of its three records, and results are cached for a few minutes, so use Re-check DNS after publishing. The SPF check is shallow: it looks for this server's address in the record itself and does not follow <code>include:</code> or <code>redirect=</code>, so a record that relies on them is reported as a warning, not a failure. <code>p=none</code> does not affect delivery; tighten to <code>quarantine</code>, then <code>reject</code>, once the reports look clean. A domain's report address is set in its Domain settings.</p></div> <div class="sp-help-topic" id="dns"><h3>DNS records</h3><p>DKIM proves the message was signed by this relay, SPF lists the addresses allowed to send for the domain, DMARC tells receivers what to do when both fail and where to report. Publish all three exactly as shown; merge SPF into an existing record rather than adding a second one. A domain's status is the worst of its three records, and results are cached for a few minutes, so use Re-check DNS after publishing. The SPF check is shallow: it looks for this server's address in the record itself and does not follow <code>include:</code> or <code>redirect=</code>, so a record that relies on them is reported as a warning, not a failure. <code>p=none</code> does not affect delivery; tighten to <code>quarantine</code>, then <code>reject</code>, once the reports look clean. A domain's report address is set in its Domain settings.</p></div>
<div class="sp-help-topic" id="apps"><h3>Applications</h3><p>An application is one SASL login, unique across all domains. It may send as any address of its domain or only as listed addresses, and, with a list of client IPs set, only from those addresses. The password is shown once at creation or regeneration and is not stored in readable form.</p></div> <div class="sp-help-topic" id="apps"><h3>Applications</h3><p>An application is one SASL login, unique across all domains. It may send as any address of its domain or only as listed addresses, and, with a list of client IPs set, only from those addresses. The password is shown once at creation or regeneration and is not stored in readable form.</p></div>
<div class="sp-help-topic" id="limits"><h3>Rate limits</h3><p>Level 1 is a per-IP ceiling set in <code>.env</code>. Level 2 is optional, per domain and per application, entered by hand or computed from the last 30 days of sending, and can never exceed level 1. An application's own limit replaces its domain's.</p></div> <div class="sp-help-topic" id="limits"><h3>Rate limits</h3><p>Level 1 is a per-IP ceiling set in <code>.env</code>. Level 2 is optional, per domain and per application, entered by hand or computed from the last 30 days of sending, and can never exceed level 1. An application's own limit replaces its domain's.</p></div>
<div class="sp-help-topic" id="log"><h3>Outbound log</h3><p>One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out) and rejected (refused before queueing under a level-2 rate limit, so it never reached Postfix). A message's page lists these steps and the lines Postfix wrote about it in <code>mail.log</code>, found by queue id; that file is rotated daily and about two weeks are kept, so an old message may show none. Rows are deleted after the retention set in Server › Settings, 90 days by default. A domain administrator sees only the rows of their own domains.</p></div> <div class="sp-help-topic" id="log"><h3>Outbound log</h3><p>One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out) and rejected (refused before queueing under a level-2 rate limit, so it never reached Postfix). A message's page lists these steps and the lines Postfix wrote about it in <code>mail.log</code>, found by queue id. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains.</p></div>
<div class="sp-help-topic" id="queue"><h3>Queue and retries</h3><p>The page lists, as <code>postqueue -p</code> prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged.</p></div> <div class="sp-help-topic" id="queue"><h3>Queue and retries</h3><p>The page lists, as <code>postqueue -p</code> prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged.</p></div>
<div class="sp-help-topic" id="dmarc"><h3>DMARC reports</h3><p>An aggregate report is the summary a receiving provider sends, usually daily, to the <code>rua=</code> address of your DMARC record: which servers sent mail as your domain and whether SPF or DKIM passed for it. A domain's report address is one of three choices, set in its Domain settings: no reports (the default for a new domain), the SelfPost hosted address (an address on this server whose reports are parsed and shown under DMARC reports; offered only while hosted reports are enabled on the server), or an address typed for the domain (an ordinary mailbox that receives the raw XML; a button fills in your own profile e-mail). When the typed address is on another domain than the one sending, that domain must publish a report-authorization record, or providers will not send; the domain's page shows it with the other DNS records and checks it. In the tables pass means SPF or DKIM passed and aligned, fail means neither did, and your own server shows as <em>this relay</em>. A fail from any other source is someone else sending as your domain — a forwarder, an application you forgot, or abuse — so do not tighten <code>p=</code> until that sender is fixed or removed. A domain administrator reads the reports of their own domains.</p></div> <div class="sp-help-topic" id="dmarc"><h3>DMARC reports</h3><p>An aggregate report is the summary a receiving provider sends, usually daily, to the <code>rua=</code> address of your DMARC record: which servers sent mail as your domain and whether SPF or DKIM passed for it. A domain's report address is one of three choices, set in its Domain settings: no reports (the default for a new domain), the SelfPost hosted address (an address on this server whose reports are parsed and shown under DMARC reports; offered only while hosted reports are enabled on the server), or an address typed for the domain (an ordinary mailbox that receives the raw XML; a button fills in your own profile e-mail). When the typed address is on another domain than the one sending, that domain must publish a report-authorization record, or providers will not send; the domain's page shows it with the other DNS records and checks it. In the tables pass means SPF or DKIM passed and aligned, fail means neither did, and your own server shows as <em>this relay</em>. A fail from any other source is someone else sending as your domain — a forwarder, an application you forgot, or abuse — so do not tighten <code>p=</code> until that sender is fixed or removed. A domain administrator reads the reports of their own domains.</p></div>
</div> </div>
+1
View File
@@ -126,6 +126,7 @@ than the default «meaningful step» rule in [§ Commits and release build](#com
| 13 | panel-redesign | `2.0.0` (MAJOR, no compatibility) | | 13 | panel-redesign | `2.0.0` (MAJOR, no compatibility) |
| 14 | DMARC ingest drops and bounds, full backup from the panel, no queue in a backup | `2.0.1` (PATCH) | | 14 | DMARC ingest drops and bounds, full backup from the panel, no queue in a backup | `2.0.1` (PATCH) |
| 15 | inbound-antispam-panel | `2.1.0` (was `1.10.0`, reordered 2026-10-09) | | 15 | inbound-antispam-panel | `2.1.0` (was `1.10.0`, reordered 2026-10-09) |
| 16 | delivery-log-storage | `2.2.0` |
Docs-only prep (checklists in plans, no product code) uses the same per-step Docs-only prep (checklists in plans, no product code) uses the same per-step
commit rule but **no** version cut until the next product stage ships. commit rule but **no** version cut until the next product stage ships.
+5 -3
View File
@@ -215,7 +215,7 @@ expected to set; defaults match the code exactly.
| `INBOUND_MESSAGE_SIZE_LIMIT` | Maximum message size in bytes on inbound smtpd (`message_size_limit`). When both inbound relay and DMARC ingest are on, the shared listener uses the **greater** of this and `DMARC_MESSAGE_SIZE_LIMIT`. | `26214400` (25 MiB) | `.env` | | `INBOUND_MESSAGE_SIZE_LIMIT` | Maximum message size in bytes on inbound smtpd (`message_size_limit`). When both inbound relay and DMARC ingest are on, the shared listener uses the **greater** of this and `DMARC_MESSAGE_SIZE_LIMIT`. | `26214400` (25 MiB) | `.env` |
| `RATE_LIMIT_MESSAGES_PER_IP` | Level-1 backstop: maximum messages one client IP may submit per window (Postfix `smtpd_client_message_rate_limit`). See [Rate limiting — level 1](#rate-limiting--level-1-ip-backstop). | `100` | `.env` | | `RATE_LIMIT_MESSAGES_PER_IP` | Level-1 backstop: maximum messages one client IP may submit per window (Postfix `smtpd_client_message_rate_limit`). See [Rate limiting — level 1](#rate-limiting--level-1-ip-backstop). | `100` | `.env` |
| `RATE_LIMIT_WINDOW_SECONDS` | Level-1 window length in seconds (Postfix `anvil_rate_time_unit`). | `3600` | `.env` | | `RATE_LIMIT_WINDOW_SECONDS` | Level-1 window length in seconds (Postfix `anvil_rate_time_unit`). | `3600` | `.env` |
| `SEND_LOG_RETENTION_DAYS` | Initial default for how many days of send-log history are kept before the background sweep deletes rows — the main driver of `/data` growth over time. After the first panel start, change retention under **Server › Settings** (global role); the env value is only used to seed SQLite when the setting has never been saved. | `90` | `.env` | | `SEND_LOG_RETENTION_DAYS` | Initial default for how many days of send-log history are kept before the background sweep deletes rows, and with them the `mail.log` lines kept for each message (1–2 KB a message) — the main driver of `/data` growth over time and of the size of a full backup. After the first panel start, change retention under **Server › Settings** (global role); the env value is only used to seed SQLite when the setting has never been saved. | `90` | `.env` |
| `PANEL_SESSION_IDLE_DAYS` | Sliding idle timeout for the panel login session, in days. There is no absolute cap: a user who keeps coming back stays signed in indefinitely. | `7` | `.env` | | `PANEL_SESSION_IDLE_DAYS` | Sliding idle timeout for the panel login session, in days. There is no absolute cap: a user who keeps coming back stays signed in indefinitely. | `7` | `.env` |
| `SELFPOST_DNS_RESOLVERS` | Comma-separated recursive resolvers the panel's PTR/SPF/DKIM/DMARC checks query directly (so they report what the internet sees, not what this host's stub resolver synthesises). | `1.1.1.1:53`, `8.8.8.8:53`, `9.9.9.9:53` when unset | `.env` | | `SELFPOST_DNS_RESOLVERS` | Comma-separated recursive resolvers the panel's PTR/SPF/DKIM/DMARC checks query directly (so they report what the internet sees, not what this host's stub resolver synthesises). | `1.1.1.1:53`, `8.8.8.8:53`, `9.9.9.9:53` when unset | `.env` |
| `TRUSTED_PROXY_CIDR` | Comma-separated CIDRs (bare IPs allowed) of reverse proxies allowed to supply `X-Forwarded-For` for login, setup, and account-change rate-limiting. **Leave unset unless you know the exact address of your reverse proxy.** A wrong value lets a client spoof its rate-limit key by sending a forged `X-Forwarded-For` header — the panel trusts the last hop only when the TCP peer matches one of these CIDRs. Behind the default Apache host-network setup this is typically the Docker bridge gateway, e.g. `172.18.0.1`. | *(empty — XFF ignored)* | `.env` | | `TRUSTED_PROXY_CIDR` | Comma-separated CIDRs (bare IPs allowed) of reverse proxies allowed to supply `X-Forwarded-For` for login, setup, and account-change rate-limiting. **Leave unset unless you know the exact address of your reverse proxy.** A wrong value lets a client spoof its rate-limit key by sending a forged `X-Forwarded-For` header — the panel trusts the last hop only when the TCP peer matches one of these CIDRs. Behind the default Apache host-network setup this is typically the Docker bridge gateway, e.g. `172.18.0.1`. | *(empty — XFF ignored)* | `.env` |
@@ -1144,8 +1144,10 @@ backoff cap, queue lifetime), the same numbers the Outbound queue shows; users
with the *domain* role see them here because they cannot open the queue. Under with the *domain* role see them here because they cannot open the queue. Under
both sit the `mail.log` lines for its queue id: the connection to the both sit the `mail.log` lines for its queue id: the connection to the
receiving server, the server's reply, and the status that reply was filed receiving server, the server's reply, and the status that reply was filed
as. Rows outlive `mail.log`, so an older message's lines may have rotated as. The lines are kept in the database with the row, so they stay on the
away; the page says so. Retention is set under **Server › Settings** (global page after `mail.log` has rotated and are deleted together with the row; a
message accepted before `2.2.0` shows them only while they are still in the
current file, and the page says so when there are none. Retention is set under **Server › Settings** (global
role); `SEND_LOG_RETENTION_DAYS` in `.env` is only the initial default until it role); `SEND_LOG_RETENTION_DAYS` in `.env` is only the initial default until it
is changed there. is changed there.
+184
View File
@@ -0,0 +1,184 @@
# Plan: delivery-log-storage
**Status:** agreed 2026-10-12 (owner: option 1 of the roadmap item, "store the lines")
**Date:** 2026-10-12
**Version:** `2.2.0` MINOR (one DDL migration; a 2.1.0 data directory boots unchanged).
---
## Goal
A message's page (`/outbound/log/{id}`, mockup `out-message`) shows what
Postfix wrote about the message for as long as its row is in the send log.
Today the *Delivery log* box is filled by a search of the current `mail.log`
on every page view, so it is empty for anything sent before the last daily
rotation, while the row itself lives for ninety days.
## Context (as-built)
- The log tailer ([internal/logtail](../../internal/logtail/logtail.go))
already reads every `mail.log` line once, from a persisted offset, to
advance delivery statuses.
- `logtail.QueueLines` searches the last 4 MB of the current file for one
queue id; `Handlers.deliveryLog` calls it per page view.
- A message with several recipients is several send-log rows under one queue
id; the page of each shows every line of the message, as the search does
today.
## Decisions
### What is stored
A `mail.log` line whose head is a queue id - after the timestamp, the host
name and `program[pid]:` - goes into a new table with that id, the line's own
time (`lineTime`, the same reading the inbound journal uses) and the line as
written, cut to 4096 bytes on a character boundary. The head is matched from
the start of the line: the tail is the far end's words. `NOQUEUE` and
`warning` are not queue ids - the pattern takes Postfix's short form
(hexadecimal) and its long form (no vowels) and nothing else.
The tailer does not ask whether the id belongs to a send-log row before it
writes. The first lines of a message (`client=`, `message-id=`) are logged
before the journal milter writes the row at end-of-message, so such a check
would drop exactly them.
**Mail that came in on port 25 is left out** (security review, 2026-10-12). A
queue id that `postfix/inbound/smtpd` opened is a stranger's message; it never
gets a send-log row, and what a stranger can make Postfix log - his own
`message-id`, up to the cut - is not stored to be pruned later. The tailer
remembers such ids (4096 at most) until qmgr's `removed` or until another
listener opens a message under the id. What is still stored without a row is
little: the bounces Postfix generates, and port-25 mail met in mid-flight
after a restart.
Lines are written in one transaction per pass over the log, 500 at most
(technical review): a commit per line is a disk sync per line on the one
connection the journal milter writes through.
### Which lines are a row's
A line is shown on a row's page when the queue id is the same **and** the
line's time lies between one hour before the row was written and the queue
lifetime (the larger of `maximal_queue_lifetime` and `bounce_queue_lifetime`,
as `postconf` reports them) plus a day after it. Postfix reuses a short queue
id once the message has left the queue - the id is the microsecond of arrival
and the inode of the queue file - so a row that lives ninety days can meet a
later message under its id. The window does not rule that out, it limits it
to the days the row's own message could still be in the queue; this is the
bound the roadmap item asked for. The search of the current file that the
page did before had the same exposure for a day. `enable_long_queue_ids`
would end it and is a change to the mail path, not part of this item.
### Retention
Lines live as long as a send-log row with their queue id does. One rule covers
both ends: a line older than an hour whose queue id has no send-log row is
deleted. That removes the lines of a row the retention sweep has just deleted,
and the lines of messages that never had a row. It runs at start and after
every send-log sweep, six-hourly. It asks the send log once per queue id; at a
million lines that is still a scan of the table, of the order of a second,
during which the one connection is taken.
There is no cap of its own: with port-25 mail left out, the table is bounded
by what authenticated applications send, which level 1 and level 2 limit.
### After an unclean stop
The tailer saves its place every few seconds, so after a crash it reads some
lines twice. While it is catching up at start a line is written only if the
same line is not there already - the rule the inbound journal follows.
### What is not kept
- Lines the tailer never reads are not stored: the tail of a file that was
rotated away while the panel was down, as with delivery statuses
(architecture.md § Log tailer).
- A message in the queue across the upgrade to 2.2.0 has only its later lines
stored, and the page then shows those alone: the search of the file runs
only for a row with nothing stored. The only installation is the owner's
test server; no merge of the two sources is built for one moment of it.
### The page
The page reads the table: the latest 200 lines of the row, oldest first. When
the table has none, it still searches the current `mail.log` as before - that
is what shows a message accepted before 2.2.0 while its lines are in today's
file. Lines in rotated files are not imported: the only installation is the
owner's test server.
Nothing in the page's layout changes; the `out-message` mockup already draws
the box as a `log_pane`. Two texts change, mockup first: the *Outbound log*
help topic (it says an old message may show no lines) and the note shown when
there are none.
### Size
Six to ten lines of about 200 bytes per message: 1-2 KB next to a row of a few
hundred bytes. The table becomes the larger part of what the send log costs in
`/data` and in a backup; the retention setting bounds both together.
## Schema (migration `0003_send_log_lines.sql`)
```sql
CREATE TABLE send_log_lines (
id INTEGER PRIMARY KEY AUTOINCREMENT,
queue_id TEXT NOT NULL,
logged_at TEXT NOT NULL,
line TEXT NOT NULL
);
CREATE INDEX idx_send_log_lines_queue_id ON send_log_lines (queue_id, logged_at);
```
No foreign key: a line is written before its row exists, and one queue id is
several rows.
## Scope
In: the table, the tailer writing and pruning it, the page reading it, the two
texts, docs.
Out: the inbound journal (it decides for itself, roadmap § delivery-log-storage);
importing rotated files; `enable_long_queue_ids`; any change to `mail.log`
rotation or to the Server › Mail log page.
## Security
- The lines carry the far end's text (replies, HELO names). They are shown
today from the file through the same escaping; storing them changes where
they are read from, not what is shown or to whom. A domain administrator
sees the lines of messages of their own domains, as now.
- They now enter the database and so a full backup, which `log/` does not:
submitting clients' addresses and SASL logins, message ids, receivers'
replies. [security.md](../security.md) says so.
- A line is matched from its head, so a reply cannot make itself a line of
another message; Postfix does not log raw line breaks, and `postlogd` is the
file's only writer.
- A stranger on port 25 does not write to the table (above).
## Done when
A message sent before the last rotation shows its lines on its page; the lines
disappear with the row; the page's wording no longer blames rotation for an
ordinary case.
## Model routing (this plan)
| Role | Model |
|------|-------|
| All implementation (code, tests, docs) | **Opus** |
| Technical review (reviewer ≠ author: a separate read-only agent) | **Opus** |
| Security review | **Fable** |
## Implementation checklist
Target version cut: **`2.2.0`** (MINOR). One commit per step;
[development.md](../development.md) § Plan checklists.
- [x] Migration `0003_send_log_lines.sql`, store methods (insert, insert once, lines of a row, prune) and their tests — **Opus**
- [x] Log tailer: store queue-id lines, write once while catching up, prune with the send-log sweep — **Opus** (hourly as first built; six-hourly after the reviews)
- [x] The two texts, mockup first: the *Outbound log* help topic and the empty note (`design:` commit) — **Opus** (the help topic is in the mockups; the empty note is not drawn there - the `out-message` mockup shows a message with lines - and changes with the page)
- [x] Message page reads the table, falls back to the current `mail.log`; help text in `help.go` — **Opus**
- [x] [architecture.md](../architecture.md), [guide.md](../guide.md), [schema-migrations.md](../schema-migrations.md) — **Opus** (schema-migrations.md went in with the migration)
- [x] `go vet`, `go test`, e2e: a message's page still lists its lines after a forced rotation — **Opus** (on the test server: vet ok, 22 packages ok, e2e ok with the new step `delivery_log_survives_rotation`)
- [x] Technical review — **Opus** (2026-10-12; no Critical or High. Fixed: one transaction per pass instead of a commit per line, the prune asks the send log once per queue id and runs six-hourly, the cut keeps characters whole, tests for what the comments claimed. Left as found and written down under *What is not kept*: lines the tailer never read, and a message in the queue across the upgrade)
- [x] Security review — **Fable** (2026-10-12; no Critical or High. Fixed: port-25 mail is not stored, so a stranger cannot grow the table; [security.md](../security.md) states what a backup now carries. The window against queue-id reuse is described as the limit it is)
+2 -2
View File
@@ -34,8 +34,8 @@ Lists let the operator correct false positives/negatives (e.g. always allow
## Quarantine ## Quarantine
**Not in this plan.** Held-mail review/release is tracked separately as roadmap **Not in this plan.** Held-mail review/release is an idea kept outside the roadmap,
candidate [inbound-quarantine](inbound-quarantine.md). The journal may still [inbound-quarantine](inbound-quarantine.md). The journal may still
record a `quarantine` **decision label** when the external filter reports it, record a `quarantine` **decision label** when the external filter reports it,
without SelfPost storing the message. without SelfPost storing the message.
+1 -1
View File
@@ -1,6 +1,6 @@
# Plan: inbound-quarantine # Plan: inbound-quarantine
**Status:** candidate — design TBD; needs explicit agreement before any code **Status:** an idea to think about, not on the roadmap (owner, 2026-10-12) — design TBD; needs explicit agreement before any code
**Version:** TBD (`1.x` MINOR if opt-in and backward-compatible; may warrant `2.x` **Version:** TBD (`1.x` MINOR if opt-in and backward-compatible; may warrant `2.x`
if it changes inbound storage or backup contract). if it changes inbound storage or backup contract).
+3 -3
View File
@@ -235,7 +235,7 @@ the first step of that feature's plan — not invented during implementation.
| Roadmap item | Where it lands | Built from | Drawn | | Roadmap item | Where it lands | Built from | Drawn |
|---|---|---|---| |---|---|---|---|
| inbound-antispam-panel (agreed, `2.1.0`) | journal = **Inbound › Log** (add client IP and engine to the mockup's columns; `quarantine` joins the decisions); lists = new **Inbound › Filter lists**, global-only because the lists are instance-wide | list layout: add form + two tables, `status_tag`, filter form in `box_head`; the log links *Allow / Deny sender* to the lists | `in-log`, `in-filter-lists` | | inbound-antispam-panel (agreed, `2.1.0`) | journal = **Inbound › Log** (add client IP and engine to the mockup's columns; `quarantine` joins the decisions); lists = new **Inbound › Filter lists**, global-only because the lists are instance-wide | list layout: add form + two tables, `status_tag`, filter form in `box_head`; the log links *Allow / Deny sender* to the lists | `in-log`, `in-filter-lists` |
| inbound-quarantine (candidate) | new **Inbound › Quarantine**, list + detail with *Release* / *Discard* | list layout; detail like `out-message` with `facts`, `log_pane` for headers only, Release beside a `sp-danger-zone` Discard | `in-quarantine`, `in-quarantine-message` — the open questions of its plan (where mail lives, what release means, retention, RBAC) stay open; the mockup assumes SelfPost-held mail, release to upstream, 14 days, delegated like the rest of Inbound | | inbound-quarantine (an idea, off the roadmap since 2026-10-12) | new **Inbound › Quarantine**, list + detail with *Release* / *Discard* | list layout; detail like `out-message` with `facts`, `log_pane` for headers only, Release beside a `sp-danger-zone` Discard | `in-quarantine`, `in-quarantine-message` — the open questions of its plan (where mail lives, what release means, retention, RBAC) stay open; the mockup assumes SelfPost-held mail, release to upstream, 14 days, delegated like the rest of Inbound |
| preflight (candidate) | new **Server › Preflight**, next to Health: Health is what runs now, Preflight is the deeper on-demand installation check with a test e-mail form | `postmark` verdict, a table of checks with `status_tag` and a *What to do* column, one form box for the test e-mail | `preflight` | | preflight (candidate) | new **Server › Preflight**, next to Health: Health is what runs now, Preflight is the deeper on-demand installation check with a test e-mail form | `postmark` verdict, a table of checks with `status_tag` and a *What to do* column, one form box for the test e-mail | `preflight` |
| panel-notifications (candidate) | per-user event choice on **Account**; one switch under **Server › Settings** | checkboxes in a box, `help` | **no** — drawn once, taken out of `account` and `settings` on 2026-10-10 (owner): 2.0 ships no box for a feature that is not built; redrawn as the first step of its plan | | panel-notifications (candidate) | per-user event choice on **Account**; one switch under **Server › Settings** | checkboxes in a box, `help` | **no** — drawn once, taken out of `account` and `settings` on 2026-10-10 (owner): 2.0 ships no box for a feature that is not built; redrawn as the first step of its plan |
| password-reset (candidate) | a link on sign-in, two signed-out screens (request, set new password) | the signed-out layout | **no** | | password-reset (candidate) | a link on sign-in, two signed-out screens (request, set new password) | the signed-out layout | **no** |
@@ -539,5 +539,5 @@ only when both are done. Every stage-2 step ends with the evidence of
order suits development, preflight, delivery-log-storage, panel-notifications, order suits development, preflight, delivery-log-storage, panel-notifications,
password-reset (two screens to draw first), queue as a table with the inbound password-reset (two screens to draw first), queue as a table with the inbound
queue, csrf-tokens queue, csrf-tokens
(one hidden field in the form partial once security.md is settled), (one hidden field in the form partial once security.md is settled).
inbound-quarantine after its open questions. inbound-quarantine is an idea outside the roadmap.
+24 -30
View File
@@ -31,13 +31,12 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md).
| preflight | Installation check page (`/preflight`) | candidate | — | [plans/preflight.md](plans/preflight.md) | | preflight | Installation check page (`/preflight`) | candidate | — | [plans/preflight.md](plans/preflight.md) |
| contributing | `CONTRIBUTING.md` | candidate | — | — | | contributing | `CONTRIBUTING.md` | candidate | — | — |
| inbound-antispam-panel | Inbound antispam journal + allow/deny lists | shipped `2.1.0` | 12/12 | [plans/inbound-antispam-panel.md](plans/inbound-antispam-panel.md) | | inbound-antispam-panel | Inbound antispam journal + allow/deny lists | shipped `2.1.0` | 12/12 | [plans/inbound-antispam-panel.md](plans/inbound-antispam-panel.md) |
| inbound-quarantine | Inbound spam quarantine (hold / review / release) | candidate | — | [plans/inbound-quarantine.md](plans/inbound-quarantine.md) |
| csrf-tokens | Per-session CSRF tokens on state-changing forms | candidate | — | — | | csrf-tokens | Per-session CSRF tokens on state-changing forms | candidate | — | — |
| template-data-typing | Typed structs for template data instead of `map[string]any` | candidate | — | — | | template-data-typing | Typed structs for template data instead of `map[string]any` | candidate | — | — |
| structured-logging | `log/slog` with levels and fields | candidate | — | — | | structured-logging | `log/slog` with levels and fields | candidate | — | — |
| review-2026-08-followups | Remaining findings of the 2026-08-19 code review | candidate | — | — | | review-2026-08-followups | Remaining findings of the 2026-08-19 code review | candidate | — | — |
| panel-notifications | E-mail notifications about important events | candidate | — | — | | panel-notifications | E-mail notifications about important events | candidate | — | — |
| delivery-log-storage | Keep a message's `mail.log` lines with its send-log row | candidate | — | — | | delivery-log-storage | Keep a message's `mail.log` lines with its send-log row | in progress | 8/8 | [plans/delivery-log-storage.md](plans/delivery-log-storage.md) |
| password-reset | Password reset by e-mail | candidate | — | — | | password-reset | Password reset by e-mail | candidate | — | — |
| phone-desktop-mode | A phone browser in "desktop site" mode gets the phone navigation | candidate | — | — | | phone-desktop-mode | A phone browser in "desktop site" mode gets the phone navigation | candidate | — | — |
| panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) | | panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) |
@@ -46,8 +45,9 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md).
**Recommended order** (not binding; owner, 2026-10-09: feature order follows **Recommended order** (not binding; owner, 2026-10-09: feature order follows
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and
**inbound-antispam-panel** as `2.1.0` (2026-10-12), built in the new component **inbound-antispam-panel** as `2.1.0` (2026-10-12), built in the new component
kit — styling its two screens once instead of twice. Nothing is agreed after kit — styling its two screens once instead of twice. After it the owner
it: every remaining item is a candidate. panel-docs shipped in agreed **delivery-log-storage** (2026-10-12, `2.2.0`); every other remaining
item is a candidate. panel-docs shipped in
[CHANGELOG.md](../CHANGELOG.md) `[1.8.0]`; dmarc-reports in `[1.7.0]` [CHANGELOG.md](../CHANGELOG.md) `[1.8.0]`; dmarc-reports in `[1.7.0]`
(its ingest path first ran in `2.0.0` and was reviewed on 2026-10-11, see (its ingest path first ran in `2.0.0` and was reviewed on 2026-10-11, see
[security.md](security.md)); domain-stats-auto-ratelimit in [security.md](security.md)); domain-stats-auto-ratelimit in
@@ -124,8 +124,8 @@ action) plus editable allow/deny lists that tune the external filter — without
shipping rspamd or another engine inside the image. shipping rspamd or another engine inside the image.
**Boundary:** metadata journal and list sync only; SelfPost does not run the **Boundary:** metadata journal and list sync only; SelfPost does not run the
filter ([product.md](product.md)). Quarantine: filter ([product.md](product.md)). Quarantine is not on the roadmap
[inbound-quarantine](#inbound-quarantine). Design closed in ([Ideas](#ideas-not-on-the-roadmap)). Design closed in
[plans/inbound-antispam-panel.md](plans/inbound-antispam-panel.md) § Decisions. [plans/inbound-antispam-panel.md](plans/inbound-antispam-panel.md) § Decisions.
**Done when:** with inbound relay enabled, the operator sees journal rows **Done when:** with inbound relay enabled, the operator sees journal rows
@@ -140,27 +140,6 @@ journal PII; global-admin-only RBAC.
--- ---
## inbound-quarantine
**Goal:** optional hold for suspicious inbound mail — review in the panel, then
release to upstream, discard, or tune lists. Design not settled.
**Boundary:** expands inbound from pure relay toward short-lived message
storage; may conflict with "no mailboxes" in [product.md](product.md) until
product explicitly agrees. Alternatives (rspamd-only quarantine vs SelfPost
store) are listed in [plans/inbound-quarantine.md](plans/inbound-quarantine.md).
**Done when:** TBD after open questions in the plan are answered.
**Dependencies / risks:** inbound relay `[1.4.0]`; storage/retention/backup
size; malware in held MIME; overlap with
[inbound-antispam-panel](#inbound-antispam-panel). No implementation checklist
yet.
**Version:** TBD; `candidate` until explicitly agreed.
---
## preflight ## preflight
**Goal:** a `/preflight` page (global-admin only) that verifies instance-level **Goal:** a `/preflight` page (global-admin only) that verifies instance-level
@@ -351,8 +330,8 @@ time to final status plus the queue lifetime), not to the id alone; the table
grows with the send log (small — a few hundred bytes per message) and is grows with the send log (small — a few hundred bytes per message) and is
covered by the same retention. covered by the same retention.
**Version:** `2.x` MINOR; `candidate`. Fits after the redesign, built against **Version:** `2.2.0` MINOR; agreed 2026-10-12, option 1. Decisions and
the kit's `log_pane`. checklist: [plans/delivery-log-storage.md](plans/delivery-log-storage.md).
--- ---
@@ -361,7 +340,7 @@ the kit's `log_pane`.
**Goal:** the panel tells its administrators when something needs them instead **Goal:** the panel tells its administrators when something needs them instead
of waiting to be opened: a DNS record stops matching, a domain or application of waiting to be opened: a DNS record stops matching, a domain or application
hits its rate limit and mail is refused, an inbound upstream is unreachable, hits its rate limit and mail is refused, an inbound upstream is unreachable,
DMARC failures appear, mail is held in quarantine; for the global DMARC failures appear; for the global
administrator also the TLS certificate nearing expiry, a process or milter administrator also the TLS certificate nearing expiry, a process or milter
socket down, a queue older than a day. socket down, a queue older than a day.
@@ -520,3 +499,18 @@ explicit major). Squashing the current short chain is not a reason to cut 2.x on
its own. A missed gate leaves a mid-chain 1.x database silently stuck. its own. A missed gate leaves a mid-chain 1.x database silently stuck.
**Version:** `2.x` major only; not a 1.x item. **Version:** `2.x` major only; not a 1.x item.
---
## Ideas, not on the roadmap
Thoughts kept so they are not lost. They are not candidates: nothing here is
waiting for an OK, has a version or takes a place in the order above. An idea
joins the index only when the owner says so.
- **Inbound quarantine** (moved here by the owner on 2026-10-12: "an idea to
think about") - hold suspicious inbound mail, review it in the panel, then
release it to the upstream or discard it. It would take the relay from
passing mail on to storing it for a while, against "no mailboxes" in
[product.md](product.md). Notes and open questions:
[plans/inbound-quarantine.md](plans/inbound-quarantine.md); the screens
`in-quarantine` and `in-quarantine-message` are drawn and stay unbuilt.
+6 -3
View File
@@ -17,8 +17,8 @@ When you add or review a migration, update this file in the same change.
| Field | Value | | Field | Value |
|---|---| |---|---|
| Chain head | `user_version = 2` | | Chain head | `user_version = 3` |
| Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql` | | Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql`, `0003_send_log_lines.sql` |
| File mark | `PRAGMA application_id = 0x53503230` ("SP20") | | File mark | `PRAGMA application_id = 0x53503230` ("SP20") |
| Database file | `/data/selfpost.db` (bind mount) | | Database file | `/data/selfpost.db` (bind mount) |
| Compatibility | 2.x MINOR releases must boot a `2.0.0` data directory. **Nothing is carried over from 1.x.** | | Compatibility | 2.x MINOR releases must boot a `2.0.0` data directory. **Nothing is carried over from 1.x.** |
@@ -62,7 +62,8 @@ What that means in practice:
again and no file is deleted, renamed or reordered — every 2.x database has again and no file is deleted, renamed or reordered — every 2.x database has
already run it. `2.0.0` and `2.0.1` shipped with the baseline alone; the already run it. `2.0.0` and `2.0.1` shipped with the baseline alone; the
features after them add files, the first being `0002_inbound_spam_log.sql` of features after them add files, the first being `0002_inbound_spam_log.sql` of
inbound-antispam-panel (`2.1.0`). inbound-antispam-panel (`2.1.0`), then `0003_send_log_lines.sql` of
delivery-log-storage (`2.2.0`).
--- ---
@@ -72,6 +73,7 @@ inbound-antispam-panel (`2.1.0`).
|-----|------|---------|------|---------| |-----|------|---------|------|---------|
| 1 | `0001_init.sql` | 2.0.0 | DDL | The whole 2.0 schema, below | | 1 | `0001_init.sql` | 2.0.0 | DDL | The whole 2.0 schema, below |
| 2 | `0002_inbound_spam_log.sql` | 2.1.0 | DDL | `inbound_spam_log`, `inbound_spam_list` and two indexes; nothing existing changes | | 2 | `0002_inbound_spam_log.sql` | 2.1.0 | DDL | `inbound_spam_log`, `inbound_spam_list` and two indexes; nothing existing changes |
| 3 | `0003_send_log_lines.sql` | 2.2.0 | DDL | `send_log_lines` and one index; nothing existing changes |
**Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct **Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct
for operators upgrading from older 2.x images. for operators upgrading from older 2.x images.
@@ -100,6 +102,7 @@ for operators upgrading from older 2.x images.
| `dmarc_report_records` | Per-source rows inside a report | | `dmarc_report_records` | Per-source rows inside a report |
| `inbound_spam_log` | Inbound antispam journal: one row per recipient of a message offered on port 25, with the decision (`accept`, `reject`, `tempfail`, `quarantine`) and who made it (`rspamd`, `postfix`, `selfpost`). Metadata only (v2) | | `inbound_spam_log` | Inbound antispam journal: one row per recipient of a message offered on port 25, with the decision (`accept`, `reject`, `tempfail`, `quarantine`) and who made it (`rspamd`, `postfix`, `selfpost`). Metadata only (v2) |
| `inbound_spam_list` | Allow / deny entries for the external filter (`address`, `domain`, `ip`), instance-wide; unique per list (v2) | | `inbound_spam_list` | Allow / deny entries for the external filter (`address`, `domain`, `ip`), instance-wide; unique per list (v2) |
| `send_log_lines` | The `mail.log` lines Postfix wrote under a queue id, with the line's own time; what a message's page shows once the log has rotated. No reference to `send_log`: a line belongs to a row by queue id and time, and goes when no row carries its id (v3) |
`TestBaselineSchema` (`internal/store/schema_test.go`) pins every table, column `TestBaselineSchema` (`internal/store/schema_test.go`) pins every table, column
and index of this list; `TestOpenMigratesA20Database` opens a database that and index of this list; `TestOpenMigratesA20Database` opens a database that
+20 -1
View File
@@ -244,6 +244,11 @@ operator can act on it.
private key from `certs/` when present; a domain export carries the DKIM key private key from `certs/` when present; a domain export carries the DKIM key
and **working** application passwords in the clear (otherwise a transfer and **working** application passwords in the clear (otherwise a transfer
without recreating credentials would be impossible). without recreating credentials would be impossible).
- Since 2.2.0 a full backup also carries, in the database, what Postfix logged
about each message still in the send log (`send_log_lines`): the submitting
client's address and SASL login, the message id, the receiving server and
its reply. `mail.log` itself stays out of a backup; these lines are state
the panel shows, kept for the send log's retention and no longer.
- Both downloads are encrypted with a password unless the box on the form is - Both downloads are encrypted with a password unless the box on the form is
unticked (it is ticked by default): unticked (it is ticked by default):
scrypt (N=2¹⁵, r=8, p=1) → AES-256-GCM, streamed in 64 KiB chunks, each scrypt (N=2¹⁵, r=8, p=1) → AES-256-GCM, streamed in 64 KiB chunks, each
@@ -404,7 +409,21 @@ deferred item from the roadmap.
the file is inaccessible to others. The log holds envelope addresses and the file is inaccessible to others. The log holds envelope addresses and
client IPs, but neither message bodies nor headers; it is excluded from client IPs, but neither message bodies nor headers; it is excluded from
backups (`log/` is skipped) so that a dump stays state rather than backups (`log/` is skipped) so that a dump stays state rather than
diagnostics. diagnostics. Since 2.2.0 the tailer copies the lines of queued outbound
messages into the database for the message's page, and those are in a
backup (§ Backup and domain export); mail offered on port 25 is not copied.
- **A message's page can show another message's log lines after a queue-id
collision.** Postfix's short queue ids repeat: the id is the microsecond of
arrival and the queue file's inode, and inodes come round within seconds.
The page takes the stored lines of the row's queue id dated within the
row's own queue lifetime (about six days), so a second message has to get
the same microsecond on the same inode in that span - about one in a
million per reuse of the inode, and not something a sender can aim. When it
happens, a `domain` user could read the log lines of a message that is not
theirs. The search of the current `mail.log` that the page did before
2.2.0 had the same exposure over a day. Trigger to revisit: a report of
foreign lines on a page, or a reason to turn on `enable_long_queue_ids`,
which ends it.
- **A `domain` user may point an inbound domain's upstream at any host and - **A `domain` user may point an inbound domain's upstream at any host and
port.** The upstream form checks that the host is a well-formed name or IP port.** The upstream form checks that the host is a well-formed name or IP
and the port is 1–65535; loopback, private and link-local addresses are and the port is 1–65535; loopback, private and link-local addresses are
+160
View File
@@ -0,0 +1,160 @@
package logtail
import (
"log"
"regexp"
"time"
"github.com/mixeme/selfpost/internal/store"
)
// A message's page shows what Postfix wrote about it. mail.log is rotated
// daily and fourteen files are kept, while a send-log row lives for the
// retention window, so the lines are kept in the database as the tailer reads
// them (architecture.md § Log tailer).
//
// queueLineRe finds the queue id at the head of a line, after the timestamp
// (already taken off by lineTime), the host name and "program[pid]:":
//
// mail postfix/smtp[26]: 41E862C00D9E: to=<a@example.net>, relay=…, status=sent (250 OK)
//
// It is matched from the start of the line and nowhere else: the tail of a
// line is the far end's words - a reply, a HELO name - and a pattern that
// could start anywhere would let them file a line under a queue id of their
// choosing.
//
// What stands in that place is not always a queue id: "NOQUEUE:" and
// "warning:" stand there too. A queue id is hexadecimal in capitals, or, with
// enable_long_queue_ids, digits and letters without vowels; neither word is
// either.
var queueLineRe = regexp.MustCompile(`^\S+ ([^\s\[]+)\[\d+\]: ([0-9A-F]{6,24}|[0-9B-DF-HJ-NP-TV-Zb-df-hj-np-tv-z]{10,24}): (.*)`)
// smtpdProgramRe tells an smtpd from the other programs, whatever listener it
// serves: "postfix/smtpd", "postfix/submission/smtpd", "postfix/inbound/smtpd".
var smtpdProgramRe = regexp.MustCompile(`^postfix/(?:[a-z0-9-]+/)?smtpd$`)
// port25Program is the smtpd of the inbound relay's listener, which
// build/postfix-config.sh names so that its lines are told from those of the
// submission ports.
const port25Program = "postfix/inbound/smtpd"
const (
// lineGrace is how old a line must be before the prune asks whether a
// send-log row carries its queue id. The first lines of a message are
// logged when it arrives and its row is written at end-of-message; an hour
// is a message body sent slowly.
lineGrace = time.Hour
// lineBatch is how many lines are held before they are written without
// waiting for the end of the pass over the log. A pass is a second's worth
// of lines while following, and the whole backlog when the tailer starts.
lineBatch = 500
// port25IDs is how many queue ids opened on port 25 are remembered so that
// their lines are not kept. Beyond it the oldest knowledge is given up, and
// those messages' lines are kept until the prune finds them without a row.
port25IDs = 4096
)
// lineKeeper collects the lines headed by a queue id and writes them in
// batches. It is used from the follow loop only, so it needs no locking.
type lineKeeper struct {
st StatusStore
// buf holds the lines not yet written; once says they were read while
// catching up and may have been read before the last stop.
buf []store.SendLogLine
once bool
// port25 holds the queue ids the port-25 smtpd opened: mail offered by
// strangers, which never gets a send-log row. Its lines are not kept - what
// a stranger can make Postfix log is not something to store on his say-so
// and prune later. An id leaves when qmgr removes the message or when
// another listener opens a message under it (Postfix reuses ids).
port25 map[string]struct{}
}
func newLineKeeper(st StatusStore) *lineKeeper {
return &lineKeeper{st: st, port25: make(map[string]struct{})}
}
// add takes one mail.log line and keeps it if it is headed by the queue id of
// a message that did not come in on port 25. It does not ask whether a
// send-log row exists for the id: for a message's first lines none does yet,
// and the lines of messages that never get one - the bounces Postfix
// generates, port-25 mail met in mid-flight after a restart - are removed by
// pruneLines.
//
// catchingUp is as in inboundJournal.handle: the line may have been read
// before the last stop, and is then written only if it is not there already.
// The line is dated by its own stamp - after the panel was down, that and now
// are hours apart, and a line is matched to its row by time.
func (k *lineKeeper) add(line string, now time.Time, catchingUp bool) {
at, rest := lineTime(line, now)
m := queueLineRe.FindStringSubmatch(rest)
if m == nil {
return
}
program, queueID, text := m[1], m[2], m[3]
if smtpdProgramRe.MatchString(program) && len(text) >= 7 && text[:7] == "client=" {
if program == port25Program {
k.rememberPort25(queueID)
} else {
delete(k.port25, queueID)
}
}
if _, inbound := k.port25[queueID]; inbound {
if program == "postfix/qmgr" && text == "removed" {
delete(k.port25, queueID)
}
return
}
if catchingUp != k.once {
k.flush()
k.once = catchingUp
}
k.buf = append(k.buf, store.SendLogLine{QueueID: queueID, At: at, Line: line})
if len(k.buf) >= lineBatch {
k.flush()
}
}
func (k *lineKeeper) rememberPort25(queueID string) {
if len(k.port25) >= port25IDs {
// Which one goes does not matter: the cost of forgetting an id is its
// remaining lines kept until the prune.
for id := range k.port25 {
delete(k.port25, id)
break
}
}
k.port25[queueID] = struct{}{}
}
// flush writes the lines held. The follow loop calls it after every pass over
// the log and before it saves its place, so the place saved is never ahead of
// what was written. Lines that cannot be written are dropped and said so: the
// tailer goes on, and a page without them falls back to the log file.
func (k *lineKeeper) flush() {
if len(k.buf) == 0 {
return
}
if _, err := k.st.InsertSendLogLines(k.buf, k.once); err != nil {
log.Printf("log-tailer: keep %d log lines: %v", len(k.buf), err)
}
k.buf = k.buf[:0]
}
// pruneLines removes the stored lines no send-log row carries the queue id of:
// those of rows the retention sweep deleted, and those of messages that never
// had a row.
func pruneLines(st StatusStore) {
n, err := st.PruneSendLogLines(time.Now().UTC().Add(-lineGrace))
if err != nil {
log.Printf("log-tailer: prune stored log lines: %v", err)
return
}
if n > 0 {
log.Printf("log-tailer: pruned %d stored log lines with no send-log row", n)
}
}
+230
View File
@@ -0,0 +1,230 @@
package logtail
import (
"context"
"os"
"path/filepath"
"strings"
"testing"
"time"
)
// Which lines are kept for a message's page, and under which queue id: the id
// at the head of the line and nothing the far end wrote further along it.
func TestQueueLineHead(t *testing.T) {
cases := []struct {
name, rest, want string
}{
{"delivery", "mail postfix/smtp[26]: 41E862C00D9E: to=<a@example.net>, relay=mx.example.net[203.0.113.9]:25, dsn=2.0.0, status=sent (250 OK)", "41E862C00D9E"},
{"submission smtpd opens the id", "mail postfix/submission/smtpd[10]: 41E862C00D9E: client=unknown[203.0.113.7], sasl_method=PLAIN, sasl_username=app", "41E862C00D9E"},
{"port-25 smtpd", "mail postfix/inbound/smtpd[41]: 4A1B2C3D: client=mx.example.net[203.0.113.9]", "4A1B2C3D"},
{"cleanup", "mail postfix/cleanup[52]: 41E862C00D9E: message-id=<1@example.com>", "41E862C00D9E"},
{"qmgr removes it", "mail postfix/qmgr[10]: 41E862C00D9E: removed", "41E862C00D9E"},
{"a bounce is sent: the id at the head, not the new message's", "mail postfix/bounce[30]: 41E862C00D9E: sender non-delivery notification: 5F00AA12", "41E862C00D9E"},
{"long queue id", "mail postfix/qmgr[10]: 3sJ8Xh2Cgqz4Xy1: removed", "3sJ8Xh2Cgqz4Xy1"},
{"refused before queueing", "mail postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from mx.example.net[203.0.113.9]: 550 5.1.1 <n@in.example.com>: Recipient address rejected; from=<a@example.net> to=<n@in.example.com> proto=ESMTP helo=<mx.example.net>", ""},
{"a warning", "mail postfix/smtpd[10]: warning: hostname mx.example.net does not resolve to address 203.0.113.9", ""},
{"a connection", "mail postfix/smtpd[10]: connect from unknown[203.0.113.7]", ""},
{"no program", "preexisting line, ignored on start", ""},
{
// The reply is the receiving server's text. One that spells the head
// of a line is still the tail of this one: the line is the message's
// it was written about, and no other's.
"a reply that quotes a line head",
"mail postfix/smtp[26]: 9F1A2C00D9E: to=<a@example.net>, relay=mx.example.net[203.0.113.9]:25, dsn=5.1.1, status=bounced (host said: 550 mail postfix/smtp[1]: 41E862C00D9E: to=<b@example.net>, status=sent)",
"9F1A2C00D9E",
},
}
for _, c := range cases {
got := ""
if m := queueLineRe.FindStringSubmatch(c.rest); m != nil {
got = m[2]
}
if got != c.want {
t.Errorf("%s: queue id %q, want %q", c.name, got, c.want)
}
}
}
// A line is dated by its own stamp, not by when the tailer got to it, and is
// kept as the log has it. Nothing is written until the pass over the log ends.
func TestLineKeeperDatesByTheLine(t *testing.T) {
cs := &captureStore{}
k := newLineKeeper(cs)
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
line := "Oct 12 09:00:00 mail postfix/qmgr[7]: 41E862C00D9E: removed"
k.add(line, now, false)
k.add("Oct 12 09:00:01 mail postfix/smtpd[7]: connect from unknown[203.0.113.7]", now, false)
if len(cs.lines) != 0 {
t.Fatalf("written before the pass ended: %v", cs.kept())
}
k.flush()
if len(cs.lines) != 1 {
t.Fatalf("kept %d lines, want 1: %v", len(cs.lines), cs.kept())
}
got := cs.lines[0]
if got.QueueID != "41E862C00D9E" || got.Line != line {
t.Errorf("kept %q under %q", got.Line, got.QueueID)
}
if want := time.Date(2026, 10, 12, 9, 0, 0, 0, time.Local).UTC(); !got.At.Equal(want) {
t.Errorf("dated %v, want %v", got.At, want)
}
}
// A backlog is written in batches of lineBatch, not held whole, and a pass
// that changes from catching up to following does not write the later lines
// under the earlier rule.
func TestLineKeeperWritesInBatches(t *testing.T) {
cs := &captureStore{}
k := newLineKeeper(cs)
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
line := func(i int) string {
return "host postfix/qmgr[7]: 41E862C00D9E: from=<a@example.com>, size=" + itoa(i) + ", nrcpt=1 (queue active)"
}
for i := 0; i < lineBatch+10; i++ {
k.add(line(i), now, true)
}
if len(cs.lines) != lineBatch || cs.batches != 1 {
t.Fatalf("after %d lines: %d written in %d batches, want %d in 1", lineBatch+10, len(cs.lines), cs.batches, lineBatch)
}
// The same line again, now as one read while following: it is a new line,
// and the ten still held from the catch-up are written first, under theirs.
k.add(line(0), now, false)
k.flush()
if got, want := len(cs.lines), lineBatch+11; got != want {
t.Errorf("%d lines written, want %d", got, want)
}
if cs.batches != 3 {
t.Errorf("%d batches, want 3", cs.batches)
}
}
// Mail that comes in on port 25 is a stranger's and never gets a send-log row:
// none of its lines are kept, from the smtpd that opened the queue id to
// qmgr's "removed". The id is then anybody's again.
func TestLineKeeperLeavesOutPort25Mail(t *testing.T) {
cs := &captureStore{}
k := newLineKeeper(cs)
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
const (
outClient = "host postfix/submission/smtpd[10]: 41E862C00D9E: client=app.example.com[203.0.113.7], sasl_method=PLAIN, sasl_username=app"
outSent = "host postfix/smtp[26]: 41E862C00D9E: to=<a@example.net>, relay=mx.example.net[203.0.113.9]:25, dsn=2.0.0, status=sent (250 OK)"
reused = "host postfix/submission/smtpd[10]: 4A1B2C3D: client=app.example.com[203.0.113.7], sasl_method=PLAIN, sasl_username=app"
bounce = "host postfix/cleanup[52]: 5F00AA12: message-id=<20261012180000.5F00AA12@mail.example.com>"
)
for _, line := range []string{
"host postfix/inbound/smtpd[41]: 4A1B2C3D: client=mx.example.net[198.51.100.9]",
outClient,
"host postfix/cleanup[52]: 4A1B2C3D: message-id=<whatever-the-stranger-wrote@example.net>",
"host postfix/qmgr[10]: 4A1B2C3D: from=<a@example.net>, size=900, nrcpt=1 (queue active)",
outSent,
"host postfix/smtp[27]: 4A1B2C3D: to=<b@in.example.com>, relay=upstream.example.com[192.0.2.1]:25, dsn=2.0.0, status=sent (250 OK)",
"host postfix/qmgr[10]: 4A1B2C3D: removed",
// The id comes round again for a submitted message, and a bounce has no
// smtpd at all: both are kept.
reused,
bounce,
} {
k.add(line, now, false)
}
k.flush()
want := []string{"41E862C00D9E|" + outClient, "41E862C00D9E|" + outSent, "4A1B2C3D|" + reused, "5F00AA12|" + bounce}
if got := cs.kept(); strings.Join(got, "\n") != strings.Join(want, "\n") {
t.Errorf("kept:\n%s\nwant:\n%s", strings.Join(got, "\n"), strings.Join(want, "\n"))
}
// A port-25 id that a submission listener opens before qmgr's "removed" was
// seen (the line was lost, the panel restarted) is the submitted message's.
k.add("host postfix/inbound/smtpd[41]: 6C00BB34: client=mx.example.net[198.51.100.9]", now, false)
again := "host postfix/smtps/smtpd[11]: 6C00BB34: client=app.example.com[203.0.113.7], sasl_method=PLAIN, sasl_username=app"
k.add(again, now, false)
k.flush()
if got := cs.kept(); got[len(got)-1] != "6C00BB34|"+again {
t.Errorf("a reused port-25 id was not kept for the submitted message: %v", got[len(got)-1])
}
// What is remembered of port 25 has a ceiling.
for i := 0; i < port25IDs+50; i++ {
k.rememberPort25("7D" + itoa(100000+i))
}
if len(k.port25) > port25IDs {
t.Errorf("%d port-25 ids remembered, ceiling is %d", len(k.port25), port25IDs)
}
}
// The tailer keeps queue-id lines as it follows the log, and after an unclean
// stop - its saved place lies before lines it had already read - it does not
// keep them a second time.
func TestRunKeepsQueueLinesOnce(t *testing.T) {
old := pollInterval
pollInterval = 10 * time.Millisecond
t.Cleanup(func() { pollInterval = old })
dir := t.TempDir()
path := filepath.Join(dir, "mail.log")
// Longer than a fingerprint, so the file is recognised across the restart.
seed := strings.Repeat("host postfix/smtpd[1]: connect from unknown[203.0.113.7]\n", 20)
if err := os.WriteFile(path, []byte(seed), 0o644); err != nil {
t.Fatalf("seed log: %v", err)
}
const (
client = "host postfix/submission/smtpd[1]: 41E862C00D9E: client=unknown[203.0.113.7]"
sent = "host postfix/smtp[1]: 41E862C00D9E: to=<a@example.net>, dsn=2.0.0, status=sent (ok)"
later = "host postfix/qmgr[1]: 41E862C00D9E: removed"
)
cs := &captureStore{}
stop := startRun(t, path, cs)
appendLine(t, path, client)
appendLine(t, path, "host postfix/smtpd[1]: disconnect from unknown[203.0.113.7]")
appendLine(t, path, sent)
waitFor(t, func() bool { return len(cs.kept()) == 2 })
stop()
// The process died before it saved its place: what it has is the place it
// was at before those lines.
cs.mu.Lock()
cs.state.Offset = int64(len(seed))
cs.mu.Unlock()
appendLine(t, path, later)
stop = startRun(t, path, cs)
waitFor(t, func() bool { return len(cs.kept()) >= 3 })
stop()
want := []string{"41E862C00D9E|" + client, "41E862C00D9E|" + sent, "41E862C00D9E|" + later}
if got := cs.kept(); strings.Join(got, "\n") != strings.Join(want, "\n") {
t.Errorf("kept:\n%s\nwant:\n%s", strings.Join(got, "\n"), strings.Join(want, "\n"))
}
}
// Lines without a send-log row are removed at the start and after every
// send-log sweep, and only once they are old enough for the row to have been
// written.
func TestRetentionLoopPrunesLines(t *testing.T) {
old := retentionInterval
retentionInterval = 20 * time.Millisecond
t.Cleanup(func() { retentionInterval = old })
cs := &captureStore{}
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
go retentionLoop(ctx, cs, func() int { return 90 })
waitFor(t, func() bool { return cs.prunes() >= 3 })
cs.mu.Lock()
defer cs.mu.Unlock()
for _, cutoff := range cs.pruned {
if age := time.Since(cutoff); age < lineGrace || age > lineGrace+time.Minute {
t.Errorf("prune cutoff %v ago, want %v", age, lineGrace)
}
}
}
+30 -9
View File
@@ -4,7 +4,8 @@
// Postfix only decides sent / deferred / bounced later, per recipient, and // Postfix only decides sent / deferred / bounced later, per recipient, and
// reports it in mail.log. This package parses those lines by queue-id + // reports it in mail.log. This package parses those lines by queue-id +
// recipient and advances the matching rows, and prunes rows past the retention // recipient and advances the matching rows, and prunes rows past the retention
// window. // window. It also keeps every line Postfix wrote under a queue id, so that a
// message's page can show them after the log has rotated (lines.go).
package logtail package logtail
import ( import (
@@ -25,12 +26,14 @@ import (
// StatusStore is the slice of the store the log-tailer needs: advancing // StatusStore is the slice of the store the log-tailer needs: advancing
// delivery statuses, finding the rows still waiting for one, pruning the // delivery statuses, finding the rows still waiting for one, pruning the
// retention window, and remembering how far into mail.log it has read. // retention window, keeping the lines of queued messages, and remembering how
// *store.Store satisfies it. // far into mail.log it has read. *store.Store satisfies it.
type StatusStore interface { type StatusStore interface {
UpdateStatus(queueID, recipient, status string) (int64, error) UpdateStatus(queueID, recipient, status string) (int64, error)
ListQueuedOlderThan(cutoff time.Time) ([]store.QueuedDelivery, error) ListQueuedOlderThan(cutoff time.Time) ([]store.QueuedDelivery, error)
DeleteSendLogBefore(cutoff time.Time) (int64, error) DeleteSendLogBefore(cutoff time.Time) (int64, error)
InsertSendLogLines(lines []store.SendLogLine, once bool) (int, error)
PruneSendLogLines(cutoff time.Time) (int64, error)
LogtailState(path string) (store.LogtailState, bool, error) LogtailState(path string) (store.LogtailState, bool, error)
SaveLogtailState(path string, st store.LogtailState) error SaveLogtailState(path string, st store.LogtailState) error
} }
@@ -107,7 +110,9 @@ func parseDelivery(line string) (queueID, recipient, status string, ok bool) {
// Run follows path and updates send-log statuses until ctx is cancelled, while // Run follows path and updates send-log statuses until ctx is cancelled, while
// a background sweep prunes rows older than retention(). Reading resumes at // a background sweep prunes rows older than retention(). Reading resumes at
// the offset the previous run persisted, so a restart parses the delivery lines // the offset the previous run persisted, so a restart parses the delivery lines
// written while the panel was down. With inbound set it also writes the // written while the panel was down. The lines headed by a queue id are kept
// for the message's page, except those of mail that came in on port 25
// (lines.go). With inbound set it also writes the
// inbound journal's rows for refused mail and prunes that journal // inbound journal's rows for refused mail and prunes that journal
// (inbound.go). It returns nil on a clean shutdown. // (inbound.go). It returns nil on a clean shutdown.
func Run(ctx context.Context, path string, st StatusStore, retention RetentionDays, inbound *Inbound) error { func Run(ctx context.Context, path string, st StatusStore, retention RetentionDays, inbound *Inbound) error {
@@ -125,16 +130,22 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa
caughtUp := make(chan struct{}) caughtUp := make(chan struct{})
go reconcileLoop(ctx, st, caughtUp) go reconcileLoop(ctx, st, caughtUp)
return follow(ctx, path, &tracker{st: st, path: path}, caughtUp, func(line string) { keeper := newLineKeeper(st)
if journal != nil { return follow(ctx, path, &tracker{st: st, path: path}, caughtUp, keeper.flush, func(line string) {
// Until the first read reaches end-of-file the lines are those written
// while the panel was down - and, after an unclean stop, some it had
// read already.
catchingUp := true catchingUp := true
select { select {
case <-caughtUp: case <-caughtUp:
catchingUp = false catchingUp = false
default: default:
} }
journal.handle(line, time.Now().UTC(), catchingUp) now := time.Now().UTC()
if journal != nil {
journal.handle(line, now, catchingUp)
} }
keeper.add(line, now, catchingUp)
queueID, recipient, status, ok := parseDelivery(line) queueID, recipient, status, ok := parseDelivery(line)
if !ok { if !ok {
return return
@@ -214,7 +225,10 @@ func reconcile(st StatusStore, cutoff time.Time) {
} }
} }
// retentionLoop prunes expired send-log rows immediately and then periodically. // retentionLoop prunes expired send-log rows immediately and then periodically,
// and after each sweep the stored log lines no row carries the queue id of:
// those the deleted rows leave behind, and those that never had a row
// (lines.go).
func retentionLoop(ctx context.Context, st StatusStore, retention RetentionDays) { func retentionLoop(ctx context.Context, st StatusStore, retention RetentionDays) {
prune := func() { prune := func() {
retentionDays := retention() retentionDays := retention()
@@ -233,6 +247,7 @@ func retentionLoop(ctx context.Context, st StatusStore, retention RetentionDays)
} }
prune() prune()
pruneLines(st)
t := time.NewTicker(retentionInterval) t := time.NewTicker(retentionInterval)
defer t.Stop() defer t.Stop()
for { for {
@@ -241,6 +256,7 @@ func retentionLoop(ctx context.Context, st StatusStore, retention RetentionDays)
return return
case <-t.C: case <-t.C:
prune() prune()
pruneLines(st)
} }
} }
} }
@@ -442,7 +458,11 @@ func SplitTimestamp(line string) (stamp, rest string) {
// caughtUp is closed after the first read that reaches end-of-file, which is // caughtUp is closed after the first read that reaches end-of-file, which is
// the point where every line the panel missed while it was down has been // the point where every line the panel missed while it was down has been
// handled. // handled.
func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{}, handle func(string)) error { //
// flush is called at the end of every pass over the file, before the read
// position is saved: a handler that gathers lines to write them together
// writes them there, so the saved position is never ahead of what was written.
func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{}, flush func(), handle func(string)) error {
var ( var (
f *os.File f *os.File
r *bufio.Reader r *bufio.Reader
@@ -492,6 +512,7 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
}() }()
drain := func() { drain := func() {
defer flush()
for { for {
line, err := r.ReadString('\n') line, err := r.ReadString('\n')
if err == io.EOF { if err == io.EOF {
+52
View File
@@ -147,6 +147,58 @@ type captureStore struct {
// queued is what ListQueuedOlderThan returns, for the reconcile sweep. // queued is what ListQueuedOlderThan returns, for the reconcile sweep.
queued []store.QueuedDelivery queued []store.QueuedDelivery
queuedErr error queuedErr error
// lines are the log lines kept for messages' pages; pruned is the cutoff of
// each PruneSendLogLines call.
lines []store.SendLogLine
batches int
pruned []time.Time
}
// InsertSendLogLines keeps what the store would: with once, a line is not
// kept a second time under its queue id. batches counts the calls.
func (c *captureStore) InsertSendLogLines(lines []store.SendLogLine, once bool) (int, error) {
c.mu.Lock()
defer c.mu.Unlock()
c.batches++
wrote := 0
next:
for _, l := range lines {
if once {
for _, have := range c.lines {
if have.QueueID == l.QueueID && have.Line == l.Line {
continue next
}
}
}
c.lines = append(c.lines, l)
wrote++
}
return wrote, nil
}
func (c *captureStore) PruneSendLogLines(cutoff time.Time) (int64, error) {
c.mu.Lock()
defer c.mu.Unlock()
c.pruned = append(c.pruned, cutoff)
return 0, nil
}
// kept returns the stored lines as "queue-id|line".
func (c *captureStore) kept() []string {
c.mu.Lock()
defer c.mu.Unlock()
out := make([]string, len(c.lines))
for i, l := range c.lines {
out[i] = l.QueueID + "|" + l.Line
}
return out
}
func (c *captureStore) prunes() int {
c.mu.Lock()
defer c.mu.Unlock()
return len(c.pruned)
} }
func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, error) { func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, error) {
+6
View File
@@ -30,6 +30,12 @@ func (s *retentionProbeStore) DeleteSendLogBefore(cutoff time.Time) (int64, erro
return 0, nil return 0, nil
} }
func (s *retentionProbeStore) InsertSendLogLines([]store.SendLogLine, bool) (int, error) {
return 0, nil
}
func (s *retentionProbeStore) PruneSendLogLines(time.Time) (int64, error) { return 0, nil }
func (s *retentionProbeStore) LogtailState(string) (store.LogtailState, bool, error) { func (s *retentionProbeStore) LogtailState(string) (store.LogtailState, bool, error) {
return store.LogtailState{}, false, nil return store.LogtailState{}, false, nil
} }
+11
View File
@@ -129,6 +129,17 @@ func (p RetryPolicy) BackoffCap() string {
return FormatDuration(p.MaximalBackoff) return FormatDuration(p.MaximalBackoff)
} }
// LongestLifetime is how long Postfix may go on working on a message: the
// larger of the queue lifetime for ordinary mail and for mail from the null
// sender, which an application may submit too. It bounds which stored log
// lines can be about a send-log row (store.SendLogLines).
func (p RetryPolicy) LongestLifetime() time.Duration {
if p.BounceQueueLifetime > p.MaximalQueueLifetime {
return p.BounceQueueLifetime
}
return p.MaximalQueueLifetime
}
// QueueLifetime is the human string for maximal_queue_lifetime. // QueueLifetime is the human string for maximal_queue_lifetime.
func (p RetryPolicy) QueueLifetime() string { func (p RetryPolicy) QueueLifetime() string {
return FormatDuration(p.MaximalQueueLifetime) return FormatDuration(p.MaximalQueueLifetime)
@@ -0,0 +1,22 @@
-- What Postfix wrote about a message, kept with its send-log rows
-- (delivery-log-storage, 2.2.0). DDL only: a 2.1.0 database gains one empty
-- table and nothing in it changes.
-- One row per mail.log line headed by a queue id, written by the log tailer as
-- it reads the log. mail.log is rotated daily and fourteen files are kept; a
-- send-log row lives for the retention window, ninety days by default, and
-- its page shows these lines for as long.
--
-- There is no reference to send_log: the first lines of a message are logged
-- before the journal milter writes its row, and a message with several
-- recipients is several rows under one queue id. A line belongs to a row by
-- queue id and by time (Postfix reuses queue ids), and a line whose queue id
-- has no send-log row is deleted by the tailer's prune.
CREATE TABLE send_log_lines (
id INTEGER PRIMARY KEY AUTOINCREMENT,
queue_id TEXT NOT NULL,
logged_at TEXT NOT NULL,
line TEXT NOT NULL
);
-- A message's page reads the lines of one queue id within a span of time.
CREATE INDEX idx_send_log_lines_queue_id ON send_log_lines (queue_id, logged_at);
+7 -6
View File
@@ -57,6 +57,7 @@ func TestBaselineSchema(t *testing.T) {
"dmarc_report_records": "id report_row_id source_ip count disposition spf_result dkim_result header_from", "dmarc_report_records": "id report_row_id source_ip count disposition spf_result dkim_result header_from",
"inbound_spam_log": "id inbound_domain client_ip from_addr to_addr subject decision engine detail created_at", "inbound_spam_log": "id inbound_domain client_ip from_addr to_addr subject decision engine detail created_at",
"inbound_spam_list": "id list_type entry_type value note created_at", "inbound_spam_list": "id list_type entry_type value note created_at",
"send_log_lines": "id queue_id logged_at line",
} }
rows, err := st.db.Query("SELECT name FROM sqlite_master WHERE type = 'table' AND name NOT LIKE 'sqlite_%' ORDER BY name") rows, err := st.db.Query("SELECT name FROM sqlite_master WHERE type = 'table' AND name NOT LIKE 'sqlite_%' ORDER BY name")
if err != nil { if err != nil {
@@ -102,7 +103,7 @@ func TestBaselineSchema(t *testing.T) {
wantIdx := []string{ wantIdx := []string{
"idx_dmarc_report_records_report", "idx_dmarc_reports_domain", "idx_dmarc_reports_received", "idx_dmarc_report_records_report", "idx_dmarc_reports_domain", "idx_dmarc_reports_received",
"idx_inbound_spam_log_created_at", "idx_inbound_spam_log_domain_created_at", "idx_inbound_spam_log_created_at", "idx_inbound_spam_log_domain_created_at",
"idx_send_log_app_login_created_at", "idx_send_log_created_at", "idx_send_log_domain", "idx_send_log_queue_id", "idx_send_log_app_login_created_at", "idx_send_log_created_at", "idx_send_log_domain", "idx_send_log_lines_queue_id", "idx_send_log_queue_id",
"idx_sessions_expires_at", "idx_sessions_expires_at",
} }
sort.Strings(wantIdx) sort.Strings(wantIdx)
@@ -111,8 +112,8 @@ func TestBaselineSchema(t *testing.T) {
} }
var version, appID int64 var version, appID int64
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 2 { if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 3 {
t.Errorf("user_version = %d, %v; want 2", version, err) t.Errorf("user_version = %d, %v; want 3", version, err)
} }
if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID { if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID {
t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID) t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID)
@@ -188,13 +189,13 @@ func TestOpenMigratesA20Database(t *testing.T) {
} }
defer st.Close() defer st.Close()
var version int var version int
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 2 { if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 3 {
t.Errorf("user_version = %d, %v; want 2", version, err) t.Errorf("user_version = %d, %v; want 3", version, err)
} }
if ok, err := st.UserExists(); err != nil || !ok { if ok, err := st.UserExists(); err != nil || !ok {
t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err) t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err)
} }
for _, table := range []string{"inbound_spam_log", "inbound_spam_list"} { for _, table := range []string{"inbound_spam_log", "inbound_spam_list", "send_log_lines"} {
if len(tableColumns(t, st, table)) == 0 { if len(tableColumns(t, st, table)) == 0 {
t.Errorf("table %s was not created", table) t.Errorf("table %s was not created", table)
} }
+152
View File
@@ -0,0 +1,152 @@
package store
import (
"fmt"
"time"
"unicode/utf8"
)
// SendLogLine is one mail.log line Postfix wrote under a queue id, kept so a
// message's page can show it after mail.log has rotated (architecture.md § Log
// tailer). At is the line's own time, not when the tailer read it.
type SendLogLine struct {
QueueID string
At time.Time
Line string
}
// SendLogLineMax is how many bytes of a line are kept. Postfix quotes the far
// end's reply in a delivery line, so a line is as long as someone else cared
// to make it; what a page needs of it is the beginning.
const SendLogLineMax = 4096
// sendLogLineBefore is how long before a row was written a line may be dated
// and still be the row's. The journal milter writes the row at end-of-message;
// the smtpd line that opens the queue id is written when the first recipient
// is accepted, and the message body can take its time after that.
const sendLogLineBefore = time.Hour
// cutSendLogLine cuts a line to SendLogLineMax bytes, and not through the
// middle of a character.
func cutSendLogLine(line string) string {
if len(line) <= SendLogLineMax {
return line
}
end := SendLogLineMax
for end > 0 && !utf8.RuneStart(line[end]) {
end--
}
return line[:end]
}
// InsertSendLogLines stores lines in one transaction and returns how many it
// wrote. The tailer calls it with what it read in one pass over the log,
// whether or not send-log rows exist for the queue ids yet: a commit per line
// would be a disk sync per line, on the one connection the journal milter
// writes through.
//
// With once set, a line is written only if the same line is not there already
// under its queue id. That is for the lines the tailer reads again after an
// unclean stop; a line carries its time and its process id, so two that are
// equal are one line read twice.
func (s *Store) InsertSendLogLines(lines []SendLogLine, once bool) (int, error) {
if len(lines) == 0 {
return 0, nil
}
query := `INSERT INTO send_log_lines (queue_id, logged_at, line) VALUES (?1, ?2, ?3)`
if once {
query = `INSERT INTO send_log_lines (queue_id, logged_at, line)
SELECT ?1, ?2, ?3
WHERE NOT EXISTS (SELECT 1 FROM send_log_lines WHERE queue_id = ?1 AND line = ?3)`
}
tx, err := s.db.Begin()
if err != nil {
return 0, fmt.Errorf("insert send_log_lines: %w", err)
}
defer tx.Rollback()
stmt, err := tx.Prepare(query)
if err != nil {
return 0, fmt.Errorf("insert send_log_lines: %w", err)
}
defer stmt.Close()
wrote := 0
for _, l := range lines {
res, err := stmt.Exec(l.QueueID, l.At.UTC().Format(time.RFC3339), cutSendLogLine(l.Line))
if err != nil {
return 0, fmt.Errorf("insert send_log_lines: %w", err)
}
n, _ := res.RowsAffected()
wrote += int(n)
}
if err := tx.Commit(); err != nil {
return 0, fmt.Errorf("insert send_log_lines: %w", err)
}
return wrote, nil
}
// SendLogLines returns the stored lines of the message a send-log row is
// about, oldest first and at most n of them - the latest n when there are
// more, since what a message did last is what its page is opened for.
//
// Postfix reuses a queue id once the message has left the queue, and a row
// lives far longer than that, so the id alone does not say whose a line is.
// A line is the row's when it is dated from shortly before the row was written
// to lifetime after it; lifetime is how long Postfix may keep working on a
// message, with a margin, and the caller's to state (postfix.RetryPolicy).
func (s *Store) SendLogLines(row SendLogRow, lifetime time.Duration, n int) ([]SendLogLine, error) {
if row.QueueID == "" || n <= 0 {
return nil, nil
}
rows, err := s.db.Query(
`SELECT logged_at, line FROM (
SELECT id, logged_at, line FROM send_log_lines
WHERE queue_id = ? AND logged_at >= ? AND logged_at <= ?
ORDER BY id DESC LIMIT ?)
ORDER BY id`,
row.QueueID,
row.CreatedAt.Add(-sendLogLineBefore).UTC().Format(time.RFC3339),
row.CreatedAt.Add(lifetime).UTC().Format(time.RFC3339),
n,
)
if err != nil {
return nil, fmt.Errorf("query send_log_lines: %w", err)
}
defer rows.Close()
var out []SendLogLine
for rows.Next() {
var at string
l := SendLogLine{QueueID: row.QueueID}
if err := rows.Scan(&at, &l.Line); err != nil {
return nil, fmt.Errorf("scan send_log_lines row: %w", err)
}
l.At, _ = time.Parse(time.RFC3339, at)
out = append(out, l)
}
return out, rows.Err()
}
// PruneSendLogLines deletes the lines dated before cutoff whose queue id has
// no send-log row, and returns how many went. That one rule is the whole of
// the table's retention: it removes the lines of rows the send-log sweep has
// deleted, and the lines of messages that never had a row - the bounces
// Postfix generates. cutoff leaves alone the lines of a message still being
// received, whose row the journal milter has yet to write.
//
// The send log is asked once per queue id, not once per line: the ids are read
// off the index, and a message is several lines.
func (s *Store) PruneSendLogLines(cutoff time.Time) (int64, error) {
res, err := s.db.Exec(
`DELETE FROM send_log_lines
WHERE logged_at < ?
AND queue_id IN (
SELECT q.queue_id FROM (SELECT DISTINCT queue_id FROM send_log_lines) AS q
WHERE NOT EXISTS (SELECT 1 FROM send_log WHERE send_log.queue_id = q.queue_id))`,
cutoff.UTC().Format(time.RFC3339),
)
if err != nil {
return 0, fmt.Errorf("prune send_log_lines: %w", err)
}
n, _ := res.RowsAffected()
return n, nil
}
+203
View File
@@ -0,0 +1,203 @@
package store
import (
"strings"
"testing"
"time"
"unicode/utf8"
)
func sendLogLineTexts(lines []SendLogLine) []string {
out := make([]string, len(lines))
for i, l := range lines {
out[i] = l.Line
}
return out
}
func countSendLogLines(t *testing.T, s *Store) int {
t.Helper()
var n int
if err := s.db.QueryRow(`SELECT COUNT(*) FROM send_log_lines`).Scan(&n); err != nil {
t.Fatalf("count send_log_lines: %v", err)
}
return n
}
// A row's page gets the lines of its queue id, oldest first, and not the lines
// of another message.
func TestSendLogLinesOfOneMessage(t *testing.T) {
s := openTestStore(t)
at := time.Date(2026, 10, 12, 9, 0, 0, 0, time.UTC)
if n, err := s.InsertSendLogLines([]SendLogLine{
{QueueID: "41E862C00D9E", At: at, Line: "client=app"},
{QueueID: "5F00AA", At: at, Line: "someone else's"},
{QueueID: "41E862C00D9E", At: at.Add(time.Second), Line: "status=sent"},
{QueueID: "41E862C00D9E", At: at.Add(2 * time.Second), Line: "removed"},
}, false); err != nil || n != 4 {
t.Fatalf("insert: wrote %d, %v", n, err)
}
row := SendLogRow{QueueID: "41E862C00D9E", CreatedAt: at}
lines, err := s.SendLogLines(row, 6*24*time.Hour, 200)
if err != nil {
t.Fatalf("SendLogLines: %v", err)
}
if got := strings.Join(sendLogLineTexts(lines), "|"); got != "client=app|status=sent|removed" {
t.Errorf("lines = %q", got)
}
if len(lines) > 0 && !lines[0].At.Equal(at) {
t.Errorf("first line dated %v, want %v", lines[0].At, at)
}
// More than the page shows: the latest are kept, still oldest first.
lines, err = s.SendLogLines(row, 6*24*time.Hour, 2)
if err != nil {
t.Fatalf("SendLogLines: %v", err)
}
if got := strings.Join(sendLogLineTexts(lines), "|"); got != "status=sent|removed" {
t.Errorf("latest two = %q", got)
}
// A row the milter refused has no queue id and so no lines - not every line.
lines, err = s.SendLogLines(SendLogRow{CreatedAt: at}, 6*24*time.Hour, 200)
if err != nil || len(lines) != 0 {
t.Errorf("lines of a row without a queue id = %v, %v", lines, err)
}
}
// Postfix reuses a queue id once the message has left the queue. The lines of
// a later message under the same id are not the earlier row's, nor the other
// way round.
func TestSendLogLinesBoundedByTheRowsLifetime(t *testing.T) {
s := openTestStore(t)
first := time.Date(2026, 9, 1, 9, 0, 0, 0, time.UTC)
second := first.AddDate(0, 0, 30)
lifetime := 6 * 24 * time.Hour
if _, err := s.InsertSendLogLines([]SendLogLine{
{QueueID: "ABC123", At: first.Add(-30 * time.Minute), Line: "first: client"},
{QueueID: "ABC123", At: first.Add(5 * 24 * time.Hour), Line: "first: expired"},
{QueueID: "ABC123", At: second.Add(-2 * time.Hour), Line: "between the two"},
{QueueID: "ABC123", At: second, Line: "second: sent"},
}, false); err != nil {
t.Fatalf("insert: %v", err)
}
lines, err := s.SendLogLines(SendLogRow{QueueID: "ABC123", CreatedAt: first}, lifetime, 200)
if err != nil {
t.Fatalf("SendLogLines: %v", err)
}
if got := strings.Join(sendLogLineTexts(lines), "|"); got != "first: client|first: expired" {
t.Errorf("the first message's lines = %q", got)
}
lines, err = s.SendLogLines(SendLogRow{QueueID: "ABC123", CreatedAt: second}, lifetime, 200)
if err != nil {
t.Fatalf("SendLogLines: %v", err)
}
if got := strings.Join(sendLogLineTexts(lines), "|"); got != "second: sent" {
t.Errorf("the second message's lines = %q", got)
}
}
// After an unclean stop the tailer reads some lines twice; the second reading
// writes nothing, also when the line comes twice in one batch. The same text
// under another queue id is another line. Without once, what is given is
// written.
func TestInsertSendLogLinesOnce(t *testing.T) {
s := openTestStore(t)
l := SendLogLine{QueueID: "ABC123", At: time.Date(2026, 10, 12, 9, 0, 0, 0, time.UTC), Line: "Oct 12 09:00:00 mail postfix/qmgr[7]: ABC123: removed"}
other := l
other.QueueID = "DEF456"
if n, err := s.InsertSendLogLines([]SendLogLine{l, l, other}, true); err != nil || n != 2 {
t.Errorf("first reading wrote %d, %v; want 2", n, err)
}
if n, err := s.InsertSendLogLines([]SendLogLine{l, other}, true); err != nil || n != 0 {
t.Errorf("second reading wrote %d, %v; want 0", n, err)
}
if n := countSendLogLines(t, s); n != 2 {
t.Errorf("%d lines stored, want 2", n)
}
if n, err := s.InsertSendLogLines([]SendLogLine{l}, false); err != nil || n != 1 {
t.Errorf("a line as it is written: wrote %d, %v; want 1", n, err)
}
if n, err := s.InsertSendLogLines(nil, true); err != nil || n != 0 {
t.Errorf("nothing to write: %d, %v", n, err)
}
}
// The far end writes the reply a delivery line quotes; what is kept of a line
// has a ceiling, not set through the middle of a character, and a line read
// twice is still recognised past it.
func TestSendLogLineIsCut(t *testing.T) {
s := openTestStore(t)
at := time.Date(2026, 10, 12, 9, 0, 0, 0, time.UTC)
// Two bytes a character, starting at an odd offset: the ceiling falls inside one.
l := SendLogLine{QueueID: "ABC123", At: at, Line: "x" + strings.Repeat("é", SendLogLineMax)}
if _, err := s.InsertSendLogLines([]SendLogLine{l}, false); err != nil {
t.Fatalf("insert: %v", err)
}
if n, err := s.InsertSendLogLines([]SendLogLine{l}, true); err != nil || n != 0 {
t.Errorf("the same long line again: wrote %d, %v", n, err)
}
lines, err := s.SendLogLines(SendLogRow{QueueID: "ABC123", CreatedAt: at}, time.Hour, 10)
if err != nil || len(lines) != 1 {
t.Fatalf("lines = %d, %v", len(lines), err)
}
if got := lines[0].Line; len(got) != SendLogLineMax-1 || !utf8.ValidString(got) {
t.Errorf("kept %d bytes (valid UTF-8: %v), want %d whole characters", len(got), utf8.ValidString(got), SendLogLineMax-1)
}
}
// The prune is the table's retention: lines go when no send-log row carries
// their queue id - the row was pruned, or there never was one - and a message
// still being received is left alone.
func TestPruneSendLogLines(t *testing.T) {
s := openTestStore(t)
now := time.Date(2026, 10, 12, 12, 0, 0, 0, time.UTC)
old := now.Add(-3 * time.Hour)
if err := s.InsertQueued(SendLogEntry{QueueID: "KEPT01", Domain: "example.com", To: "a@example.net"}); err != nil {
t.Fatalf("insert row: %v", err)
}
// A row the milter refused has no queue id; it keeps no line alive.
if err := s.InsertRejected(SendLogEntry{Domain: "example.com", From: "a@example.com"}); err != nil {
t.Fatalf("insert rejected row: %v", err)
}
if _, err := s.InsertSendLogLines([]SendLogLine{
{QueueID: "KEPT01", At: old, Line: "has a row"},
{QueueID: "INBOUND1", At: old, Line: "never had a row"},
{QueueID: "ARRIVING", At: now.Add(-time.Minute), Line: "its row is not written yet"},
}, false); err != nil {
t.Fatalf("insert: %v", err)
}
n, err := s.PruneSendLogLines(now.Add(-time.Hour))
if err != nil || n != 1 {
t.Fatalf("prune removed %d, %v; want 1", n, err)
}
var left []string
rows, err := s.db.Query(`SELECT queue_id FROM send_log_lines ORDER BY id`)
if err != nil {
t.Fatal(err)
}
for rows.Next() {
var id string
if err := rows.Scan(&id); err != nil {
t.Fatal(err)
}
left = append(left, id)
}
rows.Close()
if got := strings.Join(left, " "); got != "KEPT01 ARRIVING" {
t.Errorf("left after the prune: %q", got)
}
// The send-log sweep deletes the row; the next prune takes its lines.
if _, err := s.DeleteSendLogBefore(time.Now().UTC().Add(time.Hour)); err != nil {
t.Fatalf("delete rows: %v", err)
}
if n, err := s.PruneSendLogLines(now.Add(-time.Hour)); err != nil || n != 1 {
t.Errorf("prune after the row went removed %d, %v; want 1", n, err)
}
}
+31 -10
View File
@@ -183,25 +183,46 @@ func deliveryEvents(row store.SendLogRow, policy postfix.RetryPolicy) []view.Ste
} }
} }
// deliveryLog reads the mail.log lines Postfix wrote about one message and // deliveryLogMargin is added to the queue lifetime when asking which stored
// splits each into the time and the text the page shows it in. The second // lines are a row's: Postfix expires a message on a queue run after the
// return value is what to say when there are none: every reason for an empty // lifetime has passed, not at the second it does, and logs the bounce after
// result here is an ordinary one — the message never reached the queue, or its // that.
// lines have aged out of the log — so none of them is an error on the page. Only const deliveryLogMargin = 24 * time.Hour
// a log that cannot be read at all is reported as a fault, and that one is
// logged for the operator as well. // deliveryLog returns the mail.log lines Postfix wrote about one message, each
// split into the time and the text the page shows it in. They come from the
// database, where the log tailer keeps them for as long as the row lives
// (architecture.md § Log tailer). A row with none stored is searched for in
// the current mail.log, as every row was before 2.2.0: that is what shows a
// message accepted before the lines were kept.
//
// The second return value is what to say when there are none: every reason for
// an empty result here is an ordinary one — the message never reached the
// queue, or it predates the stored lines and the log has rotated — so none of
// them is an error on the page. Only lines that cannot be read at all are
// reported as a fault, and that one is logged for the operator as well.
func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) { func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) {
if row.QueueID == "" { if row.QueueID == "" {
return nil, "This message never reached the queue, so Postfix wrote no delivery lines for it." return nil, "This message never reached the queue, so Postfix wrote no delivery lines for it."
} }
lines, err := logtail.QueueLines(h.cfg.MailLogPath, row.QueueID, deliveryLogLines) stored, err := h.store.SendLogLines(row, h.cfg.RetryPolicy.LongestLifetime()+deliveryLogMargin, deliveryLogLines)
if err != nil {
logf("panel: delivery log %s: %v", row.QueueID, err)
return nil, "Could not read the stored delivery log."
}
lines := make([]string, len(stored))
for i, l := range stored {
lines[i] = l.Line
}
if len(lines) == 0 {
lines, err = logtail.QueueLines(h.cfg.MailLogPath, row.QueueID, deliveryLogLines)
if err != nil && !errors.Is(err, fs.ErrNotExist) { if err != nil && !errors.Is(err, fs.ErrNotExist) {
logf("panel: delivery log %s: %v", row.QueueID, err) logf("panel: delivery log %s: %v", row.QueueID, err)
return nil, "Could not read the mail log." return nil, "Could not read the mail log."
} }
}
if len(lines) == 0 { if len(lines) == 0 {
days := h.sendLogRetentionDays() return nil, "Nothing is stored for this queue id and nothing is in the current mail log. Lines are kept with the row since version 2.2.0; a message accepted before that had them only in mail.log, which has since rotated."
return nil, fmt.Sprintf("Nothing for this queue id in the current mail log. Its lines have most likely been rotated away (send-log rows are kept for %d days).", days)
} }
out := make([]view.LogLine, len(lines)) out := make([]view.LogLine, len(lines))
for i, line := range lines { for i, line := range lines {
+38 -10
View File
@@ -188,23 +188,51 @@ func TestDeliveryPageKeepsAnUnstampedLogLineWhole(t *testing.T) {
} }
} }
// Rows outlive mail.log, and a message the milter refused never reached the // The lines are kept in the database as the tailer reads them, so a message's
// queue at all. Neither is a fault, so neither may render as an error. // page shows them when mail.log no longer holds any - the ordinary case for
// anything sent before the last daily rotation, and the reason they are kept.
// Only this message's lines: another queue id's are not, nor those of an
// earlier message that had the same queue id.
func TestDeliveryPageShowsStoredLogLinesAfterRotation(t *testing.T) {
h, row := serverWithDelivery(t)
h.cfg.RetryPolicy = postfix.DefaultRetryPolicy()
h.cfg.MailLogPath = writeMailLog(t, "2026-08-04T00:00:01.000000+00:00 host postfix/qmgr[10]: 99999999: removed")
if _, err := h.store.InsertSendLogLines([]store.SendLogLine{
{QueueID: row.QueueID, At: row.CreatedAt.AddDate(0, 0, -40), Line: "2026-06-24T05:00:00.000000+00:00 host postfix/qmgr[10]: 4A1B2C3D: an earlier message under the same id"},
{QueueID: row.QueueID, At: row.CreatedAt.Add(-time.Second), Line: "2026-08-03T05:15:52.219218+00:00 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]"},
{QueueID: "99999999", At: row.CreatedAt, Line: "2026-08-03T05:15:52.300000+00:00 host postfix/qmgr[10]: 99999999: from=<other@example.ru>, size=500, nrcpt=1 (queue active)"},
{QueueID: row.QueueID, At: row.CreatedAt.Add(11 * time.Second), Line: "2026-08-03T05:16:03.884210+00:00 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>, dsn=2.0.0, status=sent (250 OK)"},
}, false); err != nil {
t.Fatalf("InsertSendLogLines: %v", err)
}
out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID))
for _, want := range []string{
`<span class="sp-d">2026-08-03 05:15:52</span> host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`,
`<span class="sp-d">2026-08-03 05:16:03</span> host postfix/smtp[26]: 4A1B2C3D: to=&lt;public@example.ru&gt;`,
} {
if !strings.Contains(out, want) {
t.Errorf("delivery log is missing %q:\n%s", want, out)
}
}
for _, not := range []string{"99999999", "an earlier message"} {
if strings.Contains(out, not) {
t.Errorf("delivery page shows a line that is not this message's (%q):\n%s", not, out)
}
}
}
// A message accepted before the lines were kept has them only in mail.log, and
// a message the milter refused never reached the queue at all. Neither is a
// fault, so neither may render as an error.
func TestDeliveryPageExplainsAnEmptyDeliveryLog(t *testing.T) { func TestDeliveryPageExplainsAnEmptyDeliveryLog(t *testing.T) {
h, row := serverWithDelivery(t) h, row := serverWithDelivery(t)
h.cfg.SendLogRetentionEnvDefault = 60
if err := h.store.SetSendLogRetentionDays(60); err != nil {
t.Fatalf("SetSendLogRetentionDays: %v", err)
}
h.cfg.MailLogPath = filepath.Join(t.TempDir(), "mail.log") // never created h.cfg.MailLogPath = filepath.Join(t.TempDir(), "mail.log") // never created
out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID)) out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID))
if !strings.Contains(out, "rotated away") { if !strings.Contains(out, "Nothing is stored for this queue id") || !strings.Contains(out, "since version 2.2.0") {
t.Errorf("delivery page does not explain the empty delivery log:\n%s", out) t.Errorf("delivery page does not explain the empty delivery log:\n%s", out)
} }
if !strings.Contains(out, "kept for 60 days") {
t.Errorf("delivery page does not show configured retention:\n%s", out)
}
if strings.Contains(out, `class="error"`) || strings.Contains(out, "Could not read the mail log") { if strings.Contains(out, `class="error"`) || strings.Contains(out, "Could not read the mail log") {
t.Errorf("an aged-out delivery log is reported as a failure:\n%s", out) t.Errorf("an aged-out delivery log is reported as a failure:\n%s", out)
} }
+1 -1
View File
@@ -162,7 +162,7 @@ var outboundTopics = []HelpTopic{
}}, }},
{ID: HelpLog, Title: "Outbound log", Body: []Text{ {ID: HelpLog, Title: "Outbound log", Body: []Text{
Rich("One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out) and rejected (refused before queueing under a level-2 rate limit, so it never reached Postfix). A message's page lists these steps and the lines Postfix wrote about it in ", Rich("One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out) and rejected (refused before queueing under a level-2 rate limit, so it never reached Postfix). A message's page lists these steps and the lines Postfix wrote about it in ",
Code("mail.log"), ", found by queue id; that file is rotated daily and about two weeks are kept, so an old message may show none. Rows are deleted after the retention set in Server › Settings, 90 days by default. A domain administrator sees only the rows of their own domains."), Code("mail.log"), ", found by queue id. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains."),
}}, }},
{ID: HelpQueue, Title: "Queue and retries", Body: []Text{ {ID: HelpQueue, Title: "Queue and retries", Body: []Text{
Rich("The page lists, as ", Code("postqueue -p"), " prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged."), Rich("The page lists, as ", Code("postqueue -p"), " prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged."),
+1 -1
View File
@@ -189,7 +189,7 @@ type OutMessage struct {
Delivery Box Delivery Box
LogLines []LogLine LogLines []LogLine
// LogEmpty says why there are no lines: a message that never reached the // LogEmpty says why there are no lines: a message that never reached the
// queue, or whose lines have been rotated away, is an ordinary outcome. // queue, or that predates the stored lines, is an ordinary outcome.
LogEmpty EmptyState LogEmpty EmptyState
} }
+68
View File
@@ -0,0 +1,68 @@
package e2e
import (
"fmt"
"html"
"regexp"
"strings"
"testing"
"time"
)
var sendLogDetailsRe = regexp.MustCompile(`href="(/outbound/log/\d+[^"]*)"`)
// firstDeliveryPage returns the address of the page of the newest row in the
// sender domain's send log.
func firstDeliveryPage(sc *scenario) (string, error) {
rows, err := sc.panel.sendLogRows(senderDomain, "")
if err != nil {
return "", fmt.Errorf("read the send log: %w", err)
}
m := sendLogDetailsRe.FindStringSubmatch(rows)
if m == nil {
return "", fmt.Errorf("no Details link in the send log:\n%s", rows)
}
return html.UnescapeString(m[1]), nil
}
// testDeliveryLogSurvivesRotation checks that a message's page still lists
// what Postfix wrote about it after mail.log has been rotated: the lines are
// kept in the database by the log tailer, not searched for in the current
// file (architecture.md § Log tailer, Stored lines). The message is the first
// one delivered, whose page send_verify_dkim_and_status noted.
func testDeliveryLogSurvivesRotation(t *testing.T, sc *scenario) {
page := sc.deliveryPage
// What the page has to show: the line that opened the queue id and the
// delivery line. The tailer has read both - the row is "sent" - but it
// writes them one at a time, so the page is polled rather than read once.
wanted := []string{"client=", "status=sent"}
shows := func() (bool, error) {
_, body, err := sc.panel.get(page)
if err != nil {
return false, err
}
for _, w := range wanted {
if !strings.Contains(body, w) {
return false, fmt.Errorf("%s does not show a %q line", page, w)
}
}
return true, nil
}
if err := waitFor("the message's page to list its log lines", 15*time.Second, 500*time.Millisecond, shows); err != nil {
t.Fatal(err)
}
if _, err := h.execIn("selfpost", "logrotate", "-f", "/etc/logrotate.d/mail"); err != nil {
t.Fatalf("logrotate -f: %v", err)
}
// The current file must no longer hold the delivery line, or the page
// finding it there would prove nothing. grep exits 1 on no match.
if out, err := h.execIn("selfpost", "sh", "-c", "grep -c 'status=sent' /data/log/mail.log || true"); err != nil || strings.TrimSpace(out) != "0" {
t.Fatalf("mail.log still holds delivery lines after the rotation (count=%q err=%v)", strings.TrimSpace(out), err)
}
if ok, err := shows(); !ok {
t.Fatalf("after mail.log was rotated: %v", err)
}
}
+15
View File
@@ -92,6 +92,8 @@ type scenario struct {
l2AppPassword string l2AppPassword string
clientIP string clientIP string
zoneRecords []txtRecord zoneRecords []txtRecord
// deliveryPage is the panel page of the first delivered message.
deliveryPage string
} }
func TestE2E(t *testing.T) { func TestE2E(t *testing.T) {
@@ -251,6 +253,14 @@ func TestE2E(t *testing.T) {
}); err != nil { }); err != nil {
t.Fatal(err) t.Fatal(err)
} }
// The only row so far; its page is looked at again once the log has
// been rotated (delivery_log_survives_rotation).
page, err := firstDeliveryPage(sc)
if err != nil {
t.Fatal(err)
}
sc.deliveryPage = page
}) })
run("negative_level2_ratelimit_via_panel", func(t *testing.T) { run("negative_level2_ratelimit_via_panel", func(t *testing.T) {
@@ -274,6 +284,11 @@ func TestE2E(t *testing.T) {
run("negative_level1_ratelimit", func(t *testing.T) { run("negative_level1_ratelimit", func(t *testing.T) {
testLevel1RateLimit(t, sc) testLevel1RateLimit(t, sc)
}) })
// Rotates mail.log, so it comes after the steps that read what they need
// from the current file.
run("delivery_log_survives_rotation", func(t *testing.T) {
testDeliveryLogSurvivesRotation(t, sc)
})
// From here on the installation is no longer the one the run started: it // 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. // is restored from its own backup, then switched to accept mail on port 25.