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>
121 lines
4.2 KiB
Go
121 lines
4.2 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
|
|
|
|
// deliveryLogCounters are the columns addDeliveryLogDay may add to: the
|
|
// name is put into the statement, so nothing else may reach it.
|
|
var deliveryLogCounters = map[string]bool{
|
|
"reconcile_closed": true, "reconcile_missed": true, "tailer_blind_seconds": true,
|
|
}
|
|
|
|
// addDeliveryLogDay adds n to one counter of the day of at.
|
|
func (s *Store) addDeliveryLogDay(at time.Time, column string, n int64) error {
|
|
if !deliveryLogCounters[column] {
|
|
return fmt.Errorf("delivery log day: no counter %q", column)
|
|
}
|
|
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)
|
|
}
|
|
|
|
// AddReconcileMissed counts n rows the sweep closed whose delivery line was
|
|
// in mail.log all along: the tailer did not read it.
|
|
func (s *Store) AddReconcileMissed(at time.Time, n int64) error {
|
|
return s.addDeliveryLogDay(at, "reconcile_missed", 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, Missed, 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_missed, 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.Missed, &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
|
|
}
|