findings of the reviews of audit stage 2b

Technical review (Opus) and security review (Fable) of 5be109b..5154bba;
reports in the session's scratchpad. Nothing above low from security; one
bug and three risks from the technical review. Migration 0009 is not
deployed, so it was extended.

- Bug: two refusals of one second swapped their NOQUEUE lines (each line
  went to the newest lineless row). AttachRefusalLine now matches the
  client address too (send_log.client_ip, written by the journal milter -
  Postfix's line names the client and the sender, never the login: the
  sasl_username part of the pattern never matched and could be fed by HELO,
  security F1/F2), takes the nearest row in time and the oldest of equals,
  and a line already on a row goes on no other (security F6).
- Waiting lines and recoveries lived only in memory while the saved offset
  moved past them: a stop within 30 s lost them. The tracker now never saves
  an offset past the oldest waiting item in its file (tracker.hold,
  refusalLines.oldest) - for a recovery, the client= line that names its
  login - so they are read again; the "once" guards make that harmless.
- A recovered row whose login the tailer did not see was nobody's: its
  domain_id falls back to the envelope domain's.
- The fingerprint's file identity is the inode alone: the device number can
  change across a host reboot and make the same log look rotated.
- A refused row carries its queue id; UpdateStatus's "newest row" now skips
  refused rows, so a later message with that id does not flip it to sent.
- The alive mark: its age is read first and kept from then on, so asking
  supervisord for 30 s cannot make it stale; the entrypoint removes it with
  the sockets - a container restart is not the check's downtime, and a mark
  from before would have counted the whole outage as "≈".
- Security F3: the sender check prints no ";" of the client's in the From:
  text of its reply, and the tailer reads the envelope after the first ";"
  - Postfix's own text.
- A refused row with a queue id and no stored lines says so (it was told the
  mail.log text of 2.2.0); the fact's em dash is the house hyphen.
- Docs: architecture (client address, no login), guide § Health (warns on
  either count), help topics log and sender-check (design 1ca87f2).
- e2e: refusals_show_postfixs_line wants the refusal's own sender in the
  line; refusal_recovered_from_the_log waits past the tailer's 30 s and
  checks that a refusal the panel wrote got no recovered twin.

Not changed, written down: review 9 (mail.log.1 read to its end at that
moment; postlogd may still write to it until the reload), 10 (a log under
512 bytes has no fingerprint, so places fall back to time briefly after a
rotation), 6 (a 451 at MAIL FROM of another milter reads the same - the
client and sender must match too now), security F5/F12 (info). Review 12:
the refused and closed-by-the-panel variants of out-message were shown to
the owner as pictures of the real templates, not drawn in out-message.html:
the guard ties every drawn screen to a page of the engine, and a variant
has the page's outline.

Evidence on the test server for this tree: go vet clean, go test ./... 23
packages ok, make e2e exit 0 (refusal_recovered_from_the_log 70 s).

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
mix
2026-10-14 18:38:22 +03:00
co-authored by Claude Opus 5.5
parent 1ca87f2d1a
commit af130e268a
22 changed files with 295 additions and 116 deletions
+7 -4
View File
@@ -8,9 +8,12 @@ import (
"syscall"
)
// fileID names the file itself - device and inode - which a rename keeps and
// a new file does not share. It is part of the log's fingerprint, so two log
// files whose first bytes happen to match are still told apart.
// fileID names the file itself - its inode - which a rename keeps and a new
// file does not share. It is part of the log's fingerprint, so two log files
// whose first bytes happen to match are still told apart. The device number
// is left out: it can change across a host's reboot (LVM, btrfs, network
// file systems), and the same log would then pass for a rotated one (review
// of stage 2b).
func fileID(f *os.File) string {
info, err := f.Stat()
if err != nil {
@@ -20,5 +23,5 @@ func fileID(f *os.File) string {
if !ok {
return ""
}
return fmt.Sprintf("%d.%d", st.Dev, st.Ino)
return fmt.Sprintf("%d", st.Ino)
}
+3 -2
View File
@@ -168,7 +168,7 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa
keeper.flush()
refusals.retry(time.Now().UTC())
}
tr := &tracker{st: st, path: path}
tr := &tracker{st: st, path: path, hold: refusals.oldest}
return follow(ctx, path, tr, caughtUp, flush, func(line string) {
// Until the first read reaches end-of-file the lines are those written
// while the panel was down - and, after an unclean stop, some it had
@@ -187,7 +187,7 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa
deferred.handle(line, now, catchingUp, tr.line)
}
keeper.add(line, now, catchingUp)
refusals.handle(line, now)
refusals.handle(line, now, Place{FP: tr.line.FP, End: tr.lineStart})
queueID, recipient, status, ok := parseDelivery(line)
if !ok {
return
@@ -647,6 +647,7 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
full := pending + line
pending = ""
tr.line = Place{FP: tr.fp, End: consumed}
tr.lineStart = consumed - int64(len(full))
handle(strings.TrimRight(full, "\r\n"))
}
}
+16 -3
View File
@@ -47,9 +47,16 @@ type tracker struct {
behind bool
prev store.LogtailState
// line is the place of the line being handled: set by follow and
// readRotated before each call of handle.
line Place
// line is the place of the line being handled, lineStart the offset it
// starts at: set by follow and readRotated before each call of handle.
line Place
lineStart int64
// hold, when set, names the earliest place in a file that something read
// from the log still waits on (a refusal's line, a refusal to recover):
// no offset past it is saved, so a stop - clean or not - before the wait
// is over reads it again (review of stage 2b).
hold func(fp string) (Place, bool)
}
// Place is where a line of the log ends: the fingerprint of its file and the
@@ -158,6 +165,7 @@ func (t *tracker) readRotated(handle func(string)) bool {
r := bufio.NewReader(f)
for {
line, err := r.ReadString('\n')
t.lineStart = end
end += int64(len(line))
if line != "" {
t.line = Place{FP: fp, End: end}
@@ -198,6 +206,11 @@ func (t *tracker) adopt(f *os.File) {
// record persists offset, at most once per persistInterval unless force is set
// (rotation and shutdown, where the write must not be skipped).
func (t *tracker) record(f *os.File, offset int64, force bool) {
if t.hold != nil {
if p, ok := t.hold(t.fp); ok && p.End < offset {
offset = p.End
}
}
if offset == t.saved {
return
}
+60 -18
View File
@@ -2,6 +2,7 @@ package logtail
import (
"log"
"net"
"regexp"
"strings"
"time"
@@ -12,13 +13,14 @@ import (
// Postfix's line about a message the journal milter refused at MAIL FROM - a
// level-2 limit, a client address off the application's list - is put on the
// row the milter wrote, so the message's page shows it (audit 2026-10-12,
// stage 2b). The refusal has no queue id; the line is matched to its row by
// sender, login and time. As the stand writes it:
// stage 2b). The refusal has no queue id and the line no login; it is
// matched to its row by client address, sender and time. As the stand writes
// it:
//
// postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from=<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]*)>?)?`)
var refusalLineRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: NOQUEUE: milter-reject: MAIL from [^\[\s]*\[([^\]]+)\]: [45]\d\d .*?; from=<([^>]*)>`)
// refusalLineWait is how long a line waits for its row: the milter writes the
// row when it refuses, which can be read a moment after the line.
@@ -26,7 +28,7 @@ const refusalLineWait = 30 * time.Second
// RefusalStore is where the lines go. *store.Store satisfies it.
type RefusalStore interface {
AttachRefusalLine(login, from string, at time.Time, line string) (bool, error)
AttachRefusalLine(clientIP, from string, at time.Time, line string) (bool, error)
RecoverRefusal(e store.SendLogEntry, at time.Time) (bool, error)
}
@@ -36,8 +38,10 @@ type RefusalStore interface {
// postfix/cleanup[1339]: E543D3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: director@other.e2e.test - not an address this application sends as; from=<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=<([^>]*)>`)
// first semicolon; the reason after it holds neither, and the check prints no
// ";" of the client's (sender.go printable), so that semicolon is Postfix's
// and what follows it - the envelope - is Postfix's own text.
var fromRefusalRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?cleanup\[\d+\]: ([0-9A-Za-z]+): milter-reject: END-OF-MESSAGE from \S+: 5\.7\.1 From: ([^;]*) - ([^;]*); from=<([^>]*)> to=<([^>]*)>`)
// clientLoginRe is smtpd's line naming the login a queue id was submitted
// under: "<id>: client=host[addr], sasl_method=PLAIN, sasl_username=<login>".
@@ -47,8 +51,9 @@ var clientLoginRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d
const refusalLogins = 4096
type pendingRefusal struct {
login, from, line string
at, until time.Time
clientIP, from, line string
at, until time.Time
start Place // where the line starts in the log
}
// pendingRecovery is a From: refusal whose row is looked for once the panel
@@ -56,6 +61,14 @@ type pendingRefusal struct {
type pendingRecovery struct {
e store.SendLogEntry
at, until time.Time
start Place // where its client= line - or the refusal - starts
}
// loginLine is the login a queue id was submitted under and where smtpd's
// line saying so starts.
type loginLine struct {
login string
start Place
}
// refusalLines puts each refusal line on its row, and keeps for a while the
@@ -65,24 +78,49 @@ type refusalLines struct {
st RefusalStore
pending []pendingRefusal
recover []pendingRecovery
logins map[string]string // queue id -> login, from smtpd's client= line
logins map[string]loginLine // queue id -> login, from smtpd's client= line
loginKeys []string
}
// handle looks at one mail.log line.
func (r *refusalLines) handle(line string, now time.Time) {
// oldest is the earliest place in the file fp a waiting item starts at: the
// tracker saves no offset past it, so a stop before the wait is over reads the
// lines again - the client= line of a refusal to recover among them.
func (r *refusalLines) oldest(fp string) (Place, bool) {
var p Place
found := false
take := func(q Place) {
if q.FP == fp && (!found || q.End < p.End) {
p, found = q, true
}
}
for _, x := range r.pending {
take(x.start)
}
for _, x := range r.recover {
take(x.start)
}
return p, found
}
// handle looks at one mail.log line, which starts at start.
func (r *refusalLines) handle(line string, now time.Time, start Place) {
at, rest := lineTime(line, now)
if m := clientLoginRe.FindStringSubmatch(rest); m != nil && m[1] != "inbound" {
r.remember(m[2], m[3])
r.remember(m[2], loginLine{login: m[3], start: start})
return
}
if m := fromRefusalRe.FindStringSubmatch(rest); m != nil {
from := start
login, ok := r.logins[m[1]]
if ok && login.start.FP == start.FP && login.start.End < start.End {
from = login.start
}
r.recover = append(r.recover, pendingRecovery{
e: store.SendLogEntry{
QueueID: m[1], AppLogin: r.logins[m[1]], From: m[4], To: m[5], Domain: domainOf(m[4]),
QueueID: m[1], AppLogin: login.login, From: m[4], To: m[5], Domain: domainOf(m[4]),
Reason: store.ReasonFrom, HeaderFrom: m[2],
},
at: at, until: now.Add(refusalLineWait),
at: at, until: now.Add(refusalLineWait), start: from,
})
return
}
@@ -90,7 +128,11 @@ func (r *refusalLines) handle(line string, now time.Time) {
if m == nil || m[1] == "inbound" {
return
}
p := pendingRefusal{login: m[3], from: m[2], line: line, at: at, until: now.Add(refusalLineWait)}
ip := net.ParseIP(strings.TrimPrefix(m[2], "IPv6:"))
if ip == nil {
return
}
p := pendingRefusal{clientIP: ip.String(), from: m[3], line: line, at: at, until: now.Add(refusalLineWait), start: start}
if !r.attach(p) {
r.pending = append(r.pending, p)
}
@@ -127,9 +169,9 @@ func (r *refusalLines) retry(now time.Time) {
// remember keeps the login a queue id was submitted under, the oldest going
// first beyond refusalLogins.
func (r *refusalLines) remember(queueID, login string) {
func (r *refusalLines) remember(queueID string, login loginLine) {
if r.logins == nil {
r.logins = make(map[string]string)
r.logins = make(map[string]loginLine)
}
if _, ok := r.logins[queueID]; !ok {
r.loginKeys = append(r.loginKeys, queueID)
@@ -150,7 +192,7 @@ func domainOf(addr string) string {
}
func (r *refusalLines) attach(p pendingRefusal) bool {
ok, err := r.st.AttachRefusalLine(p.login, p.from, p.at, p.line)
ok, err := r.st.AttachRefusalLine(p.clientIP, p.from, p.at, p.line)
if err != nil {
log.Printf("log-tailer: refusal line: %v", err)
return true // not retried: the store said no for its own reason
+40 -8
View File
@@ -19,13 +19,13 @@ func (r *refusalProbe) RecoverRefusal(e store.SendLogEntry, _ time.Time) (bool,
return true, nil
}
func (r *refusalProbe) AttachRefusalLine(login, from string, _ time.Time, line string) (bool, error) {
func (r *refusalProbe) AttachRefusalLine(clientIP, from string, _ time.Time, line string) (bool, error) {
if r.rows == 0 {
return false, nil
}
r.rows--
r.lines = append(r.lines, line)
r.who = append(r.who, login+"|"+from)
r.who = append(r.who, clientIP+"|"+from)
return true, nil
}
@@ -42,23 +42,23 @@ func TestRefusalLines(t *testing.T) {
`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`,
`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: NOQUEUE: reject: RCPT from unknown[10.77.0.1]: 553 5.7.1 <a@x>: Sender address rejected: not owned by user app1; from=<a@x> to=<b@y> proto=ESMTP helo=<x>`,
} {
r.handle(other, now)
r.handle(other, now, Place{})
}
if len(r.pending) != 0 {
t.Fatalf("lines that are not an application's refusal at MAIL wait: %+v", r.pending)
}
r.handle(limit, now) // its row is not there yet
r.handle(limit, now, Place{}) // its row is not there yet
if len(r.pending) != 1 {
t.Fatalf("pending %d, want the line waiting", len(r.pending))
}
st.rows = 1 // the milter's row is written
r.retry(now.Add(time.Second))
if len(r.pending) != 0 || len(st.lines) != 1 || st.who[0] != "l2app|billing@sender.e2e.test" {
if len(r.pending) != 0 || len(st.lines) != 1 || st.who[0] != "10.77.0.1|billing@sender.e2e.test" {
t.Fatalf("after the retry: pending %d, attached %v", len(r.pending), st.who)
}
r.handle(limit, now) // no row ever comes
r.handle(limit, now, Place{}) // no row ever comes
r.retry(now.Add(refusalLineWait + time.Second))
if len(r.pending) != 0 {
t.Fatal("a line kept waiting past its time")
@@ -73,8 +73,8 @@ func TestFromRefusalIsRecoveredAfterTheWait(t *testing.T) {
now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC)
st := &refusalProbe{}
r := &refusalLines{st: st}
r.handle(`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: E543D3C75DA0: client=unknown[10.77.0.1], sasl_method=PLAIN, sasl_username=app1`, now)
r.handle(`2026-10-14T12:00:01+00:00 mail postfix/cleanup[13]: E543D3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: "The - Shop" <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.handle(`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: E543D3C75DA0: client=unknown[10.77.0.1], sasl_method=PLAIN, sasl_username=app1`, now, Place{})
r.handle(`2026-10-14T12:00:01+00:00 mail postfix/cleanup[13]: E543D3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: "The - Shop" <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, Place{})
r.retry(now.Add(time.Second))
if len(st.recovered) != 0 {
t.Fatal("recovered before the panel had the time to write the row")
@@ -90,3 +90,35 @@ func TestFromRefusalIsRecoveredAfterTheWait(t *testing.T) {
t.Fatalf("recovered %+v, want %+v", e, want)
}
}
// While a line or a recovery waits, the offset saved for its file stays at the
// earliest line it needs - for a recovery the client= line that names its
// login - so a stop before the wait is over reads them again (review of stage
// 2b).
func TestWaitingLinesHoldTheSavedOffset(t *testing.T) {
now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC)
r := &refusalLines{st: &refusalProbe{}}
if _, held := r.oldest("fp"); held {
t.Fatal("nothing waits, yet the offset is held")
}
r.handle(`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: Q1: client=unknown[10.77.0.1], sasl_method=PLAIN, sasl_username=app1`, now, Place{FP: "fp", End: 100})
r.handle(`2026-10-14T12:00:01+00:00 mail postfix/cleanup[13]: Q1: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: d@other.example - not an address this application sends as; from=<a@sender.example> to=<r@x> proto=ESMTP helo=<x>`, now, Place{FP: "fp", End: 300})
if p, held := r.oldest("fp"); !held || p.End != 100 {
t.Fatalf("held at %+v %v, want the client= line at 100", p, held)
}
if _, held := r.oldest("another"); held {
t.Fatal("a place in another file holds this one")
}
r.retry(now.Add(refusalLineWait + time.Second))
if _, held := r.oldest("fp"); held {
t.Fatal("still held after the wait")
}
// The tracker clamps what it saves to the hold.
cs := &captureStore{}
tr := &tracker{st: cs, path: "x", fp: "fp", hold: func(string) (Place, bool) { return Place{FP: "fp", End: 50}, true }}
tr.record(nil, 400, true)
if cs.state.Offset != 50 {
t.Fatalf("saved %d, want the hold at 50", cs.state.Offset)
}
}
+1
View File
@@ -103,6 +103,7 @@ func (s *session) recordRejected(reason string) {
AppLogin: s.login,
From: s.from,
Reason: reason,
ClientIP: s.clientIP, // Postfix's line about the refusal names it
})
if err != nil {
log.Printf("journal-milter: record rejected %s: %v", s.from, err)
+5
View File
@@ -463,6 +463,11 @@ func printable(v string) string {
switch {
case r == '%' || r < 0x20 || r > 0x7e:
sb.WriteByte('?')
case r == ';':
// Postfix logs the reply and then "; from=<...> to=<...>" of
// its own; a ";" of the client's would let its text pass for
// Postfix's where the log tailer reads that line.
sb.WriteByte(',')
default:
sb.WriteRune(r)
}
@@ -7,6 +7,12 @@
-- headers are judged), and its lines are found by it like any other's.
-- DDL only; a row written earlier has '' and says so on its page.
ALTER TABLE send_log ADD COLUMN refusal_line TEXT NOT NULL DEFAULT '';
-- The client a refusal at MAIL FROM came from, as the milter saw it: Postfix's
-- line names the client and the envelope sender and nothing else - no login
-- - so the two together are what finds the line's row; the sender alone would
-- let one application's line land on another's row of the same sender
-- (security review of stage 2b).
ALTER TABLE send_log ADD COLUMN client_ip TEXT NOT NULL DEFAULT '';
-- A refusal row the panel did not get to write - the sender check answers 550
-- and writes the row a moment later, and a panel stopped in between wrote
+57 -23
View File
@@ -1,20 +1,23 @@
package store
import (
"fmt"
"testing"
"time"
)
// Postfix's line about a refusal at MAIL FROM goes on the row of that sender
// and login refused about then, the newest without a line; a queued row, a
// row of another sender and a row from long ago are not it (audit
// 2026-10-12, stage 2b).
// Postfix's line about a refusal at MAIL FROM goes on the row of that client
// and sender refused about then; a queued row, a row of another client or
// sender, and a row from long ago are not it; a line already on a row goes on
// no other; and two refusals of one second take one line each, in the order
// they were written (security and technical reviews of stage 2b).
func TestAttachRefusalLine(t *testing.T) {
st := openTestStore(t)
now := time.Now().UTC()
for _, e := range []SendLogEntry{
{AppLogin: "l2app", From: "billing@example.com", Reason: ReasonLimit},
{AppLogin: "l2app", From: "other@example.com", Reason: ReasonLimit},
{AppLogin: "l2app", From: "billing@example.com", Reason: ReasonLimit, ClientIP: "10.0.0.1"},
{AppLogin: "l2app", From: "billing@example.com", Reason: ReasonLimit, ClientIP: "10.0.0.1"},
{AppLogin: "other", From: "billing@example.com", Reason: ReasonClient, ClientIP: "10.0.0.2"},
} {
if err := st.InsertRejected(e); err != nil {
t.Fatal(err)
@@ -23,33 +26,37 @@ func TestAttachRefusalLine(t *testing.T) {
if err := st.InsertQueued(SendLogEntry{QueueID: "Q1", AppLogin: "l2app", From: "billing@example.com", To: "x@example.net"}); err != nil {
t.Fatal(err)
}
line := "Oct 14 12:00:00 mail postfix/smtpd[1]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable"
if ok, err := st.AttachRefusalLine("l2app", "Billing@example.com", now, line); err != nil || !ok {
t.Fatalf("attach = %v, %v", ok, err)
first := "Oct 14 12:00:00 mail postfix/smtpd[1]: NOQUEUE: milter-reject: MAIL from unknown[10.0.0.1]: 451 4.7.1 first"
second := "Oct 14 12:00:00 mail postfix/smtpd[2]: NOQUEUE: milter-reject: MAIL from unknown[10.0.0.1]: 451 4.7.1 second"
for _, line := range []string{first, second} {
if ok, err := st.AttachRefusalLine("10.0.0.1", "Billing@example.com", now, line); err != nil || !ok {
t.Fatalf("attach %q = %v, %v", line, ok, err)
}
}
// The row has its line now; a second line finds no row without one.
if ok, _ := st.AttachRefusalLine("l2app", "billing@example.com", now, line); ok {
t.Fatal("a second line took a row that has one")
// Read again after a restart: no row takes it a second time.
if ok, _ := st.AttachRefusalLine("10.0.0.1", "billing@example.com", now, first); ok {
t.Fatal("a line already on a row took another")
}
if ok, _ := st.AttachRefusalLine("l2app", "other@example.com", now.Add(-time.Hour), line); ok {
if ok, _ := st.AttachRefusalLine("10.0.0.3", "billing@example.com", now, "a third"); ok {
t.Fatal("a line of another client took a row")
}
if ok, _ := st.AttachRefusalLine("10.0.0.2", "billing@example.com", now.Add(-time.Hour), "an hour off"); ok {
t.Fatal("a line an hour off took a row")
}
if ok, _ := st.AttachRefusalLine("someone", "other@example.com", now, line); ok {
t.Fatal("a line of another login took a row")
}
lines := map[string]string{}
rows, _ := st.QuerySendLog(SendLogFilter{AllDomains: true}, 10, 0)
got := 0
for _, r := range rows {
full, _ := st.GetSendLog(r.ID)
if full.RefusalLine != "" {
got++
if full.From != "billing@example.com" || full.Status != StatusRejected {
t.Errorf("the line went to %+v", full)
}
lines[fmt.Sprint(full.ID)] = full.RefusalLine
}
}
if got != 1 {
t.Fatalf("%d rows have a line, want 1", got)
if len(lines) != 2 {
t.Fatalf("lines on rows: %v, want the first two rows", lines)
}
r1, _ := st.GetSendLog(rows[len(rows)-1].ID) // the oldest row
if r1.RefusalLine != first {
t.Fatalf("the first row has %q, want the first line", r1.RefusalLine)
}
}
@@ -113,3 +120,30 @@ func TestRecoverRefusal(t *testing.T) {
t.Fatalf("the recovered row: %+v", found)
}
}
// A recovered row whose login the tailer did not see is its envelope
// domain's, not nobody's (review of stage 2b).
func TestRecoverRefusalWithoutALogin(t *testing.T) {
st := openTestStore(t)
d := addTestDomain(t, st, "sender.example")
e := SendLogEntry{QueueID: "NOLOGIN", From: "a@sender.example", To: "r@x", Domain: "sender.example", Reason: ReasonFrom}
if wrote, err := st.RecoverRefusal(e, time.Now()); err != nil || !wrote {
t.Fatalf("recover = %v, %v", wrote, err)
}
rows, _ := st.QuerySendLog(SendLogFilter{DomainIDs: []int64{d.ID}}, 10, 0)
if len(rows) != 1 {
t.Fatalf("the domain's log has %d rows, want the recovered one", len(rows))
}
}
// A refused row carries the queue id it was given; a delivery line of a later
// message with that id does not touch it.
func TestUpdateStatusLeavesARefusalAlone(t *testing.T) {
st := openTestStore(t)
if err := st.InsertRejected(SendLogEntry{QueueID: "REUSED", To: "a@example.net", Reason: ReasonFrom}); err != nil {
t.Fatal(err)
}
if n, err := st.UpdateStatus("REUSED", "a@example.net", StatusSent); err != nil || n != 0 {
t.Fatalf("UpdateStatus = %d, %v; want 0 rows", n, err)
}
}
+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",
"application_addresses": "id application_id address",
"rate_limits": "id scope ref_id max_messages window_seconds mode auto_multiplier auto_updated_at",
"send_log": "id queue_id domain app_login from_addr to_addr subject status created_at updated_at reason header_from domain_id refusal_line recovered",
"send_log": "id queue_id domain app_login from_addr to_addr subject status created_at updated_at reason header_from domain_id refusal_line client_ip recovered",
"logtail_state": "path fingerprint read_offset updated_at",
"inbound_domains": "id name recipient_mode created_at",
"inbound_transports": "inbound_domain_id host port tls_mode",
+33 -19
View File
@@ -38,6 +38,9 @@ type SendLogEntry struct {
// was refused (Reason*), and for ReasonFrom what its From: line said.
Reason string
HeaderFrom string
// ClientIP is the client a refusal at MAIL FROM came from (InsertRejected
// only), which Postfix's line about it names.
ClientIP string
}
// loginDomainID is the domain_id a row is written with: the domain of the
@@ -73,9 +76,9 @@ func (s *Store) InsertRejected(e SendLogEntry) error {
now := time.Now().UTC().Format(time.RFC3339)
_, err := s.db.Exec(
`INSERT INTO send_log
(queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, created_at, updated_at, domain_id)
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, `+loginDomainID+`)`,
e.QueueID, e.Domain, e.AppLogin, e.From, e.To, e.Subject, StatusRejected, e.Reason, e.HeaderFrom, now, now, e.AppLogin,
(queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, client_ip, created_at, updated_at, domain_id)
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, `+loginDomainID+`)`,
e.QueueID, e.Domain, e.AppLogin, e.From, e.To, e.Subject, StatusRejected, e.Reason, e.HeaderFrom, e.ClientIP, now, now, e.AppLogin,
)
if err != nil {
return fmt.Errorf("insert rejected send_log: %w", err)
@@ -113,7 +116,9 @@ func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) {
return 0, fmt.Errorf("update send_log status: %w", err)
}
defer tx.Rollback()
const newest = `id = (SELECT MAX(id) FROM send_log WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE)`
// A refused row carries the queue id it was given, and that id may be the
// next message's: a delivery line is never about a refusal.
const newest = `id = (SELECT MAX(id) FROM send_log WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE AND status <> 'rejected')`
marked, err := tx.Exec(
`UPDATE send_log SET reason = ? WHERE `+newest+` AND reason = ?`,
ReasonReconcileContradicted, queueID, recipient, ReasonReconcile,
@@ -235,22 +240,27 @@ type SendLogRow struct {
// AttachRefusalLine puts Postfix's line about a refusal at MAIL FROM on the
// row the journal milter wrote for it (audit 2026-10-12, stage 2b). Such a
// refusal has no queue id, so the row is found by what the line says: a
// refused row of that sender - and login, when the line names one - without a
// line yet, written within two minutes of the line's time; the newest when
// there are several. It reports whether a row took the line.
func (s *Store) AttachRefusalLine(login, from string, at time.Time, line string) (bool, error) {
// refusal has no queue id, and the line names no login, so the row is found
// by what the line says: a refused row of that client and sender without a
// line yet, written within two minutes of the line's time; the nearest in
// time, the oldest of equals, when there are several - lines are read in the
// order the rows were written, so two refusals of one second take one line
// each in turn (review of stage 2b). A line already on a row - read again
// after a restart - goes on no other. It reports whether a row took the line.
func (s *Store) AttachRefusalLine(clientIP, from string, at time.Time, line string) (bool, error) {
res, err := s.db.Exec(
`UPDATE send_log SET refusal_line = ? WHERE id = (
`UPDATE send_log SET refusal_line = ?1 WHERE id = (
SELECT id FROM send_log
WHERE status = ? AND queue_id = '' AND refusal_line = ''
AND reason IN ('', ?, ?) AND from_addr = ? COLLATE NOCASE
AND (? = '' OR app_login = ?)
AND created_at BETWEEN ? AND ?
ORDER BY id DESC LIMIT 1)`,
line, StatusRejected, ReasonLimit, ReasonClient, from, login, login,
WHERE status = ?2 AND queue_id = '' AND refusal_line = ''
AND reason IN ('', ?3, ?4) AND from_addr = ?5 COLLATE NOCASE AND client_ip = ?6
AND created_at BETWEEN ?7 AND ?8
ORDER BY ABS(julianday(created_at) - julianday(?9)), id
LIMIT 1)
AND NOT EXISTS (SELECT 1 FROM send_log WHERE refusal_line = ?1)`,
line, StatusRejected, ReasonLimit, ReasonClient, from, clientIP,
at.Add(-refusalLineWindow).UTC().Format(time.RFC3339),
at.Add(refusalLineWindow).UTC().Format(time.RFC3339),
at.UTC().Format(time.RFC3339),
)
if err != nil {
return false, fmt.Errorf("attach refusal line: %w", err)
@@ -264,16 +274,20 @@ func (s *Store) AttachRefusalLine(login, from string, at time.Time, line string)
// wrote the row itself (audit 2026-10-12, stage 2b): the check answers 550
// and writes the row through a buffer a moment later. The message had a queue
// id; a refused row with that id from around at means the row was written,
// and nothing is. It reports whether it wrote one.
// and nothing is. The domain is the login's, or - when the tailer did not see the login, its
// client= line read before a restart - the envelope's, so the row is still
// its domain's administrator's (review of stage 2b). It reports whether it
// wrote one.
func (s *Store) RecoverRefusal(e SendLogEntry, at time.Time) (bool, error) {
stamp := at.UTC().Format(time.RFC3339)
res, err := s.db.Exec(
`INSERT INTO send_log
(queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, recovered, created_at, updated_at, domain_id)
SELECT ?, ?, ?, ?, ?, '', ?, ?, ?, 1, ?, ?, `+loginDomainID+`
SELECT ?, ?, ?, ?, ?, '', ?, ?, ?, 1, ?, ?,
COALESCE(`+loginDomainID+`, (SELECT d.id FROM domains d WHERE d.name = ?))
WHERE NOT EXISTS (SELECT 1 FROM send_log
WHERE queue_id = ? AND status = ? AND created_at BETWEEN ? AND ?)`,
e.QueueID, e.Domain, e.AppLogin, e.From, e.To, StatusRejected, e.Reason, e.HeaderFrom, stamp, stamp, e.AppLogin,
e.QueueID, e.Domain, e.AppLogin, e.From, e.To, StatusRejected, e.Reason, e.HeaderFrom, stamp, stamp, e.AppLogin, e.Domain,
e.QueueID, StatusRejected,
at.Add(-refusalLineWindow).UTC().Format(time.RFC3339), at.Add(refusalLineWindow).UTC().Format(time.RFC3339),
)
@@ -273,6 +273,9 @@ func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) {
return nil, "Could not read the mail log."
}
}
if len(lines) == 0 && row.Status == store.StatusRejected {
return nil, "Postfix's lines about this refusal are not stored: the message was refused before version 2.5.1, or the lines were never read."
}
if len(lines) == 0 {
return nil, "Nothing is stored for this queue id and nothing is in the current mail log. Lines are kept with the row since version 2.2.0; a message accepted before that had them only in mail.log, which has since rotated."
}
+2 -2
View File
@@ -162,12 +162,12 @@ func TestARefusedMessageShowsPostfixsLine(t *testing.T) {
d, _ := st.AddDomain("example.org", "mail")
st.AddApplication(d.ID, "alerts", store.AddressModeWildcard, nil)
for _, subject := range []string{"with its line", "from before"} {
if err := st.InsertRejected(store.SendLogEntry{Domain: "example.org", AppLogin: "alerts", From: "alerts@example.org", Subject: subject, Reason: store.ReasonLimit}); err != nil {
if err := st.InsertRejected(store.SendLogEntry{Domain: "example.org", AppLogin: "alerts", From: "alerts@example.org", Subject: subject, Reason: store.ReasonLimit, ClientIP: "198.51.100.7"}); err != nil {
t.Fatal(err)
}
if subject == "with its line" {
line := time.Now().UTC().Format("2006-01-02T15:04:05Z") + " mail postfix/smtpd[2131]: NOQUEUE: milter-reject: MAIL from unknown[198.51.100.7]: 451 4.7.1 Service unavailable - try again later; from=<alerts@example.org> proto=ESMTP helo=<app>"
if ok, err := st.AttachRefusalLine("alerts", "alerts@example.org", time.Now(), line); err != nil || !ok {
if ok, err := st.AttachRefusalLine("198.51.100.7", "alerts@example.org", time.Now(), line); err != nil || !ok {
t.Fatalf("attach = %v, %v", ok, err)
}
}
+2 -2
View File
@@ -171,14 +171,14 @@ var outboundTopics = []HelpTopic{
Code("From:"), " - another of your domains, the server's own name, an address somewhere else, or none at all - is refused for good with ",
Code("550 5.7.1"), ". It is a rejected row of the Outbound log, and its page says which address was refused. This is what keeps one application from getting mail signed with another domain's key.",
Br(), Br(),
"The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, at most what Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own."),
"The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, which may be more than Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own."),
}},
{ID: HelpLimits, Title: "Rate limits", Body: []Text{
Rich("Level 1 is a per-IP ceiling set in ", Code(".env"), ". Level 2 is optional, per domain and per application, entered by hand or computed from the last 30 days of sending, and can never exceed level 1. An application's own limit replaces its domain's."),
}},
{ID: HelpLog, Title: "Outbound log", Body: []Text{
Rich("One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out; or closed by the panel when Postfix no longer held the message and ", Code("mail.log"), " never said what became of it) and rejected (refused before queueing, so it never reached the queue: under a level-2 rate limit, from a client address the application does not allow, or for a ", Code("From:"), " line that is not the application's - the message's page says which). A message's page lists these steps and the lines Postfix wrote about it in ",
Code("mail.log"), ", found by queue id. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains."),
Code("mail.log"), ", found by queue id - and for a message refused before it had one, Postfix's one line about the refusal. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains."),
}},
{ID: HelpQueue, Title: "Queue and retries", Body: []Text{
Rich("The page lists, as ", Code("postqueue -p"), " prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged."),
+1 -1
View File
@@ -265,7 +265,7 @@ func NewOutMessage(m Meta, in MessageInput) *OutMessage {
facts = append(facts, Fact{Label: "Written", Value: Rich("from ", Code("mail.log"), " after a restart: the panel stopped before it wrote the refusal")})
}
if in.QueueID != "" {
facts = append(facts, Fact{Label: "Queue id", Value: Rich(Mono(in.QueueID), " — given, the message was not queued")})
facts = append(facts, Fact{Label: "Queue id", Value: Rich(Mono(in.QueueID), " - given, the message was not queued")})
} else {
facts = append(facts, Fact{Label: "Queue id", Value: Rich("none - refused at ", Mono("MAIL FROM"), ", before one is given")})
delivery.End = Rich("The line from ", Code("mail.log"), " for this refusal")
+1 -1
View File
@@ -144,7 +144,7 @@ func TestOutMessageRefusedForItsFromLine(t *testing.T) {
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>`,
`<span class="sp-mono">7BCAF3C75DA0</span> — given, the message was not queued`, `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`)
}