test / test (push) Canceled after 0s
Expiry (assumptions A-8). Postfix 3.7.11 logs the end of a message's queue lifetime once per message, "<id>: from=<..>, status=expired, returned to sender" (src/qmgr/qmgr_active.c, qmgr_active_done_25_generic()), with no line per recipient; the tailer waited for "to=..., status=expired", which no Postfix writes, and the sweep closed only queued rows, so such rows stayed deferred. The tailer now reads qmgr's line (ExpireMessage: each recipient's newest open row of the id becomes bounced); the sweep closes a deferred row too when Postfix no longer holds the message, and counts as missed only a final line (sent, bounced, expiry). The queue listing's '#' (forced expiry, showq_compat.c showq_message()) is read as a flag (B-PQ1). Time values (B-PQ10, B-PQ11): conv_time() ported - one number, one lower-case unit, the parameter's default unit when none (get_def_time_unit: d for the lifetimes, h for delay_warning_time), the rest ignored; postconf -h -x expands $name; bounce_queue_lifetime capped at maximal_queue_lifetime as qmgr_post_init() caps it, so LongestLifetime is the queue lifetime. Refusals (A-21, A-23, A-24, A-15): smtpd_whatsup() ends the NOQUEUE line with sasl_username=<login> on an authenticated session; the line is now matched to its row by client, login and sender, and a line without a login is no application's. The client= line's login ends at the comma. The "IPv6:" trim goes (namaddr is built from state->addr). A row recovered from cleanup's line says that line names the last recipient only. Stand (2026-10-14, make e2e, exit 0): new expired_message_is_closed - defer_transports=smtp makes the retry service defer the message, postsuper -e and postqueue -i force its expiry; mail.log has "<id>: from=<alerts@sender.e2e.test>, status=force-expired, returned to sender" and the row goes deferred -> bounced; refusals_show_postfixs_line passes with the login match. go vet and go test ./... pass on the server. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
122 lines
4.3 KiB
Go
122 lines
4.3 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
|
|
}
|
|
|
|
// CountOpenOlderThan counts the rows still open - "queued" or "deferred" -
|
|
// that were accepted before cutoff. created_at is RFC3339 UTC, so the strings
|
|
// compare as times.
|
|
func (s *Store) CountOpenOlderThan(cutoff time.Time) (int64, error) {
|
|
var n int64
|
|
err := s.db.QueryRow(
|
|
`SELECT COUNT(*) FROM send_log WHERE status IN (?, ?) AND queue_id <> '' AND created_at < ?`,
|
|
StatusQueued, StatusDeferred, 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
|
|
}
|