delivery log: measure the sweep before deciding its fate (audit H3, 0007)

Migration 0007 (DDL only): delivery_log_days, a row per UTC day, kept a year, shown nowhere - read off a copy of the database after a month by the decision rule written in the audit plan. - reconcile_closed: the sweep adds the rows it actually closed. - reconcile_contradicted: store.UpdateStatus, in one transaction, counts the rows with reason "reconcile" a delivery line now speaks of, writes the log's status and clears the reason - so a re-read line counts once. - tailer_blind_seconds: follow() tracks stretches in which the file is gone or reopening fails (logtail.blindness); stored when a stretch ends and every minute while it lasts; under 3 s not counted (the rotation's tick between rename and create loses nothing). - queued_over_lifetime: every sweep overwrites the day's level with the rows queued past LongestLifetime + MaximalBackoff (a message Postfix still works on stays queued until its first retry after the lifetime). - retentionLoop prunes days older than a year. Tests: store (sums per day, the level overwritten, under a second nothing, prune; a contradicted sweep counted once and its reason cleared; count of queued rows); logtail (the sweep counts what it closed; countStuck records the level; blindness - a one-tick gap not counted, 75 s stored as 60 + 15 from where the last part ended). Schema tests at user_version 7. schema-migrations.md: chain head 7 (it still said 5 since 2.4.0), row 7. CHANGELOG [Unreleased], audit plan line ticked, roadmap 10/61. Evidence: go vet ./... clean; go test ./internal/store ok, ./internal/logtail ok but for TestFollowTailsAndRotates (Windows); the server run of the stage follows before the push. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 14:20:44 +03:00
parent 9adb44845c
commit ffefa9d6df
13 changed files with 459 additions and 14 deletions
@@ -0,0 +1,106 @@
+package store
+
+import (
+	"fmt"
+	"time"
+)
+
+// The counters of delivery_log_days (migration 0007): what the reconcile sweep
+// and the log tailer did, a row per UTC day, read off a copy of the database
+// to decide the sweep's fate (audit 2026-10-12, stage 1). No page shows them.
+
+// deliveryLogKeepDays is how long a day of the counters is kept.
+const deliveryLogKeepDays = 366
+
+// addDeliveryLogDay adds n to one counter of the day of at. column is one of
+// the fixed names below, never anything a request carries.
+func (s *Store) addDeliveryLogDay(at time.Time, column string, n int64) error {
+	if n <= 0 {
+		return nil
+	}
+	_, err := s.db.Exec(fmt.Sprintf(
+		`INSERT INTO delivery_log_days (day, %[1]s) VALUES (?, ?)
+		 ON CONFLICT (day) DO UPDATE SET %[1]s = %[1]s + excluded.%[1]s`, column),
+		at.UTC().Format(dayLayout), n,
+	)
+	if err != nil {
+		return fmt.Errorf("delivery log day, %s: %w", column, err)
+	}
+	return nil
+}
+
+// AddReconcileClosed counts n rows the reconcile sweep closed.
+func (s *Store) AddReconcileClosed(at time.Time, n int64) error {
+	return s.addDeliveryLogDay(at, "reconcile_closed", n)
+}
+
+// AddTailerBlind counts a stretch the log tailer could not read mail.log,
+// on the day it began. Under a second counts nothing.
+func (s *Store) AddTailerBlind(from time.Time, d time.Duration) error {
+	return s.addDeliveryLogDay(from, "tailer_blind_seconds", int64(d/time.Second))
+}
+
+// SetQueuedOverLifetime records how many rows are still queued past Postfix's
+// queue lifetime. It is a level, not a sum: each sweep overwrites the day's
+// value, so a past day keeps what its last sweep saw.
+func (s *Store) SetQueuedOverLifetime(at time.Time, n int64) error {
+	_, err := s.db.Exec(
+		`INSERT INTO delivery_log_days (day, queued_over_lifetime) VALUES (?, ?)
+		 ON CONFLICT (day) DO UPDATE SET queued_over_lifetime = excluded.queued_over_lifetime`,
+		at.UTC().Format(dayLayout), n,
+	)
+	if err != nil {
+		return fmt.Errorf("delivery log day, queued_over_lifetime: %w", err)
+	}
+	return nil
+}
+
+// CountQueuedOlderThan counts the rows still "queued" that were accepted
+// before cutoff. created_at is RFC3339 UTC, so the strings compare as times.
+func (s *Store) CountQueuedOlderThan(cutoff time.Time) (int64, error) {
+	var n int64
+	err := s.db.QueryRow(
+		`SELECT COUNT(*) FROM send_log WHERE status = ? AND queue_id <> '' AND created_at < ?`,
+		StatusQueued, cutoff.UTC().Format(time.RFC3339),
+	).Scan(&n)
+	if err != nil {
+		return 0, fmt.Errorf("count queued send_log rows: %w", err)
+	}
+	return n, nil
+}
+
+// DeliveryLogDay is one day of the counters, for tests and for reading a copy.
+type DeliveryLogDay struct {
+	Day                                       string
+	Closed, Contradicted, BlindSeconds, Stuck int64
+}
+
+// DeliveryLogDays returns the counted days, oldest first.
+func (s *Store) DeliveryLogDays() ([]DeliveryLogDay, error) {
+	rows, err := s.db.Query(
+		`SELECT day, reconcile_closed, reconcile_contradicted, tailer_blind_seconds, queued_over_lifetime
+		 FROM delivery_log_days ORDER BY day`)
+	if err != nil {
+		return nil, fmt.Errorf("delivery log days: %w", err)
+	}
+	defer rows.Close()
+	var out []DeliveryLogDay
+	for rows.Next() {
+		var d DeliveryLogDay
+		if err := rows.Scan(&d.Day, &d.Closed, &d.Contradicted, &d.BlindSeconds, &d.Stuck); err != nil {
+			return nil, fmt.Errorf("scan delivery log day: %w", err)
+		}
+		out = append(out, d)
+	}
+	return out, rows.Err()
+}
+
+// PruneDeliveryLogDays deletes the days older than a year.
+func (s *Store) PruneDeliveryLogDays(now time.Time) error {
+	_, err := s.db.Exec(`DELETE FROM delivery_log_days WHERE day < ?`,
+		now.UTC().AddDate(0, 0, -deliveryLogKeepDays).Format(dayLayout))
+	if err != nil {
+		return fmt.Errorf("prune delivery log days: %w", err)
+	}
+	return nil
+}
@@ -0,0 +1,69 @@
+package store
+
+import (
+	"testing"
+	"time"
+)
+
+// The counters add up per UTC day, the stuck level is overwritten rather than
+// added, nothing is written for nothing, and a year is kept.
+func TestDeliveryLogDays(t *testing.T) {
+	st := openTestStore(t)
+	day1 := time.Date(2026, 10, 14, 23, 59, 0, 0, time.UTC)
+	day2 := day1.Add(2 * time.Minute)
+
+	must := func(err error) {
+		t.Helper()
+		if err != nil {
+			t.Fatal(err)
+		}
+	}
+	must(st.AddReconcileClosed(day1, 2))
+	must(st.AddReconcileClosed(day1, 3))
+	must(st.AddReconcileClosed(day1, 0))
+	must(st.AddTailerBlind(day1, 1500*time.Millisecond))
+	must(st.AddTailerBlind(day1, 900*time.Millisecond)) // under a second: nothing
+	must(st.SetQueuedOverLifetime(day1, 4))
+	must(st.SetQueuedOverLifetime(day1, 1))
+	must(st.AddTailerBlind(day2, time.Minute))
+
+	days, err := st.DeliveryLogDays()
+	must(err)
+	want := []DeliveryLogDay{
+		{Day: "2026-10-14", Closed: 5, BlindSeconds: 1, Stuck: 1},
+		{Day: "2026-10-15", BlindSeconds: 60},
+	}
+	if len(days) != len(want) {
+		t.Fatalf("days = %+v, want %+v", days, want)
+	}
+	for i := range want {
+		if days[i] != want[i] {
+			t.Errorf("day %d = %+v, want %+v", i, days[i], want[i])
+		}
+	}
+
+	must(st.PruneDeliveryLogDays(day2.AddDate(1, 0, 1)))
+	days, err = st.DeliveryLogDays()
+	must(err)
+	if len(days) != 1 || days[0].Day != "2026-10-15" {
+		t.Fatalf("after pruning a year and a day later: %+v, want 2026-10-15 alone", days)
+	}
+}
+
+func TestCountQueuedOlderThan(t *testing.T) {
+	st := openTestStore(t)
+	for _, e := range []SendLogEntry{{QueueID: "Q1", To: "a@example.net"}, {QueueID: "Q2", To: "b@example.net"}} {
+		if err := st.InsertQueued(e); err != nil {
+			t.Fatal(err)
+		}
+	}
+	if _, err := st.UpdateStatus("Q2", "b@example.net", StatusSent); err != nil {
+		t.Fatal(err)
+	}
+	if n, err := st.CountQueuedOlderThan(time.Now().Add(time.Hour)); err != nil || n != 1 {
+		t.Fatalf("queued rows before an hour from now = %d, %v; want 1", n, err)
+	}
+	if n, err := st.CountQueuedOlderThan(time.Now().Add(-time.Hour)); err != nil || n != 0 {
+		t.Fatalf("queued rows before an hour ago = %d, %v; want 0", n, err)
+	}
+}
@@ -0,0 +1,19 @@
+-- What the delivery log's own machinery did, a row per UTC day that has
+-- something to say, kept a year (audit 2026-10-12, stage 1). These are the
+-- numbers the reconcile sweep's fate is decided by; no page reads them, they
+-- are read off a copy of the database. DDL only; nothing existing changes.
+--   reconcile_closed        rows the sweep closed as bounced (reason 'reconcile')
+--   reconcile_contradicted  rows closed by the sweep that a delivery line later
+--                           rewrote - the log wins, and is counted here
+--   tailer_blind_seconds    seconds the log tailer could not read mail.log
+--                           (the file gone, reopening it failing)
+--   queued_over_lifetime    rows still queued past Postfix's queue lifetime,
+--                           as measured by the day's last sweep (a level, not
+--                           a sum)
+CREATE TABLE delivery_log_days (
+    day                    TEXT PRIMARY KEY,
+    reconcile_closed       INTEGER NOT NULL DEFAULT 0,
+    reconcile_contradicted INTEGER NOT NULL DEFAULT 0,
+    tailer_blind_seconds   INTEGER NOT NULL DEFAULT 0,
+    queued_over_lifetime   INTEGER NOT NULL DEFAULT 0
+);
@@ -60,6 +60,7 @@ func TestBaselineSchema(t *testing.T) {
 		"send_log_lines":        "id queue_id logged_at line",
 		"notify_state":          "key phase count mark since sent_at",
 		"sender_check_days":     "day down_seconds deferred",
+		"delivery_log_days":     "day reconcile_closed reconcile_contradicted tailer_blind_seconds queued_over_lifetime",
 	}
 	rows, err := st.db.Query("SELECT name FROM sqlite_master WHERE type = 'table' AND name NOT LIKE 'sqlite_%' ORDER BY name")
 	if err != nil {
@@ -114,8 +115,8 @@ func TestBaselineSchema(t *testing.T) {
 	}

 	var version, appID int64
-	if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 6 {
-		t.Errorf("user_version = %d, %v; want 6", version, err)
+	if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 7 {
+		t.Errorf("user_version = %d, %v; want 7", version, err)
 	}
 	if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID {
 		t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID)
@@ -191,8 +192,8 @@ func TestOpenMigratesA20Database(t *testing.T) {
 	}
 	defer st.Close()
 	var version int
-	if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 6 {
-		t.Errorf("user_version = %d, %v; want 6", version, err)
+	if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 7 {
+		t.Errorf("user_version = %d, %v; want 7", version, err)
 	}
 	if ok, err := st.UserExists(); err != nil || !ok {
 		t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err)
@@ -83,16 +83,46 @@ func (s *Store) InsertRejected(e SendLogEntry) error {
 // case between the milter (envelope) and the delivery log. It returns the
 // number of rows updated so the caller can tell whether the line matched a
 // journal entry.
+//
+// A row the reconcile sweep closed (reason "reconcile") that a delivery line
+// now speaks of was closed on a guess the log could have settled: the log
+// wins, the reason is cleared, and the day's reconcile_contradicted counts it
+// (delivery_log_days) - once, since the row no longer carries the reason.
 func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) {
-	now := time.Now().UTC().Format(time.RFC3339)
-	res, err := s.db.Exec(
-		`UPDATE send_log SET status = ?, updated_at = ?
+	now := time.Now().UTC()
+	tx, err := s.db.Begin()
+	if err != nil {
+		return 0, fmt.Errorf("update send_log status: %w", err)
+	}
+	defer tx.Rollback()
+	var contradicted int64
+	if err := tx.QueryRow(
+		`SELECT COUNT(*) FROM send_log WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE AND reason = ?`,
+		queueID, recipient, ReasonReconcile,
+	).Scan(&contradicted); err != nil {
+		return 0, fmt.Errorf("update send_log status: %w", err)
+	}
+	res, err := tx.Exec(
+		`UPDATE send_log SET status = ?, updated_at = ?,
+			reason = CASE WHEN reason = ? THEN '' ELSE reason END
 		 WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE`,
-		status, now, queueID, recipient,
+		status, now.Format(time.RFC3339), ReasonReconcile, queueID, recipient,
 	)
 	if err != nil {
 		return 0, fmt.Errorf("update send_log status: %w", err)
 	}
+	if contradicted > 0 {
+		if _, err := tx.Exec(
+			`INSERT INTO delivery_log_days (day, reconcile_contradicted) VALUES (?, ?)
+			 ON CONFLICT (day) DO UPDATE SET reconcile_contradicted = reconcile_contradicted + excluded.reconcile_contradicted`,
+			now.Format(dayLayout), contradicted,
+		); err != nil {
+			return 0, fmt.Errorf("update send_log status: count the contradicted sweep: %w", err)
+		}
+	}
+	if err := tx.Commit(); err != nil {
+		return 0, fmt.Errorf("update send_log status: %w", err)
+	}
 	n, _ := res.RowsAffected()
 	return n, nil
 }
@@ -132,6 +132,38 @@ func TestCloseUnreportedClosesOnlyQueuedRows(t *testing.T) {
 	}
 }

+// A delivery line about a row the sweep closed proves the sweep guessed what
+// the log could have said: the log's status wins, the reason goes, and the day
+// counts one contradiction - once, however often the line is read again.
+func TestUpdateStatusCountsAContradictedSweep(t *testing.T) {
+	st := openTestStore(t)
+	if err := st.InsertQueued(SendLogEntry{QueueID: "Q1", To: "a@example.net"}); err != nil {
+		t.Fatal(err)
+	}
+	if _, err := st.CloseUnreported("Q1", "a@example.net"); err != nil {
+		t.Fatal(err)
+	}
+	for i := 0; i < 2; i++ {
+		if n, err := st.UpdateStatus("Q1", "A@example.net", StatusSent); err != nil || n != 1 {
+			t.Fatalf("UpdateStatus = %d, %v", n, err)
+		}
+	}
+	var status, reason string
+	if err := st.db.QueryRow(`SELECT status, reason FROM send_log WHERE queue_id = 'Q1'`).Scan(&status, &reason); err != nil {
+		t.Fatal(err)
+	}
+	if status != StatusSent || reason != "" {
+		t.Fatalf("status %q reason %q, want sent and no reason", status, reason)
+	}
+	days, err := st.DeliveryLogDays()
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(days) != 1 || days[0].Contradicted != 1 {
+		t.Fatalf("days = %+v, want one day with one contradiction", days)
+	}
+}
+
 // 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