fix(logtail): keep mail.log in /data and reconcile stuck rows (v1.x closure phase 2)

Move the delivery log from the ephemeral /var/log to /data/log/mail.log so
the lines that resolve a queued send-log row survive a container recreate.
postlogd writes it as postfix, the panel reads it through the selfpost group
(dir 2750, file 0640, normalised every start); backups exclude log/.

Close the residual gap with a queue sweep: rows queued for over two minutes
whose id postqueue -p no longer lists are marked bounced. The sweep waits
until the tailer has read the log to its end and does nothing when the queue
cannot be listed, so a message in flight is never touched.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Co-authored-by: Cursor <cursoragent@cursor.com>

internal/backup/backup.go

@@ -63,10 +63,12 @@ type Params struct {
 // The live database files are replaced by a consistent VACUUM INTO snapshot
 // written under the canonical name; the setup token is transient bootstrap
 // state; a stale manifest from a previous restore must not be re-captured (a
-// fresh one is written instead); and a "tls" directory holds the reverse
-// proxy's certificates, which are explicitly out of scope for a SelfPost
-// backup (architecture.md § Persistence) — excluding it keeps that guarantee
-// even when an operator points TLS_CERT_FILE inside /data.
+// fresh one is written instead); a "tls" directory holds the reverse proxy's
+// certificates, which are explicitly out of scope for a SelfPost backup
+// (architecture.md § Persistence) — excluding it keeps that guarantee even when
+// an operator points TLS_CERT_FILE inside /data; and "log" is Postfix's raw
+// delivery log plus its fourteen rotated files, which is diagnostic output, not
+// state to restore, and by far the largest thing under /data.
 var excludedFromArchive = map[string]bool{
 	"selfpost.db":         true,
 	"selfpost.db-wal":     true,
@@ -74,6 +76,7 @@ var excludedFromArchive = map[string]bool{
 	"selfpost.db-journal": true,
 	"setup-token":         true,
 	"tls":                 true,
+	"log":                 true,
 	ManifestName:          true,
 }
 

internal/backup/backup_test.go

@@ -39,6 +39,10 @@ func seedDataDir(t *testing.T) (dataDir, dbPath string) {
 	writeFile(t, filepath.Join(dataDir, "setup-token"), "secret-token")
 	writeFile(t, filepath.Join(dataDir, "selfpost.db-wal"), "wal")
 	writeFile(t, filepath.Join(dataDir, "selfpost.db-shm"), "shm")
+	// Postfix's delivery log and its rotated files: diagnostic output, not
+	// state, and the bulkiest thing under /data.
+	writeFile(t, filepath.Join(dataDir, "log", "mail.log"), "Aug  8 07:26:41 mail postfix/smtp[1]: ABC: to=<a@example.net>, status=sent (ok)")
+	writeFile(t, filepath.Join(dataDir, "log", "mail.log.1"), "older")
 	return dataDir, dbPath
 }
 
@@ -104,7 +108,10 @@ func TestCreateIncludesStateExcludesTransient(t *testing.T) {
 		}
 	}
 	// Excluded.
-	for _, name := range []string{"setup-token", "selfpost.db-wal", "selfpost.db-shm"} {
+	for _, name := range []string{
+		"setup-token", "selfpost.db-wal", "selfpost.db-shm",
+		"log/mail.log", "log/mail.log.1",
+	} {
 		if _, ok := files[name]; ok {
 			t.Errorf("archive should not contain %s", name)
 		}

internal/logtail/logtail.go

@@ -16,16 +16,20 @@ import (
 	"os"
 	"regexp"
 	"strings"
+	"sync"
 	"time"
 
+	"github.com/mixeme/selfpost/internal/postfix"
 	"github.com/mixeme/selfpost/internal/store"
 )
 
 // StatusStore is the slice of the store the log-tailer needs: advancing
-// delivery statuses, pruning the retention window, and remembering how far into
-// mail.log it has read. *store.Store satisfies it.
+// delivery statuses, finding the rows still waiting for one, pruning the
+// retention window, and remembering how far into mail.log it has read.
+// *store.Store satisfies it.
 type StatusStore interface {
 	UpdateStatus(queueID, recipient, status string) (int64, error)
+	ListQueuedOlderThan(cutoff time.Time) ([]store.QueuedDelivery, error)
 	DeleteSendLogBefore(cutoff time.Time) (int64, error)
 	LogtailState(path string) (store.LogtailState, bool, error)
 	SaveLogtailState(path string, st store.LogtailState) error
@@ -35,6 +39,10 @@ type StatusStore interface {
 // is a var so tests can shorten it.
 var pollInterval = time.Second
 
+// queueIDs lists the messages Postfix currently holds, for the reconcile sweep.
+// It is a var so tests can answer without a running Postfix.
+var queueIDs = postfix.QueueIDs
+
 const (
 	// retentionInterval is how often the retention sweep runs (also once at
 	// startup). The window itself is configurable; the cadence need not be.
@@ -42,6 +50,13 @@ const (
 	// defaultRetentionDays applies when the configured value is unset/invalid
 	// (guide § Environment variables: SEND_LOG_RETENTION_DAYS).
 	defaultRetentionDays = 90
+	// reconcileInterval is how often the sweep compares stuck rows against the
+	// Postfix queue, and reconcileGrace how long a row is left alone first.
+	// The grace covers the ordinary lag between the milter writing the row and
+	// Postfix logging the result — seconds, generously rounded up — so a
+	// message merely in flight is never touched.
+	reconcileInterval = 5 * time.Minute
+	reconcileGrace    = 2 * time.Minute
 )
 
 // deliveryRe matches a Postfix delivery line and captures queue-id, recipient
@@ -89,7 +104,14 @@ func parseDelivery(line string) (queueID, recipient, status string, ok bool) {
 func Run(ctx context.Context, path string, st StatusStore, retentionDays int) error {
 	go retentionLoop(ctx, st, retentionDays)
 
-	return follow(ctx, path, &tracker{st: st, path: path}, func(line string) {
+	// The reconcile sweep must not run against a backlog the tailer has not
+	// read yet: on a restart the log holds the very lines that resolve the rows
+	// the sweep would otherwise close. follow() closes this once it has read to
+	// end-of-file for the first time.
+	caughtUp := make(chan struct{})
+	go reconcileLoop(ctx, st, caughtUp)
+
+	return follow(ctx, path, &tracker{st: st, path: path}, caughtUp, func(line string) {
 		queueID, recipient, status, ok := parseDelivery(line)
 		if !ok {
 			return
@@ -100,6 +122,75 @@ func Run(ctx context.Context, path string, st StatusStore, retentionDays int) er
 	})
 }
 
+// reconcileLoop periodically closes send-log rows Postfix has stopped working
+// on (architecture.md § Log tailer). It starts only once the tailer has caught
+// up with the log, and then leaves the first sweep a full interval away, so a
+// restart resolves rows from the log — the accurate source — before the sweep
+// gets to guess at whatever the log could not explain.
+func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{}) {
+	select {
+	case <-ctx.Done():
+		return
+	case <-caughtUp:
+	}
+
+	t := time.NewTicker(reconcileInterval)
+	defer t.Stop()
+	for {
+		select {
+		case <-ctx.Done():
+			return
+		case <-t.C:
+			reconcile(st, time.Now().UTC().Add(-reconcileGrace))
+		}
+	}
+}
+
+// reconcile marks as bounced every row still "queued" from before cutoff whose
+// message Postfix no longer holds.
+//
+// A row reaches this state only when its delivery lines are gone for good — the
+// log rotated past its fourteen files while the panel was down, or was deleted
+// — since the log itself now outlives the container. Postfix having dropped the
+// message means it will never report anything more about it, so the row can
+// only be closed on an assumption; it is closed as a failure rather than a
+// success because a delivery the panel cannot evidence must not be shown as
+// one. Rows whose message is still in the queue, and every row when the queue
+// cannot be listed at all, are left exactly as they are.
+func reconcile(st StatusStore, cutoff time.Time) {
+	rows, err := st.ListQueuedOlderThan(cutoff)
+	if err != nil {
+		log.Printf("log-tailer: reconcile: list queued rows: %v", err)
+		return
+	}
+	if len(rows) == 0 {
+		return
+	}
+
+	held, err := queueIDs()
+	if err != nil {
+		// No listing is no information: closing rows now would be a guess made
+		// against nothing.
+		log.Printf("log-tailer: reconcile: read postfix queue: %v", err)
+		return
+	}
+
+	var closed int
+	for _, row := range rows {
+		if _, still := held[row.QueueID]; still {
+			continue
+		}
+		if _, err := st.UpdateStatus(row.QueueID, row.To, store.StatusBounced); err != nil {
+			log.Printf("log-tailer: reconcile: close %s/%s: %v", row.QueueID, row.To, err)
+			continue
+		}
+		closed++
+	}
+	if closed > 0 {
+		log.Printf("log-tailer: reconcile: closed %d row(s) Postfix no longer holds and never reported", closed)
+	}
+}
+
 // retentionLoop prunes expired send-log rows immediately and then periodically.
 func retentionLoop(ctx context.Context, st StatusStore, retentionDays int) {
 	if retentionDays <= 0 {
@@ -323,7 +414,11 @@ func SplitTimestamp(line string) (stamp, rest string) {
 // start of a file that changed while the panel was down, or end-of-file on a
 // first ever run); it reopens the file when it is rotated (inode change from
 // logrotate's create, or truncation from copytruncate) so nothing is missed.
-func follow(ctx context.Context, path string, tr *tracker, handle func(string)) error {
+//
+// caughtUp is closed after the first read that reaches end-of-file, which is
+// the point where every line the panel missed while it was down has been
+// handled.
+func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{}, handle func(string)) error {
 	var (
 		f       *os.File
 		r       *bufio.Reader
@@ -397,6 +492,8 @@ func follow(ctx context.Context, path string, tr *tracker, handle func(string))
 		return pos - int64(len(pending))
 	}
 
+	var once sync.Once
+
 	ticker := time.NewTicker(pollInterval)
 	defer ticker.Stop()
 	for {
@@ -406,6 +503,7 @@ func follow(ctx context.Context, path string, tr *tracker, handle func(string))
 			return nil
 		case <-ticker.C:
 			drain()
+			once.Do(func() { close(caughtUp) })
 			ni, err := os.Stat(path)
 			if err != nil {
 				continue // file briefly gone mid-rotation; try again next tick

internal/logtail/logtail_test.go

@@ -2,6 +2,7 @@ package logtail
 
 import (
 	"context"
+	"errors"
 	"os"
 	"path/filepath"
 	"strconv"
@@ -142,6 +143,10 @@ type captureStore struct {
 	state     store.LogtailState
 	haveState bool
 	stateErr  error
+
+	// queued is what ListQueuedOlderThan returns, for the reconcile sweep.
+	queued    []store.QueuedDelivery
+	queuedErr error
 }
 
 func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, error) {
@@ -153,6 +158,12 @@ func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, e
 
 func (c *captureStore) DeleteSendLogBefore(time.Time) (int64, error) { return 0, nil }
 
+func (c *captureStore) ListQueuedOlderThan(time.Time) ([]store.QueuedDelivery, error) {
+	c.mu.Lock()
+	defer c.mu.Unlock()
+	return c.queued, c.queuedErr
+}
+
 func (c *captureStore) LogtailState(string) (store.LogtailState, bool, error) {
 	c.mu.Lock()
 	defer c.mu.Unlock()
@@ -335,6 +346,73 @@ func waitFor(t *testing.T, cond func() bool) {
 	t.Fatal("condition not met within timeout")
 }
 
+// stubQueue makes the reconcile sweep answer from a fixed list of queue ids
+// instead of a running Postfix, or fail if err is non-nil.
+func stubQueue(t *testing.T, err error, ids ...string) *int {
+	t.Helper()
+	calls := 0
+	old := queueIDs
+	queueIDs = func() (map[string]struct{}, error) {
+		calls++
+		if err != nil {
+			return nil, err
+		}
+		set := make(map[string]struct{}, len(ids))
+		for _, id := range ids {
+			set[id] = struct{}{}
+		}
+		return set, nil
+	}
+	t.Cleanup(func() { queueIDs = old })
+	return &calls
+}
+
+// A row stays "queued" forever when its delivery lines are gone for good. The
+// queue is what settles it: a message Postfix still holds is simply in flight
+// and must be left alone, while one it no longer holds will never be reported
+// on and is closed.
+func TestReconcileClosesOnlyWhatPostfixNoLongerHolds(t *testing.T) {
+	stubQueue(t, nil, "STILLQ")
+
+	cs := &captureStore{queued: []store.QueuedDelivery{
+		{QueueID: "STILLQ", To: "inflight@example.net"},
+		{QueueID: "GONEQ", To: "lost@example.net"},
+	}}
+	reconcile(cs, time.Now().UTC())
+
+	got := cs.snapshot()
+	if len(got) != 1 || got[0] != "GONEQ|lost@example.net|"+store.StatusBounced {
+		t.Fatalf("got %v, want only the message Postfix dropped closed as bounced", got)
+	}
+}
+
+// A queue that cannot be listed says nothing about any message — treating the
+// failure as an empty queue would close every stale row at once.
+func TestReconcileLeavesRowsAloneWhenTheQueueCannotBeRead(t *testing.T) {
+	stubQueue(t, errors.New("postqueue: Permission denied"))
+
+	cs := &captureStore{queued: []store.QueuedDelivery{
+		{QueueID: "GONEQ", To: "lost@example.net"},
+	}}
+	reconcile(cs, time.Now().UTC())
+
+	if got := cs.snapshot(); len(got) != 0 {
+		t.Fatalf("got %v, want no row touched", got)
+	}
+}
+
+// With nothing stale to explain there is no reason to shell out to postqueue at
+// all — which is the normal state of a relay that is keeping up.
+func TestReconcileSkipsTheQueueWhenNoRowIsStuck(t *testing.T) {
+	calls := stubQueue(t, nil)
+
+	reconcile(&captureStore{}, time.Now().UTC())
+
+	if *calls != 0 {
+		t.Fatalf("queue listed %d time(s), want none", *calls)
+	}
+}
+
 // A delivery's page shows what Postfix wrote about that one message, so the
 // read has to pick its queue-id's lines out of everything else the mail path
 // logged around them — and only its own: queue ids are hexadecimal runs, and a

internal/postfix/queue.go

@@ -3,6 +3,7 @@ package postfix
 import (
 	"fmt"
 	"os/exec"
+	"regexp"
 	"strings"
 )
 
@@ -20,3 +21,43 @@ func Queue() (string, error) {
 	}
 	return string(out), nil
 }
+
+// QueueIDs returns the set of queue ids Postfix is still holding — everything
+// in the maildrop, incoming, active, deferred and hold queues. It answers the
+// one question the log-tailer's reconcile sweep asks about a send-log row stuck
+// at "queued": is Postfix still working on this message, or has it left the
+// queue without the panel ever seeing a delivery line for it (architecture.md §
+// Log tailer)?
+//
+// An error means the queue could not be listed and therefore says nothing about
+// any message; the caller must treat it as "no information", never as an empty
+// queue.
+func QueueIDs() (map[string]struct{}, error) {
+	out, err := Queue()
+	if err != nil {
+		return nil, err
+	}
+	return parseQueueIDs(out), nil
+}
+
+// queueEntryRe matches the first line of a `postqueue -p` entry, e.g.
+//
+//	3C5B04E6C1*     446 Thu Aug  7 10:12:31  app@example.com
+//
+// The id is at the start of the line, optionally flagged '*' (in the active
+// queue) or '!' (on hold), and is followed by the message size. Requiring the
+// size is what separates an entry from the listing's other left-margin lines:
+// the '-Queue ID-' header, the '-- 5 Kbytes in 2 Requests.' trailer, a deferred
+// entry's '(connect timed out)' reason, and 'Mail queue is empty'. Recipient
+// lines are indented and never match.
+var queueEntryRe = regexp.MustCompile(`^([0-9A-Za-z]+)[*!]?\s+\d+\s`)
+
+func parseQueueIDs(listing string) map[string]struct{} {
+	ids := make(map[string]struct{})
+	for _, line := range strings.Split(listing, "\n") {
+		if m := queueEntryRe.FindStringSubmatch(line); m != nil {
+			ids[m[1]] = struct{}{}
+		}
+	}
+	return ids
+}

internal/postfix/queue_test.go

@@ -0,0 +1,43 @@
+package postfix
+
+import "testing"
+
+// The reconcile sweep decides whether a message is still Postfix's problem, so
+// the parser must pick queue ids out of a real listing and nothing else out of
+// it: not the header, not the byte-count trailer, and above all not a deferred
+// entry's reason line, which — unlike the recipient lines — starts at the left
+// margin just as an entry does.
+func TestParseQueueIDs(t *testing.T) {
+	listing := `-Queue ID-  --Size-- ----Arrival Time---- -Sender/Recipient-------
+3C5B04E6C1*     446 Fri Aug  8 10:12:31  app@example.com
+                                         rcpt@example.net
+
+5B4A2C1D3E      446 Fri Aug  8 10:13:31  app@example.com
+(connect to mx.example.net[203.0.113.9]:25: Connection timed out)
+                                         deferred@example.net
+
+A1B2C3D4E5F!    891 Fri Aug  8 10:14:31  app@example.com
+                                         held@example.net
+
+-- 1 Kbytes in 3 Requests.
+`
+	ids := parseQueueIDs(listing)
+	want := []string{"3C5B04E6C1", "5B4A2C1D3E", "A1B2C3D4E5F"}
+	for _, id := range want {
+		if _, ok := ids[id]; !ok {
+			t.Errorf("queue id %s not found in %v", id, ids)
+		}
+	}
+	if len(ids) != len(want) {
+		t.Errorf("got %d ids %v, want exactly %v", len(ids), ids, want)
+	}
+}
+
+// An empty queue must come back as an empty set, not as a phantom id parsed out
+// of Postfix's prose — every stale row would otherwise be compared against a
+// listing that claims to hold a message called "Mail".
+func TestParseQueueIDsOnAnEmptyQueue(t *testing.T) {
+	if ids := parseQueueIDs("Mail queue is empty\n"); len(ids) != 0 {
+		t.Errorf("got %v, want no ids", ids)
+	}
+}

internal/store/sendlog.go

@@ -93,6 +93,45 @@ func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) {
 	return n, nil
 }
 
+// QueuedDelivery is a send-log row still waiting for a delivery result,
+// reduced to what the log-tailer's reconcile sweep needs to look it up in the
+// Postfix queue and, failing that, to close it (architecture.md § Log tailer).
+type QueuedDelivery struct {
+	QueueID string
+	To      string
+}
+
+// ListQueuedOlderThan returns the rows still marked "queued" that were accepted
+// before cutoff — old enough that Postfix should long since have reported a
+// result for them. Rows without a queue-id are skipped: the milter refused
+// those before Postfix ever saw the message, so the queue has nothing to say
+// about them.
+//
+// created_at is stored as RFC3339 UTC, so a lexical comparison against the same
+// format is chronologically correct.
+func (s *Store) ListQueuedOlderThan(cutoff time.Time) ([]QueuedDelivery, error) {
+	rows, err := s.db.Query(
+		`SELECT queue_id, to_addr FROM send_log
+		 WHERE status = ? AND queue_id <> '' AND created_at < ?
+		 ORDER BY id`,
+		StatusQueued, cutoff.UTC().Format(time.RFC3339),
+	)
+	if err != nil {
+		return nil, fmt.Errorf("list queued send_log rows: %w", err)
+	}
+	defer rows.Close()
+
+	var out []QueuedDelivery
+	for rows.Next() {
+		var d QueuedDelivery
+		if err := rows.Scan(&d.QueueID, &d.To); err != nil {
+			return nil, fmt.Errorf("scan queued send_log row: %w", err)
+		}
+		out = append(out, d)
+	}
+	return out, rows.Err()
+}
+
 // SendLogRow is one row as returned to the monitoring UI (architecture.md §
 // Persistence): a SendLogEntry plus the fields that only exist once a row has
 // been written (id, current status, timestamps).

internal/store/sendlog_test.go

@@ -95,6 +95,58 @@ func TestUpdateStatusRecipientCaseInsensitive(t *testing.T) {
 	}
 }
 
+// The reconcile sweep asks for the rows old enough that Postfix should have
+// reported on them by now. A message accepted moments ago is simply in flight,
+// and one the milter refused never reached the queue at all, so neither is the
+// sweep's business.
+func TestListQueuedOlderThan(t *testing.T) {
+	st := openTestStore(t)
+
+	for _, e := range []SendLogEntry{
+		{QueueID: "OLD1", To: "stale@example.net"},
+		{QueueID: "NEW1", To: "fresh@example.net"},
+	} {
+		if err := st.InsertQueued(e); err != nil {
+			t.Fatalf("InsertQueued: %v", err)
+		}
+	}
+	// A row the milter refused: no queue-id, and a status the sweep never sees.
+	if err := st.InsertRejected(SendLogEntry{To: "refused@example.net"}); err != nil {
+		t.Fatalf("InsertRejected: %v", err)
+	}
+	// A row that has already been delivered, aged the same as the stale one.
+	if err := st.InsertQueued(SendLogEntry{QueueID: "DONE1", To: "done@example.net"}); err != nil {
+		t.Fatalf("InsertQueued: %v", err)
+	}
+	if _, err := st.UpdateStatus("DONE1", "done@example.net", StatusSent); err != nil {
+		t.Fatalf("UpdateStatus: %v", err)
+	}
+
+	cutoff := time.Now().UTC().Add(-2 * time.Minute)
+	backdate(t, st, "OLD1", cutoff.Add(-time.Hour))
+	backdate(t, st, "DONE1", cutoff.Add(-time.Hour))
+
+	got, err := st.ListQueuedOlderThan(cutoff)
+	if err != nil {
+		t.Fatalf("ListQueuedOlderThan: %v", err)
+	}
+	if len(got) != 1 || got[0] != (QueuedDelivery{QueueID: "OLD1", To: "stale@example.net"}) {
+		t.Fatalf("got %+v, want only the stale queued row", got)
+	}
+}
+
+// backdate rewrites a row's acceptance time, so a test can age it past a cutoff
+// without waiting.
+func backdate(t *testing.T, s *Store, queueID string, at time.Time) {
+	t.Helper()
+	if _, err := s.db.Exec(
+		`UPDATE send_log SET created_at = ? WHERE queue_id = ?`,
+		at.UTC().Format(time.RFC3339), queueID,
+	); err != nil {
+		t.Fatalf("backdate %s: %v", queueID, err)
+	}
+}
+
 func TestUpdateStatusNoMatch(t *testing.T) {
 	st := openTestStore(t)
 	if err := st.InsertQueued(SendLogEntry{QueueID: "Q1", To: "a@example.net"}); err != nil {