Compare commits
9
Commits
ae06d8b47e
...
a990e7cc23
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
a990e7cc23 | ||
|
|
815236a607 | ||
|
|
a6845ae948 | ||
|
|
1e6836b3c1 | ||
|
|
fc184ecc01 | ||
|
|
81df131217 | ||
|
|
3d17206063 | ||
|
|
4468aa8dd7 | ||
|
|
977d63a2ea |
@@ -5,6 +5,43 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version
|
||||
|
||||
## [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
|
||||
|
||||
### Security
|
||||
|
||||
+61
-6
@@ -184,6 +184,8 @@ One process, four roles:
|
||||
3. **log-tailer** — follows `MAIL_LOG`, updates send-log delivery status by
|
||||
queue-id. Send-log `queued → sent` transitions depend on this goroutine alone
|
||||
(`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
|
||||
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 —
|
||||
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
|
||||
serving panel pages on request: `TailLines` (the last *n* lines, for
|
||||
`/server/log`) and `QueueLines` (the lines carrying one queue-id, for
|
||||
`/outbound/log/{id}`). `QueueLines` scans a bounded tail of the current file —
|
||||
`/server/log`) and `QueueLines` (the lines carrying one queue-id). `QueueLines`
|
||||
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
|
||||
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
|
||||
(retention 90 days, rotation 14 files), so an empty result is the expected end
|
||||
state for an older message and the page reports it as such, not as a failure.
|
||||
shorter one is regularly the tail of a longer one. For such a message an empty
|
||||
result is the expected end state once the log has rotated, and the page reports
|
||||
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.
|
||||
- `applications` (with `auth_ip_restrict` / `auth_allowed_ips`),
|
||||
`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`,
|
||||
`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
|
||||
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 +
|
||||
`postfix reload` in `postrotate` — see § Log tailer above).
|
||||
|
||||
|
||||
@@ -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="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="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="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>
|
||||
|
||||
@@ -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="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="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="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>
|
||||
|
||||
@@ -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) |
|
||||
| 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) |
|
||||
| 16 | delivery-log-storage | `2.2.0` |
|
||||
|
||||
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.
|
||||
|
||||
+5
-3
@@ -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` |
|
||||
| `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` |
|
||||
| `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` |
|
||||
| `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` |
|
||||
@@ -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
|
||||
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
|
||||
as. Rows outlive `mail.log`, so an older message's lines may have rotated
|
||||
away; the page says so. Retention is set under **Server › Settings** (global
|
||||
as. The lines are kept in the database with the row, so they stay on the
|
||||
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
|
||||
is changed there.
|
||||
|
||||
|
||||
@@ -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)
|
||||
@@ -34,8 +34,8 @@ Lists let the operator correct false positives/negatives (e.g. always allow
|
||||
|
||||
## Quarantine
|
||||
|
||||
**Not in this plan.** Held-mail review/release is tracked separately as roadmap
|
||||
candidate [inbound-quarantine](inbound-quarantine.md). The journal may still
|
||||
**Not in this plan.** Held-mail review/release is an idea kept outside the roadmap,
|
||||
[inbound-quarantine](inbound-quarantine.md). The journal may still
|
||||
record a `quarantine` **decision label** when the external filter reports it,
|
||||
without SelfPost storing the message.
|
||||
|
||||
|
||||
@@ -1,6 +1,6 @@
|
||||
# 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`
|
||||
if it changes inbound storage or backup contract).
|
||||
|
||||
|
||||
@@ -235,7 +235,7 @@ the first step of that feature's plan — not invented during implementation.
|
||||
| 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-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` |
|
||||
| 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** |
|
||||
@@ -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,
|
||||
password-reset (two screens to draw first), queue as a table with the inbound
|
||||
queue, csrf-tokens
|
||||
(one hidden field in the form partial once security.md is settled),
|
||||
inbound-quarantine after its open questions.
|
||||
(one hidden field in the form partial once security.md is settled).
|
||||
inbound-quarantine is an idea outside the roadmap.
|
||||
|
||||
+24
-30
@@ -31,13 +31,12 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md).
|
||||
| preflight | Installation check page (`/preflight`) | candidate | — | [plans/preflight.md](plans/preflight.md) |
|
||||
| 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-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 | — | — |
|
||||
| template-data-typing | Typed structs for template data instead of `map[string]any` | candidate | — | — |
|
||||
| structured-logging | `log/slog` with levels and fields | candidate | — | — |
|
||||
| review-2026-08-followups | Remaining findings of the 2026-08-19 code review | 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 | — | — |
|
||||
| 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) |
|
||||
@@ -46,8 +45,9 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md).
|
||||
**Recommended order** (not binding; owner, 2026-10-09: feature order follows
|
||||
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and
|
||||
**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
|
||||
it: every remaining item is a candidate. panel-docs shipped in
|
||||
kit — styling its two screens once instead of twice. After it the owner
|
||||
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]`
|
||||
(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
|
||||
@@ -124,8 +124,8 @@ action) plus editable allow/deny lists that tune the external filter — without
|
||||
shipping rspamd or another engine inside the image.
|
||||
|
||||
**Boundary:** metadata journal and list sync only; SelfPost does not run the
|
||||
filter ([product.md](product.md)). Quarantine:
|
||||
[inbound-quarantine](#inbound-quarantine). Design closed in
|
||||
filter ([product.md](product.md)). Quarantine is not on the roadmap
|
||||
([Ideas](#ideas-not-on-the-roadmap)). Design closed in
|
||||
[plans/inbound-antispam-panel.md](plans/inbound-antispam-panel.md) § Decisions.
|
||||
|
||||
**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
|
||||
|
||||
**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
|
||||
covered by the same retention.
|
||||
|
||||
**Version:** `2.x` MINOR; `candidate`. Fits after the redesign, built against
|
||||
the kit's `log_pane`.
|
||||
**Version:** `2.2.0` MINOR; agreed 2026-10-12, option 1. Decisions and
|
||||
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
|
||||
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,
|
||||
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
|
||||
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.
|
||||
**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.
|
||||
|
||||
@@ -17,8 +17,8 @@ When you add or review a migration, update this file in the same change.
|
||||
|
||||
| Field | Value |
|
||||
|---|---|
|
||||
| Chain head | `user_version = 2` |
|
||||
| Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql` |
|
||||
| Chain head | `user_version = 3` |
|
||||
| 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") |
|
||||
| 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.** |
|
||||
@@ -62,7 +62,8 @@ What that means in practice:
|
||||
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
|
||||
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 |
|
||||
| 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
|
||||
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 |
|
||||
| `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) |
|
||||
| `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
|
||||
and index of this list; `TestOpenMigratesA20Database` opens a database that
|
||||
|
||||
+20
-1
@@ -244,6 +244,11 @@ operator can act on it.
|
||||
private key from `certs/` when present; a domain export carries the DKIM key
|
||||
and **working** application passwords in the clear (otherwise a transfer
|
||||
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
|
||||
unticked (it is ticked by default):
|
||||
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
|
||||
client IPs, but neither message bodies nor headers; it is excluded from
|
||||
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
|
||||
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
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -4,7 +4,8 @@
|
||||
// Postfix only decides sent / deferred / bounced later, per recipient, and
|
||||
// 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
|
||||
// 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
|
||||
|
||||
import (
|
||||
@@ -25,12 +26,14 @@ import (
|
||||
|
||||
// StatusStore is the slice of the store the log-tailer needs: advancing
|
||||
// delivery statuses, finding the rows still waiting for one, pruning the
|
||||
// retention window, and remembering how far into mail.log it has read.
|
||||
// *store.Store satisfies it.
|
||||
// retention window, keeping the lines of queued messages, and remembering how
|
||||
// far into mail.log it has read. *store.Store satisfies it.
|
||||
type StatusStore interface {
|
||||
UpdateStatus(queueID, recipient, status string) (int64, error)
|
||||
ListQueuedOlderThan(cutoff time.Time) ([]store.QueuedDelivery, error)
|
||||
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)
|
||||
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
|
||||
// a background sweep prunes rows older than retention(). Reading resumes at
|
||||
// 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.go). It returns nil on a clean shutdown.
|
||||
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{})
|
||||
go reconcileLoop(ctx, st, caughtUp)
|
||||
|
||||
return follow(ctx, path, &tracker{st: st, path: path}, caughtUp, func(line string) {
|
||||
if journal != nil {
|
||||
keeper := newLineKeeper(st)
|
||||
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
|
||||
select {
|
||||
case <-caughtUp:
|
||||
catchingUp = false
|
||||
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)
|
||||
if !ok {
|
||||
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) {
|
||||
prune := func() {
|
||||
retentionDays := retention()
|
||||
@@ -233,6 +247,7 @@ func retentionLoop(ctx context.Context, st StatusStore, retention RetentionDays)
|
||||
}
|
||||
|
||||
prune()
|
||||
pruneLines(st)
|
||||
t := time.NewTicker(retentionInterval)
|
||||
defer t.Stop()
|
||||
for {
|
||||
@@ -241,6 +256,7 @@ func retentionLoop(ctx context.Context, st StatusStore, retention RetentionDays)
|
||||
return
|
||||
case <-t.C:
|
||||
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
|
||||
// the point where every line the panel missed while it was down has been
|
||||
// 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 (
|
||||
f *os.File
|
||||
r *bufio.Reader
|
||||
@@ -492,6 +512,7 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
|
||||
}()
|
||||
|
||||
drain := func() {
|
||||
defer flush()
|
||||
for {
|
||||
line, err := r.ReadString('\n')
|
||||
if err == io.EOF {
|
||||
|
||||
@@ -147,6 +147,58 @@ type captureStore struct {
|
||||
// queued is what ListQueuedOlderThan returns, for the reconcile sweep.
|
||||
queued []store.QueuedDelivery
|
||||
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) {
|
||||
|
||||
@@ -30,6 +30,12 @@ func (s *retentionProbeStore) DeleteSendLogBefore(cutoff time.Time) (int64, erro
|
||||
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) {
|
||||
return store.LogtailState{}, false, nil
|
||||
}
|
||||
|
||||
@@ -129,6 +129,17 @@ func (p RetryPolicy) BackoffCap() string {
|
||||
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.
|
||||
func (p RetryPolicy) QueueLifetime() string {
|
||||
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);
|
||||
@@ -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",
|
||||
"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",
|
||||
"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")
|
||||
if err != nil {
|
||||
@@ -102,7 +103,7 @@ func TestBaselineSchema(t *testing.T) {
|
||||
wantIdx := []string{
|
||||
"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_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",
|
||||
}
|
||||
sort.Strings(wantIdx)
|
||||
@@ -111,8 +112,8 @@ func TestBaselineSchema(t *testing.T) {
|
||||
}
|
||||
|
||||
var version, appID int64
|
||||
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 2 {
|
||||
t.Errorf("user_version = %d, %v; want 2", version, err)
|
||||
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 3 {
|
||||
t.Errorf("user_version = %d, %v; want 3", version, err)
|
||||
}
|
||||
if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID {
|
||||
t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID)
|
||||
@@ -188,13 +189,13 @@ func TestOpenMigratesA20Database(t *testing.T) {
|
||||
}
|
||||
defer st.Close()
|
||||
var version int
|
||||
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 2 {
|
||||
t.Errorf("user_version = %d, %v; want 2", version, err)
|
||||
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 3 {
|
||||
t.Errorf("user_version = %d, %v; want 3", version, err)
|
||||
}
|
||||
if ok, err := st.UserExists(); err != nil || !ok {
|
||||
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 {
|
||||
t.Errorf("table %s was not created", table)
|
||||
}
|
||||
|
||||
@@ -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
|
||||
}
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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
|
||||
// splits each into the time and the text the page shows it in. 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 its
|
||||
// lines have aged out of the log — so none of them is an error on the page. Only
|
||||
// a log that cannot be read at all is reported as a fault, and that one is
|
||||
// logged for the operator as well.
|
||||
// deliveryLogMargin is added to the queue lifetime when asking which stored
|
||||
// lines are a row's: Postfix expires a message on a queue run after the
|
||||
// lifetime has passed, not at the second it does, and logs the bounce after
|
||||
// that.
|
||||
const deliveryLogMargin = 24 * time.Hour
|
||||
|
||||
// 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) {
|
||||
if row.QueueID == "" {
|
||||
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) {
|
||||
logf("panel: delivery log %s: %v", row.QueueID, err)
|
||||
return nil, "Could not read the mail log."
|
||||
}
|
||||
}
|
||||
if len(lines) == 0 {
|
||||
days := h.sendLogRetentionDays()
|
||||
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)
|
||||
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."
|
||||
}
|
||||
out := make([]view.LogLine, len(lines))
|
||||
for i, line := range lines {
|
||||
|
||||
@@ -188,23 +188,51 @@ func TestDeliveryPageKeepsAnUnstampedLogLineWhole(t *testing.T) {
|
||||
}
|
||||
}
|
||||
|
||||
// Rows outlive 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.
|
||||
// The lines are kept in the database as the tailer reads them, so a message's
|
||||
// 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=<public@example.ru>`,
|
||||
} {
|
||||
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) {
|
||||
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
|
||||
|
||||
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)
|
||||
}
|
||||
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") {
|
||||
t.Errorf("an aged-out delivery log is reported as a failure:\n%s", out)
|
||||
}
|
||||
|
||||
@@ -162,7 +162,7 @@ var outboundTopics = []HelpTopic{
|
||||
}},
|
||||
{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 ",
|
||||
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{
|
||||
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."),
|
||||
|
||||
@@ -189,7 +189,7 @@ type OutMessage struct {
|
||||
Delivery Box
|
||||
LogLines []LogLine
|
||||
// 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
|
||||
}
|
||||
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -92,6 +92,8 @@ type scenario struct {
|
||||
l2AppPassword string
|
||||
clientIP string
|
||||
zoneRecords []txtRecord
|
||||
// deliveryPage is the panel page of the first delivered message.
|
||||
deliveryPage string
|
||||
}
|
||||
|
||||
func TestE2E(t *testing.T) {
|
||||
@@ -251,6 +253,14 @@ func TestE2E(t *testing.T) {
|
||||
}); err != nil {
|
||||
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) {
|
||||
@@ -274,6 +284,11 @@ func TestE2E(t *testing.T) {
|
||||
run("negative_level1_ratelimit", func(t *testing.T) {
|
||||
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
|
||||
// is restored from its own backup, then switched to accept mail on port 25.
|
||||
|
||||
Reference in New Issue
Block a user