Compare commits

..
2 Commits
Author SHA1 Message Date
mixandClaude Opus 5.5 65d916f26a logtail: a refusal the panel did not get to write is written from mail.log (stage 2b)
test / test (push) Canceled after 0s
The sender check answers 550 5.7.1 and writes the refused row through a
buffer a moment later; a panel stopped in between (a rollout, a kill) left
an application refused and a log that did not know it. A refusal at MAIL
FROM needs nothing: the journal milter writes its row before it answers.

- logtail.refusalLines remembers each queue id's login from smtpd's
  "<id>: client=..., sasl_username=<login>" (4096 ids at most) and, on
  cleanup's "<id>: milter-reject: END-OF-MESSAGE ...: 5.7.1 From: <line> -
  <why>; from=<...> to=<...>", waits 30 s and hands it to
  store.RecoverRefusal - an INSERT ... WHERE NOT EXISTS a refused row of that
  queue id within two minutes: the row the panel wrote, or one recovered
  before, means nothing is written. It is read from the saved offset on, so
  a kill is covered as well as a clean stop - which a flush of the buffer at
  shutdown would not.
- Migration 0009 (not deployed yet) gains send_log.recovered; the row is
  written with the line's time, the login's domain id, reason "from", the
  From: line as the check printed it (to the last " - " before ";").
- The message page: a fact "Written: from mail.log after a restart: the
  panel stopped before it wrote the refusal".

Tests: store (not written when the panel wrote it; written once however
often); logtail (the login from client=, the From: line with a " - " in it,
nothing before the wait is over); view (the fact). e2e
refusal_recovered_from_the_log: a From: refusal, the panel stopped, its row
deleted and the tailer's saved place moved before the message's first line
(python3 in the container, as the panel's user - a kill cannot be timed to
that moment from outside); started again, the row is back, recovered, once.

Also fixed: handlers TestMessagePageOfARefusedMessage still expected the
old sentence; it failed on the server after e166a2e, whose run showed only
the schema failures - now it wants the new one.

schema-migrations row 9, CHANGELOG [Unreleased], audit plan line ticked,
roadmap 26/62.
Evidence on the test server for this tree but the handler-test fix: make e2e
exit 0 (the new case 37 s); go test 22/23 ok, the 23rd that test - fixed,
passes locally; the full run follows before the push.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 17:09:05 +03:00
mixandClaude Opus 5.5 e166a2ebd6 refused messages: the page shows what Postfix wrote (stage 2b, 0009)
The Delivery log box of every refused row said "This message never reached
the queue, so Postfix wrote no delivery lines for it" - untrue: Postfix
wrote a line for each. The owner, 2026-10-13: the box is required on every
message page. Pictured for him first (dev/shots, the refused variant of
out-message: wrong From with its queue id lines, rate-limited with the
NOQUEUE line); the variant has no mockup screen of its own - the guard ties
screens to pages, and its outline is out-message's.

- Wrong From: cleanup gives the message a queue id before the headers are
  judged; the sender check reads {i} at end-of-headers and writes it on the
  refused row. Its lines - stored under the id like any other's - are on the
  page, but only those from 10 minutes before to 1 minute after the refusal
  (store.SendLogLines for a rejected row): Postfix frees the id at once, and
  a later message with it lends nothing. No mail.log fallback for a refused
  row, for the same reason.
- Rate-limited and wrong client: refused at MAIL FROM, no queue id. Migration
  0009 adds send_log.refusal_line; logtail.refusalLines matches smtpd's
  "NOQUEUE: milter-reject: MAIL from ...; from=<...>" (not port 25's, not
  CONNECT/EHLO) and store.AttachRefusalLine puts it on the newest refused row
  of that sender (and login, when the line names it) within two minutes; a
  line whose row is not written yet waits up to 30 s (retried at each pass).
- The page: the queue id fact says "given, the message was not queued" or
  "none - refused at MAIL FROM, before one is given"; the box's caption is
  "The line from mail.log for this refusal" for the latter; a row from
  before says the line was not kept. LogLineLevel colours a refusal by its
  reply: 5xx red, 4xx amber (IPv6 clients included). The id in the fact is
  not muted as in the picture: the kit has no muted inline.

Tests: store (attach by sender, login, time; not a queued row, not one an
hour off; a refused row's lines are its own minutes); logtail (attach, wait
and retry, port 25 and other lines ignored); milter (the refused row carries
{i}); view (facts, caption, line levels); handlers (the line on the page,
the sentence without it). e2e refusals_show_postfixs_line: a client-address
refusal made there, and the pages of a wrong From, a rate-limited and a
wrong client refusal each show Postfix's line.

schema-migrations row 9, CHANGELOG [Unreleased], audit plan line ticked,
roadmap 25/62.
Evidence on the test server for this tree: make e2e exit 0 (the new case
in 5.4 s); go test ./... ok but for two schema tests, fixed after the run
(the schema at 0009) - store tests ok locally; the full run follows before
the push.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 16:56:29 +03:00
23 changed files with 793 additions and 42 deletions
+19
View File
@@ -22,6 +22,25 @@ 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).
- **A refusal the panel did not get to write is written from the log.** The
sender check answers 550 and writes the row a moment later; a panel that
stopped in between - a rollout, a crash - left an application refused and
a log that did not know it. When the log tailer reads cleanup's refusal
line and, after giving the panel half a minute, finds no row for that
queue id, it writes the row from the line, marked on its page as written
from `mail.log` after a restart. A refusal at `MAIL FROM` needs no such
thing: its row is written before Postfix is answered.
## [2.5.0] - 2026-10-14
+2 -2
View File
@@ -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
@@ -793,7 +793,7 @@ order - each stands on the one before.
`mail.log` never said what became of it, so the panel closed it as a
failure. Wording in the mockup `out-message` first (`design:` commit),
with the box of the step above. - **Sonnet**
- [ ] **A refusal the panel did not get to write is written from
- [x] **A refusal the panel did not get to write is written from
`mail.log`** (owner, 2026-10-13, from the Not done list of
from-header-binding; built on the step above). The check answers 550 and
writes the row a moment later, through a buffer; a panel that stops in
+1 -1
View File
@@ -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`) | 26/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
+3 -2
View File
@@ -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; and `send_log.recovered`, a refusal row the tailer wrote from `mail.log` because the panel stopped before writing it (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.
+8 -1
View File
@@ -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
+4
View File
@@ -283,6 +283,10 @@ 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) RecoverRefusal(store.SendLogEntry, time.Time) (bool, error) { return false, nil }
func (c *captureStore) CountQueuedOlderThan(time.Time) (int64, error) {
c.mu.Lock()
defer c.mu.Unlock()
+159
View File
@@ -0,0 +1,159 @@
package logtail
import (
"log"
"regexp"
"strings"
"time"
"github.com/mixeme/selfpost/internal/store"
)
// 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=<billing@sender.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>
//
// 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)
RecoverRefusal(e store.SendLogEntry, at time.Time) (bool, error)
}
// fromRefusalRe is cleanup's line about a message the sender check refused
// for its From: line, as the stand writes it:
//
// 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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>
//
// 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=<([^>]*)>`)
// clientLoginRe is smtpd's line naming the login a queue id was submitted
// under: "<id>: client=host[addr], sasl_method=PLAIN, sasl_username=<login>".
var clientLoginRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: ([0-9A-Za-z]+): client=.*?, sasl_username=(\S+)`)
// refusalLogins bounds the queue ids whose login is remembered.
const refusalLogins = 4096
type pendingRefusal struct {
login, from, line string
at, until time.Time
}
// pendingRecovery is a From: refusal whose row is looked for once the panel
// has had the time to write it.
type pendingRecovery struct {
e store.SendLogEntry
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. It also writes, from cleanup's line, the
// row of a From: refusal the panel did not get to write.
type refusalLines struct {
st RefusalStore
pending []pendingRefusal
recover []pendingRecovery
logins map[string]string // 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) {
at, rest := lineTime(line, now)
if m := clientLoginRe.FindStringSubmatch(rest); m != nil && m[1] != "inbound" {
r.remember(m[2], m[3])
return
}
if m := fromRefusalRe.FindStringSubmatch(rest); m != nil {
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]),
Reason: store.ReasonFrom, HeaderFrom: m[2],
},
at: at, until: now.Add(refusalLineWait),
})
return
}
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; and writes, once their wait is over, the rows of From: refusals the
// panel did not write.
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
waiting := r.recover[:0]
for _, p := range r.recover {
if !now.After(p.until) {
waiting = append(waiting, p)
continue
}
wrote, err := r.st.RecoverRefusal(p.e, p.at)
if err != nil {
log.Printf("log-tailer: recover refusal: %v", err)
} else if wrote {
log.Printf("log-tailer: wrote the refusal of %s (%s) from mail.log: the panel had not written it", p.e.QueueID, p.e.From)
}
}
r.recover = waiting
}
// remember keeps the login a queue id was submitted under, the oldest going
// first beyond refusalLogins.
func (r *refusalLines) remember(queueID, login string) {
if r.logins == nil {
r.logins = make(map[string]string)
}
if _, ok := r.logins[queueID]; !ok {
r.loginKeys = append(r.loginKeys, queueID)
if len(r.loginKeys) > refusalLogins {
delete(r.logins, r.loginKeys[0])
r.loginKeys = r.loginKeys[1:]
}
}
r.logins[queueID] = login
}
// domainOf is the domain of an address, lower-cased; "" without one.
func domainOf(addr string) string {
if i := strings.LastIndexByte(addr, '@'); i >= 0 {
return strings.ToLower(addr[i+1:])
}
return ""
}
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
}
+92
View File
@@ -0,0 +1,92 @@
package logtail
import (
"testing"
"time"
"github.com/mixeme/selfpost/internal/store"
)
type refusalProbe struct {
rows int // rows waiting for a line
lines []string
who []string
recovered []store.SendLogEntry
}
func (r *refusalProbe) RecoverRefusal(e store.SendLogEntry, _ time.Time) (bool, error) {
r.recovered = append(r.recovered, e)
return true, nil
}
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=<billing@sender.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test> sasl_username=<l2app>`
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=<a@stranger.example> proto=ESMTP helo=<x>`,
`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 <a@x>: Sender address rejected: not owned by user app1; from=<a@x> to=<b@y> proto=ESMTP helo=<x>`,
} {
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")
}
}
// cleanup's line about a From: refusal is the row's, written by the panel; once
// the panel has had the time to, the line is handed to RecoverRefusal, which
// writes the row only if it is missing - with the login smtpd named for the
// queue id, the sender, the recipient and the From: line as printed.
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" <director@other.e2e.test> - it names another sender of this server; from=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<x>`, now)
r.retry(now.Add(time.Second))
if len(st.recovered) != 0 {
t.Fatal("recovered before the panel had the time to write the row")
}
r.retry(now.Add(refusalLineWait + time.Second))
if len(st.recovered) != 1 {
t.Fatalf("recovered %d, want 1", len(st.recovered))
}
e := st.recovered[0]
want := store.SendLogEntry{QueueID: "E543D3C75DA0", AppLogin: "app1", From: "alerts@sender.e2e.test", To: "rcpt@sink.e2e.test",
Domain: "sender.e2e.test", Reason: store.ReasonFrom, HeaderFrom: `"The - Shop" <director@other.e2e.test>`}
if e != want {
t.Fatalf("recovered %+v, want %+v", e, want)
}
}
+8
View File
@@ -98,3 +98,11 @@ 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
}
func (s *retentionProbeStore) RecoverRefusal(store.SendLogEntry, time.Time) (bool, error) {
return false, nil
}
+6 -2
View File
@@ -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,
+3 -2
View File
@@ -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)
}
})
@@ -0,0 +1,15 @@
-- 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 '';
-- 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
-- none - is written by the log tailer from Postfix's line about it, and marked
-- so: recovered = 1.
ALTER TABLE send_log ADD COLUMN recovered INTEGER NOT NULL DEFAULT 0;
+115
View File
@@ -0,0 +1,115 @@
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)
}
}
// A From: refusal's row is written from the log only when the panel wrote
// none for that queue id about then; once, however often the line is read.
func TestRecoverRefusal(t *testing.T) {
st := openTestStore(t)
d := addTestDomain(t, st, "sender.example")
if _, err := st.AddApplication(d.ID, "app1", AddressModeWildcard, nil); err != nil {
t.Fatal(err)
}
now := time.Now().UTC()
// The panel wrote this one itself.
if err := st.InsertRejected(SendLogEntry{QueueID: "WRITTEN", AppLogin: "app1", From: "a@sender.example", Reason: ReasonFrom}); err != nil {
t.Fatal(err)
}
e := SendLogEntry{QueueID: "WRITTEN", AppLogin: "app1", From: "a@sender.example", To: "r@x", Domain: "sender.example", Reason: ReasonFrom, HeaderFrom: "x@y"}
if wrote, err := st.RecoverRefusal(e, now); err != nil || wrote {
t.Fatalf("a refusal the panel wrote was written again: %v, %v", wrote, err)
}
e.QueueID = "LOST"
for i := 0; i < 2; i++ {
wrote, err := st.RecoverRefusal(e, now)
if err != nil || wrote != (i == 0) {
t.Fatalf("recovery %d: wrote %v, %v", i, wrote, err)
}
}
rows, _ := st.QuerySendLog(SendLogFilter{DomainIDs: []int64{d.ID}}, 10, 0)
var found SendLogRow
for _, r := range rows {
if r.QueueID == "LOST" {
found, _ = st.GetSendLog(r.ID)
}
}
if !found.Recovered || found.Status != StatusRejected || found.Reason != ReasonFrom || found.HeaderFrom != "x@y" || found.DomainID != d.ID {
t.Fatalf("the recovered row: %+v", found)
}
}
+5 -5
View File
@@ -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 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",
@@ -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)
+65 -3
View File
@@ -221,12 +221,74 @@ 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
// Recovered is a refusal row the log tailer wrote from mail.log because
// the panel stopped before it wrote the row itself.
Recovered bool
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
}
// RecoverRefusal writes the row of a message the sender check refused for its
// From: line, from Postfix's line about it, when the panel stopped before it
// 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.
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+`
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, StatusRejected,
at.Add(-refusalLineWindow).UTC().Format(time.RFC3339), at.Add(refusalLineWindow).UTC().Format(time.RFC3339),
)
if err != nil {
return false, fmt.Errorf("recover refusal %s: %w", e.QueueID, 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 +302,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, recovered, 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, &row.Recovered, &createdAt, &updatedAt)
if errors.Is(err, sql.ErrNoRows) {
return SendLogRow{}, ErrSendLogNotFound
}
+17 -1
View File
@@ -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
)
+16 -3
View File
@@ -104,7 +104,7 @@ func (h *Handlers) HandleDelivery(w http.ResponseWriter, r *http.Request) {
in := view.MessageInput{
ID: row.ID, QueueID: row.QueueID, Domain: row.Domain, App: row.AppLogin,
From: row.From, To: row.To, Subject: row.Subject, Status: row.Status,
Reason: row.Reason, HeaderFrom: row.HeaderFrom,
Reason: row.Reason, HeaderFrom: row.HeaderFrom, Recovered: row.Recovered,
Accepted: row.CreatedAt, Reported: row.UpdatedAt,
// Where the row came from, so the way back returns to the page and filters
// the operator was looking at rather than the top of an unfiltered log.
@@ -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
@@ -176,8 +176,9 @@ func TestMessagePageDrawsTheOutcomeAtItsLevel(t *testing.T) {
}
}
// A message the milter refused never reached the queue: it has no queue id and
// no lines to show, and says why instead of showing an empty log.
// A message the milter refused never reached the queue: it has no queue id,
// and a row from before Postfix's line about it was kept says so instead of
// showing an empty log.
func TestMessagePageOfARefusedMessage(t *testing.T) {
h, _ := serverWithDelivery(t)
if err := h.store.InsertRejected(store.SendLogEntry{
@@ -190,7 +191,7 @@ func TestMessagePageOfARefusedMessage(t *testing.T) {
t.Fatalf("query: %v (%d rows)", err, len(rows))
}
body := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(rows[0].ID))
has(t, "refused message", body, `Refused before queueing`, `class="sp-fail"`, `never reached the queue`, `<span class="tag is-light">rejected</span>`)
has(t, "refused message", body, `Refused before queueing`, `class="sp-fail"`, `the line was never read`, `<span class="tag is-light">rejected</span>`)
lacks(t, "refused message", body, `<pre`)
}
@@ -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=<alerts@example.org> proto=ESMTP helo=<app>"
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, `<span class="sp-w">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")
}
}
}
+32 -5
View File
@@ -12,6 +12,7 @@ package view
import (
"net/url"
"regexp"
"strconv"
"strings"
"time"
@@ -172,8 +173,11 @@ type MessageInput struct {
// (store.Reason*) and, for its From: line, what that line said.
Reason string
HeaderFrom string
Accepted time.Time
Reported time.Time
// Recovered is a refused row the log tailer wrote from mail.log: the
// panel stopped before it wrote the row itself.
Recovered bool
Accepted time.Time
Reported time.Time
// BackHref is the log the message was opened from, filters and page kept.
BackHref string
}
@@ -246,15 +250,26 @@ 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.Recovered {
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")})
} 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 +291,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 +345,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: <stage> from <client>[<address>]:", from
// smtpd ("reject:") and cleanup ("milter-reject:") alike.
var rejectCodeRe = regexp.MustCompile(`reject: \S+ from [^\]]*\]: ([45])(?:\d\d|\.\d+\.\d+) `)
+30 -12
View File
@@ -124,23 +124,38 @@ func TestOutMessageWithoutSubjectOrRecipient(t *testing.T) {
out := renderSignedIn(t, "out-message", p)
pageHas(t, "Message", out, `<h1 class="title is-4">(no subject)</h1>`, `<span>—</span><i class="ti ti-arrow-right sp-muted"></i><span>—</span>`,
`<span class="tag is-light">rejected</span>`, `href="/outbound/log?domain=gone.example&amp;p=2"`,
`<dd>gone.example</dd>`, `<dd class="sp-mono">old</dd>`, `<dt>Refused</dt>`, `<dd>none - never queued</dd>`,
`never reached the queue`)
`<dd>gone.example</dd>`, `<dd class="sp-mono">old</dd>`, `<dt>Refused</dt>`,
`<dd>none - refused at <span class="sp-mono">MAIL FROM</span>, before one is given</dd>`,
`The line from <code>mail.log</code> for this refusal`, `never reached the queue`)
pageLacks(t, "Message", out, `<pre`, `<a href="/outbound/domains/`, `Status reported`, `From: line`)
}
// A row refused for its From: line says so in its tag, shows what the line
// said, and its History links to the topic that explains the rule.
// said, and its History links to the topic that explains the rule. The
// message had a queue id - cleanup gives one before the headers are judged -
// and its box shows Postfix's lines by it, the refusal red.
func TestOutMessageRefusedForItsFromLine(t *testing.T) {
at := time.Date(2026, 9, 21, 13, 40, 55, 0, time.UTC)
p := NewOutMessage(admin(), MessageInput{ID: 184231, Domain: "shop.example.org", App: "shop",
p := NewOutMessage(admin(), MessageInput{ID: 184231, QueueID: "7BCAF3C75DA0", Domain: "shop.example.org", App: "shop",
From: "shop@shop.example.org", To: "k.berg@web.de", Subject: "A message from the director",
Status: "rejected", Reason: "from", HeaderFrom: "director@example.org", Accepted: at, Reported: at}).
WithDeliveryLog(nil, "This message never reached the queue, so Postfix wrote no delivery lines for it.")
WithDeliveryLog([]LogLine{{Time: "13:40:55", Text: "postfix/cleanup[2120]: 7BCAF3C75DA0: milter-reject: END-OF-MESSAGE from unknown[198.51.100.7]: 5.7.1 From: director@example.org - not an address this application sends as",
Level: LogLineLevel("postfix/cleanup[2120]: 7BCAF3C75DA0: milter-reject: END-OF-MESSAGE from unknown[198.51.100.7]: 5.7.1 From: director@example.org - not an address this application sends as")}}, "")
out := renderSignedIn(t, "out-message", p)
pageHas(t, "Message", out, `<span class="tag is-danger is-light">wrong From</span>`,
`<dt>From: line</dt><dd class="sp-mono sp-small">director@example.org</dd>`, `<dt>Refused</dt>`,
`<dd>none - never queued</dd>`, `href="/help#sender-check"`)
`<span class="sp-mono">7BCAF3C75DA0</span> — given, the message was not queued`, `href="/help#sender-check"`,
`Lines from <code>mail.log</code> with this queue id`, `<span class="sp-e">postfix/cleanup[2120]: 7BCAF3C75DA0: milter-reject`)
}
// A refused row the log tailer wrote from mail.log says so.
func TestOutMessageRecoveredFromTheLog(t *testing.T) {
at := time.Date(2026, 9, 21, 13, 40, 55, 0, time.UTC)
p := NewOutMessage(admin(), MessageInput{ID: 184232, QueueID: "E543D3C75DA0", Domain: "shop.example.org", App: "shop",
From: "shop@shop.example.org", To: "k.berg@web.de", Status: "rejected", Reason: "from", HeaderFrom: "director@example.org",
Recovered: true, Accepted: at, Reported: at}).WithDeliveryLog(nil, "")
out := renderSignedIn(t, "out-message", p)
pageHas(t, "Message", out, `<dt>Written</dt>`, `after a restart: the panel stopped before it wrote the refusal`)
}
func TestSendLogTag(t *testing.T) {
@@ -184,12 +199,15 @@ func TestStepLevelAndLogLineLevel(t *testing.T) {
}
}
for text, want := range map[string]string{
"postfix/smtp[1]: Q1: to=<a@b>, status=sent (250 OK)": "",
"postfix/smtp[1]: Q1: to=<a@b>, status=deferred (try later)": "warn",
"postfix/smtp[1]: Q1: to=<a@b>, 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=<a@b>, status=sent (250 OK)": "",
"postfix/smtp[1]: Q1: to=<a@b>, status=deferred (try later)": "warn",
"postfix/smtp[1]: Q1: to=<a@b>, 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 <a@b>: Relay access denied": "error",
} {
if got := LogLineLevel(text); got != want {
t.Errorf("LogLineLevel(%q) = %q, want %q", text, got, want)
+6
View File
@@ -313,6 +313,12 @@ 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("refusal_recovered_from_the_log", func(t *testing.T) {
testRefusalRecoveredFromTheLog(t, sc)
})
run("lines_naming_another_sender_never_signed_for_it", func(t *testing.T) {
testNeverSignedForAnother(t, sc)
})
+147
View File
@@ -5,8 +5,10 @@ import (
"errors"
"fmt"
"net"
"net/http"
"net/smtp"
"net/textproto"
"net/url"
"regexp"
"strconv"
"strings"
@@ -311,3 +313,148 @@ 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)<tr>.*?</tr>`)
tagRe := regexp.MustCompile(`<span class="tag[^"]*">(wrong From|rate-limited|wrong client)</span>`)
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)
}
}
}
// asPanel runs python3 code inside the container as the panel's user, so the
// database's WAL files stay the panel's.
func asPanel(code string, args ...string) (string, error) {
full := append([]string{"exec", "-T", "-u", "panel", "selfpost", "python3", "-c", code}, args...)
out, err := h.compose(full...)
return strings.TrimSpace(string(out)), err
}
// testRefusalRecoveredFromTheLog: the sender check answers 550 and writes the
// row a moment later; a panel stopped in between leaves a refusal the log
// knows and the panel does not (audit 2026-10-12, stage 2b). The stop cannot
// be timed to that moment from outside, so what it leaves is made by hand: a
// From: refusal, then - the panel stopped - its row deleted and the tailer's
// 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) {
token := uniqueToken("recover")
res := attemptSend(sendAttempt{authLogin: sc.appLogin, authPassword: sc.appPassword,
from: "alerts@" + senderDomain, headerFrom: "director@" + otherDomain, to: recipient,
subject: "e2e " + token, body: "refused, and its row lost"})
if err := res.refusedAt("DATA", 550, "5.7.1 From:"); err != nil {
t.Fatal(err)
}
var queueID string
if err := waitFor("the refused row", 15*time.Second, 300*time.Millisecond, func() (bool, error) {
out, err := asPanel(`import sqlite3,sys
r=sqlite3.connect("/data/selfpost.db").execute("select queue_id from send_log where subject like ?",("%"+sys.argv[1]+"%",)).fetchone()
print(r[0] if r else "")`, token)
queueID = out
return err == nil && out != "", err
}); err != nil {
t.Fatal(err)
}
supervisorctl := func(verb string) {
if _, err := h.execIn("selfpost", "supervisorctl", "-c", "/etc/supervisor/supervisord.conf", verb, "panel"); err != nil {
t.Fatalf("%s panel: %v", verb, err)
}
}
supervisorctl("stop")
t.Cleanup(func() {
_, _ = h.execIn("selfpost", "supervisorctl", "-c", "/etc/supervisor/supervisord.conf", "start", "panel")
})
if out, err := asPanel(`import sqlite3,sys
q=sys.argv[1]
data=open("/data/log/mail.log","rb").read()
pos=data.find((q+": client=").encode())
if pos < 0: sys.exit("no client= line for "+q)
start=data.rfind(b"\n",0,pos)+1
c=sqlite3.connect("/data/selfpost.db")
c.execute("delete from send_log where queue_id=?",(q,))
c.execute("update logtail_state set read_offset=?",(start,))
c.commit()
print(start)`, queueID); err != nil {
t.Fatalf("lose the row: %v %s", err, out)
}
supervisorctl("start")
if err := waitFor("panel HTTP to answer again", 30*time.Second, 300*time.Millisecond, func() (bool, error) {
_, err := sc.panel.status()
return err == nil, err
}); err != nil {
t.Fatal(err)
}
count := func() (string, error) {
return asPanel(`import sqlite3,sys
print(sqlite3.connect("/data/selfpost.db").execute("select count(*), coalesce(sum(recovered),0) from send_log where queue_id=? and status='rejected'",(sys.argv[1],)).fetchone())`, queueID)
}
if err := waitFor("the refusal written from mail.log", 90*time.Second, time.Second, func() (bool, error) {
out, err := count()
return err == nil && out == "(1, 1)", fmt.Errorf("rows (count, recovered) = %s, %v", out, err)
}); err != nil {
t.Fatal(err)
}
// Once: the next passes over the log write it no more.
time.Sleep(3 * time.Second)
if out, _ := count(); out != "(1, 1)" {
t.Fatalf("after more passes the rows are %s, want (1, 1)", out)
}
}