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>
This commit is contained in:
mix
2026-10-14 16:56:29 +03:00
co-authored by Claude Opus 5.5
parent c452606175
commit e166a2ebd6
22 changed files with 484 additions and 35 deletions
@@ -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 '';
+79
View File
@@ -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)
}
}
+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",
"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)
+37 -3
View File
@@ -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
}
+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
)