From af130e268a511a1166aaae04f4b456e1670576b3 Mon Sep 17 00:00:00 2001 From: Mix Date: Wed, 14 Oct 2026 18:38:22 +0300 Subject: [PATCH] findings of the reviews of audit stage 2b MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Technical review (Opus) and security review (Fable) of 5be109b..5154bba; reports in the session's scratchpad. Nothing above low from security; one bug and three risks from the technical review. Migration 0009 is not deployed, so it was extended. - Bug: two refusals of one second swapped their NOQUEUE lines (each line went to the newest lineless row). AttachRefusalLine now matches the client address too (send_log.client_ip, written by the journal milter - Postfix's line names the client and the sender, never the login: the sasl_username part of the pattern never matched and could be fed by HELO, security F1/F2), takes the nearest row in time and the oldest of equals, and a line already on a row goes on no other (security F6). - Waiting lines and recoveries lived only in memory while the saved offset moved past them: a stop within 30 s lost them. The tracker now never saves an offset past the oldest waiting item in its file (tracker.hold, refusalLines.oldest) - for a recovery, the client= line that names its login - so they are read again; the "once" guards make that harmless. - A recovered row whose login the tailer did not see was nobody's: its domain_id falls back to the envelope domain's. - The fingerprint's file identity is the inode alone: the device number can change across a host reboot and make the same log look rotated. - A refused row carries its queue id; UpdateStatus's "newest row" now skips refused rows, so a later message with that id does not flip it to sent. - The alive mark: its age is read first and kept from then on, so asking supervisord for 30 s cannot make it stale; the entrypoint removes it with the sockets - a container restart is not the check's downtime, and a mark from before would have counted the whole outage as "≈". - Security F3: the sender check prints no ";" of the client's in the From: text of its reply, and the tailer reads the envelope after the first ";" - Postfix's own text. - A refused row with a queue id and no stored lines says so (it was told the mail.log text of 2.2.0); the fact's em dash is the house hyphen. - Docs: architecture (client address, no login), guide § Health (warns on either count), help topics log and sender-check (design 1ca87f2). - e2e: refusals_show_postfixs_line wants the refusal's own sender in the line; refusal_recovered_from_the_log waits past the tailer's 30 s and checks that a refusal the panel wrote got no recovered twin. Not changed, written down: review 9 (mail.log.1 read to its end at that moment; postlogd may still write to it until the reload), 10 (a log under 512 bytes has no fingerprint, so places fall back to time briefly after a rotation), 6 (a 451 at MAIL FROM of another milter reads the same - the client and sender must match too now), security F5/F12 (info). Review 12: the refused and closed-by-the-panel variants of out-message were shown to the owner as pictures of the real templates, not drawn in out-message.html: the guard ties every drawn screen to a page of the engine, and a variant has the page's outline. Evidence on the test server for this tree: go vet clean, go test ./... 23 packages ok, make e2e exit 0 (refusal_recovered_from_the_log 70 s). Co-Authored-By: Claude Opus 5.5 --- build/entrypoint.sh | 7 +- cmd/panel/sendercheck.go | 25 +++--- cmd/panel/sendercheck_test.go | 14 +--- docs/architecture.md | 8 +- docs/guide.md | 2 +- internal/logtail/fileid_unix.go | 11 ++- internal/logtail/logtail.go | 5 +- internal/logtail/offset.go | 19 ++++- internal/logtail/refusals.go | 78 +++++++++++++----- internal/logtail/refusals_test.go | 48 +++++++++-- internal/milter/ratelimit.go | 1 + internal/milter/sender.go | 5 ++ .../store/migrations/0009_refusal_line.sql | 6 ++ internal/store/refusal_test.go | 80 +++++++++++++------ internal/store/schema_test.go | 2 +- internal/store/sendlog.go | 52 +++++++----- internal/web/handlers/handlers_monitor.go | 3 + internal/web/handlers/handlers_users_test.go | 4 +- internal/web/view/help.go | 4 +- internal/web/view/outbound_log.go | 2 +- internal/web/view/outbound_log_test.go | 2 +- test/e2e/sender_check_test.go | 33 ++++++-- 22 files changed, 295 insertions(+), 116 deletions(-) diff --git a/build/entrypoint.sh b/build/entrypoint.sh index bda3199..15e4419 100644 --- a/build/entrypoint.sh +++ b/build/entrypoint.sh @@ -156,8 +156,11 @@ chmod 2750 /run/opendkim /run/selfpost # A container that was killed leaves its sockets behind, and a file nobody # listens on would satisfy postfix-wrapper.sh's wait: Postfix would start # before the sender check does and defer mail until it is there. The check's -# alive mark stays - it is how the downtime of a restart is told. -rm -f /run/opendkim/*.sock /run/selfpost/*.sock +# alive mark goes too: it tells the downtime of the panel restarting inside a +# running container, and a restart of the whole container is not the check's +# downtime (guide § Health) - a mark left from before would count the whole +# outage when supervisord cannot say since when Postfix runs. +rm -f /run/opendkim/*.sock /run/selfpost/*.sock /run/selfpost/*.alive # Generate the outbound-relay Postfix configuration from the environment (spec # 5). Kept out of the image build so cert paths, rate limits, hostname and the diff --git a/cmd/panel/sendercheck.go b/cmd/panel/sendercheck.go index 5de8f50..05896ae 100644 --- a/cmd/panel/sendercheck.go +++ b/cmd/panel/sendercheck.go @@ -33,13 +33,21 @@ func serveSenderCheck(ctx context.Context, cfg config, st *store.Store) error { // Statistics are the database's business and supervisord's, and the check // is neither: they are kept beside it, and nothing of them is waited for // before it serves. + now := time.Now() + mark := cfg.senderSocket + ".alive" + // The mark's age is read before the mark is kept again: asking supervisord + // may take half a minute, and the mark must not go stale meanwhile, or a + // restart in that half minute would count it as downtime. + var markAt time.Time + if fi, err := os.Stat(mark); err == nil { + markAt = fi.ModTime() + } + go keepAlive(ctx, mark, st) go func() { - now := time.Now() - mark := cfg.senderSocket + ".alive" if err := st.StartSenderCheckStats(now); err != nil { log.Printf("sender-check: statistics: %v", err) } - if down, estimated := senderCheckDowntime(mark, now, postfixStarted); down > 0 { + if down, estimated := senderCheckDowntime(markAt, now, postfixStarted); down > 0 { if estimated { log.Printf("sender-check: was not answering for at most %s (supervisord did not say since when Postfix ran)", down.Round(time.Second)) } else { @@ -51,7 +59,6 @@ func serveSenderCheck(ctx context.Context, cfg config, st *store.Store) error { } } } - keepAlive(ctx, mark, st) }() // The two tables the mail path itself goes by: whom Postfix lets send as @@ -69,19 +76,19 @@ type postfixState struct { } // senderCheckDowntime is for how long the check was not serving before now -// while Postfix was: the time since the mark at path was last set, or since +// while Postfix was: the time since the mark was last set (markAt; zero +// when there is none), or since // Postfix started if that was later. No mark means the container is new, and // a Postfix that is not running means mail was stopped for another reason - // a rollout, a reboot - and neither is the check's downtime. When supervisord // could not say, the time since the mark is taken and estimated is true: an // upper bound, since Postfix may not have been running all of it (audit // 2026-10-12, stage 2b - until then such a start counted nothing). -func senderCheckDowntime(path string, now time.Time, ask func() postfixState) (down time.Duration, estimated bool) { - fi, err := os.Stat(path) - if err != nil { +func senderCheckDowntime(markAt, now time.Time, ask func() postfixState) (down time.Duration, estimated bool) { + if markAt.IsZero() { return 0, false } - from := fi.ModTime() + from := markAt p := ask() switch { case !p.known: diff --git a/cmd/panel/sendercheck_test.go b/cmd/panel/sendercheck_test.go index a2f6452..df03724 100644 --- a/cmd/panel/sendercheck_test.go +++ b/cmd/panel/sendercheck_test.go @@ -1,8 +1,6 @@ package main import ( - "os" - "path/filepath" "testing" "time" ) @@ -13,16 +11,8 @@ import ( // that time. func TestSenderCheckDowntime(t *testing.T) { now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC) - mark := filepath.Join(t.TempDir(), "sender.sock.alive") - set := func(at time.Time) { - t.Helper() - if err := os.WriteFile(mark, nil, 0o644); err != nil { - t.Fatal(err) - } - if err := os.Chtimes(mark, at, at); err != nil { - t.Fatal(err) - } - } + var mark time.Time // the alive mark's time; zero is no mark + set := func(at time.Time) { mark = at } postfix := func(started time.Time, running bool) func() postfixState { return func() postfixState { return postfixState{started: started, running: running, known: true} } } diff --git a/docs/architecture.md b/docs/architecture.md index d4ca974..373ba64 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -422,9 +422,11 @@ judged); the sender check writes it on the row, and the message's page shows the lines stored under it - only those of the minutes around the refusal, since Postfix frees the id at once. A message the journal milter refused at `MAIL FROM` has none: the tailer reads smtpd's `NOQUEUE: milter-reject: MAIL -from …; from=<…>` and puts it on the newest refused row of that sender (and -login, when the line names it) within two minutes (`send_log.refusal_line`), -retrying for 30 s when the row is not written yet. The sender check writes its +from [
]: …; from=<…>` - it names no login - and puts it on +the newest refused row of that client address and sender within two minutes +(`send_log.refusal_line`; the milter writes `send_log.client_ip`), retrying +for 30 s when the row is not written yet; a line already on a row goes on no +other. The sender check writes its row through a buffer after answering 550; a panel stopped in between wrote none. The tailer remembers each queue id's login from smtpd's `client=` line, and 30 s after cleanup's `milter-reject: END-OF-MESSAGE … 5.7.1 From:` line it diff --git a/docs/guide.md b/docs/guide.md index 199eafd..932626d 100644 --- a/docs/guide.md +++ b/docs/guide.md @@ -414,7 +414,7 @@ readings, in the order of what stops mail first: is one the panel stopped answering for after it had begun. A time marked ≈ is at most what it shows: at that start supervisord could not say since when Postfix ran. Days are UTC days. The card warns when - a message was deferred in the last 24 hours. If these numbers do not stay + a connection was turned away or a message deferred in the last 24 hours. If these numbers do not stay at nothing, the panel is in the way of your mail more than it should be - report it. - **Hostname and reverse DNS** — compares `SELFPOST_HOSTNAME` against the PTR diff --git a/internal/logtail/fileid_unix.go b/internal/logtail/fileid_unix.go index 34968d5..004dde3 100644 --- a/internal/logtail/fileid_unix.go +++ b/internal/logtail/fileid_unix.go @@ -8,9 +8,12 @@ import ( "syscall" ) -// fileID names the file itself - device and inode - which a rename keeps and -// a new file does not share. It is part of the log's fingerprint, so two log -// files whose first bytes happen to match are still told apart. +// fileID names the file itself - its inode - which a rename keeps and a new +// file does not share. It is part of the log's fingerprint, so two log files +// whose first bytes happen to match are still told apart. The device number +// is left out: it can change across a host's reboot (LVM, btrfs, network +// file systems), and the same log would then pass for a rotated one (review +// of stage 2b). func fileID(f *os.File) string { info, err := f.Stat() if err != nil { @@ -20,5 +23,5 @@ func fileID(f *os.File) string { if !ok { return "" } - return fmt.Sprintf("%d.%d", st.Dev, st.Ino) + return fmt.Sprintf("%d", st.Ino) } diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index 7cb81de..8aee284 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -168,7 +168,7 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa keeper.flush() refusals.retry(time.Now().UTC()) } - tr := &tracker{st: st, path: path} + tr := &tracker{st: st, path: path, hold: refusals.oldest} return follow(ctx, path, tr, caughtUp, 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 @@ -187,7 +187,7 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa deferred.handle(line, now, catchingUp, tr.line) } keeper.add(line, now, catchingUp) - refusals.handle(line, now) + refusals.handle(line, now, Place{FP: tr.line.FP, End: tr.lineStart}) queueID, recipient, status, ok := parseDelivery(line) if !ok { return @@ -647,6 +647,7 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{ full := pending + line pending = "" tr.line = Place{FP: tr.fp, End: consumed} + tr.lineStart = consumed - int64(len(full)) handle(strings.TrimRight(full, "\r\n")) } } diff --git a/internal/logtail/offset.go b/internal/logtail/offset.go index b30e6f4..1221742 100644 --- a/internal/logtail/offset.go +++ b/internal/logtail/offset.go @@ -47,9 +47,16 @@ type tracker struct { behind bool prev store.LogtailState - // line is the place of the line being handled: set by follow and - // readRotated before each call of handle. - line Place + // line is the place of the line being handled, lineStart the offset it + // starts at: set by follow and readRotated before each call of handle. + line Place + lineStart int64 + + // hold, when set, names the earliest place in a file that something read + // from the log still waits on (a refusal's line, a refusal to recover): + // no offset past it is saved, so a stop - clean or not - before the wait + // is over reads it again (review of stage 2b). + hold func(fp string) (Place, bool) } // Place is where a line of the log ends: the fingerprint of its file and the @@ -158,6 +165,7 @@ func (t *tracker) readRotated(handle func(string)) bool { r := bufio.NewReader(f) for { line, err := r.ReadString('\n') + t.lineStart = end end += int64(len(line)) if line != "" { t.line = Place{FP: fp, End: end} @@ -198,6 +206,11 @@ func (t *tracker) adopt(f *os.File) { // record persists offset, at most once per persistInterval unless force is set // (rotation and shutdown, where the write must not be skipped). func (t *tracker) record(f *os.File, offset int64, force bool) { + if t.hold != nil { + if p, ok := t.hold(t.fp); ok && p.End < offset { + offset = p.End + } + } if offset == t.saved { return } diff --git a/internal/logtail/refusals.go b/internal/logtail/refusals.go index f0d06d7..a332c17 100644 --- a/internal/logtail/refusals.go +++ b/internal/logtail/refusals.go @@ -2,6 +2,7 @@ package logtail import ( "log" + "net" "regexp" "strings" "time" @@ -12,13 +13,14 @@ import ( // Postfix's line about a message the journal milter refused at MAIL FROM - a // level-2 limit, a client address off the application's list - is put on the // row the milter wrote, so the message's page shows it (audit 2026-10-12, -// stage 2b). The refusal has no queue id; the line is matched to its row by -// sender, login and time. As the stand writes it: +// stage 2b). The refusal has no queue id and the line no login; it is +// matched to its row by client address, sender and time. As the stand writes +// it: // // postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo= // // Port 25's smtpd (postfix/inbound/smtpd) is a stranger's and has no such row. -var refusalLineRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: NOQUEUE: milter-reject: MAIL from \S+: [45]\d\d .*?; from=<([^>]*)>(?:.*? sasl_username=\s]*)>?)?`) +var refusalLineRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: NOQUEUE: milter-reject: MAIL from [^\[\s]*\[([^\]]+)\]: [45]\d\d .*?; from=<([^>]*)>`) // refusalLineWait is how long a line waits for its row: the milter writes the // row when it refuses, which can be read a moment after the line. @@ -26,7 +28,7 @@ const refusalLineWait = 30 * time.Second // RefusalStore is where the lines go. *store.Store satisfies it. type RefusalStore interface { - AttachRefusalLine(login, from string, at time.Time, line string) (bool, error) + AttachRefusalLine(clientIP, from string, at time.Time, line string) (bool, error) RecoverRefusal(e store.SendLogEntry, at time.Time) (bool, error) } @@ -36,8 +38,10 @@ type RefusalStore interface { // postfix/cleanup[1339]: E543D3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: director@other.e2e.test - not an address this application sends as; from= to= proto=ESMTP helo= // // The From: line as the check printed it runs to the last " - " before the -// semicolon; the reason after it holds neither. -var fromRefusalRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?cleanup\[\d+\]: ([0-9A-Za-z]+): milter-reject: END-OF-MESSAGE from \S+: 5\.7\.1 From: (.*) - ([^;]*); from=<([^>]*)> to=<([^>]*)>`) +// first semicolon; the reason after it holds neither, and the check prints no +// ";" of the client's (sender.go printable), so that semicolon is Postfix's +// and what follows it - the envelope - is Postfix's own text. +var fromRefusalRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?cleanup\[\d+\]: ([0-9A-Za-z]+): milter-reject: END-OF-MESSAGE from \S+: 5\.7\.1 From: ([^;]*) - ([^;]*); from=<([^>]*)> to=<([^>]*)>`) // clientLoginRe is smtpd's line naming the login a queue id was submitted // under: ": client=host[addr], sasl_method=PLAIN, sasl_username=". @@ -47,8 +51,9 @@ var clientLoginRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d const refusalLogins = 4096 type pendingRefusal struct { - login, from, line string - at, until time.Time + clientIP, from, line string + at, until time.Time + start Place // where the line starts in the log } // pendingRecovery is a From: refusal whose row is looked for once the panel @@ -56,6 +61,14 @@ type pendingRefusal struct { type pendingRecovery struct { e store.SendLogEntry at, until time.Time + start Place // where its client= line - or the refusal - starts +} + +// loginLine is the login a queue id was submitted under and where smtpd's +// line saying so starts. +type loginLine struct { + login string + start Place } // refusalLines puts each refusal line on its row, and keeps for a while the @@ -65,24 +78,49 @@ type refusalLines struct { st RefusalStore pending []pendingRefusal recover []pendingRecovery - logins map[string]string // queue id -> login, from smtpd's client= line + logins map[string]loginLine // queue id -> login, from smtpd's client= line loginKeys []string } -// handle looks at one mail.log line. -func (r *refusalLines) handle(line string, now time.Time) { +// oldest is the earliest place in the file fp a waiting item starts at: the +// tracker saves no offset past it, so a stop before the wait is over reads the +// lines again - the client= line of a refusal to recover among them. +func (r *refusalLines) oldest(fp string) (Place, bool) { + var p Place + found := false + take := func(q Place) { + if q.FP == fp && (!found || q.End < p.End) { + p, found = q, true + } + } + for _, x := range r.pending { + take(x.start) + } + for _, x := range r.recover { + take(x.start) + } + return p, found +} + +// handle looks at one mail.log line, which starts at start. +func (r *refusalLines) handle(line string, now time.Time, start Place) { at, rest := lineTime(line, now) if m := clientLoginRe.FindStringSubmatch(rest); m != nil && m[1] != "inbound" { - r.remember(m[2], m[3]) + r.remember(m[2], loginLine{login: m[3], start: start}) return } if m := fromRefusalRe.FindStringSubmatch(rest); m != nil { + from := start + login, ok := r.logins[m[1]] + if ok && login.start.FP == start.FP && login.start.End < start.End { + from = login.start + } r.recover = append(r.recover, pendingRecovery{ e: store.SendLogEntry{ - QueueID: m[1], AppLogin: r.logins[m[1]], From: m[4], To: m[5], Domain: domainOf(m[4]), + QueueID: m[1], AppLogin: login.login, From: m[4], To: m[5], Domain: domainOf(m[4]), Reason: store.ReasonFrom, HeaderFrom: m[2], }, - at: at, until: now.Add(refusalLineWait), + at: at, until: now.Add(refusalLineWait), start: from, }) return } @@ -90,7 +128,11 @@ func (r *refusalLines) handle(line string, now time.Time) { if m == nil || m[1] == "inbound" { return } - p := pendingRefusal{login: m[3], from: m[2], line: line, at: at, until: now.Add(refusalLineWait)} + ip := net.ParseIP(strings.TrimPrefix(m[2], "IPv6:")) + if ip == nil { + return + } + p := pendingRefusal{clientIP: ip.String(), from: m[3], line: line, at: at, until: now.Add(refusalLineWait), start: start} if !r.attach(p) { r.pending = append(r.pending, p) } @@ -127,9 +169,9 @@ func (r *refusalLines) retry(now time.Time) { // remember keeps the login a queue id was submitted under, the oldest going // first beyond refusalLogins. -func (r *refusalLines) remember(queueID, login string) { +func (r *refusalLines) remember(queueID string, login loginLine) { if r.logins == nil { - r.logins = make(map[string]string) + r.logins = make(map[string]loginLine) } if _, ok := r.logins[queueID]; !ok { r.loginKeys = append(r.loginKeys, queueID) @@ -150,7 +192,7 @@ func domainOf(addr string) string { } func (r *refusalLines) attach(p pendingRefusal) bool { - ok, err := r.st.AttachRefusalLine(p.login, p.from, p.at, p.line) + ok, err := r.st.AttachRefusalLine(p.clientIP, p.from, p.at, p.line) if err != nil { log.Printf("log-tailer: refusal line: %v", err) return true // not retried: the store said no for its own reason diff --git a/internal/logtail/refusals_test.go b/internal/logtail/refusals_test.go index 1a1885e..da2b6f9 100644 --- a/internal/logtail/refusals_test.go +++ b/internal/logtail/refusals_test.go @@ -19,13 +19,13 @@ func (r *refusalProbe) RecoverRefusal(e store.SendLogEntry, _ time.Time) (bool, return true, nil } -func (r *refusalProbe) AttachRefusalLine(login, from string, _ time.Time, line string) (bool, error) { +func (r *refusalProbe) AttachRefusalLine(clientIP, from string, _ time.Time, line string) (bool, error) { if r.rows == 0 { return false, nil } r.rows-- r.lines = append(r.lines, line) - r.who = append(r.who, login+"|"+from) + r.who = append(r.who, clientIP+"|"+from) return true, nil } @@ -42,23 +42,23 @@ func TestRefusalLines(t *testing.T) { `2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`, `2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: NOQUEUE: reject: RCPT from unknown[10.77.0.1]: 553 5.7.1 : Sender address rejected: not owned by user app1; from= to= proto=ESMTP helo=`, } { - r.handle(other, now) + r.handle(other, now, Place{}) } if len(r.pending) != 0 { t.Fatalf("lines that are not an application's refusal at MAIL wait: %+v", r.pending) } - r.handle(limit, now) // its row is not there yet + r.handle(limit, now, Place{}) // its row is not there yet if len(r.pending) != 1 { t.Fatalf("pending %d, want the line waiting", len(r.pending)) } st.rows = 1 // the milter's row is written r.retry(now.Add(time.Second)) - if len(r.pending) != 0 || len(st.lines) != 1 || st.who[0] != "l2app|billing@sender.e2e.test" { + if len(r.pending) != 0 || len(st.lines) != 1 || st.who[0] != "10.77.0.1|billing@sender.e2e.test" { t.Fatalf("after the retry: pending %d, attached %v", len(r.pending), st.who) } - r.handle(limit, now) // no row ever comes + r.handle(limit, now, Place{}) // no row ever comes r.retry(now.Add(refusalLineWait + time.Second)) if len(r.pending) != 0 { t.Fatal("a line kept waiting past its time") @@ -73,8 +73,8 @@ func TestFromRefusalIsRecoveredAfterTheWait(t *testing.T) { now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC) st := &refusalProbe{} r := &refusalLines{st: st} - r.handle(`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: E543D3C75DA0: client=unknown[10.77.0.1], sasl_method=PLAIN, sasl_username=app1`, now) - r.handle(`2026-10-14T12:00:01+00:00 mail postfix/cleanup[13]: E543D3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: "The - Shop" - it names another sender of this server; from= to= proto=ESMTP helo=`, now) + r.handle(`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: E543D3C75DA0: client=unknown[10.77.0.1], sasl_method=PLAIN, sasl_username=app1`, now, Place{}) + r.handle(`2026-10-14T12:00:01+00:00 mail postfix/cleanup[13]: E543D3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: "The - Shop" - it names another sender of this server; from= to= proto=ESMTP helo=`, now, Place{}) r.retry(now.Add(time.Second)) if len(st.recovered) != 0 { t.Fatal("recovered before the panel had the time to write the row") @@ -90,3 +90,35 @@ func TestFromRefusalIsRecoveredAfterTheWait(t *testing.T) { t.Fatalf("recovered %+v, want %+v", e, want) } } + +// While a line or a recovery waits, the offset saved for its file stays at the +// earliest line it needs - for a recovery the client= line that names its +// login - so a stop before the wait is over reads them again (review of stage +// 2b). +func TestWaitingLinesHoldTheSavedOffset(t *testing.T) { + now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC) + r := &refusalLines{st: &refusalProbe{}} + if _, held := r.oldest("fp"); held { + t.Fatal("nothing waits, yet the offset is held") + } + r.handle(`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: Q1: client=unknown[10.77.0.1], sasl_method=PLAIN, sasl_username=app1`, now, Place{FP: "fp", End: 100}) + r.handle(`2026-10-14T12:00:01+00:00 mail postfix/cleanup[13]: Q1: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: d@other.example - not an address this application sends as; from= to= proto=ESMTP helo=`, now, Place{FP: "fp", End: 300}) + if p, held := r.oldest("fp"); !held || p.End != 100 { + t.Fatalf("held at %+v %v, want the client= line at 100", p, held) + } + if _, held := r.oldest("another"); held { + t.Fatal("a place in another file holds this one") + } + r.retry(now.Add(refusalLineWait + time.Second)) + if _, held := r.oldest("fp"); held { + t.Fatal("still held after the wait") + } + + // The tracker clamps what it saves to the hold. + cs := &captureStore{} + tr := &tracker{st: cs, path: "x", fp: "fp", hold: func(string) (Place, bool) { return Place{FP: "fp", End: 50}, true }} + tr.record(nil, 400, true) + if cs.state.Offset != 50 { + t.Fatalf("saved %d, want the hold at 50", cs.state.Offset) + } +} diff --git a/internal/milter/ratelimit.go b/internal/milter/ratelimit.go index 7fa8e6b..f6cc0be 100644 --- a/internal/milter/ratelimit.go +++ b/internal/milter/ratelimit.go @@ -103,6 +103,7 @@ func (s *session) recordRejected(reason string) { AppLogin: s.login, From: s.from, Reason: reason, + ClientIP: s.clientIP, // Postfix's line about the refusal names it }) if err != nil { log.Printf("journal-milter: record rejected %s: %v", s.from, err) diff --git a/internal/milter/sender.go b/internal/milter/sender.go index 0520c2a..a7dad36 100644 --- a/internal/milter/sender.go +++ b/internal/milter/sender.go @@ -463,6 +463,11 @@ func printable(v string) string { switch { case r == '%' || r < 0x20 || r > 0x7e: sb.WriteByte('?') + case r == ';': + // Postfix logs the reply and then "; from=<...> to=<...>" of + // its own; a ";" of the client's would let its text pass for + // Postfix's where the log tailer reads that line. + sb.WriteByte(',') default: sb.WriteRune(r) } diff --git a/internal/store/migrations/0009_refusal_line.sql b/internal/store/migrations/0009_refusal_line.sql index 6b8de49..0ea958b 100644 --- a/internal/store/migrations/0009_refusal_line.sql +++ b/internal/store/migrations/0009_refusal_line.sql @@ -7,6 +7,12 @@ -- headers are judged), and its lines are found by it like any other's. -- DDL only; a row written earlier has '' and says so on its page. ALTER TABLE send_log ADD COLUMN refusal_line TEXT NOT NULL DEFAULT ''; +-- The client a refusal at MAIL FROM came from, as the milter saw it: Postfix's +-- line names the client and the envelope sender and nothing else - no login +-- - so the two together are what finds the line's row; the sender alone would +-- let one application's line land on another's row of the same sender +-- (security review of stage 2b). +ALTER TABLE send_log ADD COLUMN client_ip TEXT NOT NULL DEFAULT ''; -- A refusal row the panel did not get to write - the sender check answers 550 -- and writes the row a moment later, and a panel stopped in between wrote diff --git a/internal/store/refusal_test.go b/internal/store/refusal_test.go index 9f1f4bf..66bc291 100644 --- a/internal/store/refusal_test.go +++ b/internal/store/refusal_test.go @@ -1,20 +1,23 @@ package store import ( + "fmt" "testing" "time" ) -// Postfix's line about a refusal at MAIL FROM goes on the row of that sender -// and login refused about then, the newest without a line; a queued row, a -// row of another sender and a row from long ago are not it (audit -// 2026-10-12, stage 2b). +// Postfix's line about a refusal at MAIL FROM goes on the row of that client +// and sender refused about then; a queued row, a row of another client or +// sender, and a row from long ago are not it; a line already on a row goes on +// no other; and two refusals of one second take one line each, in the order +// they were written (security and technical reviews of stage 2b). func TestAttachRefusalLine(t *testing.T) { st := openTestStore(t) now := time.Now().UTC() for _, e := range []SendLogEntry{ - {AppLogin: "l2app", From: "billing@example.com", Reason: ReasonLimit}, - {AppLogin: "l2app", From: "other@example.com", Reason: ReasonLimit}, + {AppLogin: "l2app", From: "billing@example.com", Reason: ReasonLimit, ClientIP: "10.0.0.1"}, + {AppLogin: "l2app", From: "billing@example.com", Reason: ReasonLimit, ClientIP: "10.0.0.1"}, + {AppLogin: "other", From: "billing@example.com", Reason: ReasonClient, ClientIP: "10.0.0.2"}, } { if err := st.InsertRejected(e); err != nil { t.Fatal(err) @@ -23,33 +26,37 @@ func TestAttachRefusalLine(t *testing.T) { if err := st.InsertQueued(SendLogEntry{QueueID: "Q1", AppLogin: "l2app", From: "billing@example.com", To: "x@example.net"}); err != nil { t.Fatal(err) } - line := "Oct 14 12:00:00 mail postfix/smtpd[1]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable" - if ok, err := st.AttachRefusalLine("l2app", "Billing@example.com", now, line); err != nil || !ok { - t.Fatalf("attach = %v, %v", ok, err) + first := "Oct 14 12:00:00 mail postfix/smtpd[1]: NOQUEUE: milter-reject: MAIL from unknown[10.0.0.1]: 451 4.7.1 first" + second := "Oct 14 12:00:00 mail postfix/smtpd[2]: NOQUEUE: milter-reject: MAIL from unknown[10.0.0.1]: 451 4.7.1 second" + for _, line := range []string{first, second} { + if ok, err := st.AttachRefusalLine("10.0.0.1", "Billing@example.com", now, line); err != nil || !ok { + t.Fatalf("attach %q = %v, %v", line, ok, err) + } } - // The row has its line now; a second line finds no row without one. - if ok, _ := st.AttachRefusalLine("l2app", "billing@example.com", now, line); ok { - t.Fatal("a second line took a row that has one") + // Read again after a restart: no row takes it a second time. + if ok, _ := st.AttachRefusalLine("10.0.0.1", "billing@example.com", now, first); ok { + t.Fatal("a line already on a row took another") } - if ok, _ := st.AttachRefusalLine("l2app", "other@example.com", now.Add(-time.Hour), line); ok { + if ok, _ := st.AttachRefusalLine("10.0.0.3", "billing@example.com", now, "a third"); ok { + t.Fatal("a line of another client took a row") + } + if ok, _ := st.AttachRefusalLine("10.0.0.2", "billing@example.com", now.Add(-time.Hour), "an hour off"); ok { t.Fatal("a line an hour off took a row") } - if ok, _ := st.AttachRefusalLine("someone", "other@example.com", now, line); ok { - t.Fatal("a line of another login took a row") - } + lines := map[string]string{} rows, _ := st.QuerySendLog(SendLogFilter{AllDomains: true}, 10, 0) - got := 0 for _, r := range rows { full, _ := st.GetSendLog(r.ID) if full.RefusalLine != "" { - got++ - if full.From != "billing@example.com" || full.Status != StatusRejected { - t.Errorf("the line went to %+v", full) - } + lines[fmt.Sprint(full.ID)] = full.RefusalLine } } - if got != 1 { - t.Fatalf("%d rows have a line, want 1", got) + if len(lines) != 2 { + t.Fatalf("lines on rows: %v, want the first two rows", lines) + } + r1, _ := st.GetSendLog(rows[len(rows)-1].ID) // the oldest row + if r1.RefusalLine != first { + t.Fatalf("the first row has %q, want the first line", r1.RefusalLine) } } @@ -113,3 +120,30 @@ func TestRecoverRefusal(t *testing.T) { t.Fatalf("the recovered row: %+v", found) } } + +// A recovered row whose login the tailer did not see is its envelope +// domain's, not nobody's (review of stage 2b). +func TestRecoverRefusalWithoutALogin(t *testing.T) { + st := openTestStore(t) + d := addTestDomain(t, st, "sender.example") + e := SendLogEntry{QueueID: "NOLOGIN", From: "a@sender.example", To: "r@x", Domain: "sender.example", Reason: ReasonFrom} + if wrote, err := st.RecoverRefusal(e, time.Now()); err != nil || !wrote { + t.Fatalf("recover = %v, %v", wrote, err) + } + rows, _ := st.QuerySendLog(SendLogFilter{DomainIDs: []int64{d.ID}}, 10, 0) + if len(rows) != 1 { + t.Fatalf("the domain's log has %d rows, want the recovered one", len(rows)) + } +} + +// A refused row carries the queue id it was given; a delivery line of a later +// message with that id does not touch it. +func TestUpdateStatusLeavesARefusalAlone(t *testing.T) { + st := openTestStore(t) + if err := st.InsertRejected(SendLogEntry{QueueID: "REUSED", To: "a@example.net", Reason: ReasonFrom}); err != nil { + t.Fatal(err) + } + if n, err := st.UpdateStatus("REUSED", "a@example.net", StatusSent); err != nil || n != 0 { + t.Fatalf("UpdateStatus = %d, %v; want 0 rows", n, err) + } +} diff --git a/internal/store/schema_test.go b/internal/store/schema_test.go index 27af04e..0ae1b7f 100644 --- a/internal/store/schema_test.go +++ b/internal/store/schema_test.go @@ -47,7 +47,7 @@ func TestBaselineSchema(t *testing.T) { "applications": "id domain_id login address_mode auth_ip_restrict auth_allowed_ips created_at", "application_addresses": "id application_id address", "rate_limits": "id scope ref_id max_messages window_seconds mode auto_multiplier auto_updated_at", - "send_log": "id queue_id domain app_login from_addr to_addr subject status created_at updated_at reason header_from domain_id refusal_line recovered", + "send_log": "id queue_id domain app_login from_addr to_addr subject status created_at updated_at reason header_from domain_id refusal_line client_ip recovered", "logtail_state": "path fingerprint read_offset updated_at", "inbound_domains": "id name recipient_mode created_at", "inbound_transports": "inbound_domain_id host port tls_mode", diff --git a/internal/store/sendlog.go b/internal/store/sendlog.go index a64bfd8..98332a7 100644 --- a/internal/store/sendlog.go +++ b/internal/store/sendlog.go @@ -38,6 +38,9 @@ type SendLogEntry struct { // was refused (Reason*), and for ReasonFrom what its From: line said. Reason string HeaderFrom string + // ClientIP is the client a refusal at MAIL FROM came from (InsertRejected + // only), which Postfix's line about it names. + ClientIP string } // loginDomainID is the domain_id a row is written with: the domain of the @@ -73,9 +76,9 @@ func (s *Store) InsertRejected(e SendLogEntry) error { now := time.Now().UTC().Format(time.RFC3339) _, err := s.db.Exec( `INSERT INTO send_log - (queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, created_at, updated_at, domain_id) - VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, `+loginDomainID+`)`, - e.QueueID, e.Domain, e.AppLogin, e.From, e.To, e.Subject, StatusRejected, e.Reason, e.HeaderFrom, now, now, e.AppLogin, + (queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, client_ip, created_at, updated_at, domain_id) + VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, `+loginDomainID+`)`, + e.QueueID, e.Domain, e.AppLogin, e.From, e.To, e.Subject, StatusRejected, e.Reason, e.HeaderFrom, e.ClientIP, now, now, e.AppLogin, ) if err != nil { return fmt.Errorf("insert rejected send_log: %w", err) @@ -113,7 +116,9 @@ func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) { return 0, fmt.Errorf("update send_log status: %w", err) } defer tx.Rollback() - const newest = `id = (SELECT MAX(id) FROM send_log WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE)` + // A refused row carries the queue id it was given, and that id may be the + // next message's: a delivery line is never about a refusal. + const newest = `id = (SELECT MAX(id) FROM send_log WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE AND status <> 'rejected')` marked, err := tx.Exec( `UPDATE send_log SET reason = ? WHERE `+newest+` AND reason = ?`, ReasonReconcileContradicted, queueID, recipient, ReasonReconcile, @@ -235,22 +240,27 @@ type SendLogRow struct { // AttachRefusalLine puts Postfix's line about a refusal at MAIL FROM on the // row the journal milter wrote for it (audit 2026-10-12, stage 2b). Such a -// refusal has no queue id, so the row is found by what the line says: a -// refused row of that sender - and login, when the line names one - without a -// line yet, written within two minutes of the line's time; the newest when -// there are several. It reports whether a row took the line. -func (s *Store) AttachRefusalLine(login, from string, at time.Time, line string) (bool, error) { +// refusal has no queue id, and the line names no login, so the row is found +// by what the line says: a refused row of that client and sender without a +// line yet, written within two minutes of the line's time; the nearest in +// time, the oldest of equals, when there are several - lines are read in the +// order the rows were written, so two refusals of one second take one line +// each in turn (review of stage 2b). A line already on a row - read again +// after a restart - goes on no other. It reports whether a row took the line. +func (s *Store) AttachRefusalLine(clientIP, from string, at time.Time, line string) (bool, error) { res, err := s.db.Exec( - `UPDATE send_log SET refusal_line = ? WHERE id = ( + `UPDATE send_log SET refusal_line = ?1 WHERE id = ( SELECT id FROM send_log - WHERE status = ? AND queue_id = '' AND refusal_line = '' - AND reason IN ('', ?, ?) AND from_addr = ? COLLATE NOCASE - AND (? = '' OR app_login = ?) - AND created_at BETWEEN ? AND ? - ORDER BY id DESC LIMIT 1)`, - line, StatusRejected, ReasonLimit, ReasonClient, from, login, login, + WHERE status = ?2 AND queue_id = '' AND refusal_line = '' + AND reason IN ('', ?3, ?4) AND from_addr = ?5 COLLATE NOCASE AND client_ip = ?6 + AND created_at BETWEEN ?7 AND ?8 + ORDER BY ABS(julianday(created_at) - julianday(?9)), id + LIMIT 1) + AND NOT EXISTS (SELECT 1 FROM send_log WHERE refusal_line = ?1)`, + line, StatusRejected, ReasonLimit, ReasonClient, from, clientIP, at.Add(-refusalLineWindow).UTC().Format(time.RFC3339), at.Add(refusalLineWindow).UTC().Format(time.RFC3339), + at.UTC().Format(time.RFC3339), ) if err != nil { return false, fmt.Errorf("attach refusal line: %w", err) @@ -264,16 +274,20 @@ func (s *Store) AttachRefusalLine(login, from string, at time.Time, line string) // wrote the row itself (audit 2026-10-12, stage 2b): the check answers 550 // and writes the row through a buffer a moment later. The message had a queue // id; a refused row with that id from around at means the row was written, -// and nothing is. It reports whether it wrote one. +// and nothing is. The domain is the login's, or - when the tailer did not see the login, its +// client= line read before a restart - the envelope's, so the row is still +// its domain's administrator's (review of stage 2b). It reports whether it +// wrote one. func (s *Store) RecoverRefusal(e SendLogEntry, at time.Time) (bool, error) { stamp := at.UTC().Format(time.RFC3339) res, err := s.db.Exec( `INSERT INTO send_log (queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, recovered, created_at, updated_at, domain_id) - SELECT ?, ?, ?, ?, ?, '', ?, ?, ?, 1, ?, ?, `+loginDomainID+` + SELECT ?, ?, ?, ?, ?, '', ?, ?, ?, 1, ?, ?, + COALESCE(`+loginDomainID+`, (SELECT d.id FROM domains d WHERE d.name = ?)) WHERE NOT EXISTS (SELECT 1 FROM send_log WHERE queue_id = ? AND status = ? AND created_at BETWEEN ? AND ?)`, - e.QueueID, e.Domain, e.AppLogin, e.From, e.To, StatusRejected, e.Reason, e.HeaderFrom, stamp, stamp, e.AppLogin, + e.QueueID, e.Domain, e.AppLogin, e.From, e.To, StatusRejected, e.Reason, e.HeaderFrom, stamp, stamp, e.AppLogin, e.Domain, e.QueueID, StatusRejected, at.Add(-refusalLineWindow).UTC().Format(time.RFC3339), at.Add(refusalLineWindow).UTC().Format(time.RFC3339), ) diff --git a/internal/web/handlers/handlers_monitor.go b/internal/web/handlers/handlers_monitor.go index 223ceee..c16fb01 100644 --- a/internal/web/handlers/handlers_monitor.go +++ b/internal/web/handlers/handlers_monitor.go @@ -273,6 +273,9 @@ func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) { return nil, "Could not read the mail log." } } + if len(lines) == 0 && row.Status == store.StatusRejected { + return nil, "Postfix's lines about this refusal are not stored: the message was refused before version 2.5.1, or the lines were never read." + } if len(lines) == 0 { 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." } diff --git a/internal/web/handlers/handlers_users_test.go b/internal/web/handlers/handlers_users_test.go index a804535..f57db85 100644 --- a/internal/web/handlers/handlers_users_test.go +++ b/internal/web/handlers/handlers_users_test.go @@ -162,12 +162,12 @@ func TestARefusedMessageShowsPostfixsLine(t *testing.T) { d, _ := st.AddDomain("example.org", "mail") st.AddApplication(d.ID, "alerts", store.AddressModeWildcard, nil) for _, subject := range []string{"with its line", "from before"} { - if err := st.InsertRejected(store.SendLogEntry{Domain: "example.org", AppLogin: "alerts", From: "alerts@example.org", Subject: subject, Reason: store.ReasonLimit}); err != nil { + if err := st.InsertRejected(store.SendLogEntry{Domain: "example.org", AppLogin: "alerts", From: "alerts@example.org", Subject: subject, Reason: store.ReasonLimit, ClientIP: "198.51.100.7"}); err != nil { t.Fatal(err) } if subject == "with its line" { line := time.Now().UTC().Format("2006-01-02T15:04:05Z") + " mail postfix/smtpd[2131]: NOQUEUE: milter-reject: MAIL from unknown[198.51.100.7]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=" - if ok, err := st.AttachRefusalLine("alerts", "alerts@example.org", time.Now(), line); err != nil || !ok { + if ok, err := st.AttachRefusalLine("198.51.100.7", "alerts@example.org", time.Now(), line); err != nil || !ok { t.Fatalf("attach = %v, %v", ok, err) } } diff --git a/internal/web/view/help.go b/internal/web/view/help.go index 5186ebb..0c5c39f 100644 --- a/internal/web/view/help.go +++ b/internal/web/view/help.go @@ -171,14 +171,14 @@ var outboundTopics = []HelpTopic{ Code("From:"), " - another of your domains, the server's own name, an address somewhere else, or none at all - is refused for good with ", Code("550 5.7.1"), ". It is a rejected row of the Outbound log, and its page says which address was refused. This is what keeps one application from getting mail signed with another domain's key.", Br(), Br(), - "The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, at most what Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own."), + "The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, which may be more than Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own."), }}, {ID: HelpLimits, Title: "Rate limits", Body: []Text{ Rich("Level 1 is a per-IP ceiling set in ", Code(".env"), ". 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."), }}, {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; or closed by the panel when Postfix no longer held the message and ", Code("mail.log"), " never said what became of it) and rejected (refused before queueing, so it never reached the queue: under a level-2 rate limit, from a client address the application does not allow, or for a ", Code("From:"), " line that is not the application's - the message's page says which). A message's page lists these steps and the lines Postfix wrote about it in ", - 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."), + Code("mail.log"), ", found by queue id - and for a message refused before it had one, Postfix's one line about the refusal. 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."), diff --git a/internal/web/view/outbound_log.go b/internal/web/view/outbound_log.go index 80135e7..7c36b84 100644 --- a/internal/web/view/outbound_log.go +++ b/internal/web/view/outbound_log.go @@ -265,7 +265,7 @@ func NewOutMessage(m Meta, in MessageInput) *OutMessage { facts = append(facts, Fact{Label: "Written", Value: Rich("from ", Code("mail.log"), " after a restart: the panel stopped before it wrote the refusal")}) } if in.QueueID != "" { - facts = append(facts, Fact{Label: "Queue id", Value: Rich(Mono(in.QueueID), " — given, the message was not queued")}) + facts = append(facts, Fact{Label: "Queue id", Value: Rich(Mono(in.QueueID), " - given, the message was not queued")}) } else { facts = append(facts, Fact{Label: "Queue id", Value: Rich("none - refused at ", Mono("MAIL FROM"), ", before one is given")}) delivery.End = Rich("The line from ", Code("mail.log"), " for this refusal") diff --git a/internal/web/view/outbound_log_test.go b/internal/web/view/outbound_log_test.go index a78f416..742985c 100644 --- a/internal/web/view/outbound_log_test.go +++ b/internal/web/view/outbound_log_test.go @@ -144,7 +144,7 @@ func TestOutMessageRefusedForItsFromLine(t *testing.T) { out := renderSignedIn(t, "out-message", p) pageHas(t, "Message", out, `wrong From`, `
From: line
director@example.org
`, `
Refused
`, - `7BCAF3C75DA0 — given, the message was not queued`, `href="/help#sender-check"`, + `7BCAF3C75DA0 - given, the message was not queued`, `href="/help#sender-check"`, `Lines from mail.log with this queue id`, `postfix/cleanup[2120]: 7BCAF3C75DA0: milter-reject`) } diff --git a/test/e2e/sender_check_test.go b/test/e2e/sender_check_test.go index 25d171d..abc8e65 100644 --- a/test/e2e/sender_check_test.go +++ b/test/e2e/sender_check_test.go @@ -349,10 +349,18 @@ func testRefusalsShowPostfixsLine(t *testing.T, sc *scenario) { rowRe := regexp.MustCompile(`(?s).*?`) tagRe := regexp.MustCompile(`(wrong From|rate-limited|wrong client)`) linkRe := regexp.MustCompile(`href="(/outbound/log/\d+)[^"]*"`) + // Each with the refusal's own sender in Postfix's line: the line of one + // application's refusal must not land on another's row (review of + // stage 2b; the rate-limited refusals are l2app's, from billing@). want := map[string]string{ "wrong From": "milter-reject: END-OF-MESSAGE", - "rate-limited": "NOQUEUE: milter-reject: MAIL from", - "wrong client": "NOQUEUE: milter-reject: MAIL from", + "rate-limited": "NOQUEUE: milter-reject: MAIL from unknown[", + "wrong client": "NOQUEUE: milter-reject: MAIL from unknown[", + } + sender := map[string]string{ + "wrong From": "", + "rate-limited": "from=<billing@" + senderDomain + ">", + "wrong client": "from=<alerts@" + senderDomain + ">", } for tag, line := range want { if err := waitFor("the page of a "+tag+" refusal to show Postfix's line", 30*time.Second, time.Second, func() (bool, error) { @@ -370,7 +378,7 @@ func testRefusalsShowPostfixsLine(t *testing.T, sc *scenario) { if err != nil { return false, err } - if strings.Contains(page, line) { + if strings.Contains(page, line) && strings.Contains(page, sender[tag]) { return true, nil } } @@ -397,6 +405,14 @@ func asPanel(code string, args ...string) (string, error) { // saved place moved back before the message's first line. Started again, the // panel writes the row from mail.log, marked, and once. func testRefusalRecoveredFromTheLog(t *testing.T, sc *scenario) { + // A refusal whose row the panel writes as usual: it must not get a second + // row from the log once the wait is over. + written := uniqueToken("written") + if res := attemptSend(sendAttempt{authLogin: sc.appLogin, authPassword: sc.appPassword, + from: "alerts@" + senderDomain, headerFrom: "director@" + otherDomain, to: recipient, + subject: "e2e " + written, body: "refused, its row written"}); res.refusedAt("DATA", 550, "5.7.1 From:") != nil { + t.Fatalf("the written refusal: %v", res.firstErr()) + } token := uniqueToken("recover") res := attemptSend(sendAttempt{authLogin: sc.appLogin, authPassword: sc.appPassword, from: "alerts@" + senderDomain, headerFrom: "director@" + otherDomain, to: recipient, @@ -454,9 +470,16 @@ print(sqlite3.connect("/data/selfpost.db").execute("select count(*), coalesce(su }); err != nil { t.Fatal(err) } - // Once: the next passes over the log write it no more. - time.Sleep(3 * time.Second) + // Once: past another wait of the tailer's (30 s), the passes over the log + // write it no more, and the refusal the panel wrote itself is still one + // row, not recovered. + time.Sleep(35 * time.Second) if out, _ := count(); out != "(1, 1)" { t.Fatalf("after more passes the rows are %s, want (1, 1)", out) } + out, err := asPanel(`import sqlite3,sys +print(sqlite3.connect("/data/selfpost.db").execute("select count(*), coalesce(sum(recovered),0) from send_log where subject like ?",("%"+sys.argv[1]+"%",)).fetchone())`, written) + if err != nil || out != "(1, 0)" { + t.Fatalf("the refusal the panel wrote: rows (count, recovered) = %s, %v; want (1, 0)", out, err) + } }