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>
362 lines
13 KiB
Go
362 lines
13 KiB
Go
package store
|
|
|
|
import (
|
|
"database/sql"
|
|
"errors"
|
|
"fmt"
|
|
"strings"
|
|
"time"
|
|
)
|
|
|
|
// Send-log status values (architecture.md § Persistence). "queued" is written
|
|
// by the journal-milter when a message is accepted; the log-tailer advances it
|
|
// to one of the final states as Postfix reports delivery per recipient.
|
|
const (
|
|
StatusQueued = "queued"
|
|
StatusSent = "sent"
|
|
StatusDeferred = "deferred"
|
|
StatusBounced = "bounced"
|
|
// StatusRejected marks a message the journal-milter refused with a 4xx under
|
|
// a level-2 rate limit (guide § Rate limiting). Such a row never gets a
|
|
// queue-id and is excluded from the level-2 message count (it was never
|
|
// sent).
|
|
StatusRejected = "rejected"
|
|
)
|
|
|
|
// SendLogEntry is a single queued send-log row. The journal-milter creates one
|
|
// per (queue-id, recipient) pair at end-of-message (architecture.md §
|
|
// Persistence); every field except the status/timestamps comes from the
|
|
// accepted message.
|
|
type SendLogEntry struct {
|
|
QueueID string
|
|
Domain string
|
|
AppLogin string
|
|
From string
|
|
To string
|
|
Subject string
|
|
// Reason and HeaderFrom are set on refused rows only: why the message
|
|
// was refused (Reason*), and for ReasonFrom what its From: line said.
|
|
Reason string
|
|
HeaderFrom string
|
|
}
|
|
|
|
// InsertQueued records an accepted message in the send log with status
|
|
// "queued". It is called from the journal-milter hot path, so it returns any
|
|
// error for the caller to log rather than deciding policy here; the milter
|
|
// must stay fail-open regardless (architecture.md § Persistence).
|
|
func (s *Store) InsertQueued(e SendLogEntry) error {
|
|
now := time.Now().UTC().Format(time.RFC3339)
|
|
_, err := s.db.Exec(
|
|
`INSERT INTO send_log
|
|
(queue_id, domain, app_login, from_addr, to_addr, subject, status, created_at, updated_at)
|
|
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)`,
|
|
e.QueueID, e.Domain, e.AppLogin, e.From, e.To, e.Subject, StatusQueued, now, now,
|
|
)
|
|
if err != nil {
|
|
return fmt.Errorf("insert send_log: %w", err)
|
|
}
|
|
return nil
|
|
}
|
|
|
|
// InsertRejected records a message the journal-milter refused under a level-2
|
|
// rate limit (guide § Rate limiting), so the rejection is visible in the
|
|
// send-log UI. Only the fields known at MAIL FROM are set (domain, sender, app
|
|
// login); there is no queue-id or recipient because the message was rejected
|
|
// before it was queued.
|
|
func (s *Store) InsertRejected(e SendLogEntry) error {
|
|
now := time.Now().UTC().Format(time.RFC3339)
|
|
_, err := s.db.Exec(
|
|
`INSERT INTO send_log
|
|
(queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, created_at, updated_at)
|
|
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)`,
|
|
e.QueueID, e.Domain, e.AppLogin, e.From, e.To, e.Subject, StatusRejected, e.Reason, e.HeaderFrom, now, now,
|
|
)
|
|
if err != nil {
|
|
return fmt.Errorf("insert rejected send_log: %w", err)
|
|
}
|
|
return nil
|
|
}
|
|
|
|
// UpdateStatus advances the delivery status of the send-log rows matching a
|
|
// (queue-id, recipient) pair, which the log-tailer parses out of mail.log.
|
|
// Recipient matching is case-insensitive because Postfix may normalise address
|
|
// 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.
|
|
//
|
|
// Only the newest row of the pair is updated. Postfix reuses a short queue id
|
|
// once the message has left the queue, and a row outlives that by months; a
|
|
// line about today's message must not rewrite an old one (audit 2026-10-12,
|
|
// review of stage 1).
|
|
//
|
|
// 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's
|
|
// status wins, the reason becomes "reconcile-contradicted" - which row, and
|
|
// updated_at says when - and the day's reconcile_contradicted counts it
|
|
// (delivery_log_days), once, since the row no longer reads "reconcile".
|
|
//
|
|
// The transaction's first statement is a write. A transaction that reads
|
|
// first and then writes fails at once with "database is locked" when another
|
|
// connection - the dmarc-ingest process opens the same file - commits in
|
|
// between, and the line would be lost; a write first takes the write lock,
|
|
// and the busy timeout waits for it.
|
|
func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) {
|
|
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()
|
|
const newest = `id = (SELECT MAX(id) FROM send_log WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE)`
|
|
marked, err := tx.Exec(
|
|
`UPDATE send_log SET reason = ? WHERE `+newest+` AND reason = ?`,
|
|
ReasonReconcileContradicted, queueID, recipient, ReasonReconcile,
|
|
)
|
|
if err != nil {
|
|
return 0, fmt.Errorf("update send_log status: %w", err)
|
|
}
|
|
contradicted, _ := marked.RowsAffected()
|
|
res, err := tx.Exec(
|
|
`UPDATE send_log SET status = ?, updated_at = ? WHERE `+newest,
|
|
status, now.Format(time.RFC3339), 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
|
|
}
|
|
|
|
// CloseUnreported is the reconcile sweep's close of one row, by its id:
|
|
// "bounced", marked reason "reconcile" so it is known who decided it
|
|
// (architecture.md § Log tailer). Only a row still "queued" is closed - a
|
|
// result the log wrote an instant earlier stands (audit 2026-10-12, H3). It
|
|
// returns the number of rows closed, 0 or 1.
|
|
func (s *Store) CloseUnreported(id int64) (int64, error) {
|
|
now := time.Now().UTC().Format(time.RFC3339)
|
|
res, err := s.db.Exec(
|
|
`UPDATE send_log SET status = ?, reason = ?, updated_at = ? WHERE id = ? AND status = ?`,
|
|
StatusBounced, ReasonReconcile, now, id, StatusQueued,
|
|
)
|
|
if err != nil {
|
|
return 0, fmt.Errorf("close unreported send_log row: %w", err)
|
|
}
|
|
n, _ := res.RowsAffected()
|
|
return n, nil
|
|
}
|
|
|
|
// QueuedDelivery is a send-log row still waiting for a delivery result,
|
|
// reduced to what the log-tailer's reconcile sweep needs to look it up in the
|
|
// Postfix queue and, failing that, to close it (architecture.md § Log tailer).
|
|
type QueuedDelivery struct {
|
|
ID int64
|
|
QueueID string
|
|
To string
|
|
}
|
|
|
|
// ListQueuedOlderThan returns the rows still marked "queued" that were accepted
|
|
// before cutoff — old enough that Postfix should long since have reported a
|
|
// result for them. Rows without a queue-id are skipped: the milter refused
|
|
// those before Postfix ever saw the message, so the queue has nothing to say
|
|
// about them.
|
|
//
|
|
// created_at is stored as RFC3339 UTC, so a lexical comparison against the same
|
|
// format is chronologically correct.
|
|
func (s *Store) ListQueuedOlderThan(cutoff time.Time) ([]QueuedDelivery, error) {
|
|
rows, err := s.db.Query(
|
|
`SELECT id, queue_id, to_addr FROM send_log
|
|
WHERE status = ? AND queue_id <> '' AND created_at < ?
|
|
ORDER BY id`,
|
|
StatusQueued, cutoff.UTC().Format(time.RFC3339),
|
|
)
|
|
if err != nil {
|
|
return nil, fmt.Errorf("list queued send_log rows: %w", err)
|
|
}
|
|
defer rows.Close()
|
|
|
|
var out []QueuedDelivery
|
|
for rows.Next() {
|
|
var d QueuedDelivery
|
|
if err := rows.Scan(&d.ID, &d.QueueID, &d.To); err != nil {
|
|
return nil, fmt.Errorf("scan queued send_log row: %w", err)
|
|
}
|
|
out = append(out, d)
|
|
}
|
|
return out, rows.Err()
|
|
}
|
|
|
|
// SendLogRow is one row as returned to the monitoring UI (architecture.md §
|
|
// Persistence): a SendLogEntry plus the fields that only exist once a row has
|
|
// been written (id, current status, timestamps).
|
|
type SendLogRow struct {
|
|
ID int64
|
|
QueueID string
|
|
Domain string
|
|
AppLogin string
|
|
From string
|
|
To string
|
|
Subject string
|
|
Status string
|
|
// Reason and HeaderFrom: see SendLogEntry.
|
|
Reason string
|
|
HeaderFrom string
|
|
CreatedAt time.Time
|
|
// UpdatedAt is when the status last changed — the log-tailer's report of
|
|
// the delivery attempt. It equals CreatedAt while a row is still queued.
|
|
UpdatedAt time.Time
|
|
}
|
|
|
|
// ErrSendLogNotFound is returned by GetSendLog for an id that no longer exists.
|
|
// Send-log rows are pruned on the retention window, so a bookmarked delivery
|
|
// disappearing is expected, not a fault.
|
|
var ErrSendLogNotFound = errors.New("send-log entry not found")
|
|
|
|
// GetSendLog returns a single send-log row by id, for the delivery detail page
|
|
// the log links each row to.
|
|
func (s *Store) GetSendLog(id int64) (SendLogRow, error) {
|
|
var (
|
|
row SendLogRow
|
|
createdAt, updatedAt string
|
|
)
|
|
err := s.db.QueryRow(
|
|
`SELECT id, queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, created_at, updated_at
|
|
FROM send_log WHERE id = ?`, id,
|
|
).Scan(&row.ID, &row.QueueID, &row.Domain, &row.AppLogin, &row.From, &row.To,
|
|
&row.Subject, &row.Status, &row.Reason, &row.HeaderFrom, &createdAt, &updatedAt)
|
|
if errors.Is(err, sql.ErrNoRows) {
|
|
return SendLogRow{}, ErrSendLogNotFound
|
|
}
|
|
if err != nil {
|
|
return SendLogRow{}, fmt.Errorf("get send_log %d: %w", id, err)
|
|
}
|
|
row.CreatedAt, _ = time.Parse(time.RFC3339, createdAt)
|
|
row.UpdatedAt, _ = time.Parse(time.RFC3339, updatedAt)
|
|
return row, nil
|
|
}
|
|
|
|
// SendLogFilter narrows QuerySendLog/CountSendLog. It carries two kinds of
|
|
// narrowing, and they behave in opposite ways on purpose.
|
|
//
|
|
// Domain and AppLogin are the operator's own filters, chosen in the UI: an
|
|
// empty field matches everything.
|
|
//
|
|
// Domains and AllDomains are the authorization scope, which no query parameter
|
|
// may widen. Domains is the exhaustive set of domain names the caller is
|
|
// entitled to read, applied as an IN constraint; AllDomains lifts that
|
|
// restriction and is the only way to read the whole journal. A zero-valued
|
|
// filter therefore matches *no* rows: a caller that forgets to state a scope
|
|
// gets an empty log rather than every tenant's mail, which is the failure mode
|
|
// this struct exists to make impossible.
|
|
type SendLogFilter struct {
|
|
Domain string
|
|
AppLogin string
|
|
Domains []string
|
|
AllDomains bool
|
|
}
|
|
|
|
// QuerySendLog returns send-log rows matching filter, newest first, for the
|
|
// monitoring screen's server-side pagination (product.md's send-log view).
|
|
// The filter's authorization scope is mandatory: see SendLogFilter.
|
|
func (s *Store) QuerySendLog(filter SendLogFilter, limit, offset int) ([]SendLogRow, error) {
|
|
where, args := sendLogWhere(filter)
|
|
args = append(args, limit, offset)
|
|
rows, err := s.db.Query(
|
|
`SELECT id, queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, created_at, updated_at
|
|
FROM send_log`+where+`
|
|
ORDER BY id DESC
|
|
LIMIT ? OFFSET ?`,
|
|
args...,
|
|
)
|
|
if err != nil {
|
|
return nil, fmt.Errorf("query send_log: %w", err)
|
|
}
|
|
defer rows.Close()
|
|
|
|
var out []SendLogRow
|
|
for rows.Next() {
|
|
var (
|
|
row SendLogRow
|
|
createdAt, updatedAt string
|
|
)
|
|
if err := rows.Scan(&row.ID, &row.QueueID, &row.Domain, &row.AppLogin,
|
|
&row.From, &row.To, &row.Subject, &row.Status, &row.Reason, &row.HeaderFrom, &createdAt, &updatedAt); err != nil {
|
|
return nil, fmt.Errorf("scan send_log row: %w", err)
|
|
}
|
|
row.CreatedAt, _ = time.Parse(time.RFC3339, createdAt)
|
|
row.UpdatedAt, _ = time.Parse(time.RFC3339, updatedAt)
|
|
out = append(out, row)
|
|
}
|
|
return out, rows.Err()
|
|
}
|
|
|
|
// CountSendLog returns how many send-log rows match filter, so the monitoring
|
|
// screen can render page numbers/next-prev links.
|
|
func (s *Store) CountSendLog(filter SendLogFilter) (int64, error) {
|
|
where, args := sendLogWhere(filter)
|
|
var n int64
|
|
if err := s.db.QueryRow(`SELECT COUNT(*) FROM send_log`+where, args...).Scan(&n); err != nil {
|
|
return 0, fmt.Errorf("count send_log: %w", err)
|
|
}
|
|
return n, nil
|
|
}
|
|
|
|
func sendLogWhere(f SendLogFilter) (string, []any) {
|
|
var clauses []string
|
|
var args []any
|
|
if !f.AllDomains {
|
|
// No scope is not "no restriction": a domain administrator whose last
|
|
// assignment was deleted owns nothing in the journal and must see
|
|
// nothing, and the same clause catches a caller that never set a scope.
|
|
if len(f.Domains) == 0 {
|
|
return " WHERE 1 = 0", nil
|
|
}
|
|
marks := make([]string, len(f.Domains))
|
|
for i, name := range f.Domains {
|
|
marks[i] = "?"
|
|
args = append(args, name)
|
|
}
|
|
clauses = append(clauses, "domain IN ("+strings.Join(marks, ", ")+")")
|
|
}
|
|
if f.Domain != "" {
|
|
clauses = append(clauses, "domain = ?")
|
|
args = append(args, f.Domain)
|
|
}
|
|
if f.AppLogin != "" {
|
|
clauses = append(clauses, "app_login = ?")
|
|
args = append(args, f.AppLogin)
|
|
}
|
|
if len(clauses) == 0 {
|
|
return "", nil
|
|
}
|
|
return " WHERE " + strings.Join(clauses, " AND "), args
|
|
}
|
|
|
|
// DeleteSendLogBefore removes send-log rows created before cutoff,
|
|
// implementing the configurable retention window (architecture.md §
|
|
// Persistence, SEND_LOG_RETENTION_DAYS). It returns the number of rows pruned.
|
|
// created_at is stored as RFC3339 UTC, so a lexical comparison against the
|
|
// same format is chronologically correct.
|
|
func (s *Store) DeleteSendLogBefore(cutoff time.Time) (int64, error) {
|
|
res, err := s.db.Exec(
|
|
`DELETE FROM send_log WHERE created_at < ?`,
|
|
cutoff.UTC().Format(time.RFC3339),
|
|
)
|
|
if err != nil {
|
|
return 0, fmt.Errorf("prune send_log: %w", err)
|
|
}
|
|
n, _ := res.RowsAffected()
|
|
return n, nil
|
|
}
|