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>
This commit is contained in:
mix
2026-10-14 17:09:05 +03:00
co-authored by Claude Opus 5.5
parent e166a2ebd6
commit 65d916f26a
18 changed files with 322 additions and 20 deletions
+8
View File
@@ -33,6 +33,14 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version
the page shows it. A row refused before this says the line was not kept. 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 A refusal's line is red for a permanent reply, amber for a temporary one
(audit 2026-10-12, stage 2b). (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.5.0] - 2026-10-14
+1 -1
View File
@@ -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 `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), failure. Wording in the mockup `out-message` first (`design:` commit),
with the box of the step above. - **Sonnet** 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 `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 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 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) | | 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) | | 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) | | 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`) | 25/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 **Recommended order** (not binding; owner, 2026-10-09: feature order follows
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and
+1 -1
View File
@@ -83,7 +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` | | 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 | | 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) | | 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) | | 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 **Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct
for operators upgrading from older 2.x images. for operators upgrading from older 2.x images.
+1
View File
@@ -286,6 +286,7 @@ func (c *captureStore) AddTailerBlind(time.Time, time.Duration) error { return n
func (c *captureStore) AttachRefusalLine(string, string, time.Time, string) (bool, error) { func (c *captureStore) AttachRefusalLine(string, string, time.Time, string) (bool, error) {
return true, nil return true, nil
} }
func (c *captureStore) RecoverRefusal(store.SendLogEntry, time.Time) (bool, error) { return false, nil }
func (c *captureStore) CountQueuedOlderThan(time.Time) (int64, error) { func (c *captureStore) CountQueuedOlderThan(time.Time) (int64, error) {
c.mu.Lock() c.mu.Lock()
defer c.mu.Unlock() defer c.mu.Unlock()
+89 -4
View File
@@ -3,7 +3,10 @@ package logtail
import ( import (
"log" "log"
"regexp" "regexp"
"strings"
"time" "time"
"github.com/mixeme/selfpost/internal/store"
) )
// Postfix's line about a message the journal milter refused at MAIL FROM - a // Postfix's line about a message the journal milter refused at MAIL FROM - a
@@ -24,23 +27,65 @@ const refusalLineWait = 30 * time.Second
// RefusalStore is where the lines go. *store.Store satisfies it. // RefusalStore is where the lines go. *store.Store satisfies it.
type RefusalStore interface { type RefusalStore interface {
AttachRefusalLine(login, from string, at time.Time, line string) (bool, error) 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 { type pendingRefusal struct {
login, from, line string login, from, line string
at, until time.Time 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 // refusalLines puts each refusal line on its row, and keeps for a while the
// lines whose row is not there yet. // 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 { type refusalLines struct {
st RefusalStore st RefusalStore
pending []pendingRefusal 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. // handle looks at one mail.log line.
func (r *refusalLines) handle(line string, now time.Time) { func (r *refusalLines) handle(line string, now time.Time) {
at, rest := lineTime(line, now) 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) m := refusalLineRe.FindStringSubmatch(rest)
if m == nil || m[1] == "inbound" { if m == nil || m[1] == "inbound" {
return return
@@ -52,7 +97,8 @@ func (r *refusalLines) handle(line string, now time.Time) {
} }
// retry tries the waiting lines again and lets go of those that waited long // retry tries the waiting lines again and lets go of those that waited long
// enough. // 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) { func (r *refusalLines) retry(now time.Time) {
kept := r.pending[:0] kept := r.pending[:0]
for _, p := range r.pending { for _, p := range r.pending {
@@ -62,6 +108,45 @@ func (r *refusalLines) retry(now time.Time) {
kept = append(kept, p) kept = append(kept, p)
} }
r.pending = kept 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 { func (r *refusalLines) attach(p pendingRefusal) bool {
+37 -3
View File
@@ -3,12 +3,20 @@ package logtail
import ( import (
"testing" "testing"
"time" "time"
"github.com/mixeme/selfpost/internal/store"
) )
type refusalProbe struct { type refusalProbe struct {
rows int // rows waiting for a line rows int // rows waiting for a line
lines []string lines []string
who []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) { func (r *refusalProbe) AttachRefusalLine(login, from string, _ time.Time, line string) (bool, error) {
@@ -56,3 +64,29 @@ func TestRefusalLines(t *testing.T) {
t.Fatal("a line kept waiting past its time") 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)
}
}
+4
View File
@@ -102,3 +102,7 @@ func TestRetentionLoopUsesUpdatedValue(t *testing.T) {
func (s *retentionProbeStore) AttachRefusalLine(string, string, time.Time, string) (bool, error) { func (s *retentionProbeStore) AttachRefusalLine(string, string, time.Time, string) (bool, error) {
return true, nil return true, nil
} }
func (s *retentionProbeStore) RecoverRefusal(store.SendLogEntry, time.Time) (bool, error) {
return false, nil
}
@@ -7,3 +7,9 @@
-- headers are judged), and its lines are found by it like any other's. -- 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. -- 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 ''; 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;
+36
View File
@@ -77,3 +77,39 @@ func TestSendLogLinesOfARefusalAreItsOwn(t *testing.T) {
t.Fatalf("lines = %+v, want its own alone", lines) 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)
}
}
+1 -1
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", "applications": "id domain_id login address_mode auth_ip_restrict auth_allowed_ips created_at",
"application_addresses": "id application_id address", "application_addresses": "id application_id address",
"rate_limits": "id scope ref_id max_messages window_seconds mode auto_multiplier auto_updated_at", "rate_limits": "id scope ref_id max_messages window_seconds mode auto_multiplier auto_updated_at",
"send_log": "id queue_id domain app_login from_addr to_addr subject status created_at updated_at reason header_from domain_id refusal_line", "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", "logtail_state": "path fingerprint read_offset updated_at",
"inbound_domains": "id name recipient_mode created_at", "inbound_domains": "id name recipient_mode created_at",
"inbound_transports": "inbound_domain_id host port tls_mode", "inbound_transports": "inbound_domain_id host port tls_mode",
+31 -3
View File
@@ -224,7 +224,10 @@ type SendLogRow struct {
// RefusalLine is Postfix's line about a refusal that has no queue id // RefusalLine is Postfix's line about a refusal that has no queue id
// (migration 0009); "" for every other row, and for one refused before. // (migration 0009); "" for every other row, and for one refused before.
RefusalLine string RefusalLine string
CreatedAt time.Time // 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 // 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. // the delivery attempt. It equals CreatedAt while a row is still queued.
UpdatedAt time.Time UpdatedAt time.Time
@@ -256,6 +259,31 @@ func (s *Store) AttachRefusalLine(login, from string, at time.Time, line string)
return n > 0, nil 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 // 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 // dated: the milter writes the row at MAIL FROM, Postfix the line a moment
// later, and the log's stamps are whole seconds. // later, and the log's stamps are whole seconds.
@@ -274,10 +302,10 @@ func (s *Store) GetSendLog(id int64) (SendLogRow, error) {
createdAt, updatedAt string createdAt, updatedAt string
) )
err := s.db.QueryRow( err := s.db.QueryRow(
`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 `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, FROM send_log WHERE id = ?`, id,
).Scan(&row.ID, &row.QueueID, &row.Domain, &row.DomainID, &row.AppLogin, &row.From, &row.To, ).Scan(&row.ID, &row.QueueID, &row.Domain, &row.DomainID, &row.AppLogin, &row.From, &row.To,
&row.Subject, &row.Status, &row.Reason, &row.HeaderFrom, &row.RefusalLine, &createdAt, &updatedAt) &row.Subject, &row.Status, &row.Reason, &row.HeaderFrom, &row.RefusalLine, &row.Recovered, &createdAt, &updatedAt)
if errors.Is(err, sql.ErrNoRows) { if errors.Is(err, sql.ErrNoRows) {
return SendLogRow{}, ErrSendLogNotFound return SendLogRow{}, ErrSendLogNotFound
} }
+1 -1
View File
@@ -104,7 +104,7 @@ func (h *Handlers) HandleDelivery(w http.ResponseWriter, r *http.Request) {
in := view.MessageInput{ in := view.MessageInput{
ID: row.ID, QueueID: row.QueueID, Domain: row.Domain, App: row.AppLogin, ID: row.ID, QueueID: row.QueueID, Domain: row.Domain, App: row.AppLogin,
From: row.From, To: row.To, Subject: row.Subject, Status: row.Status, 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, Accepted: row.CreatedAt, Reported: row.UpdatedAt,
// Where the row came from, so the way back returns to the page and filters // 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. // the operator was looking at rather than the top of an unfiltered log.
@@ -176,8 +176,9 @@ func TestMessagePageDrawsTheOutcomeAtItsLevel(t *testing.T) {
} }
} }
// A message the milter refused never reached the queue: it has no queue id and // A message the milter refused never reached the queue: it has no queue id,
// no lines to show, and says why instead of showing an empty log. // 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) { func TestMessagePageOfARefusedMessage(t *testing.T) {
h, _ := serverWithDelivery(t) h, _ := serverWithDelivery(t)
if err := h.store.InsertRejected(store.SendLogEntry{ 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)) t.Fatalf("query: %v (%d rows)", err, len(rows))
} }
body := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(rows[0].ID)) 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`) lacks(t, "refused message", body, `<pre`)
} }
+8 -2
View File
@@ -173,8 +173,11 @@ type MessageInput struct {
// (store.Reason*) and, for its From: line, what that line said. // (store.Reason*) and, for its From: line, what that line said.
Reason string Reason string
HeaderFrom string HeaderFrom string
Accepted time.Time // Recovered is a refused row the log tailer wrote from mail.log: the
Reported time.Time // 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 is the log the message was opened from, filters and page kept.
BackHref string BackHref string
} }
@@ -258,6 +261,9 @@ func NewOutMessage(m Meta, in MessageInput) *OutMessage {
facts = append(facts, Fact{Label: "From: line", Value: Plain(orDash(in.HeaderFrom)), Mono: true, Small: true}) 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:") history.Help = topicLink(HelpSenderCheck, "What an application may write in From:")
} }
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 != "" { if in.QueueID != "" {
facts = append(facts, Fact{Label: "Queue id", Value: Rich(Mono(in.QueueID), " — given, the message was not queued")}) facts = append(facts, Fact{Label: "Queue id", Value: Rich(Mono(in.QueueID), " — given, the message was not queued")})
} else { } else {
+10
View File
@@ -148,6 +148,16 @@ func TestOutMessageRefusedForItsFromLine(t *testing.T) {
`Lines from <code>mail.log</code> with this queue id`, `<span class="sp-e">postfix/cleanup[2120]: 7BCAF3C75DA0: milter-reject`) `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) { func TestSendLogTag(t *testing.T) {
for _, c := range []struct { for _, c := range []struct {
status, reason string status, reason string
+3
View File
@@ -316,6 +316,9 @@ func TestE2E(t *testing.T) {
run("refusals_show_postfixs_line", func(t *testing.T) { run("refusals_show_postfixs_line", func(t *testing.T) {
testRefusalsShowPostfixsLine(t, sc) 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) { run("lines_naming_another_sender_never_signed_for_it", func(t *testing.T) {
testNeverSignedForAnother(t, sc) testNeverSignedForAnother(t, sc)
}) })
+80
View File
@@ -378,3 +378,83 @@ func testRefusalsShowPostfixsLine(t *testing.T, sc *scenario) {
} }
} }
} }
// 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)
}
}