delivery-log-storage: findings of the technical and security reviews

Neither review (read-only agents, Opus and Fable, over ae06d8b..815236a) has a Critical or High finding. What they found and what was done: - A stranger on port 25 could grow the table: every queue-id line of inbound mail was stored and pruned an hour or more later, his own message-id among them. The tailer now leaves out the lines of a queue id that postfix/inbound/smtpd opened, until qmgr removes the message or another listener opens one under the id; 4096 such ids are remembered. - A commit, so a disk sync, per stored line on the connection the journal milter shares, and a backlog written line by line. Lines are now written in one transaction per pass over the log, 500 at most, before the read offset is saved (InsertSendLogLines; follow() calls the keeper's flush). - The prune asked the send log once per line and ran hourly. It asks once per queue id and runs at start and with the six-hourly sweep; with port-25 mail left out there is little without a row to wait for. - The 4096-byte cut could split a character; it keeps characters whole. - security.md did not say that a backup now carries these lines, and the plan said the time window excludes a reused queue id where it only limits the chance to the row's queue lifetime. Both are corrected; the collision is recorded as an accepted risk with its trigger. - Tests that did not prove their comments: the prune is now tested with the sweep, a rejected row next to the prune, batching and the change from catching up to following, port-25 mail left out and its id reused. Left as found and written down in the plan: lines the tailer never reads (a file rotated away while the panel was down), and a message in the queue across the upgrade, which shows only its later lines. On the test server, for this tree: go vet clean, go test ./... 22 packages ok, make e2e ok. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:41:04 +03:00
parent 815236a607
commit a990e7cc23
14 changed files with 456 additions and 178 deletions
@@ -3,6 +3,7 @@ package store
 import (
 	"fmt"
 	"time"
+	"unicode/utf8"
 )

 // SendLogLine is one mail.log line Postfix wrote under a queue id, kept so a
@@ -25,44 +26,62 @@ const SendLogLineMax = 4096
 // is accepted, and the message body can take its time after that.
 const sendLogLineBefore = time.Hour

+// cutSendLogLine cuts a line to SendLogLineMax bytes, and not through the
+// middle of a character.
 func cutSendLogLine(line string) string {
-	if len(line) > SendLogLineMax {
-		return line[:SendLogLineMax]
+	if len(line) <= SendLogLineMax {
+		return line
 	}
-	return line
+	end := SendLogLineMax
+	for end > 0 && !utf8.RuneStart(line[end]) {
+		end--
+	}
+	return line[:end]
 }

-// InsertSendLogLine stores one line. The tailer calls it for every line headed
-// by a queue id, whether or not a send-log row exists for it yet.
-func (s *Store) InsertSendLogLine(l SendLogLine) error {
-	_, err := s.db.Exec(
-		`INSERT INTO send_log_lines (queue_id, logged_at, line) VALUES (?, ?, ?)`,
-		l.QueueID, l.At.UTC().Format(time.RFC3339), cutSendLogLine(l.Line),
-	)
-	if err != nil {
-		return fmt.Errorf("insert send_log_lines: %w", err)
+// InsertSendLogLines stores lines in one transaction and returns how many it
+// wrote. The tailer calls it with what it read in one pass over the log,
+// whether or not send-log rows exist for the queue ids yet: a commit per line
+// would be a disk sync per line, on the one connection the journal milter
+// writes through.
+//
+// With once set, a line is written only if the same line is not there already
+// under its queue id. That is for the lines the tailer reads again after an
+// unclean stop; a line carries its time and its process id, so two that are
+// equal are one line read twice.
+func (s *Store) InsertSendLogLines(lines []SendLogLine, once bool) (int, error) {
+	if len(lines) == 0 {
+		return 0, nil
 	}
-	return nil
-}
-
-// InsertSendLogLineOnce stores a line unless the same one is already there,
-// and reports whether it wrote. It is for the lines the tailer reads again
-// after an unclean stop; a line carries its time and its process id, so two
-// that are equal are one line read twice.
-func (s *Store) InsertSendLogLineOnce(l SendLogLine) (bool, error) {
-	line := cutSendLogLine(l.Line)
-	res, err := s.db.Exec(
-		`INSERT INTO send_log_lines (queue_id, logged_at, line)
-		 SELECT ?, ?, ?
-		 WHERE NOT EXISTS (SELECT 1 FROM send_log_lines WHERE queue_id = ? AND line = ?)`,
-		l.QueueID, l.At.UTC().Format(time.RFC3339), line,
-		l.QueueID, line,
-	)
-	if err != nil {
-		return false, fmt.Errorf("insert send_log_lines once: %w", err)
+	query := `INSERT INTO send_log_lines (queue_id, logged_at, line) VALUES (?1, ?2, ?3)`
+	if once {
+		query = `INSERT INTO send_log_lines (queue_id, logged_at, line)
+			 SELECT ?1, ?2, ?3
+			 WHERE NOT EXISTS (SELECT 1 FROM send_log_lines WHERE queue_id = ?1 AND line = ?3)`
 	}
-	n, _ := res.RowsAffected()
-	return n > 0, nil
+	tx, err := s.db.Begin()
+	if err != nil {
+		return 0, fmt.Errorf("insert send_log_lines: %w", err)
+	}
+	defer tx.Rollback()
+	stmt, err := tx.Prepare(query)
+	if err != nil {
+		return 0, fmt.Errorf("insert send_log_lines: %w", err)
+	}
+	defer stmt.Close()
+	wrote := 0
+	for _, l := range lines {
+		res, err := stmt.Exec(l.QueueID, l.At.UTC().Format(time.RFC3339), cutSendLogLine(l.Line))
+		if err != nil {
+			return 0, fmt.Errorf("insert send_log_lines: %w", err)
+		}
+		n, _ := res.RowsAffected()
+		wrote += int(n)
+	}
+	if err := tx.Commit(); err != nil {
+		return 0, fmt.Errorf("insert send_log_lines: %w", err)
+	}
+	return wrote, nil
 }

 // SendLogLines returns the stored lines of the message a send-log row is
@@ -110,14 +129,19 @@ func (s *Store) SendLogLines(row SendLogRow, lifetime time.Duration, n int) ([]S
 // PruneSendLogLines deletes the lines dated before cutoff whose queue id has
 // no send-log row, and returns how many went. That one rule is the whole of
 // the table's retention: it removes the lines of rows the send-log sweep has
-// deleted, and the lines of messages that never had a row - inbound relay
-// mail, the bounces Postfix generates. cutoff leaves alone the lines of a
-// message still being received, whose row the journal milter has yet to write.
+// deleted, and the lines of messages that never had a row - the bounces
+// Postfix generates. cutoff leaves alone the lines of a message still being
+// received, whose row the journal milter has yet to write.
+//
+// The send log is asked once per queue id, not once per line: the ids are read
+// off the index, and a message is several lines.
 func (s *Store) PruneSendLogLines(cutoff time.Time) (int64, error) {
 	res, err := s.db.Exec(
 		`DELETE FROM send_log_lines
 		 WHERE logged_at < ?
-		   AND NOT EXISTS (SELECT 1 FROM send_log WHERE send_log.queue_id = send_log_lines.queue_id)`,
+		   AND queue_id IN (
+			SELECT q.queue_id FROM (SELECT DISTINCT queue_id FROM send_log_lines) AS q
+			WHERE NOT EXISTS (SELECT 1 FROM send_log WHERE send_log.queue_id = q.queue_id))`,
 		cutoff.UTC().Format(time.RFC3339),
 	)
 	if err != nil {
@@ -4,6 +4,7 @@ import (
 	"strings"
 	"testing"
 	"time"
+	"unicode/utf8"
 )

 func sendLogLineTexts(lines []SendLogLine) []string {
@@ -28,15 +29,13 @@ func countSendLogLines(t *testing.T, s *Store) int {
 func TestSendLogLinesOfOneMessage(t *testing.T) {
 	s := openTestStore(t)
 	at := time.Date(2026, 10, 12, 9, 0, 0, 0, time.UTC)
-	for i, l := range []SendLogLine{
+	if n, err := s.InsertSendLogLines([]SendLogLine{
 		{QueueID: "41E862C00D9E", At: at, Line: "client=app"},
 		{QueueID: "5F00AA", At: at, Line: "someone else's"},
 		{QueueID: "41E862C00D9E", At: at.Add(time.Second), Line: "status=sent"},
 		{QueueID: "41E862C00D9E", At: at.Add(2 * time.Second), Line: "removed"},
-	} {
-		if err := s.InsertSendLogLine(l); err != nil {
-			t.Fatalf("insert line %d: %v", i, err)
-		}
+	}, false); err != nil || n != 4 {
+		t.Fatalf("insert: wrote %d, %v", n, err)
 	}
 	row := SendLogRow{QueueID: "41E862C00D9E", CreatedAt: at}

@@ -75,15 +74,13 @@ func TestSendLogLinesBoundedByTheRowsLifetime(t *testing.T) {
 	first := time.Date(2026, 9, 1, 9, 0, 0, 0, time.UTC)
 	second := first.AddDate(0, 0, 30)
 	lifetime := 6 * 24 * time.Hour
-	for _, l := range []SendLogLine{
+	if _, err := s.InsertSendLogLines([]SendLogLine{
 		{QueueID: "ABC123", At: first.Add(-30 * time.Minute), Line: "first: client"},
 		{QueueID: "ABC123", At: first.Add(5 * 24 * time.Hour), Line: "first: expired"},
 		{QueueID: "ABC123", At: second.Add(-2 * time.Hour), Line: "between the two"},
 		{QueueID: "ABC123", At: second, Line: "second: sent"},
-	} {
-		if err := s.InsertSendLogLine(l); err != nil {
-			t.Fatalf("insert: %v", err)
-		}
+	}, false); err != nil {
+		t.Fatalf("insert: %v", err)
 	}

 	lines, err := s.SendLogLines(SendLogRow{QueueID: "ABC123", CreatedAt: first}, lifetime, 200)
@@ -103,45 +100,52 @@ func TestSendLogLinesBoundedByTheRowsLifetime(t *testing.T) {
 }

 // After an unclean stop the tailer reads some lines twice; the second reading
-// writes nothing. The same text under another queue id is another line.
-func TestInsertSendLogLineOnce(t *testing.T) {
+// writes nothing, also when the line comes twice in one batch. The same text
+// under another queue id is another line. Without once, what is given is
+// written.
+func TestInsertSendLogLinesOnce(t *testing.T) {
 	s := openTestStore(t)
 	l := SendLogLine{QueueID: "ABC123", At: time.Date(2026, 10, 12, 9, 0, 0, 0, time.UTC), Line: "Oct 12 09:00:00 mail postfix/qmgr[7]: ABC123: removed"}
-
-	for i, want := range []bool{true, false} {
-		wrote, err := s.InsertSendLogLineOnce(l)
-		if err != nil || wrote != want {
-			t.Errorf("reading %d: wrote = %v, %v; want %v", i+1, wrote, err, want)
-		}
-	}
 	other := l
 	other.QueueID = "DEF456"
-	if wrote, err := s.InsertSendLogLineOnce(other); err != nil || !wrote {
-		t.Errorf("another queue id: wrote = %v, %v", wrote, err)
+
+	if n, err := s.InsertSendLogLines([]SendLogLine{l, l, other}, true); err != nil || n != 2 {
+		t.Errorf("first reading wrote %d, %v; want 2", n, err)
+	}
+	if n, err := s.InsertSendLogLines([]SendLogLine{l, other}, true); err != nil || n != 0 {
+		t.Errorf("second reading wrote %d, %v; want 0", n, err)
 	}
 	if n := countSendLogLines(t, s); n != 2 {
 		t.Errorf("%d lines stored, want 2", n)
 	}
+	if n, err := s.InsertSendLogLines([]SendLogLine{l}, false); err != nil || n != 1 {
+		t.Errorf("a line as it is written: wrote %d, %v; want 1", n, err)
+	}
+	if n, err := s.InsertSendLogLines(nil, true); err != nil || n != 0 {
+		t.Errorf("nothing to write: %d, %v", n, err)
+	}
 }

 // The far end writes the reply a delivery line quotes; what is kept of a line
-// has a ceiling, and a line read twice is still recognised past it.
+// has a ceiling, not set through the middle of a character, and a line read
+// twice is still recognised past it.
 func TestSendLogLineIsCut(t *testing.T) {
 	s := openTestStore(t)
 	at := time.Date(2026, 10, 12, 9, 0, 0, 0, time.UTC)
-	l := SendLogLine{QueueID: "ABC123", At: at, Line: strings.Repeat("x", SendLogLineMax+500)}
-	if err := s.InsertSendLogLine(l); err != nil {
+	// Two bytes a character, starting at an odd offset: the ceiling falls inside one.
+	l := SendLogLine{QueueID: "ABC123", At: at, Line: "x" + strings.Repeat("é", SendLogLineMax)}
+	if _, err := s.InsertSendLogLines([]SendLogLine{l}, false); err != nil {
 		t.Fatalf("insert: %v", err)
 	}
-	if wrote, err := s.InsertSendLogLineOnce(l); err != nil || wrote {
-		t.Errorf("the same long line again: wrote = %v, %v", wrote, err)
+	if n, err := s.InsertSendLogLines([]SendLogLine{l}, true); err != nil || n != 0 {
+		t.Errorf("the same long line again: wrote %d, %v", n, err)
 	}
 	lines, err := s.SendLogLines(SendLogRow{QueueID: "ABC123", CreatedAt: at}, time.Hour, 10)
 	if err != nil || len(lines) != 1 {
 		t.Fatalf("lines = %d, %v", len(lines), err)
 	}
-	if len(lines[0].Line) != SendLogLineMax {
-		t.Errorf("kept %d bytes, want %d", len(lines[0].Line), SendLogLineMax)
+	if got := lines[0].Line; len(got) != SendLogLineMax-1 || !utf8.ValidString(got) {
+		t.Errorf("kept %d bytes (valid UTF-8: %v), want %d whole characters", len(got), utf8.ValidString(got), SendLogLineMax-1)
 	}
 }

@@ -156,14 +160,16 @@ func TestPruneSendLogLines(t *testing.T) {
 	if err := s.InsertQueued(SendLogEntry{QueueID: "KEPT01", Domain: "example.com", To: "a@example.net"}); err != nil {
 		t.Fatalf("insert row: %v", err)
 	}
-	for _, l := range []SendLogLine{
+	// A row the milter refused has no queue id; it keeps no line alive.
+	if err := s.InsertRejected(SendLogEntry{Domain: "example.com", From: "a@example.com"}); err != nil {
+		t.Fatalf("insert rejected row: %v", err)
+	}
+	if _, err := s.InsertSendLogLines([]SendLogLine{
 		{QueueID: "KEPT01", At: old, Line: "has a row"},
 		{QueueID: "INBOUND1", At: old, Line: "never had a row"},
 		{QueueID: "ARRIVING", At: now.Add(-time.Minute), Line: "its row is not written yet"},
-	} {
-		if err := s.InsertSendLogLine(l); err != nil {
-			t.Fatalf("insert: %v", err)
-		}
+	}, false); err != nil {
+		t.Fatalf("insert: %v", err)
 	}

 	n, err := s.PruneSendLogLines(now.Add(-time.Hour))