diff --git a/CHANGELOG.md b/CHANGELOG.md index 46a95e9..332506a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -22,6 +22,17 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version `mail.log` stamps whole seconds, so a second warning of that second was passed over too. It now remembers the place in the log, saved with the count in one transaction (audit 2026-10-12, stage 2b). +- **A refused message's page shows what Postfix wrote.** Its Delivery log + box said Postfix wrote nothing about it, which was untrue. A message + refused for its `From:` line had a queue id, given before its headers were + judged; the row now keeps it and the page shows the message's lines, the + refusal among them - only those of the minutes around the refusal, since + Postfix frees the id at once. A message refused at `MAIL FROM` (a level-2 + limit, a client address off the list) has no queue id; the log tailer puts + Postfix's `NOQUEUE: milter-reject` line on its row (migration `0009`) and + the page shows it. A row refused before this says the line was not kept. + A refusal's line is red for a permanent reply, amber for a temporary one + (audit 2026-10-12, stage 2b). ## [2.5.0] - 2026-10-14 diff --git a/docs/audit-2026-10-12.md b/docs/audit-2026-10-12.md index 7b4abcf..8db5360 100644 --- a/docs/audit-2026-10-12.md +++ b/docs/audit-2026-10-12.md @@ -764,7 +764,7 @@ order - each stands on the one before. place must stay true across a rotated file. A test that stops the tailer between two warnings of one second and finds both counted, once each. - **Opus** -- [ ] **A refused message's page shows what Postfix wrote** (owner, +- [x] **A refused message's page shows what Postfix wrote** (owner, 2026-10-13: "the log box is required" - the box is the reason delivery-log-storage was built, and its absence from the picture he approved for 2.4.0 was an oversight, not a decision). Today every diff --git a/docs/roadmap.md b/docs/roadmap.md index 021371d..0334b06 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -42,7 +42,7 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md). | from-header-binding | Hold a message's `From:` header against the application that sends it | shipped `2.4.0` | 9/9 | [plans/from-header-binding.md](plans/from-header-binding.md) | | panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) | | schema-squash | Squash SQLite migrations into a 2.x baseline | built in panel-redesign (stage 1) | — | [plans/panel-redesign.md](plans/panel-redesign.md) | -| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`, stages 1+2 `2.5.0`; next stage 2b → `2.5.1`) | 24/62 | [audit-2026-10-12.md](audit-2026-10-12.md) | +| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`, stages 1+2 `2.5.0`; next stage 2b → `2.5.1`) | 25/62 | [audit-2026-10-12.md](audit-2026-10-12.md) | **Recommended order** (not binding; owner, 2026-10-09: feature order follows development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and diff --git a/docs/schema-migrations.md b/docs/schema-migrations.md index 07b8fe7..c6f0808 100644 --- a/docs/schema-migrations.md +++ b/docs/schema-migrations.md @@ -17,8 +17,8 @@ When you add or review a migration, update this file in the same change. | Field | Value | |---|---| -| Chain head | `user_version = 8` | -| Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql`, `0003_send_log_lines.sql`, `0004_notifications.sql`, `0005_send_log_rejected_index.sql`, `0006_sender_check.sql`, `0007_delivery_log_days.sql`, `0008_tenant_boundary.sql` | +| Chain head | `user_version = 9` | +| Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql`, `0003_send_log_lines.sql`, `0004_notifications.sql`, `0005_send_log_rejected_index.sql`, `0006_sender_check.sql`, `0007_delivery_log_days.sql`, `0008_tenant_boundary.sql`, `0009_refusal_line.sql` | | File mark | `PRAGMA application_id = 0x53503230` ("SP20") | | Database file | `/data/selfpost.db` (bind mount) | | Compatibility | 2.x MINOR releases must boot a `2.0.0` data directory. **Nothing is carried over from 1.x.** | @@ -83,6 +83,7 @@ audit (`2.5.0`). | 6 | `0006_sender_check.sql` | 2.4.0 | DDL | `send_log.reason` and `send_log.header_from` (both default `''`: a row refused earlier keeps no reason), and `sender_check_days` | | 7 | `0007_delivery_log_days.sql` | 2.5.0 | DDL | `delivery_log_days`: what the reconcile sweep and the log tailer did, a row per UTC day, kept a year, shown nowhere - the measurement that decides the sweep's fate (audit 2026-10-12, stage 1). `send_log.reason` gains the values `reconcile` and `reconcile-contradicted` without a schema change | | 8 | `0008_tenant_boundary.sql` | 2.5.0 | DDL + data | `idx_applications_login_nocase`: an application login is unique without regard to case (audit 2026-10-12, H4). `send_log.domain_id` and `inbound_spam_log.inbound_domain_id` (`ON DELETE SET NULL`), each with an index, filled once by name from the registry as it was then: a row belongs to a domain by id, and a domain deleted and added again starts with an empty log (L12) | +| 9 | `0009_refusal_line.sql` | 2.5.1 | DDL | `send_log.refusal_line`: Postfix's line about a refusal at MAIL FROM (a level-2 limit, a client address off the list), which has no queue id; the log tailer puts it on the row (audit 2026-10-12, stage 2b) | **Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct for operators upgrading from older 2.x images. diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index 2125491..7cb81de 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -39,6 +39,7 @@ type StatusStore interface { CountQueuedOlderThan(cutoff time.Time) (int64, error) SetQueuedOverLifetime(at time.Time, n int64) error PruneDeliveryLogDays(now time.Time) error + RefusalStore DeleteSendLogBefore(cutoff time.Time) (int64, error) InsertSendLogLines(lines []store.SendLogLine, once bool) (int, error) PruneSendLogLines(cutoff time.Time) (int64, error) @@ -162,8 +163,13 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa } keeper := newLineKeeper(st) + refusals := &refusalLines{st: st} + flush := func() { + keeper.flush() + refusals.retry(time.Now().UTC()) + } tr := &tracker{st: st, path: path} - return follow(ctx, path, tr, caughtUp, keeper.flush, func(line string) { + 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 // read already. @@ -181,6 +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) queueID, recipient, status, ok := parseDelivery(line) if !ok { return diff --git a/internal/logtail/logtail_test.go b/internal/logtail/logtail_test.go index bf2c4ef..b44c914 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -283,6 +283,9 @@ func (c *captureStore) AddReconcileMissed(_ time.Time, n int64) error { return nil } func (c *captureStore) AddTailerBlind(time.Time, time.Duration) error { return nil } +func (c *captureStore) AttachRefusalLine(string, string, time.Time, string) (bool, error) { + return true, nil +} func (c *captureStore) CountQueuedOlderThan(time.Time) (int64, error) { c.mu.Lock() defer c.mu.Unlock() diff --git a/internal/logtail/refusals.go b/internal/logtail/refusals.go new file mode 100644 index 0000000..e556694 --- /dev/null +++ b/internal/logtail/refusals.go @@ -0,0 +1,74 @@ +package logtail + +import ( + "log" + "regexp" + "time" +) + +// 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: +// +// 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]*)>?)?`) + +// 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. +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) +} + +type pendingRefusal struct { + login, from, line string + at, until time.Time +} + +// refusalLines puts each refusal line on its row, and keeps for a while the +// lines whose row is not there yet. +type refusalLines struct { + st RefusalStore + pending []pendingRefusal +} + +// handle looks at one mail.log line. +func (r *refusalLines) handle(line string, now time.Time) { + at, rest := lineTime(line, now) + m := refusalLineRe.FindStringSubmatch(rest) + if m == nil || m[1] == "inbound" { + return + } + p := pendingRefusal{login: m[3], from: m[2], line: line, at: at, until: now.Add(refusalLineWait)} + if !r.attach(p) { + r.pending = append(r.pending, p) + } +} + +// retry tries the waiting lines again and lets go of those that waited long +// enough. +func (r *refusalLines) retry(now time.Time) { + kept := r.pending[:0] + for _, p := range r.pending { + if r.attach(p) || now.After(p.until) { + continue + } + kept = append(kept, p) + } + r.pending = kept +} + +func (r *refusalLines) attach(p pendingRefusal) bool { + ok, err := r.st.AttachRefusalLine(p.login, p.from, p.at, p.line) + if err != nil { + log.Printf("log-tailer: refusal line: %v", err) + return true // not retried: the store said no for its own reason + } + return ok +} diff --git a/internal/logtail/refusals_test.go b/internal/logtail/refusals_test.go new file mode 100644 index 0000000..df9a5ba --- /dev/null +++ b/internal/logtail/refusals_test.go @@ -0,0 +1,58 @@ +package logtail + +import ( + "testing" + "time" +) + +type refusalProbe struct { + rows int // rows waiting for a line + lines []string + who []string +} + +func (r *refusalProbe) AttachRefusalLine(login, from string, _ time.Time, line string) (bool, error) { + if r.rows == 0 { + return false, nil + } + r.rows-- + r.lines = append(r.lines, line) + r.who = append(r.who, login+"|"+from) + return true, nil +} + +// The NOQUEUE line of a refusal at MAIL FROM goes on its row; a line whose +// row is not written yet waits and is tried again; port 25's and other +// lines are not refusals of an application. +func TestRefusalLines(t *testing.T) { + now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC) + st := &refusalProbe{} + r := &refusalLines{st: st} + limit := `2026-10-14T12:00:00+00:00 mail 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= sasl_username=` + for _, other := range []string{ + `2026-10-14T12:00:00+00:00 mail postfix/inbound/smtpd[372]: NOQUEUE: milter-reject: MAIL from unknown[203.0.113.7]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, + `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) + } + 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 + 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" { + t.Fatalf("after the retry: pending %d, attached %v", len(r.pending), st.who) + } + + r.handle(limit, now) // 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") + } +} diff --git a/internal/logtail/retention_test.go b/internal/logtail/retention_test.go index e174bb9..f5d793d 100644 --- a/internal/logtail/retention_test.go +++ b/internal/logtail/retention_test.go @@ -98,3 +98,7 @@ func TestRetentionLoopUsesUpdatedValue(t *testing.T) { age := time.Since(st.lastCutoff()) t.Fatalf("second prune cutoff age %v, want about 7 days", age) } + +func (s *retentionProbeStore) AttachRefusalLine(string, string, time.Time, string) (bool, error) { + return true, nil +} diff --git a/internal/milter/sender.go b/internal/milter/sender.go index c060fc3..0520c2a 100644 --- a/internal/milter/sender.go +++ b/internal/milter/sender.go @@ -268,7 +268,10 @@ func (s *senderSession) Headers(h textproto.MIMEHeader, m *milter.Modifier) (mil return milter.RespContinue, nil } log.Printf("sender-check: application %q refused: %s (From: %s)", s.login, why, shown) - s.record(shown) + // cleanup has given the message a queue id by the end of its headers + // (milter_end_of_header_macros has {i}); Postfix's lines about it - the + // refusal among them - are found by it on the message's page. + s.record(shown, macro(m, "i")) // A reply code of its own, so that the application is told what is wrong // and, the refusal being permanent, does not send the message again. return milter.NewResponseStr('y', "550 5.7.1 From: "+shown+" - "+why), nil @@ -352,7 +355,7 @@ func (s *senderSession) judge() (shown, why string, err error) { // each recipient as an accepted message has: nothing was sent to anybody, and // a refused message with a thousand recipients would otherwise be a thousand // rows at the price of one. -func (s *senderSession) record(shown string) { +func (s *senderSession) record(shown, queueID string) { if s.refused == nil { return } @@ -364,6 +367,7 @@ func (s *senderSession) record(shown string) { to += fmt.Sprintf(" and %d more", more) } e := store.SendLogEntry{ + QueueID: queueID, Domain: s.domain(), AppLogin: s.login, From: s.from, diff --git a/internal/milter/sender_test.go b/internal/milter/sender_test.go index 69b7319..aeb3a01 100644 --- a/internal/milter/sender_test.go +++ b/internal/milter/sender_test.go @@ -63,7 +63,8 @@ func offer(t *testing.T, bind *Bindings, login, envelope string, headers ...[2]s t.Fatal(err) } } - resp, err := s.Headers(nil, mods(nil)) + // cleanup has given the message its queue id by the end of the headers. + resp, err := s.Headers(nil, mods(map[string]string{"i": "7BCAF3C75DA0"})) if err != nil { t.Fatal(err) } @@ -153,7 +154,7 @@ func TestSenderCheck(t *testing.T) { t.Fatalf("the reason %q names %s", reason, other) } } - if len(rows) != 1 || rows[0].Reason != store.ReasonFrom || rows[0].To != "someone@elsewhere.example" || rows[0].AppLogin != c.login { + if len(rows) != 1 || rows[0].Reason != store.ReasonFrom || rows[0].To != "someone@elsewhere.example" || rows[0].AppLogin != c.login || rows[0].QueueID != "7BCAF3C75DA0" { t.Fatalf("log rows: %+v", rows) } }) diff --git a/internal/store/migrations/0009_refusal_line.sql b/internal/store/migrations/0009_refusal_line.sql new file mode 100644 index 0000000..f81178c --- /dev/null +++ b/internal/store/migrations/0009_refusal_line.sql @@ -0,0 +1,9 @@ +-- What Postfix wrote about a refusal (audit 2026-10-12, stage 2b). A message +-- the journal milter refuses at MAIL FROM - a level-2 limit, a client address +-- off the application's list - has no queue id, and Postfix's one line about +-- it, "NOQUEUE: milter-reject: MAIL from ...", was nowhere the message's page +-- could find it. The log tailer puts it on the row it belongs to. A message +-- refused for its From: line has a queue id (cleanup gives one before the +-- 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 ''; diff --git a/internal/store/refusal_test.go b/internal/store/refusal_test.go new file mode 100644 index 0000000..a942fd7 --- /dev/null +++ b/internal/store/refusal_test.go @@ -0,0 +1,79 @@ +package store + +import ( + "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). +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}, + } { + if err := st.InsertRejected(e); err != nil { + t.Fatal(err) + } + } + 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) + } + // 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") + } + if ok, _ := st.AttachRefusalLine("l2app", "other@example.com", now.Add(-time.Hour), line); 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") + } + 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) + } + } + } + if got != 1 { + t.Fatalf("%d rows have a line, want 1", got) + } +} + +// A refused message's lines are those of a few minutes around the refusal: +// its queue id was freed at once, and a later message with the same id lends +// it nothing. +func TestSendLogLinesOfARefusalAreItsOwn(t *testing.T) { + st := openTestStore(t) + if err := st.InsertRejected(SendLogEntry{QueueID: "7BCAF3C75DA0", AppLogin: "shop", From: "shop@shop.example", Reason: ReasonFrom}); err != nil { + t.Fatal(err) + } + now := time.Now().UTC() + if _, err := st.InsertSendLogLines([]SendLogLine{ + {QueueID: "7BCAF3C75DA0", At: now.Add(-time.Second), Line: "its own refusal"}, + {QueueID: "7BCAF3C75DA0", At: now.Add(20 * time.Minute), Line: "a later message with the id"}, + }, false); err != nil { + t.Fatal(err) + } + rows, _ := st.QuerySendLog(SendLogFilter{AllDomains: true}, 1, 0) + lines, err := st.SendLogLines(rows[0], 5*24*time.Hour, 10) + if err != nil { + t.Fatal(err) + } + if len(lines) != 1 || lines[0].Line != "its own refusal" { + t.Fatalf("lines = %+v, want its own alone", lines) + } +} diff --git a/internal/store/schema_test.go b/internal/store/schema_test.go index 0387dbb..dfd2614 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", + "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", "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", @@ -115,8 +115,8 @@ func TestBaselineSchema(t *testing.T) { } var version, appID int64 - if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 8 { - t.Errorf("user_version = %d, %v; want 8", version, err) + if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 9 { + t.Errorf("user_version = %d, %v; want 9", version, err) } if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID { t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID) @@ -192,8 +192,8 @@ func TestOpenMigratesA20Database(t *testing.T) { } defer st.Close() var version int - if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 8 { - t.Errorf("user_version = %d, %v; want 8", version, err) + if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 9 { + t.Errorf("user_version = %d, %v; want 9", version, err) } if ok, err := st.UserExists(); err != nil || !ok { t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err) diff --git a/internal/store/sendlog.go b/internal/store/sendlog.go index bd90379..7b8e2a9 100644 --- a/internal/store/sendlog.go +++ b/internal/store/sendlog.go @@ -221,12 +221,46 @@ type SendLogRow struct { // Reason and HeaderFrom: see SendLogEntry. Reason string HeaderFrom string - CreatedAt time.Time + // RefusalLine is Postfix's line about a refusal that has no queue id + // (migration 0009); "" for every other row, and for one refused before. + RefusalLine string + CreatedAt time.Time // UpdatedAt is when the status last changed — the log-tailer's report of // the delivery attempt. It equals CreatedAt while a row is still queued. UpdatedAt time.Time } +// 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) { + res, err := s.db.Exec( + `UPDATE send_log SET refusal_line = ? 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, + at.Add(-refusalLineWindow).UTC().Format(time.RFC3339), + at.Add(refusalLineWindow).UTC().Format(time.RFC3339), + ) + if err != nil { + return false, fmt.Errorf("attach refusal line: %w", err) + } + n, _ := res.RowsAffected() + return n > 0, nil +} + +// refusalLineWindow is how far apart a refusal's row and its log line may be +// dated: the milter writes the row at MAIL FROM, Postfix the line a moment +// later, and the log's stamps are whole seconds. +const refusalLineWindow = 2 * time.Minute + // ErrSendLogNotFound is returned by GetSendLog for an id that no longer exists. // Send-log rows are pruned on the retention window, so a bookmarked delivery // disappearing is expected, not a fault. @@ -240,10 +274,10 @@ func (s *Store) GetSendLog(id int64) (SendLogRow, error) { createdAt, updatedAt string ) err := s.db.QueryRow( - `SELECT id, queue_id, domain, COALESCE(domain_id, 0), app_login, from_addr, to_addr, subject, status, reason, header_from, created_at, updated_at + `SELECT id, queue_id, domain, COALESCE(domain_id, 0), app_login, from_addr, to_addr, subject, status, reason, header_from, refusal_line, created_at, updated_at FROM send_log WHERE id = ?`, id, ).Scan(&row.ID, &row.QueueID, &row.Domain, &row.DomainID, &row.AppLogin, &row.From, &row.To, - &row.Subject, &row.Status, &row.Reason, &row.HeaderFrom, &createdAt, &updatedAt) + &row.Subject, &row.Status, &row.Reason, &row.HeaderFrom, &row.RefusalLine, &createdAt, &updatedAt) if errors.Is(err, sql.ErrNoRows) { return SendLogRow{}, ErrSendLogNotFound } diff --git a/internal/store/sendloglines.go b/internal/store/sendloglines.go index cf63279..5977476 100644 --- a/internal/store/sendloglines.go +++ b/internal/store/sendloglines.go @@ -93,10 +93,19 @@ func (s *Store) InsertSendLogLines(lines []SendLogLine, once bool) (int, error) // A line is the row's when it is dated from shortly before the row was written // to lifetime after it; lifetime is how long Postfix may keep working on a // message, with a margin, and the caller's to state (postfix.RetryPolicy). +// +// A refused message - one refused for its From: line has a queue id, given +// before the headers were judged - is over in a moment, and Postfix frees the +// id at once: its lines are those of a few minutes around the refusal, so +// that the next message to get the id lends it none of its own. func (s *Store) SendLogLines(row SendLogRow, lifetime time.Duration, n int) ([]SendLogLine, error) { if row.QueueID == "" || n <= 0 { return nil, nil } + before := sendLogLineBefore + if row.Status == StatusRejected { + before, lifetime = refusedLinesBefore, refusedLinesAfter + } rows, err := s.db.Query( `SELECT logged_at, line FROM ( SELECT id, logged_at, line FROM send_log_lines @@ -104,7 +113,7 @@ func (s *Store) SendLogLines(row SendLogRow, lifetime time.Duration, n int) ([]S ORDER BY id DESC LIMIT ?) ORDER BY id`, row.QueueID, - row.CreatedAt.Add(-sendLogLineBefore).UTC().Format(time.RFC3339), + row.CreatedAt.Add(-before).UTC().Format(time.RFC3339), row.CreatedAt.Add(lifetime).UTC().Format(time.RFC3339), n, ) @@ -150,3 +159,10 @@ func (s *Store) PruneSendLogLines(cutoff time.Time) (int64, error) { n, _ := res.RowsAffected() return n, nil } + +// The lines of a refused message: from its connection - a slow client may +// take minutes to reach the end of its headers - to just after the refusal. +const ( + refusedLinesBefore = 10 * time.Minute + refusedLinesAfter = time.Minute +) diff --git a/internal/web/handlers/handlers_monitor.go b/internal/web/handlers/handlers_monitor.go index 90c1908..5019899 100644 --- a/internal/web/handlers/handlers_monitor.go +++ b/internal/web/handlers/handlers_monitor.go @@ -241,6 +241,12 @@ const deliveryLogMargin = 24 * time.Hour // reported as a fault, and that one is logged for the operator as well. func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) { if row.QueueID == "" { + if row.RefusalLine != "" { + return logLines([]string{row.RefusalLine}), "" + } + if row.Status == store.StatusRejected { + return nil, "Postfix's line about this refusal is not stored: the message was refused before version 2.5.1, or the line was never read." + } return nil, "This message never reached the queue, so Postfix wrote no delivery lines for it." } stored, err := h.store.SendLogLines(row, h.cfg.RetryPolicy.LongestLifetime()+deliveryLogMargin, deliveryLogLines) @@ -252,7 +258,9 @@ func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) { for i, l := range stored { lines[i] = l.Line } - if len(lines) == 0 { + // A refused message's id was freed at once and may be another's by now: + // what was not stored with the row is not looked for in the log. + if len(lines) == 0 && row.Status != store.StatusRejected { lines, err = logtail.QueueLines(h.cfg.MailLogPath, row.QueueID, deliveryLogLines) if err != nil && !errors.Is(err, fs.ErrNotExist) { logf("panel: delivery log %s: %v", row.QueueID, err) @@ -262,6 +270,11 @@ func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) { 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." } + return logLines(lines), "" +} + +// logLines are lines of mail.log as the delivery log box shows them. +func logLines(lines []string) []view.LogLine { out := make([]view.LogLine, len(lines)) for i, line := range lines { // A line whose head is not a timestamp the log format recognises keeps its @@ -269,7 +282,7 @@ func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) { stamp, rest := logtail.SplitTimestamp(line) out[i] = view.LogLine{Time: stamp, Text: rest, Level: view.LogLineLevel(rest)} } - return out, "" + return out } // deliveriesBackURL rebuilds the delivery-log URL a detail page was opened diff --git a/internal/web/handlers/handlers_users_test.go b/internal/web/handlers/handlers_users_test.go index 8b65b74..6f546df 100644 --- a/internal/web/handlers/handlers_users_test.go +++ b/internal/web/handlers/handlers_users_test.go @@ -5,6 +5,7 @@ import ( "net/url" "strings" "testing" + "time" "github.com/mixeme/selfpost/internal/store" "github.com/mixeme/selfpost/internal/web/auth" @@ -150,3 +151,38 @@ func TestADomainAddedAgainShowsItsAssigneeNothingOld(t *testing.T) { t.Errorf("the global log is missing a row") } } + +// A refused message's page shows what Postfix wrote about the refusal: the +// NOQUEUE line put on the row of a refusal at MAIL FROM, or, for a row from +// before that line was kept, a sentence that says so (audit 2026-10-12, +// stage 2b). +func TestARefusedMessageShowsPostfixsLine(t *testing.T) { + h, st := inboundHandlers(t) + root := userWith(t, st, "root", store.RoleGlobal, store.Reach{}) + 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 { + 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 { + t.Fatalf("attach = %v, %v", ok, err) + } + } + } + rows, _ := st.QuerySendLog(store.SendLogFilter{AllDomains: true}, 10, 0) + for _, r := range rows { + body := send(h.HandleDelivery, &root, "GET", "/outbound/log/"+idStr(r.ID), map[string]string{"id": idStr(r.ID)}, nil).Body.String() + if r.Subject == "with its line" { + if !strings.Contains(body, `mail postfix/smtpd[2131]: NOQUEUE: milter-reject: MAIL from unknown[198.51.100.7]: 451 4.7.1`) { + t.Errorf("the page of a refusal with its line lacks it:\n%s", body) + } + continue + } + if !strings.Contains(body, "the message was refused before version 2.5.1, or the line was never read") { + t.Errorf("the page of a refusal without its line does not say why") + } + } +} diff --git a/internal/web/view/outbound_log.go b/internal/web/view/outbound_log.go index 69ee0b5..635df33 100644 --- a/internal/web/view/outbound_log.go +++ b/internal/web/view/outbound_log.go @@ -12,6 +12,7 @@ package view import ( "net/url" + "regexp" "strconv" "strings" "time" @@ -246,15 +247,23 @@ func NewOutMessage(m Meta, in MessageInput) *OutMessage { {Label: "Application", Value: value(in.App, in.AppHref), Mono: true}, } history := Box{No: "02", Title: "History", Help: topicLink(HelpLog, "What the statuses mean")} + delivery := Box{No: "03", Title: "Delivery log", End: Rich("Lines from ", Code("mail.log"), " with this queue id")} if in.Status == "rejected" { // A refused message was never accepted and never queued: its one date - // is the refusal, and it has no queue id to look anything up by. + // is the refusal. One refused for its From: line was given a queue id + // before its headers were judged; one refused at MAIL FROM was not, + // and its box holds Postfix's one line about the refusal. facts = append(facts, Fact{Label: "Refused", Value: Plain(formatStamp(in.Accepted))}) if in.Reason == "from" { facts = append(facts, Fact{Label: "From: line", Value: Plain(orDash(in.HeaderFrom)), Mono: true, Small: true}) history.Help = topicLink(HelpSenderCheck, "What an application may write in From:") } - facts = append(facts, Fact{Label: "Queue id", Value: Plain("none - never queued")}) + if in.QueueID != "" { + 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") + } } else { facts = append(facts, Fact{Label: "Accepted", Value: Plain(formatStamp(in.Accepted))}, @@ -276,7 +285,7 @@ func NewOutMessage(m Meta, in MessageInput) *OutMessage { Message: Box{No: "01", Title: "Message"}, Facts: facts, History: history, - Delivery: Box{No: "03", Title: "Delivery log", End: Rich("Lines from ", Code("mail.log"), " with this queue id")}, + Delivery: delivery, LogEmpty: EmptyState{Icon: "ti-file-text"}, } } @@ -330,5 +339,17 @@ func LogLineLevel(text string) string { case strings.Contains(text, "status=deferred"), strings.Contains(text, " warning:"): return "warn" } + // A refusal is as permanent as its reply: "550"/"5.7.1" red, "451" amber. + if m := rejectCodeRe.FindStringSubmatch(text); m != nil { + if m[1] == "5" { + return "error" + } + return "warn" + } return "" } + +// rejectCodeRe finds the reply of a refusal Postfix logged: the code or the +// enhanced status after "reject: from [
]:", from +// smtpd ("reject:") and cleanup ("milter-reject:") alike. +var rejectCodeRe = regexp.MustCompile(`reject: \S+ from [^\]]*\]: ([45])(?:\d\d|\.\d+\.\d+) `) diff --git a/internal/web/view/outbound_log_test.go b/internal/web/view/outbound_log_test.go index c3c076f..cade6a7 100644 --- a/internal/web/view/outbound_log_test.go +++ b/internal/web/view/outbound_log_test.go @@ -124,23 +124,28 @@ func TestOutMessageWithoutSubjectOrRecipient(t *testing.T) { out := renderSignedIn(t, "out-message", p) pageHas(t, "Message", out, `

(no subject)

`, `——`, `rejected`, `href="/outbound/log?domain=gone.example&p=2"`, - `
gone.example
`, `
old
`, `
Refused
`, `
none - never queued
`, - `never reached the queue`) + `
gone.example
`, `
old
`, `
Refused
`, + `
none - refused at MAIL FROM, before one is given
`, + `The line from mail.log for this refusal`, `never reached the queue`) pageLacks(t, "Message", out, `wrong From`, `
From: line
director@example.org
`, `
Refused
`, - `
none - never 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`) } func TestSendLogTag(t *testing.T) { @@ -184,12 +189,15 @@ func TestStepLevelAndLogLineLevel(t *testing.T) { } } for text, want := range map[string]string{ - "postfix/smtp[1]: Q1: to=, status=sent (250 OK)": "", - "postfix/smtp[1]: Q1: to=, status=deferred (try later)": "warn", - "postfix/smtp[1]: Q1: to=, status=bounced (no such user)": "error", - "postfix/qmgr[1]: Q1: status=expired, returned to sender": "error", - "postfix/smtp[1]: warning: TLS library problem": "warn", - "opendkim[1]: Q1: DKIM-Signature field added": "", + "postfix/smtp[1]: Q1: to=, status=sent (250 OK)": "", + "postfix/smtp[1]: Q1: to=, status=deferred (try later)": "warn", + "postfix/smtp[1]: Q1: to=, status=bounced (no such user)": "error", + "postfix/qmgr[1]: Q1: status=expired, returned to sender": "error", + "postfix/smtp[1]: warning: TLS library problem": "warn", + "opendkim[1]: Q1: DKIM-Signature field added": "", + "postfix/cleanup[1]: Q1: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: x - no": "error", + "postfix/smtpd[1]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable": "warn", + "postfix/smtpd[1]: NOQUEUE: reject: RCPT from unknown[2001:db8::1]: 554 5.7.1 : Relay access denied": "error", } { if got := LogLineLevel(text); got != want { t.Errorf("LogLineLevel(%q) = %q, want %q", text, got, want) diff --git a/test/e2e/main_test.go b/test/e2e/main_test.go index 499b3e2..15a83d4 100644 --- a/test/e2e/main_test.go +++ b/test/e2e/main_test.go @@ -313,6 +313,9 @@ func TestE2E(t *testing.T) { run("passed_from_lines_signed_for_their_domain_only", func(t *testing.T) { testSignedForItsDomainOnly(t, sc) }) + run("refusals_show_postfixs_line", func(t *testing.T) { + testRefusalsShowPostfixsLine(t, sc) + }) run("lines_naming_another_sender_never_signed_for_it", func(t *testing.T) { testNeverSignedForAnother(t, sc) }) diff --git a/test/e2e/sender_check_test.go b/test/e2e/sender_check_test.go index c5ad33d..0115712 100644 --- a/test/e2e/sender_check_test.go +++ b/test/e2e/sender_check_test.go @@ -5,8 +5,10 @@ import ( "errors" "fmt" "net" + "net/http" "net/smtp" "net/textproto" + "net/url" "regexp" "strconv" "strings" @@ -311,3 +313,68 @@ func testPanelHungMidMessage(t *testing.T, sc *scenario) { t.Fatal(err) } } + +// testRefusalsShowPostfixsLine: the page of each of the three refusals shows +// what Postfix wrote about it (audit 2026-10-12, stage 2b) - for a message +// refused for its From: line, cleanup's line under the queue id the message +// had; for one refused at MAIL FROM under a level-2 limit or for its client +// address, smtpd's NOQUEUE line the log tailer put on the row. The first two +// refusals were made by earlier steps; the third is made here. +func testRefusalsShowPostfixsLine(t *testing.T, sc *scenario) { + login, password, err := sc.panel.addApplication(sc.domainID, "clientapp", "wildcard", "") + if err != nil { + t.Fatal(err) + } + if err := waitForSenderMap(login, password, "alerts@"+senderDomain); err != nil { + t.Fatal(err) + } + appID, err := sc.panel.applicationID(sc.domainID, login) + if err != nil { + t.Fatal(err) + } + resp, body, err := sc.panel.postForm("/outbound/domains/"+sc.domainID+"/applications/"+appID, url.Values{ + "mode": {"wildcard"}, "auth_ip_restrict": {"1"}, "auth_allowed_ips": {"192.0.2.1"}, + }) + if err != nil || resp.StatusCode != http.StatusOK { + t.Fatalf("restrict the client addresses: %v %d\n%.600s", err, resp.StatusCode, body) + } + res := attemptSend(sendAttempt{authLogin: login, authPassword: password, + from: "alerts@" + senderDomain, to: recipient, subject: "e2e " + uniqueToken("client"), body: "x"}) + if err := res.refusedAt("MAIL", 451, "4.7.1"); err != nil { + t.Fatalf("a client off the list: %v", err) + } + + rowRe := regexp.MustCompile(`(?s).*?`) + tagRe := regexp.MustCompile(`(wrong From|rate-limited|wrong client)`) + linkRe := regexp.MustCompile(`href="(/outbound/log/\d+)[^"]*"`) + 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", + } + 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) { + rows, err := sc.panel.sendLogRows(senderDomain, "") + if err != nil { + return false, err + } + for _, row := range rowRe.FindAllString(rows, -1) { + m := tagRe.FindStringSubmatch(row) + l := linkRe.FindStringSubmatch(row) + if m == nil || m[1] != tag || l == nil { + continue + } + _, page, err := sc.panel.get(l[1]) + if err != nil { + return false, err + } + if strings.Contains(page, line) { + return true, nil + } + } + return false, fmt.Errorf("no %s row whose page shows %q", tag, line) + }); err != nil { + t.Error(err) + } + } +}