Files
selfpost/internal/store/deliverylog.go
T
mixandClaude Opus 5.5 ffefa9d6df 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

107 lines
3.7 KiB
Go

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
}