release: 1.0.0: Public 1.0 image; delivery log; docs and SECURITY.md (incl. 1.0.1)

[1.0.0] Added: - A **Delivery log** on each delivery's page (`/deliveries/{id}`): the - A **History** block on the same page: the journal's two timestamps stated as Fixed: - Postfix config: copy TLS cert/key from the (often `:ro`, host-owned) mount - Postfix config: allow `maillog_file` under `/data` via - E2e: read `/data/setup-token` via `docker compose exec` (file is `0600` - Entrypoint: check `SELFPOST_HOSTNAME` before `/data` setup (so a bad identity - E2e gate: wait for host-published `/healthz` before panel setup, and stop … (3 more in CHANGELOG) Changed: - Document what `.spbk` and `.spde` stand for (SelfPost backup / SelfPost domain - Docs aligned with the code: setup URL is `/setup/<token>` (README and - Full backups no longer carry `/data/log`. It is Postfix's raw log plus its - Monitoring screens (status, mail queue, system log, deliveries) use adaptive - Documentation package consolidated into `docs/development.md`: Documentation … (4 more in CHANGELOG) [1.0.1] A documentation and packaging release: no change to the mail path, the database, or the on-disk layout. Upgrading is a tag bump. Added: - `SECURITY.md` — how to report a vulnerability privately (GitHub private - [docs/plans/](docs/plans/) — one document per agreed extension: the optional Changed: - The panel's **Account** entry is now called **Settings** — nav link, page - The signed-in name in the panel's nav is now labelled `User:`, so it reads as - [docs/product.md](docs/product.md) reframes the future line: the inbound - [docs/security.md](docs/security.md) is now in English, matching the rest of - The README documentation table now points at `SECURITY.md` for reporting a … (2 more in CHANGELOG) Fixed: - The panel's static assets are served with a content ETag and Squashed CHANGELOG sections: [1.0.0], [1.0.1]. Full detail: CHANGELOG.md (1.0.0, 1.0.1).
2026-09-22 15:24:51 +03:00
parent 83c488cc48
commit 75207f0d1e
80 changed files with 3670 additions and 1662 deletions
@@ -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,13 +39,24 @@ 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.
 	retentionInterval = 6 * time.Hour
 	// defaultRetentionDays applies when the configured value is unset/invalid
-	// (README § Environment variables: SEND_LOG_RETENTION_DAYS).
+	// (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 {
@@ -176,12 +267,158 @@ func TailLines(path string, n int) ([]string, error) {
 	return lines, nil
 }

+// queueScanBytes bounds how far back QueueLines reads. A message's own lines
+// are a handful, but they are scattered through everything else the mail path
+// logged around them, so finding them means reading rather than seeking. The
+// budget is what keeps that read bounded on a log that has grown for a day:
+// beyond it the answer is "not in the part of the log still on disk", which is
+// the same answer rotation gives and is reported the same way. It is a var so
+// tests can shrink it, the way pollInterval above is.
+var queueScanBytes int64 = 4 << 20
+
+// QueueLines returns the mail.log lines Postfix wrote about one queue id,
+// oldest first and at most n of them, for a single delivery's page
+// (architecture.md § Panel HTTP surface). It reads the tail of the log the way
+// TailLines does — one-shot, on request, unrelated to the follow loop above —
+// but keeps only the lines belonging to this message instead of the last n of
+// everything.
+//
+// A message older than the tail scanned, or older than the current log file,
+// comes back empty rather than as an error: send-log rows outlive mail.log
+// (retention is ninety days by default, rotation keeps fourteen files), so a
+// row with nothing left to show for it is expected.
+func QueueLines(path, queueID string, n int) ([]string, error) {
+	// No queue-id, no lines: a message the milter refused was never queued, so
+	// there is nothing to match on and every line would be someone else's.
+	if queueID == "" || n <= 0 {
+		return nil, nil
+	}
+
+	f, err := os.Open(path)
+	if err != nil {
+		return nil, err
+	}
+	defer f.Close()
+
+	info, err := f.Stat()
+	if err != nil {
+		return nil, err
+	}
+
+	// Forward from the start of the budget rather than backwards in chunks:
+	// the lines are wanted oldest first, and the whole budget is read either
+	// way, so reading it in order costs nothing and keeps them in order.
+	start := info.Size() - queueScanBytes
+	if start < 0 {
+		start = 0
+	}
+	if _, err := f.Seek(start, io.SeekStart); err != nil {
+		return nil, err
+	}
+
+	sc := bufio.NewScanner(f)
+	// A Postfix line carrying a long remote reply can pass the scanner's default
+	// 64KB token; without a bigger ceiling that one line would end the scan and
+	// silently truncate the answer.
+	sc.Buffer(make([]byte, 0, 64*1024), 1<<20)
+	// Reading into the middle of the file lands mid-line; that fragment is
+	// dropped rather than reported as a line of its own.
+	if start > 0 && sc.Scan() {
+		_ = sc.Text()
+	}
+
+	var lines []string
+	for sc.Scan() {
+		line := sc.Text()
+		if !mentionsQueueID(line, queueID) {
+			continue
+		}
+		lines = append(lines, line)
+		// Keep the latest n rather than stopping at the first n: what a message
+		// did last is what its page is opened for.
+		if len(lines) > n {
+			lines = lines[1:]
+		}
+	}
+	if err := sc.Err(); err != nil {
+		return nil, err
+	}
+	return lines, nil
+}
+
+// mentionsQueueID reports whether a mail.log line is about queueID. Postfix
+// writes the id followed by a colon ("… postfix/smtp[26]: 41E862C00D9E: to=…"),
+// and the match is anchored on the character before it so a shorter id is not
+// found inside a longer one — queue ids are hexadecimal, and one being the tail
+// of another is ordinary, not unlikely.
+func mentionsQueueID(line, queueID string) bool {
+	needle := queueID + ":"
+	for i := 0; i <= len(line)-len(needle); {
+		j := strings.Index(line[i:], needle)
+		if j < 0 {
+			return false
+		}
+		j += i
+		if j == 0 || !isQueueIDByte(line[j-1]) {
+			return true
+		}
+		i = j + 1
+	}
+	return false
+}
+
+func isQueueIDByte(b byte) bool {
+	return b >= '0' && b <= '9' || b >= 'A' && b <= 'Z' || b >= 'a' && b <= 'z'
+}
+
+// Timestamps at the head of a mail.log line, in the two formats postlogd
+// writes (maillog_file in build/postfix-config.sh).
+//
+// syslogStampRe is the one that matches in practice today: the format is
+// controlled by maillog_file_format, which arrived in Postfix 3.9, and the
+// image is built on Debian's 3.7 — where the parameter does not exist and the
+// only format is syslog's traditional one. It carries no year and no zone, so
+// the stamp shown is a wall clock and nothing more, which is all this column
+// claims to be.
+//
+// isoStampRe is for the RFC 3339 format that same parameter selects once the
+// base image carries a Postfix new enough to offer it. Matching it first costs
+// one failed anchor per line and means the upgrade needs no change here.
+var (
+	isoStampRe    = regexp.MustCompile(`^(\d{4}-\d{2}-\d{2})T(\d{2}:\d{2}:\d{2})(?:\.\d+)?(?:Z|[+-]\d{2}:?\d{2})?\s`)
+	syslogStampRe = regexp.MustCompile(`^([A-Z][a-z]{2}\s+\d{1,2} \d{2}:\d{2}:\d{2})\s`)
+)
+
+// SplitTimestamp separates the timestamp at the head of a mail.log line from
+// the rest of it, so a page can put the two in their own columns. The stamp
+// comes back without its fractional seconds and zone offset — five decimal
+// places of microsecond are the widest part of the column and the least worth
+// reading — but is otherwise the log's own wall clock, not converted: what is
+// on the page is what is in the file.
+//
+// A line whose head is not a timestamp this recognises comes back whole, as
+// rest, with an empty stamp. Nothing is ever dropped: the point of showing the
+// log is that it says what it says.
+func SplitTimestamp(line string) (stamp, rest string) {
+	if m := isoStampRe.FindStringSubmatch(line); m != nil {
+		return m[1] + " " + m[2], strings.TrimSpace(line[len(m[0]):])
+	}
+	if m := syslogStampRe.FindStringSubmatch(line); m != nil {
+		return m[1], strings.TrimSpace(line[len(m[0]):])
+	}
+	return "", line
+}
+
 // follow tails path line by line, calling handle for each complete line, until
 // ctx is cancelled. Where it starts is tr's decision (a persisted offset, the
 // 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
@@ -255,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 {
@@ -264,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