From c731a98a0fd1d4a9073cb7545e1f69aeafe87c0c Mon Sep 17 00:00:00 2001 From: Mix Date: Mon, 12 Oct 2026 07:51:50 +0300 Subject: [PATCH] inbound-antispam-panel: findings of the technical and security reviews Steps 11 and 12 of docs/plans/inbound-antispam-panel.md: 12/12. Two read-only reviews of d65d632..HEAD by different models (Opus, technical; Fable, security), each given the code and questions, not conclusions. Nothing Critical or High in the feature; the High the technical review found outside it is the commit before this one. Log tailer (internal/logtail/inbound.go): - the reply of a refusal ends at the first "; from=<", Postfix's own, and the HELO name after it is whatever is left. Taking the longest reply let a HELO name that spelt "; from=<..> to=<..> proto=.." supply the row's sender, recipient and reply - and so make a refusal read as the deny list's; - an address with a quote, a bracket or a space is not kept: a quoted sender could otherwise supply the recipient; - the journal is cut to its row cap every 500 rows written, not only every six hours; - a queue id is forgotten when the message is queued or the id is opened by another listener, and a stale place in the queue of arrivals no longer drops a live id; - milter-hold lines are not read: the held message reaches the journal milter, which writes its row - it was written twice. Lists (internal/inbound/lists.go): a change of the table and the rewrite of the files are one step under a mutex; a failed rewrite puts a removed entry back and rewrites after taking a new one out. Store: the row cap removes the oldest by time, as the page orders them. Page: on a sheet a refusal's text is a Reply whatever it starts with. Help and the guide say that an allow entry for a sender address trusts an address anyone can claim (design commit before this one). docs/security.md: the two reviews; the roles table gains Inbound > Log and Filter lists; Mail path describes the milters, the tailer and the lists; four accepted risks - the filter's verdict while it is down, an allow entry by sender address, the list files' mode, log rows held by domain name. The plan's stale lines (size and rate refusals, who reads the journal) are corrected. Left as found, told to the owner: the journal's rows after an unclean stop may be written twice (the tailer saves its place every five seconds); a "Deny sender" link is offered for an address the form then refuses; 1.2.3.4 and 1.2.3.4/32 are two entries. Checked on the test server, uncommitted tree: go vet ./... ok, go test ./... ok (22 packages), make e2e ok. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 27 ++++++++ docs/architecture.md | 5 +- docs/guide.md | 6 +- docs/plans/inbound-antispam-panel.md | 12 ++-- docs/roadmap.md | 2 +- docs/security.md | 85 ++++++++++++++++++++++++- internal/inbound/lists.go | 47 ++++++++++++-- internal/logtail/inbound.go | 86 ++++++++++++++++++++----- internal/logtail/inbound_test.go | 92 ++++++++++++++++++++++++++- internal/logtail/offset.go | 11 ++-- internal/store/inboundspam.go | 8 ++- internal/store/inboundspam_test.go | 26 ++++++++ internal/web/view/help.go | 2 +- internal/web/view/inbound_log.go | 14 ++-- internal/web/view/inbound_log_test.go | 22 ++++--- 15 files changed, 388 insertions(+), 57 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index cc637e0..e4f780b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,33 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version ## [Unreleased] +### Security + +- **The level-2 rate limit and an application's client IP list held only for + the first message of a connection.** After a refused `MAIL FROM`, a second + one on the same connection was accepted, and so was every message after the + first that a connection carried: an application over its limit could go on + sending, and one restricted to certain client addresses could send from any + other with a retry. In the code since `1.9.0` (the client IP list) and + earlier (the limit); found by the technical review of 2026-10-12 and + reproduced on the test stand. Postfix now gives the panel's milters the + client address with every message, the limit no longer depends on it, and an + application with a client IP list is refused when no address is known. +- Reviews of the inbound antispam feature before its release (technical and + security, 2026-10-12; nothing Critical or High in the feature itself). Fixed: + a client's HELO name could supply the sender, recipient and reply of an + inbound log row; the log's row cap was applied only every six hours; rows of + a connection's later messages had no client address; two changes of the + filter lists at once could leave the filter's files behind the page; a held + message was logged twice. Recorded as accepted in + [docs/security.md](docs/security.md): the filter's verdict in the log is the + sender's own while the filter is down; an allow entry for a sender address + trusts an address anyone can claim; the list files are readable by anyone on + the host. +- `INBOUND_ANTISPAM_MILTER` and `INBOUND_JOURNAL_MILTER_SOCKET` are checked + character by character at start; the check looked at their first characters + only. + ### Changed - **Port 25 logs as `postfix/inbound`.** Its lines in the mail log (Server › diff --git a/docs/architecture.md b/docs/architecture.md index 417affb..fe50069 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -28,7 +28,7 @@ Managed programs ([build/supervisord.conf](../build/supervisord.conf)): |---|---|---|---| | `opendkim` | root → `opendkim` (`UserID` in opendkim.conf) | 100 | DKIM signing milter | | `panel` | panel | 200 | HTTP UI + journal-milter + log-tailer + rate-limit recalc; with the inbound relay on also the inbound journal milter | -| `postfix` | root (wrapper) | 300 | MTA — started only after both milter sockets exist | +| `postfix` | root (wrapper) | 300 | MTA — started only after the milter sockets exist (OpenDKIM's, the journal milter's and, with the inbound relay on, the inbound journal milter's) | | `postfix-reload` | root | — | On-demand `postfix reload` (autostart off) | | `cert-reload` | root | 400 | Daily `postfix reload` for renewed TLS certs | | `logrotate` | root | 400 | Periodic `mail.log` rotation | @@ -98,7 +98,8 @@ smtp/inet` removes Debian's stock smtpd). Outbound delivery still uses the ([internal/logtail/inbound.go](../internal/logtail/inbound.go)). A line names one recipient, so a message refused at end-of-message is one row whatever its recipient count, and a line read twice (the tailer saves its - place once a second; an unclean stop can lose that second) is two rows. The + place every five seconds; an unclean stop can lose those seconds) is two + rows. The journal is pruned every six hours: rows older than the `inbound_spam_log_retention_days` setting, then down to 10 000. diff --git a/docs/guide.md b/docs/guide.md index 3c91fb2..4aa7750 100644 --- a/docs/guide.md +++ b/docs/guide.md @@ -870,7 +870,11 @@ seconds of a change - no restart. An entry is a sender address, a sender domain (that domain, not its subdomains) or a client address or network. A denied sender is refused outright. An allowed one is given a weight that no spam score outweighs, so it is accepted - unless a deny entry matches the same -message: **deny wins**, whichever entries they are. The files are readable by +message: **deny wins**, whichever entries they are. **A sender address or +domain on the allow list is not proof of anything**: it is the envelope +sender, which the sending server states and nobody checks, so whoever knows an +allowed address can send as it. Allow a client address or network where you +can. The files are readable by anyone on the host; they hold addresses, not secrets. In the panel the lists are **Inbound › Filter lists** (global role), and what diff --git a/docs/plans/inbound-antispam-panel.md b/docs/plans/inbound-antispam-panel.md index 6fdbf9f..a1a481b 100644 --- a/docs/plans/inbound-antispam-panel.md +++ b/docs/plans/inbound-antispam-panel.md @@ -74,7 +74,9 @@ antispam hook). Without an external filter: - **accept** rows — message relayed (engine `selfpost`, detail empty); - **reject** / **tempfail** rows — from the mail.log tailer (Postfix policy, - size limit, unknown recipient, etc.). + unknown recipient, a sender domain that does not exist. As built, a refusal + whose log line names no recipient - the size limit answered at MAIL FROM - + and the per-client rate limit, which Postfix logs as a warning, make no row). Panel copy explains that rspamd symbols appear only when the antispam milter is configured. @@ -260,7 +262,9 @@ flowchart LR ## Security - Same validation whitelists as inbound relay ([security.md](../security.md)). -- Journal rows contain PII — retention and global-admin-only access. +- Journal rows contain PII — retention, and access by reach: the global role + reads all of it, a `domain` user the rows of assigned inbound domains (as + built; see § RBAC). - Inbound journal milter fail-open must not block mail (backup-MX role). - List map writes injection-safe; deny wins over allow. @@ -312,5 +316,5 @@ Target version cut: **`2.1.0`** (MINOR), after `2.0.0`. One commit per step; - [x] Unit + handler tests — **Composer** (written with each step: store, milter, tailer, lists and their usage, view fixtures held to the outlines, handlers for both roles) - [x] [guide.md](../guide.md), [architecture.md](../architecture.md) — **Composer** (kept up with each step; [security.md](../security.md) follows the security review) - [x] `go vet`, `go test`, e2e if applicable — **Composer** (on the test server for every step; last on `7192c38`: vet ok, 22 packages ok, e2e ok, which relays, refuses, reads the log page and edits a list through the panel) -- [ ] Technical review of inbound antispam changes — **Opus** -- [ ] Security review inbound antispam path — **Fable** +- [x] Technical review of inbound antispam changes — **Opus** (2026-10-12; findings fixed: client address of a connection's later messages, the lists' writer under a lock, the tailer's queue-id memory, hold rows written twice, the cap by time; and, outside the feature, the level-2 limit and client-address list skipped after a connection's first message) +- [x] Security review inbound antispam path — **Fable** (2026-10-12; no Critical or High; HELO-forged journal rows and the six-hourly row cap fixed, three accepted risks recorded in [security.md](../security.md)) diff --git a/docs/roadmap.md b/docs/roadmap.md index 3acd91e..763b540 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -30,7 +30,7 @@ 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 | in progress | 10/12 | [plans/inbound-antispam-panel.md](plans/inbound-antispam-panel.md) | +| inbound-antispam-panel | Inbound antispam journal + allow/deny lists | in progress | 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 | — | — | diff --git a/docs/security.md b/docs/security.md index 8c2af8c..73a6543 100644 --- a/docs/security.md +++ b/docs/security.md @@ -33,7 +33,21 @@ Critical or High finding; a report's size was bounded only as bytes (now 5 000 records, 255 bytes a field), the retention cap was one for the whole server (now per domain), the delivery command could run a hundred at once (now one), and the reason logged for a dropped message carried the sender's bytes as they -came (now cut and reduced to printable ASCII). +came (now cut and reduced to printable ASCII). The 2026-10-12 reviews of +inbound-antispam-panel (`2.1.0`: the inbound journal milter, refusals read from +`mail.log`, the filter lists and their pages) were two, by different models +over the same diff. The technical one (Opus) found, outside the feature and +there since `1.9.0`, that **the level-2 rate limit and an application's +client-address list held only for the first message of a connection** - see +[Mail path](#mail-path-security-relevant) - which was reproduced on the test +stand and fixed. The security one (Fable) found no Critical or High: a client's +HELO name could supply the sender, recipient and reply of a journal row and so +make a refusal look like the deny list's (the reply now ends at Postfix's own +`; from=<`); the journal's row cap was applied only every six hours, between +which refusals were written at whatever rate a stranger sent recipients (the +tailer now cuts to the cap every 500 rows); and three behaviours are recorded +under Accepted risks (verdict headers while the filter is down, the allow list +keyed on an address anyone can claim, the list files readable by anyone). (2) **Accepted risks** — deliberate departures beyond the mandatory, recorded so the decision is not lost. @@ -120,6 +134,8 @@ assigned outbound domains and inbound domains **separately**, each list with | Outbound: domain page, applications, Domain settings (report address, rate limit, export), log | every domain | assigned outbound domains | | Outbound › DMARC reports | every report, with the server's ingest statistics | reports of assigned domains, without the ingest box | | Inbound: domain page, upstream, recipients | every inbound domain | assigned inbound domains | +| Inbound › Log | every row, including those of a domain deleted since | rows of assigned inbound domains (by name), without the links into the filter lists | +| Inbound › Filter lists; the inbound log's retention | yes | no — 404 | | Add or delete a domain, either direction; import a domain | yes | no | | Account, Help | yes | yes | @@ -178,6 +194,32 @@ operator can act on it. refuse unknown addresses at RCPT (no backscatter). OpenDKIM is not attached on inbound. An optional antispam milter is inbound-only; default action is fail-open (`accept`). +- **The panel's milters judge every message of a connection.** Postfix + introduces a client to a milter once per connection, and the milter library + replaces the milter's session after any reply that is not "continue". Until + `2.1.0` the journal milter knew the client's address only from that + introduction, and both of its checks passed a message that came without one: + a second `MAIL FROM` after a refused one, or any message after the first on + one connection, got past the level-2 limit and past an application's + client-address list. Now the address comes with every `MAIL FROM` + (`milter_mail_macros` carries `{client_addr}`), the level-2 limit does not + ask for it at all, an application with a client-address list is refused when + no address is known, and neither milter replies anything but "continue" to a + message it lets through. `test/e2e` sends two `MAIL FROM` on one connection. +- **The inbound journal is written from what strangers send.** The inbound + journal milter is the last on port 25, read-only and attached fail-open; it + keeps of the filter's verdict only what its patterns recognise. Refusals are + parsed from `mail.log` from the head of the line, with the reply ending at + Postfix's own `; from=<` so that the HELO name after it - the client's text, + logged as written - cannot stand in for the sender, the recipient or the + reply; an address with a quote, a bracket or a space in it is not kept. + Only a recipient at an inbound domain makes a row. The journal is cut to + 10 000 rows every 500 rows the tailer writes, and by age every six hours. +- **Filter lists** reach another container as files: values are whitelisted on + the way in (address, domain, canonical IP or network; no `/0`, no + IPv4-mapped network), the writer refuses a stored value with whitespace, a + newline or `#`, and a change of the table and the rewrite of the six files + are one step under a lock. - TLS is mandatory before credentials are transmitted (465 wrapper / 587 `encrypt`). - `TRUSTED_PROXY_CIDR` — only explicitly trusted proxies may supply @@ -295,13 +337,52 @@ deferred item from the roadmap. - **The application auth-IP allow-list is enforced fail-open.** The check runs in the journal milter (`internal/milter/authip.go`) with `default_action=accept` and skips on store errors, so if the milter is down - the restriction is not applied; the SASL login itself always succeeds. This + the restriction is not applied; the SASL login itself always succeeds. + (While the milter is up the list holds for every message, and an unknown + client address is refused - see Mail path; what is accepted here is the + milter being down.) This is documented in [guide.md](guide.md) as **not an authentication boundary** — it is a blast-radius limiter for a leaked application password, on the same fail-open path as level-2 rate limiting, and a milter outage already stops the journal from recording sends at all. The trigger to revisit is a requirement for the allow-list to hold as a security boundary — at which point it must move to the SASL/smtpd layer and fail closed. +- **With the spam filter down, a sender can write his own verdict into the + inbound journal.** The filter is attached fail-open by default, and the + inbound journal milter reads its verdict from two headers. Up, rspamd removes + headers of those names that a sender wrote and adds its own (seen on the + test server: a forged pair was replaced). Down, the sender's pair is all + there is: the row shows his action and score, a forged `quarantine` shows a + hold that never happened, and a forged allow symbol counts as a match of an + allow entry that fits him in Filter lists. Mail is not affected - the + journal decides nothing - and the page that says the filter is down is + Server › Health. Accepted because the alternative is a live check of the + filter on every message for the sake of a monitoring page. Trigger to + revisit: the journal or the match counts being used to decide something + (alerts, automatic removal of entries), or `INBOUND_ANTISPAM_MILTER_ACTION` + staying `accept` on an installation whose filter is often down. +- **An allow entry for a sender address or domain trusts what the sending + server says.** The filter matches the envelope sender, which is not + authenticated: anyone who knows or guesses an allowed address can send as it + and is given the entry's weight, which no spam score outweighs. The page's + Help and the guide say so and recommend an entry for the client's address or + network instead. Deny entries have no such problem - claiming to be a denied + sender only gets mail refused - and deny wins over allow. Trigger to + revisit: allow entries being used as the main way to receive mail from a + sender, at which point the rule should also require the sender's SPF or + DKIM to pass. +- **The filter lists are files readable by anyone on the host.** + `/data/antispam` is 0755 and its six files 0644, unlike the rest of `/data`: + the filter runs under another user in another container. They hold sender + addresses, domains and networks - who the operator blocks and whom he lets + through - but no message data. The inbound journal itself is in the + database, 0640. Trigger to revisit: a shared host, where the sidecar should + instead be given the files through a group it shares with the panel. +- **A row of the inbound log belongs to a domain by name.** A `domain` user + sees the rows whose inbound domain has the name of one assigned to them, so + an inbound domain that is deleted and added again shows its earlier rows to + whoever it is assigned to next. Accepted: the journal is of a mail domain, + and the rows age out with the retention. - **Level-2 in-flight reservations can outlive a dropped SMTP session until TTL.** The journal milter cannot observe connection-close directly through go-milter, so if a client disconnects without an explicit `Abort`, its diff --git a/internal/inbound/lists.go b/internal/inbound/lists.go index 9d08181..edd6b98 100644 --- a/internal/inbound/lists.go +++ b/internal/inbound/lists.go @@ -7,6 +7,7 @@ import ( "path/filepath" "sort" "strings" + "sync" "time" "unicode/utf8" @@ -33,6 +34,12 @@ type ListStore interface { type Lists struct { store ListStore dir string + // mu makes a change of the table and the rewrite of the files one step. + // Two requests at once could otherwise write the files in the other order + // than they changed the table - the first to read the entries being the + // last to write them - and leave the filter with an entry the page no + // longer lists. One Lists serves the panel, so a mutex is enough. + mu sync.Mutex } // NewLists builds the filter lists over the store and the map directory @@ -76,31 +83,63 @@ func (l *Lists) Add(list, kind, rawValue, rawNote string) (store.SpamListEntry, if err != nil { return store.SpamListEntry{}, err } + l.mu.Lock() + defer l.mu.Unlock() e, err := l.store.AddSpamListEntry(list, kind, value, note) if err != nil { return store.SpamListEntry{}, err } - if err := l.Sync(); err != nil { + if err := l.sync(); err != nil { // An entry the filter never got is worse than no entry: the page - // would show a rule that does nothing. + // would show a rule that does nothing. The files are written again + // after the row is taken back, since some of the six may already + // hold it; if that fails too, the next change or start puts it right. _ = l.store.DeleteSpamListEntry(e.ID) + _ = l.sync() return store.SpamListEntry{}, err } return e, nil } -// Delete removes an entry and rewrites the maps. +// Delete removes an entry and rewrites the maps. If the maps cannot be +// written the entry is put back: an entry that is gone from the page and +// still in the filter's file could not even be removed a second time. func (l *Lists) Delete(id int64) error { + l.mu.Lock() + defer l.mu.Unlock() + entries, err := l.store.ListSpamListEntries() + if err != nil { + return err + } + var gone *store.SpamListEntry + for i := range entries { + if entries[i].ID == id { + gone = &entries[i] + } + } if err := l.store.DeleteSpamListEntry(id); err != nil { return err } - return l.Sync() + if err := l.sync(); err != nil { + if gone != nil { + _, _ = l.store.AddSpamListEntry(gone.List, gone.Kind, gone.Value, gone.Note) + } + return err + } + return nil } // Sync writes all six map files from SQLite, each atomically, so the filter // reads a whole old file or a whole new one. Every file is written even when // empty: the filter's configuration names all six. func (l *Lists) Sync() error { + l.mu.Lock() + defer l.mu.Unlock() + return l.sync() +} + +// sync is Sync for a caller that holds mu. +func (l *Lists) sync() error { entries, err := l.store.ListSpamListEntries() if err != nil { return err diff --git a/internal/logtail/inbound.go b/internal/logtail/inbound.go index 77aaeea..07decbf 100644 --- a/internal/logtail/inbound.go +++ b/internal/logtail/inbound.go @@ -34,6 +34,9 @@ type Inbound struct { // postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from mx.example.net[203.0.113.9]: 550 5.1.1 : Recipient address rejected: User unknown in relay recipient table; from= to= proto=ESMTP helo= // postfix/cleanup[52]: 4A1B2C3D: milter-reject: END-OF-MESSAGE from mx.example.net[203.0.113.9]: 5.7.1 Spam message rejected; from= to= proto=ESMTP helo= // +// A message the filter holds (milter-hold) is not read here: it goes on to the +// inbound journal milter, which writes its row with the subject. +// // The first is Postfix's own policy, written by the port-25 smtpd, which // build/postfix-config.sh names postfix/inbound so that its lines are told // from those of the submission ports. The second is the filter's verdict at @@ -45,9 +48,20 @@ type Inbound struct { // name: the tail of such a line is the sender's own words (HELO name, // addresses), and a pattern that could start anywhere would let him write // journal rows. +// +// For the same reason the reply is the shortest text before "; from=<", and +// the HELO name - the last thing on the line, which Postfix logs as the client +// wrote it, spaces and brackets included - is whatever is left. Taking the +// longest reply instead would let a HELO name that itself spells +// "; from=<…> to=<…> proto=…" supply the sender, the recipient and the reply +// of the row (security review, 2026-10-12). var ( - inboundRejectRe = regexp.MustCompile(`^\S+ postfix/(inbound/smtpd|cleanup)\[\d+\]: ([0-9A-Za-z]+): (reject|milter-reject|milter-hold|milter-discard): \S+ from [^\[\s]*\[([0-9A-Fa-f:.]+)\]: (.*); from=<([^>]*)> to=<([^>]*)> proto=\S+(?: helo=<[^>]*>)?$`) + inboundRejectRe = regexp.MustCompile(`^\S+ postfix/(inbound/smtpd|cleanup)\[\d+\]: ([0-9A-Za-z]+): (reject|milter-reject|milter-discard): \S+ from [^\[\s]*\[([0-9A-Fa-f:.]+)\]: (.*?); from=<([^>]*)> to=<([^>]*)> proto=\S+(?: helo=<.*>)?$`) inboundClientRe = regexp.MustCompile(`^\S+ postfix/inbound/smtpd\[\d+\]: ([0-9A-Za-z]+): client=`) + // A queue id stops being port 25's when the message is queued (qmgr takes + // it: the filter let it through) or when another listener opens a message + // under the same id - Postfix reuses ids. + inboundForgetRe = regexp.MustCompile(`^\S+ postfix/(?:qmgr\[\d+\]: ([0-9A-Za-z]+): from=|(?:[a-z0-9-]+/)?smtpd\[\d+\]: ([0-9A-Za-z]+): client=)`) ) // A row holds one line of reason; Postfix's reply text carries the far end's @@ -55,21 +69,40 @@ var ( const inboundDetailMax = 255 // inboundQueueIDs is how many port-25 queue ids are remembered while waiting -// for cleanup's verdict line on them. A message is in that state for the -// seconds its DATA takes; the cap only bounds a flood. +// for cleanup's verdict line on them. An id is forgotten when the verdict +// comes, when the message is queued, or when another listener reuses it; the +// cap bounds what is left - messages the client abandoned - and a flood. const inboundQueueIDs = 4096 +// inboundPruneEvery is how many rows the tailer writes before it has the +// journal cut back to its row cap, without waiting for the six-hourly prune. +// Refusals are written at the rate strangers send RCPT TO, which no limit of +// Postfix's counts, so between two prunes the journal would otherwise grow as +// fast as someone cared to make it. +const inboundPruneEvery = 500 + // inboundJournal is the per-run state of the inbound half. type inboundJournal struct { st InboundStore - // port25 holds the queue ids the port-25 smtpd opened and cleanup has not - // reported on yet; order is their arrival, for dropping the oldest. - port25 map[string]struct{} - order []string + // port25 holds the queue ids the port-25 smtpd opened and nobody has + // accounted for yet, each with the number of its arrival; order is those + // arrivals, for dropping the oldest. An id that was forgotten and opened + // again is in order twice: the number tells the stale entry from the live + // one when the stale one comes up for dropping. + port25 map[string]uint64 + order []queued + seq uint64 + // written counts the rows since the journal was last cut to its cap. + written int +} + +type queued struct { + id string + seq uint64 } func newInboundJournal(st InboundStore) *inboundJournal { - return &inboundJournal{st: st, port25: make(map[string]struct{})} + return &inboundJournal{st: st, port25: make(map[string]uint64)} } // handle looks at one mail.log line and writes a journal row when it is a @@ -80,11 +113,23 @@ func (j *inboundJournal) handle(line string, now time.Time) { j.remember(m[1]) return } + if m := inboundForgetRe.FindStringSubmatch(rest); m != nil { + delete(j.port25, m[1]+m[2]) + return + } m := inboundRejectRe.FindStringSubmatch(rest) if m == nil { return } program, queueID, kind, clientIP, reason, from, to := m[1], m[2], m[3], m[4], m[5], m[6], m[7] + // The sender's address is his own text too, and with a quoted local part it + // may hold "> to=<…> proto=…" - which would end the sender early and supply + // the recipient. Such a line shows it: the sender is left with an unclosed + // quote. An address with a quote, a bracket or a space in it is not one the + // journal keeps. + if strings.ContainsAny(from, "\"<> ") || strings.ContainsAny(to, "\"<> ") { + return + } if program == "cleanup" { if _, ok := j.port25[queueID]; !ok { return // a submission-port message, or one opened before this run @@ -121,11 +166,8 @@ func (j *inboundJournal) handle(line string, now time.Time) { Detail: printable(reason, inboundDetailMax), At: at, } - switch { - case kind == "reject": + if kind == "reject" { e.Engine = store.SpamEnginePostfix - case kind == "milter-hold": - e.Decision = store.SpamDecisionQuarantine } // "450 4.7.1 …" from Postfix, "4.7.1 …" from a milter: either way a reply // that starts with 4 asks the sender to come back. @@ -134,6 +176,14 @@ func (j *inboundJournal) handle(line string, now time.Time) { } if err := j.st.InsertInboundSpam(e); err != nil { log.Printf("log-tailer: inbound journal: record %s -> %s: %v", from, to, err) + return + } + if j.written++; j.written >= inboundPruneEvery { + j.written = 0 + // The zero time removes nothing by age: this is the cap alone. + if _, err := j.st.PruneInboundSpam(time.Time{}, inboundSpamLogMaxRows); err != nil { + log.Printf("log-tailer: inbound journal: cut to %d rows: %v", inboundSpamLogMaxRows, err) + } } } @@ -141,12 +191,16 @@ func (j *inboundJournal) remember(queueID string) { if _, ok := j.port25[queueID]; ok { return } - if len(j.order) >= inboundQueueIDs { - delete(j.port25, j.order[0]) + for len(j.order) >= inboundQueueIDs { + oldest := j.order[0] j.order = j.order[1:] + if j.port25[oldest.id] == oldest.seq { + delete(j.port25, oldest.id) + } } - j.port25[queueID] = struct{}{} - j.order = append(j.order, queueID) + j.seq++ + j.port25[queueID] = j.seq + j.order = append(j.order, queued{queueID, j.seq}) } // printable cuts s to max bytes and replaces everything outside printable diff --git a/internal/logtail/inbound_test.go b/internal/logtail/inbound_test.go index 950fce2..8da41f8 100644 --- a/internal/logtail/inbound_test.go +++ b/internal/logtail/inbound_test.go @@ -106,7 +106,6 @@ func TestInboundMilterVerdictNeedsAPort25QueueID(t *testing.T) { func TestInboundMilterDecisions(t *testing.T) { for kind, c := range map[string]struct{ reply, decision string }{ "milter-reject": {"4.7.1 Try again later", store.SpamDecisionTempfail}, - "milter-hold": {"milter triggers HOLD action", store.SpamDecisionQuarantine}, "milter-discard": {"milter triggers DISCARD action", store.SpamDecisionReject}, } { j, st := inboundFixture() @@ -128,7 +127,7 @@ func TestInboundIgnores(t *testing.T) { "a connect line": head + "postfix/inbound/smtpd[41]: connect from mx.example.net[203.0.113.9]", // The HELO name is the sender's; a line cannot be started from inside one. "a refusal spelled inside another line": head + "postfix/inbound/smtpd[41]: warning: hostname x does not resolve: mail postfix/inbound/smtpd[1]: NOQUEUE: reject: RCPT from x[203.0.113.9]: 550 no; from= to= proto=ESMTP helo=", - "an address with a bracket in it": head + "postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from x[203.0.113.9]: 550 no; from= to= proto=X helo=@example.net> to= proto=ESMTP helo=", + "an address with a bracket in it": head + "postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from x[203.0.113.9]: 554 5.7.1 : Relay access denied; from=<\"a> to= proto=X helo= to= proto=ESMTP helo=", } { j, st := inboundFixture() j.handle(line, tailNow) @@ -159,6 +158,95 @@ func TestInboundLookupFailureLeavesNoRow(t *testing.T) { } } +// A message the filter holds goes on to the inbound journal milter, which +// writes its row; a second one from the log would be the same message twice. +func TestInboundHoldIsTheMiltersRow(t *testing.T) { + j, st := inboundFixture() + j.handle(head+"postfix/inbound/smtpd[41]: Q1: client=mx.example.net[203.0.113.9]", tailNow) + j.handle(head+"postfix/cleanup[52]: Q1: milter-hold: END-OF-MESSAGE from mx.example.net[203.0.113.9]: milter triggers HOLD action; from= to= proto=ESMTP helo=", tailNow) + if len(st.rows) != 0 { + t.Errorf("rows = %+v", st.rows) + } +} + +// The HELO name is the last thing on the line and is logged as the client +// wrote it. It cannot supply the row: the reply ends at the first "; from=<", +// which is Postfix's own. +func TestInboundHeloCannotWriteTheRow(t *testing.T) { + j, st := inboundFixture() + j.handle(head+"postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from x[203.0.113.9]: 550 5.1.1 : Recipient address rejected: User unknown in relay recipient table; from= to= proto=ESMTP helo= to= proto=ESMTP helo=", tailNow) + if len(st.rows) != 1 { + t.Fatalf("rows = %+v", st.rows) + } + got := st.rows[0] + if got.From != "real@example.net" || got.To != "nobody@in.example.com" || + got.Detail != "550 5.1.1 : Recipient address rejected: User unknown in relay recipient table" { + t.Errorf("row = %+v", got) + } + + // A HELO name with a closing bracket in it does not lose the line either. + j, st = inboundFixture() + j.handle(head+"postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from x[203.0.113.9]: 550 5.1.1 : no; from= to= proto=ESMTP helo=b>", tailNow) + if len(st.rows) != 1 || st.rows[0].From != "real@example.net" { + t.Errorf("rows = %+v", st.rows) + } + + // The same on a verdict line: the filter's reply is not extended by the + // HELO name, so a stranger cannot make a refusal look like the deny list's. + j, st = inboundFixture() + j.handle(head+"postfix/inbound/smtpd[41]: Q1: client=x[203.0.113.9]", tailNow) + j.handle(head+"postfix/cleanup[52]: Q1: milter-reject: END-OF-MESSAGE from x[203.0.113.9]: 5.7.1 Spam message rejected; from= to= proto=ESMTP helo= to= proto=ESMTP helo=", tailNow) + if len(st.rows) != 1 || st.rows[0].Detail != "5.7.1 Spam message rejected" || st.rows[0].From != "real@example.net" { + t.Errorf("rows = %+v", st.rows) + } +} + +// A queue id is port 25's only until the message is queued or the id is +// opened again by another listener - Postfix reuses ids. +func TestInboundQueueIDIsForgotten(t *testing.T) { + const verdict = "postfix/cleanup[52]: Q1: milter-reject: END-OF-MESSAGE from app[203.0.113.4]: 4.7.1 Service unavailable - try again later; from= to= proto=ESMTP helo=" + for name, forget := range map[string]string{ + "queued": "postfix/qmgr[58]: Q1: from=, size=600, nrcpt=1 (queue active)", + "reused by the submission port": "postfix/smtpd[20]: Q1: client=app.example.com[203.0.113.4], sasl_method=PLAIN, sasl_username=app", + } { + j, st := inboundFixture() + j.handle(head+"postfix/inbound/smtpd[41]: Q1: client=mx.example.net[203.0.113.9]", tailNow) + j.handle(head+forget, tailNow) + j.handle(head+verdict, tailNow) + if len(st.rows) != 0 || len(j.port25) != 0 { + t.Errorf("%s: rows %+v, remembered %v", name, st.rows, j.port25) + } + } +} + +// An id that was forgotten and opened again is not dropped by its own stale +// place in the queue of arrivals. +func TestInboundStaleArrivalDoesNotDropALiveID(t *testing.T) { + j, _ := inboundFixture() + j.remember("Q1") + delete(j.port25, "Q1") // its verdict came + for i := 0; i < inboundQueueIDs-2; i++ { + j.remember("F" + time.Duration(i).String()) + } + j.remember("Q1") // reused; order is now full, with the stale Q1 first + j.remember("LAST") + if _, ok := j.port25["Q1"]; !ok { + t.Error("the live Q1 was dropped by its stale arrival") + } +} + +// Between the six-hourly prunes the tailer has the journal cut to its cap +// itself, every so many rows: refusals come at the rate strangers send them. +func TestInboundCutsTheJournalAsItWrites(t *testing.T) { + j, st := inboundFixture() + for i := 0; i < inboundPruneEvery*2+10; i++ { + j.handle(unknownRcp, tailNow) + } + if len(st.pruned) != 2 || st.pruned[0] != inboundSpamLogMaxRows { + t.Errorf("cuts = %v, want two, to %d rows", st.pruned, inboundSpamLogMaxRows) + } +} + // The queue ids waiting for a verdict are bounded. func TestInboundQueueIDsAreBounded(t *testing.T) { j, _ := inboundFixture() diff --git a/internal/logtail/offset.go b/internal/logtail/offset.go index 0b965cd..6f34024 100644 --- a/internal/logtail/offset.go +++ b/internal/logtail/offset.go @@ -20,8 +20,10 @@ const ( // which os.SameFile cannot answer across a restart. fingerprintSize = 512 // persistInterval throttles the offset write. Losing up to this much - // progress on a crash only means re-parsing a few lines (UpdateStatus is - // idempotent), which is much cheaper than a database write per poll tick. + // progress on a crash means re-parsing a few lines, which is much cheaper + // than a database write per poll tick. For a delivery status that changes + // nothing (UpdateStatus is idempotent); a refusal in those lines gets a + // second row in the inbound journal. persistInterval = 5 * time.Second ) @@ -46,8 +48,9 @@ type tracker struct { // state whose fingerprint still matches means continue from it, parsing the // tail written while the panel was down; anything else means the file is not // the one the offset referred to (rotated, recreated or truncated in the -// meantime), so read it from the start. Re-parsing lines already seen is -// harmless: UpdateStatus writes the same status onto the same row. +// meantime), so read it from the start. Re-parsing lines already seen writes +// the same status onto the same send-log row, and a second inbound journal +// row for a refusal among them. func (t *tracker) resume(f *os.File) int64 { size, err := fileSize(f) if err != nil { diff --git a/internal/store/inboundspam.go b/internal/store/inboundspam.go index 851addf..cad1fa5 100644 --- a/internal/store/inboundspam.go +++ b/internal/store/inboundspam.go @@ -21,7 +21,7 @@ const ( // CHECK constraint of inbound_spam_log. const ( SpamEngineRspamd = "rspamd" // the external filter - SpamEnginePostfix = "postfix" // Postfix's own policy: unknown recipient, size, rate + SpamEnginePostfix = "postfix" // Postfix's own policy: an unknown recipient, a sender domain that does not exist SpamEngineSelfPost = "selfpost" // nobody: relayed with no filter attached ) @@ -71,9 +71,11 @@ func (s *Store) PruneInboundSpam(cutoff time.Time, keep int) (int64, error) { return 0, fmt.Errorf("prune inbound_spam_log by age: %w", err) } n, _ := res.RowsAffected() + // Oldest by when it happened, not by id: the tailer dates a refusal by its + // log line, so after the panel was down the newest ids are old rows. res, err = s.db.Exec( - `DELETE FROM inbound_spam_log WHERE id <= - (SELECT id FROM inbound_spam_log ORDER BY id DESC LIMIT 1 OFFSET ?)`, keep) + `DELETE FROM inbound_spam_log WHERE id IN + (SELECT id FROM inbound_spam_log ORDER BY created_at DESC, id DESC LIMIT -1 OFFSET ?)`, keep) if err != nil { return n, fmt.Errorf("prune inbound_spam_log by count: %w", err) } diff --git a/internal/store/inboundspam_test.go b/internal/store/inboundspam_test.go index c402000..f4d4244 100644 --- a/internal/store/inboundspam_test.go +++ b/internal/store/inboundspam_test.go @@ -284,3 +284,29 @@ func TestListSpamListHits(t *testing.T) { t.Errorf("no marks: %v, %v", hits, err) } } + +// The cap removes the oldest by when it happened. After the panel was down the +// tailer writes old refusals with the newest ids, and they are not what stays. +func TestPruneInboundSpamCapIsByTime(t *testing.T) { + st := openTestStore(t) + now := time.Now().UTC() + for _, r := range []struct { + to string + age time.Duration + }{{"new-1", time.Minute}, {"new-2", 2 * time.Minute}, {"backdated-old", 5 * time.Hour}} { + err := st.InsertInboundSpam(InboundSpamEntry{ + InboundDomain: "in.example.com", ClientIP: "203.0.113.7", To: r.to, + Decision: SpamDecisionReject, Engine: SpamEnginePostfix, At: now.Add(-r.age), + }) + if err != nil { + t.Fatal(err) + } + } + if n, err := st.PruneInboundSpam(time.Time{}, 2); err != nil || n != 1 { + t.Fatalf("prune = %d, %v", n, err) + } + rows, err := st.QueryInboundSpam(InboundSpamFilter{}, 10, 0) + if err != nil || len(rows) != 2 || rows[0].To != "new-1" || rows[1].To != "new-2" { + t.Errorf("left = %+v, %v; want the two newest by time", rows, err) + } +} diff --git a/internal/web/view/help.go b/internal/web/view/help.go index 2a206f4..a0d121c 100644 --- a/internal/web/view/help.go +++ b/internal/web/view/help.go @@ -201,7 +201,7 @@ var inboundTopics = []HelpTopic{ ", so its row has no subject, and a message refused after its text was sent is one row however many recipients it had. A refusal to relay for a domain that is not an inbound one is every scanner on the internet and is not recorded. Rows are kept for the number of days set in Settings, and never more than 10 000."), }}, {ID: HelpFilterLists, Title: "Filter lists", Body: []Text{ - Rich("Two lists for the whole server that correct the spam filter by hand. An entry is a sender address, a sender domain — that domain, not its subdomains — or a client address or network in CIDR form. A sender on the Deny list is refused outright. A sender on the Allow list is given a weight no spam score outweighs, so the filter lets it through. When entries of both lists match one message, ", + Rich("Two lists for the whole server that correct the spam filter by hand. An entry is a sender address, a sender domain — that domain, not its subdomains — or a client address or network in CIDR form. A sender on the Deny list is refused outright. A sender on the Allow list is given a weight no spam score outweighs, so the filter lets it through. The sender's address is whatever the sending server says it is - anyone can claim to be a sender you allow - so allow a client address or network where you can, and a sender address only for mail you would rather receive forged than lose. When entries of both lists match one message, ", Strong("Deny wins"), ".", Br(), Br(), "SelfPost does not apply the lists itself: it writes them as files under ", Code("/data/antispam/"), diff --git a/internal/web/view/inbound_log.go b/internal/web/view/inbound_log.go index d29f93c..840f510 100644 --- a/internal/web/view/inbound_log.go +++ b/internal/web/view/inbound_log.go @@ -146,7 +146,7 @@ func (p *InLog) NewRow(in InLogRowInput) InLogRow { Time: FormatLogTime(in.At), From: orDash(in.From), Client: in.Client, To: in.To, Subject: in.Subject, Why: Sheet{ ID: "why-" + strconv.FormatInt(in.ID, 10), Tag: Tag{Status: in.Decision}, Title: "Why", - Rows: whyRows(in.Engine, in.Detail, in.Subject), + Rows: whyRows(in.Decision, in.Engine, in.Detail, in.Subject), }, } if p.IsGlobal { @@ -157,15 +157,15 @@ func (p *InLog) NewRow(in InLogRowInput) InLogRow { // whyRows is the content of a row's sheet: who decided, what they said, and // the subject whole, which the table clips. What was said has one of two -// shapes, told apart by how it starts. The inbound journal milter writes the -// filter's verdict on mail that passed - an action and a score, then the -// symbols after a semicolon. The log tailer writes the reply a refusal was -// given, which starts with its code. -func whyRows(engine, detail, subject string) []SheetRow { +// shapes, and the decision says which. Mail that passed was written by the +// inbound journal milter with the filter's verdict - an action and a score, +// then the symbols after a semicolon. Mail that was refused or put off was +// read from mail.log by the tailer, with the reply it was given. +func whyRows(decision, engine, detail, subject string) []SheetRow { rows := []SheetRow{{Label: "Decided by", Lines: []string{engine}}} switch { case detail == "": - case detail[0] >= '0' && detail[0] <= '9': + case decision == "reject" || decision == "tempfail": rows = append(rows, SheetRow{Label: "Reply", Lines: []string{detail}, Mono: true}) default: verdict, symbols, _ := strings.Cut(detail, "; ") diff --git a/internal/web/view/inbound_log_test.go b/internal/web/view/inbound_log_test.go index eca5273..ed7dd83 100644 --- a/internal/web/view/inbound_log_test.go +++ b/internal/web/view/inbound_log_test.go @@ -284,18 +284,20 @@ func TestWhyRows(t *testing.T) { } return strings.Join(out, "; ") } - for _, c := range []struct{ engine, detail, subject, want string }{ - {"selfpost", "", "", "Decided by=selfpost"}, - {"selfpost", "", "Hello", "Decided by=selfpost; Subject=Hello"}, - {"rspamd", "no action, score 0.40 / 15.00", "Hi", "Decided by=rspamd; Verdict=no action, score 0.40 / 15.00; Subject=Hi"}, - {"rspamd", "add header, score 9.80 / 15.00; A(5.00) B(-0.10)", "", "Decided by=rspamd; Verdict=add header, score 9.80 / 15.00; Symbols=A(5.00)|B(-0.10)"}, + for _, c := range []struct{ decision, engine, detail, subject, want string }{ + {"accept", "selfpost", "", "", "Decided by=selfpost"}, + {"accept", "selfpost", "", "Hello", "Decided by=selfpost; Subject=Hello"}, + {"accept", "rspamd", "no action, score 0.40 / 15.00", "Hi", "Decided by=rspamd; Verdict=no action, score 0.40 / 15.00; Subject=Hi"}, + {"accept", "rspamd", "add header, score 9.80 / 15.00; A(5.00) B(-0.10)", "", "Decided by=rspamd; Verdict=add header, score 9.80 / 15.00; Symbols=A(5.00)|B(-0.10)"}, // a verdict with symbols and no action or score - {"rspamd", "A(5.00)", "", "Decided by=rspamd; Verdict=A(5.00)"}, - {"rspamd", "5.7.1 Spam message rejected", "", "Decided by=rspamd; Reply=5.7.1 Spam message rejected"}, - {"postfix", "450 4.1.8 : Sender address rejected; see x", "", "Decided by=postfix; Reply=450 4.1.8 : Sender address rejected; see x"}, + {"quarantine", "rspamd", "A(5.00)", "", "Decided by=rspamd; Verdict=A(5.00)"}, + {"reject", "rspamd", "5.7.1 Spam message rejected", "", "Decided by=rspamd; Reply=5.7.1 Spam message rejected"}, + {"tempfail", "postfix", "450 4.1.8 : Sender address rejected; see x", "", "Decided by=postfix; Reply=450 4.1.8 : Sender address rejected; see x"}, + // a refusal's text is a reply whatever it starts with + {"reject", "rspamd", "milter triggers DISCARD action", "", "Decided by=rspamd; Reply=milter triggers DISCARD action"}, } { - if got := flat(whyRows(c.engine, c.detail, c.subject)); got != c.want { - t.Errorf("whyRows(%q, %q, %q)\n got: %s\nwant: %s", c.engine, c.detail, c.subject, got, c.want) + if got := flat(whyRows(c.decision, c.engine, c.detail, c.subject)); got != c.want { + t.Errorf("whyRows(%q, %q, %q, %q)\n got: %s\nwant: %s", c.decision, c.engine, c.detail, c.subject, got, c.want) } } }