test / test (push) Canceled after 0s
Technical review (Opus) and security review (Fable) of 9efc9c7..a59e3d4; reports in the session's scratchpad. Fixed: - B1 (verified bug): store.UpdateStatus read before writing in its transaction; a commit by another connection in between (the dmarc-ingest process opens the same file) failed it at once with "database is locked" and the delivery line was lost. The first statement is now a write. - R3: a delivery line updated every row of its queue id and recipient; it now updates only the newest (Postfix reuses short ids). The sweep closes by row id (QueuedDelivery.ID, CloseUnreported(id)). - R4: a contradicted sweep keeps a mark, reason "reconcile-contradicted", instead of losing which row it was. - R1: contradicted cannot see a lost line (never read late). New counter reconcile_missed: at close, the sweep looks for the row's delivery line in mail.log and mail.log.1 (QueueLines). 0007 edited - it has run on no database but throwaway stands. - R2: queued_over_lifetime cannot measure "what removing the sweep would leave" while the sweep runs; its text now says rows stuck despite the sweep, and the rule uses closed - missed - contradicted. - cert-reload (R5, R6, R7, security medium/low): both files copied to .new and the copies checked as a pair before both are renamed; acts on the copy only when postconf says Postfix reads it; a failed reload is retried next pass; umask 077; says so when the mounted files cannot be read. The e2e case asserts Postfix reads the copy, the copy equals the mount, the key is 600 root. - Security low: a recipient with a quoted local part - the journal cut "a b"@x at the space, deliveryRe cut "a>b"@x at the ">" - matched no delivery line and was closed by the sweep. cleanAddress ends a bracketed address at the first ">" outside quotes; deliveryRe takes the recipient up to the ">, " before relay= (test fixtures given the relay= every real delivery line has). - Security low: postqueue -p's error carries at most 512 bytes of output. - Nits: addDeliveryLogDay refuses a column not on its list; the truncation test checks its message. - To stage 2b (page wording, mockup-first): the history step of a bounced row says the receiving server refused it, false for a row the sweep closed. To the owner when stage 2b is reached: since M13 the "deferred" figure counts whole messages too, which "Connections turned away" would not name. Found while verifying: the e2e's main positive path failed once with "553 not owned by user app1" - an smtpd idle from before the panel's reload took the connection in the reload's second. Measured on the stand (one-off probe, not committed): sending 0, 10, 40, 110 s after the save (two seconds at the soonest) always met an smtpd started after the reload. The e2e now waits for the sender map after each application it creates (waitForSenderMap: AUTH, MAIL, RCPT, RSET - no message, no row), and the level-1 case uses it instead of its own loop. Docs: architecture § Queue reconcile, schema-migrations (rows 7 and 8, chain head 8), CHANGELOG, audit plan (stage 1 note, the measured window, a new stage 2b line: 62 lines), roadmap 15/62. Evidence on the test server for this tree: go vet clean, go test ./... 23 packages ok, make e2e exit 0 (renewed certificate, hung panel, level 1 at 49/60). Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
170 lines
5.5 KiB
Go
170 lines
5.5 KiB
Go
package store
|
|
|
|
import (
|
|
"fmt"
|
|
"time"
|
|
)
|
|
|
|
// Why a send-log row with status "rejected" was refused (send_log.reason).
|
|
// A row written before the reason was recorded has "".
|
|
const (
|
|
ReasonLimit = "limit" // a level-2 rate limit
|
|
ReasonClient = "client" // the application's list of client addresses
|
|
ReasonFrom = "from" // the From: line is not the application's
|
|
)
|
|
|
|
// Who decided a "bounced" row the log did not (send_log.reason).
|
|
const (
|
|
// ReasonReconcile: the reconcile sweep closed the row - its message left
|
|
// Postfix's queue with no delivery line ever read for it.
|
|
ReasonReconcile = "reconcile"
|
|
// ReasonReconcileContradicted: the sweep closed it and a delivery line
|
|
// read afterwards gave the status the row now has.
|
|
ReasonReconcileContradicted = "reconcile-contradicted"
|
|
)
|
|
|
|
// Settings keys of the sender check's statistics.
|
|
const (
|
|
// settingSenderCheckSince is the first UTC day the statistics cover.
|
|
settingSenderCheckSince = "sender_check_since"
|
|
// settingSenderCheckDeferredAt is when a message was last deferred because
|
|
// the check did not answer (RFC3339 UTC).
|
|
settingSenderCheckDeferredAt = "sender_check_deferred_at"
|
|
)
|
|
|
|
// senderCheckKeepDays is how long a day of the statistics is kept.
|
|
const senderCheckKeepDays = 366
|
|
|
|
const dayLayout = "2006-01-02"
|
|
|
|
// SenderCheckTotals is what the strict sender check has cost over a period.
|
|
type SenderCheckTotals struct {
|
|
Down time.Duration // the panel not answering while Postfix was running
|
|
Deferred int64 // messages Postfix deferred because of it
|
|
}
|
|
|
|
// SenderCheckStats is the card of Server > Health.
|
|
type SenderCheckStats struct {
|
|
Today, Month, Year SenderCheckTotals
|
|
// Since is the first day counted; zero before anything was.
|
|
Since time.Time
|
|
// DeferredAt is when a message was last deferred; zero if never.
|
|
DeferredAt time.Time
|
|
}
|
|
|
|
// StartSenderCheckStats records the first day the statistics cover, once.
|
|
func (s *Store) StartSenderCheckStats(now time.Time) error {
|
|
v, err := s.GetSetting(settingSenderCheckSince)
|
|
if err != nil || v != "" {
|
|
return err
|
|
}
|
|
return s.SetSetting(settingSenderCheckSince, now.UTC().Format(dayLayout))
|
|
}
|
|
|
|
// AddSenderCheckDown adds to the day of at the time the panel did not answer
|
|
// while Postfix was running.
|
|
func (s *Store) AddSenderCheckDown(at time.Time, d time.Duration) error {
|
|
secs := int64(d / time.Second)
|
|
if secs <= 0 {
|
|
return nil
|
|
}
|
|
_, err := s.db.Exec(
|
|
`INSERT INTO sender_check_days (day, down_seconds) VALUES (?, ?)
|
|
ON CONFLICT (day) DO UPDATE SET down_seconds = down_seconds + excluded.down_seconds`,
|
|
at.UTC().Format(dayLayout), secs,
|
|
)
|
|
if err != nil {
|
|
return fmt.Errorf("sender check downtime: %w", err)
|
|
}
|
|
return nil
|
|
}
|
|
|
|
// AddSenderCheckDeferred counts, on the day of at, n messages deferred because
|
|
// the check did not answer, and remembers at as the last such moment.
|
|
func (s *Store) AddSenderCheckDeferred(at time.Time, n int64) error {
|
|
if n <= 0 {
|
|
return nil
|
|
}
|
|
_, err := s.db.Exec(
|
|
`INSERT INTO sender_check_days (day, deferred) VALUES (?, ?)
|
|
ON CONFLICT (day) DO UPDATE SET deferred = deferred + excluded.deferred`,
|
|
at.UTC().Format(dayLayout), n,
|
|
)
|
|
if err != nil {
|
|
return fmt.Errorf("sender check deferred: %w", err)
|
|
}
|
|
// Lines are read in order, but a re-read log must not move the mark back.
|
|
last, err := s.GetSetting(settingSenderCheckDeferredAt)
|
|
if err != nil {
|
|
return err
|
|
}
|
|
// To the fraction of a second the log gives, and of a fixed width so that
|
|
// the strings compare as the times do.
|
|
stamp := at.UTC().Format("2006-01-02T15:04:05.000000Z")
|
|
if stamp > last {
|
|
return s.SetSetting(settingSenderCheckDeferredAt, stamp)
|
|
}
|
|
return nil
|
|
}
|
|
|
|
// SenderCheckDeferredAt is when a message was last counted as deferred; zero
|
|
// if none was.
|
|
func (s *Store) SenderCheckDeferredAt() (time.Time, error) {
|
|
v, err := s.GetSetting(settingSenderCheckDeferredAt)
|
|
if err != nil || v == "" {
|
|
return time.Time{}, err
|
|
}
|
|
at, _ := time.Parse(time.RFC3339Nano, v)
|
|
return at, nil
|
|
}
|
|
|
|
// SenderCheckStats sums the days up to now: today, the last 30 days and the
|
|
// last 12 months, each including today.
|
|
func (s *Store) SenderCheckStats(now time.Time) (SenderCheckStats, error) {
|
|
now = now.UTC()
|
|
var out SenderCheckStats
|
|
sum := func(days int) (SenderCheckTotals, error) {
|
|
var secs, deferred int64
|
|
err := s.db.QueryRow(
|
|
`SELECT COALESCE(SUM(down_seconds), 0), COALESCE(SUM(deferred), 0)
|
|
FROM sender_check_days WHERE day > ? AND day <= ?`,
|
|
now.AddDate(0, 0, -days).Format(dayLayout), now.Format(dayLayout),
|
|
).Scan(&secs, &deferred)
|
|
if err != nil {
|
|
return SenderCheckTotals{}, fmt.Errorf("sender check stats: %w", err)
|
|
}
|
|
return SenderCheckTotals{Down: time.Duration(secs) * time.Second, Deferred: deferred}, nil
|
|
}
|
|
var err error
|
|
if out.Today, err = sum(1); err != nil {
|
|
return out, err
|
|
}
|
|
if out.Month, err = sum(30); err != nil {
|
|
return out, err
|
|
}
|
|
if out.Year, err = sum(365); err != nil {
|
|
return out, err
|
|
}
|
|
since, err := s.GetSetting(settingSenderCheckSince)
|
|
if err != nil {
|
|
return out, err
|
|
}
|
|
out.Since, _ = time.Parse(dayLayout, since)
|
|
deferredAt, err := s.GetSetting(settingSenderCheckDeferredAt)
|
|
if err != nil {
|
|
return out, err
|
|
}
|
|
out.DeferredAt, _ = time.Parse(time.RFC3339, deferredAt)
|
|
return out, nil
|
|
}
|
|
|
|
// PruneSenderCheckDays deletes the days older than a year.
|
|
func (s *Store) PruneSenderCheckDays(now time.Time) error {
|
|
_, err := s.db.Exec(`DELETE FROM sender_check_days WHERE day < ?`,
|
|
now.UTC().AddDate(0, 0, -senderCheckKeepDays).Format(dayLayout))
|
|
if err != nil {
|
|
return fmt.Errorf("prune sender check days: %w", err)
|
|
}
|
|
return nil
|
|
}
|