audit 3: every per-message question of the send log has its index
test / test (push) Canceled after 0s

Migration 0010 (DDL only; 0009 went to stage 2b). EXPLAIN QUERY PLAN of
every send_log statement showed, beyond M2 as written (stage 2 had already
moved the by-domain counts onto (domain_id, created_at)):

- the tailer's sweep of open rows (every 5 min) and its count scanned the
  table: partial idx_send_log_open (created_at) WHERE status IN ('queued',
  'deferred'), the statuses literal in the statements, ORDER BY +id (else
  SQLite walks the table in id order to skip a sort);
- AttachRefusalLine's NOT EXISTS (... refusal_line = ?1) scanned the table
  for every refusal line: partial idx_send_log_refusal_line, the query
  carrying the index's WHERE; its row found by idx_send_log_rejected
  (status literal, +queue_id) instead of every refusal without a queue id;
- an application's level-2 count went through its domain's index:
  +domain_id in appByLogin;
- a page of one domain's or one application's log sorted all of it:
  idx_send_log_domain_id, idx_send_log_app_login (id order; several domains
  still sort, top-N). idx_send_log_domain stays for the global filter.

The statements are constants and builders (countMessagesQuery,
peakPerHourQuery, listOpenQuery, countOpenQuery, sendLogPageQuery,
attachRefusalLineQuery, limitRefusalsQuery) and
TestSendLogQueriesUseTheirIndexes explains exactly those: the index each
must use, no SCAN of send_log, no sort where none is wanted; the literal
statuses checked against the constants. It replaces the hand-written plan
check of TestLimitRefusalsSince.

Tested on the test server: go vet + go test of 24 packages, make e2e (all
pass) on this tree.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
mix
2026-10-15 10:10:52 +03:00
co-authored by Claude Opus 5.5
parent 8e3241ef98
commit 508ac96c79
13 changed files with 268 additions and 89 deletions
+12
View File
@@ -5,8 +5,20 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version
## [Unreleased]
Migration `0010` (indexes only).
### Fixed
- **Questions asked of the send log on every message or every few minutes
walked the whole table.** Measured with SQLite's own plans against the
statements the panel runs: the sweep for rows still queued or deferred
(every 5 minutes) and the check whether a refusal line from `mail.log` is
already on a row (every such line) read every row of the retention
period; a level-2 limit of an application counted through all of its
domain's rows; a page of a domain administrator's log sorted the domain's
whole log. Migration `0010` adds four indexes, and a test now holds each
of these statements to its index (audit 2026-10-12, M2).
- **A restore whose first start failed never ran its Resync.** The panel
removed the restore manifest as soon as it had checked the version, before
it opened the database and regenerated the mail maps from it; a start that
+17 -1
View File
@@ -1092,12 +1092,28 @@ those after it move up one patch number each.
untouched, no `-wal`), a damaged key named; the domain import of a cut
plain export, a cut and an altered `.spde` (each refused, nothing
created). The CLI's `-decrypt -o` is step 3.
- [ ] **Indexes**: `idx_send_log_domain_created_at (domain_id, created_at)` —
- [x] **Indexes**: `idx_send_log_domain_created_at (domain_id, created_at)` —
on the id column stage 2 adds, replacing `idx_send_log_domain`;
partial `idx_send_log_queued (created_at) WHERE status = 'queued'`;
consider `(domain, id)` for the scoped page. Migration `0009` DDL only;
`TestLimitRefusalsSince`-style EXPLAIN tests against the **real** query
strings. — **Opus**
*Done 2026-10-15,* migration `0010` (0009 went to stage 2b). Stage 2
already counted by `(domain_id, created_at)`; `idx_send_log_domain` stays,
the global log's filter by name reads its page off it in id order. The
plans of every `send_log` statement showed four more: the sweep now asks
for queued *and* deferred rows - `idx_send_log_open (created_at) WHERE
status IN ('queued', 'deferred')`, the statuses literal and `ORDER BY +id`
(else SQLite walks the table in id order); `NOT EXISTS (... refusal_line
= ?1)` of stage 2b scanned the table per refusal line - partial
`idx_send_log_refusal_line`, and its row is found by
`idx_send_log_rejected` (status literal, `+queue_id`); the application's
level-2 count went by the domain's index - `+domain_id`; a page of one
domain or one application - `idx_send_log_domain_id`,
`idx_send_log_app_login` (id order, no sort; several domains still sort,
top-N). The statements are constants/builders the test explains
(`TestSendLogQueriesUseTheirIndexes`, which replaces the hand-written
plan check of `TestLimitRefusalsSince`).
- [ ] **CLI backup**: open the source `mode=ro`, refuse a missing file; password
floor of 12 shared with the panel (`validate.MinSecretFilePasswordLen`);
`-decrypt -o` verifies the password (first chunk) before opening the
+1 -1
View File
@@ -42,7 +42,7 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md).
| from-header-binding | Hold a message's `From:` header against the application that sends it | shipped `2.4.0` | 9/9 | [plans/from-header-binding.md](plans/from-header-binding.md) |
| panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) |
| schema-squash | Squash SQLite migrations into a 2.x baseline | built in panel-redesign (stage 1) | — | [plans/panel-redesign.md](plans/panel-redesign.md) |
| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`, stages 1+2 `2.5.0`, 2b `2.5.1`, 2c `2.5.2`; next stage 3 → `2.5.3`) | 50/81 | [audit-2026-10-12.md](audit-2026-10-12.md) |
| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`, stages 1+2 `2.5.0`, 2b `2.5.1`, 2c `2.5.2`; next stage 3 → `2.5.3`) | 51/81 | [audit-2026-10-12.md](audit-2026-10-12.md) |
**Recommended order** (not binding; owner, 2026-10-09: feature order follows
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and
+5 -3
View File
@@ -17,8 +17,8 @@ When you add or review a migration, update this file in the same change.
| Field | Value |
|---|---|
| Chain head | `user_version = 9` |
| Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql`, `0003_send_log_lines.sql`, `0004_notifications.sql`, `0005_send_log_rejected_index.sql`, `0006_sender_check.sql`, `0007_delivery_log_days.sql`, `0008_tenant_boundary.sql`, `0009_refusal_line.sql` |
| Chain head | `user_version = 10` |
| Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql`, `0003_send_log_lines.sql`, `0004_notifications.sql`, `0005_send_log_rejected_index.sql`, `0006_sender_check.sql`, `0007_delivery_log_days.sql`, `0008_tenant_boundary.sql`, `0009_refusal_line.sql`, `0010_send_log_indexes.sql` |
| File mark | `PRAGMA application_id = 0x53503230` ("SP20") |
| Database file | `/data/selfpost.db` (bind mount) |
| Compatibility | 2.x MINOR releases must boot a `2.0.0` data directory. **Nothing is carried over from 1.x.** |
@@ -67,7 +67,8 @@ delivery-log-storage (`2.2.0`), `0004_notifications.sql` and
`0005_send_log_rejected_index.sql` of panel-notifications (`2.3.0`), and
`0006_sender_check.sql` of from-header-binding (`2.4.0`), and
`0007_delivery_log_days.sql` and `0008_tenant_boundary.sql` of the 2026-10-12
audit (`2.5.0`).
audit (`2.5.0`), `0009_refusal_line.sql` (`2.5.1`) and
`0010_send_log_indexes.sql` (`2.5.3`).
---
@@ -84,6 +85,7 @@ audit (`2.5.0`).
| 7 | `0007_delivery_log_days.sql` | 2.5.0 | DDL | `delivery_log_days`: what the reconcile sweep and the log tailer did, a row per UTC day, kept a year, shown nowhere - the measurement that decides the sweep's fate (audit 2026-10-12, stage 1). `send_log.reason` gains the values `reconcile` and `reconcile-contradicted` without a schema change |
| 8 | `0008_tenant_boundary.sql` | 2.5.0 | DDL + data | `idx_applications_login_nocase`: an application login is unique without regard to case (audit 2026-10-12, H4). `send_log.domain_id` and `inbound_spam_log.inbound_domain_id` (`ON DELETE SET NULL`), each with an index, filled once by name from the registry as it was then: a row belongs to a domain by id, and a domain deleted and added again starts with an empty log (L12) |
| 9 | `0009_refusal_line.sql` | 2.5.1 | DDL | `send_log.refusal_line`: Postfix's line about a refusal at MAIL FROM (a level-2 limit, a client address off the list), which has no queue id; the log tailer puts it on the row; `send_log.recovered`, a refusal row the tailer wrote from `mail.log` because the panel stopped before writing it; `sender_check_days.messages` (messages deferred mid-message, counted apart from the connections turned away) and `sender_check_days.estimated` (a day whose downtime is an upper bound) (audit 2026-10-12, stage 2b) |
| 10 | `0010_send_log_indexes.sql` | 2.5.3 | DDL | Four indexes of `send_log`, each for a question that walked the table or sorted a domain's log (audit 2026-10-12, M2, stage 3): `idx_send_log_open`, partial, the queued and deferred rows by time (the tailer's sweep every 5 min); `idx_send_log_domain_id` and `idx_send_log_app_login`, a page of one domain's or one application's log in id order; `idx_send_log_refusal_line`, partial, whether a refusal line is already on a row. `TestSendLogQueriesUseTheirIndexes` checks the plans of the statements the store runs |
**Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct
for operators upgrading from older 2.x images.
+4 -4
View File
@@ -69,15 +69,15 @@ func (s *Store) SetQueuedOverLifetime(at time.Time, n int64) error {
return nil
}
// countOpenQuery is CountOpenOlderThan's, by idx_send_log_open (openRows).
const countOpenQuery = `SELECT COUNT(*) FROM send_log WHERE ` + openRows + ` AND created_at < ?`
// 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)
err := s.db.QueryRow(countOpenQuery, cutoff.UTC().Format(time.RFC3339)).Scan(&n)
if err != nil {
return 0, fmt.Errorf("count queued send_log rows: %w", err)
}
@@ -0,0 +1,22 @@
-- The send log's questions, each answered from an index (audit 2026-10-12,
-- M2; stage 3). Measured with EXPLAIN QUERY PLAN against the statements the
-- store runs (TestSendLogQueriesUseTheirIndexes); before this file each of
-- them walked the table or sorted a domain's whole log.
-- The rows still open - queued or deferred - older than a cutoff: the log
-- tailer asks every five minutes, and nearly every row is older than the
-- cutoff, so only an index of the open rows alone helps. The queries name
-- the two statuses as literals, which is what lets SQLite use it.
CREATE INDEX idx_send_log_open ON send_log (created_at) WHERE status IN ('queued', 'deferred');
-- A page of the log, newest first, of one domain (a domain administrator's
-- view) or one application (the filter): an index of the one column is
-- ordered by id within it, so a page reads its rows and stops. The indexes
-- with created_at after the column answer the counts over a time window and
-- cannot give that order.
CREATE INDEX idx_send_log_domain_id ON send_log (domain_id);
CREATE INDEX idx_send_log_app_login ON send_log (app_login);
-- Whether a line of Postfix's log is already on a row: asked for every
-- refusal line the tailer reads. Only refused rows carry one.
CREATE INDEX idx_send_log_refusal_line ON send_log (refusal_line) WHERE refusal_line <> '';
+15 -13
View File
@@ -168,6 +168,20 @@ type LimitRefusal struct {
First time.Time
}
// limitRefusalsQuery is LimitRefusalsSince's. The status is a literal so
// that the partial index of migration 0005 answers the question: the
// query's term matches the index's WHERE exactly
// (https://sqlite.org/partialindex.html § 3) when the statement is first
// prepared.
const limitRefusalsQuery = `SELECT d.name, a.login, COUNT(*), MIN(l.created_at)
FROM send_log l
JOIN domains d ON d.id = l.domain_id
JOIN applications a ON a.login = l.app_login AND a.domain_id = d.id
WHERE l.status = 'rejected' AND l.created_at >= ? AND l.reason IN ('', 'limit')
AND (EXISTS (SELECT 1 FROM rate_limits r WHERE r.scope = 'application' AND r.ref_id = a.id)
OR EXISTS (SELECT 1 FROM rate_limits r WHERE r.scope = 'domain' AND r.ref_id = d.id))
GROUP BY d.name, a.login ORDER BY d.name, a.login`
// LimitRefusalsSince returns, per sending domain, the messages the journal
// milter refused under a level-2 limit at or after since.
//
@@ -183,19 +197,7 @@ type LimitRefusal struct {
// address or its From: line is left out by that; a row from before has no
// reason and is still judged the old way.
func (s *Store) LimitRefusalsSince(since time.Time) ([]LimitRefusal, error) {
// The status is a literal so that the partial index of migration 0005
// answers the question: the query's term matches the index's WHERE
// exactly (https://sqlite.org/partialindex.html § 3) when the statement is
// first prepared.
rows, err := s.db.Query(
`SELECT d.name, a.login, COUNT(*), MIN(l.created_at)
FROM send_log l
JOIN domains d ON d.id = l.domain_id
JOIN applications a ON a.login = l.app_login AND a.domain_id = d.id
WHERE l.status = 'rejected' AND l.created_at >= ? AND l.reason IN ('', 'limit')
AND (EXISTS (SELECT 1 FROM rate_limits r WHERE r.scope = 'application' AND r.ref_id = a.id)
OR EXISTS (SELECT 1 FROM rate_limits r WHERE r.scope = 'domain' AND r.ref_id = d.id))
GROUP BY d.name, a.login ORDER BY d.name, a.login`,
rows, err := s.db.Query(limitRefusalsQuery,
since.UTC().Format(time.RFC3339),
)
if err != nil {
+2 -18
View File
@@ -201,22 +201,6 @@ func TestLimitRefusalsSince(t *testing.T) {
t.Errorf("other.example = %+v", g)
}
// The question is answered from the index of the refused rows alone.
var plan []string
rows, err := s.db.Query(`EXPLAIN QUERY PLAN SELECT COUNT(*) FROM send_log l WHERE l.status = 'rejected' AND l.created_at >= '2026-10-01T00:00:00Z'`)
if err != nil {
t.Fatal(err)
}
for rows.Next() {
var id, parent, notused int
var detail string
if err := rows.Scan(&id, &parent, &notused, &detail); err != nil {
t.Fatal(err)
}
plan = append(plan, detail)
}
rows.Close()
if !strings.Contains(strings.Join(plan, "; "), "idx_send_log_rejected") {
t.Errorf("refused rows are not found through their index: %v", plan)
}
// The question is answered from the index of the refused rows alone:
// TestSendLogQueriesUseTheirIndexes.
}
+110
View File
@@ -0,0 +1,110 @@
package store
import (
"strings"
"testing"
)
// explain returns SQLite's plan for query, one step a line.
func explain(t *testing.T, s *Store, query string, args ...any) string {
t.Helper()
rows, err := s.db.Query("EXPLAIN QUERY PLAN "+query, args...)
if err != nil {
t.Fatalf("explain: %v\n%s", err, query)
}
defer rows.Close()
var plan []string
for rows.Next() {
var id, parent, notused int
var detail string
if err := rows.Scan(&id, &parent, &notused, &detail); err != nil {
t.Fatal(err)
}
plan = append(plan, detail)
}
return strings.Join(plan, "\n")
}
// The send log is the one table that grows with the mail, and every question
// asked of it on a path that runs per message, per log line or every few
// minutes is answered from an index: measured with EXPLAIN QUERY PLAN against
// the statements the store runs, not copies of them (audit 2026-10-12, M2;
// stage 3). SQLite chooses without statistics here, as it does on a server -
// nothing runs ANALYZE.
func TestSendLogQueriesUseTheirIndexes(t *testing.T) {
s := openTestStore(t)
const since = "2026-10-01T00:00:00Z"
page := func(f SendLogFilter) (string, []any) {
where, args := sendLogWhere(f)
return sendLogPageQuery(where), append(args, 50, 0)
}
oneDomain, oneDomainArgs := page(SendLogFilter{DomainIDs: []int64{1}})
oneApp, oneAppArgs := page(SendLogFilter{AllDomains: true, AppLogin: "app1"})
byName, byNameArgs := page(SendLogFilter{AllDomains: true, Domain: "example.com"})
for _, c := range []struct {
name string
query string
args []any
want []string // steps the plan must have
sorts bool // whether it may sort the rows it reads
}{
{"level-2 count of a domain", countMessagesQuery(domainByName), []any{"example.com", StatusRejected, since},
[]string{"SEARCH send_log USING INDEX idx_send_log_domain_id_created_at (domain_id=? AND created_at>?)"}, false},
{"level-2 count of an application", countMessagesQuery(appByLogin), []any{"app1", StatusRejected, since},
[]string{"SEARCH send_log USING INDEX idx_send_log_app_login_created_at (app_login=? AND created_at>?)"}, false},
{"busiest hour of a domain", peakPerHourQuery(domainByName), []any{"example.com", StatusRejected, since},
[]string{"SEARCH send_log USING INDEX idx_send_log_domain_id_created_at (domain_id=? AND created_at>?)"}, true},
{"busiest hour of an application", peakPerHourQuery(appByLogin), []any{"app1", StatusRejected, since},
[]string{"SEARCH send_log USING INDEX idx_send_log_app_login_created_at (app_login=? AND created_at>?)"}, true},
{"open rows", listOpenQuery, []any{since},
[]string{"SEARCH send_log USING INDEX idx_send_log_open (created_at<?)"}, true},
{"open rows counted", countOpenQuery, []any{since},
[]string{"SEARCH send_log USING INDEX idx_send_log_open (created_at<?)"}, false},
{"a page of one domain", oneDomain, oneDomainArgs,
[]string{"SEARCH send_log USING INDEX idx_send_log_domain_id (domain_id=?)"}, false},
{"a page of one application", oneApp, oneAppArgs,
[]string{"SEARCH send_log USING INDEX idx_send_log_app_login (app_login=?)"}, false},
{"a page of a domain by name", byName, byNameArgs,
[]string{"SEARCH send_log USING INDEX idx_send_log_domain (domain=?)"}, false},
{"a refusal line", attachRefusalLineQuery,
[]any{"line", ReasonLimit, ReasonClient, "a@example.com", "192.0.2.1", since, since, since, "app1"},
[]string{
"SEARCH send_log USING INDEX idx_send_log_rejected (created_at>? AND created_at<?)",
"SEARCH send_log USING COVERING INDEX idx_send_log_refusal_line (refusal_line=?)",
}, true},
{"refusals under a limit", limitRefusalsQuery, []any{since},
[]string{"SEARCH l USING INDEX idx_send_log_rejected (created_at>?)"}, true},
} {
t.Run(c.name, func(t *testing.T) {
plan := explain(t, s, c.query, c.args...)
for _, want := range c.want {
if !strings.Contains(plan, want) {
t.Errorf("the plan has no %q:\n%s", want, plan)
}
}
for _, line := range strings.Split(plan, "\n") {
if strings.HasPrefix(line, "SCAN send_log") || strings.HasPrefix(line, "SCAN l") {
t.Errorf("the plan walks the whole send log:\n%s", plan)
}
if !c.sorts && strings.Contains(line, "TEMP B-TREE FOR ORDER BY") {
t.Errorf("the plan sorts the rows it reads:\n%s", plan)
}
}
})
}
// The partial indexes are used because the statuses are written into the
// statements as the index's WHERE has them; the constants must say the
// same.
for _, st := range []string{StatusQueued, StatusDeferred} {
if !strings.Contains(openRows, "'"+st+"'") {
t.Errorf("openRows does not name status %q: %s", st, openRows)
}
}
for _, q := range []string{attachRefusalLineQuery, limitRefusalsQuery} {
if !strings.Contains(q, "status = '"+StatusRejected+"'") {
t.Errorf("a refusal query does not name status %q", StatusRejected)
}
}
}
+1 -3
View File
@@ -187,9 +187,7 @@ func (s *Store) CountMessages(scope, ref string, since time.Time) (int64, error)
var n int64
// created_at is stored as RFC3339 UTC, so a lexical comparison against the
// same format is chronologically correct (as in DeleteSendLogBefore).
err := s.db.QueryRow(
`SELECT COUNT(DISTINCT queue_id) FROM send_log
WHERE `+match+` AND status != ? AND created_at >= ?`,
err := s.db.QueryRow(countMessagesQuery(match),
ref, StatusRejected, since.UTC().Format(time.RFC3339),
).Scan(&n)
if err != nil {
+6 -5
View File
@@ -107,7 +107,8 @@ func TestBaselineSchema(t *testing.T) {
wantIdx := []string{
"idx_applications_login_nocase", "idx_dmarc_report_records_report", "idx_dmarc_reports_domain", "idx_dmarc_reports_received",
"idx_inbound_spam_log_created_at", "idx_inbound_spam_log_domain_created_at", "idx_inbound_spam_log_domain_id_created_at",
"idx_send_log_app_login_created_at", "idx_send_log_created_at", "idx_send_log_domain", "idx_send_log_domain_id_created_at", "idx_send_log_lines_queue_id", "idx_send_log_queue_id", "idx_send_log_rejected",
"idx_send_log_app_login", "idx_send_log_app_login_created_at", "idx_send_log_created_at", "idx_send_log_domain", "idx_send_log_domain_id", "idx_send_log_domain_id_created_at",
"idx_send_log_lines_queue_id", "idx_send_log_open", "idx_send_log_queue_id", "idx_send_log_refusal_line", "idx_send_log_rejected",
"idx_sessions_expires_at",
}
sort.Strings(wantIdx)
@@ -116,8 +117,8 @@ func TestBaselineSchema(t *testing.T) {
}
var version, appID int64
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 9 {
t.Errorf("user_version = %d, %v; want 9", version, err)
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 10 {
t.Errorf("user_version = %d, %v; want 10", version, err)
}
if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID {
t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID)
@@ -193,8 +194,8 @@ func TestOpenMigratesA20Database(t *testing.T) {
}
defer st.Close()
var version int
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 9 {
t.Errorf("user_version = %d, %v; want 9", version, err)
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 10 {
t.Errorf("user_version = %d, %v; want 10", version, err)
}
if ok, err := st.UserExists(); err != nil || !ok {
t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err)
+46 -24
View File
@@ -209,6 +209,20 @@ func (s *Store) ExpireMessage(queueID string) (int64, error) {
return n, nil
}
// openRows selects the rows still open, StatusQueued and StatusDeferred
// written as literals: a term the same as the WHERE of the partial index
// idx_send_log_open (migration 0010) is what lets SQLite use it
// (https://sqlite.org/partialindex.html § 3), and a bound parameter is not.
const openRows = `status IN ('queued', 'deferred') AND queue_id <> ''`
// listOpenQuery is ListOpenOlderThan's. The unary + on the order keeps SQLite
// from walking the whole table in id order instead of the index
// (https://sqlite.org/optoverview.html § 18): the open rows are few, and
// sorting them is nothing.
const listOpenQuery = `SELECT id, queue_id, to_addr FROM send_log
WHERE ` + openRows + ` AND created_at < ?
ORDER BY +id`
// 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).
@@ -232,12 +246,7 @@ type QueuedDelivery struct {
// BINARY collation, memcmp() (https://sqlite.org/datatype3.html § 7), and
// time.RFC3339 of a UTC time is fixed-width, YYYY-MM-DDTHH:MM:SSZ.
func (s *Store) ListOpenOlderThan(cutoff time.Time) ([]QueuedDelivery, error) {
rows, err := s.db.Query(
`SELECT id, queue_id, to_addr FROM send_log
WHERE status IN (?, ?) AND queue_id <> '' AND created_at < ?
ORDER BY id`,
StatusQueued, StatusDeferred, cutoff.UTC().Format(time.RFC3339),
)
rows, err := s.db.Query(listOpenQuery, cutoff.UTC().Format(time.RFC3339))
if err != nil {
return nil, fmt.Errorf("list queued send_log rows: %w", err)
}
@@ -284,6 +293,23 @@ type SendLogRow struct {
UpdatedAt time.Time
}
// attachRefusalLineQuery is AttachRefusalLine's. The refused row is found by
// its time among the refused rows
// (idx_send_log_rejected: the status a literal, and the unary + keeps
// SQLite from walking every refusal without a queue id instead), and the
// line by idx_send_log_refusal_line (migration 0010; the second term is that
// index's WHERE) - https://sqlite.org/partialindex.html § 3,
// optoverview.html § 18.
const attachRefusalLineQuery = `UPDATE send_log SET refusal_line = ?1 WHERE id = (
SELECT id FROM send_log
WHERE status = 'rejected' AND +queue_id = '' AND refusal_line = ''
AND reason IN ('', ?2, ?3) AND from_addr = ?4 COLLATE NOCASE AND client_ip = ?5
AND app_login = ?9 COLLATE NOCASE
AND created_at BETWEEN ?6 AND ?7
ORDER BY ABS(julianday(created_at) - julianday(?8)), id
LIMIT 1)
AND NOT EXISTS (SELECT 1 FROM send_log WHERE refusal_line = ?1 AND refusal_line <> '')`
// AttachRefusalLine puts Postfix's line about a refusal at MAIL FROM on the
// row the journal milter wrote for it (audit 2026-10-12, stage 2b). Such a
// refusal has no queue id, and the line names no login, so the row is found
@@ -302,17 +328,8 @@ type SendLogRow struct {
// § 2); NOCASE folds ASCII only (datatype3.html § 7.1); ?1 is bound once and
// used twice (lang_expr.html § 4).
func (s *Store) AttachRefusalLine(clientIP, login, from string, at time.Time, line string) (bool, error) {
res, err := s.db.Exec(
`UPDATE send_log SET refusal_line = ?1 WHERE id = (
SELECT id FROM send_log
WHERE status = ?2 AND queue_id = '' AND refusal_line = ''
AND reason IN ('', ?3, ?4) AND from_addr = ?5 COLLATE NOCASE AND client_ip = ?6
AND app_login = ?10 COLLATE NOCASE
AND created_at BETWEEN ?7 AND ?8
ORDER BY ABS(julianday(created_at) - julianday(?9)), id
LIMIT 1)
AND NOT EXISTS (SELECT 1 FROM send_log WHERE refusal_line = ?1)`,
line, StatusRejected, ReasonLimit, ReasonClient, from, clientIP,
res, err := s.db.Exec(attachRefusalLineQuery,
line, ReasonLimit, ReasonClient, from, clientIP,
at.Add(-refusalLineWindow).UTC().Format(time.RFC3339),
at.Add(refusalLineWindow).UTC().Format(time.RFC3339),
at.UTC().Format(time.RFC3339),
@@ -409,19 +426,24 @@ type SendLogFilter struct {
AllDomains bool
}
// sendLogPageQuery is a page of the rows where selects, newest first. A page
// of one domain or one application reads its rows off idx_send_log_domain_id
// or idx_send_log_app_login (migration 0010), already in id order; a scope of
// several domains is sorted, keeping only the page.
func sendLogPageQuery(where string) string {
return `SELECT id, queue_id, domain, COALESCE(domain_id, 0), 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 ?`
}
// 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, COALESCE(domain_id, 0), 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...,
)
rows, err := s.db.Query(sendLogPageQuery(where), args...)
if err != nil {
return nil, fmt.Errorf("query send_log: %w", err)
}
+27 -17
View File
@@ -89,7 +89,31 @@ const domainByName = "domain_id = (SELECT d.id FROM domains d WHERE d.name = ?)"
// one more than the largest number already assigned; modernc.org/sqlite
// v1.60.1, conn.go bind() and argFinder.find(): ?NNN takes argument NNN, a
// plain ? the argument of its number.
const appByLogin = "app_login = ?1 AND domain_id = (SELECT a.domain_id FROM applications a WHERE a.login = ?1)"
//
// The unary + keeps domain_id out of the choice of index: the rows are found
// by the login and the time (idx_send_log_app_login_created_at), not among
// all of the domain's (https://sqlite.org/optoverview.html § 18,
// "Disqualifying WHERE clause terms using unary-+"; audit 2026-10-12, stage 3).
const appByLogin = "app_login = ?1 AND +domain_id = (SELECT a.domain_id FROM applications a WHERE a.login = ?1)"
// countMessagesQuery counts the distinct messages of the rows match selects
// (domainByName or appByLogin, then the status to leave out and the start of
// the window): the level-2 count and the statistics' total ask it alike.
func countMessagesQuery(match string) string {
return `SELECT COUNT(DISTINCT queue_id) FROM send_log
WHERE ` + match + ` AND status != ? AND created_at >= ?`
}
// peakPerHourQuery is the busiest UTC hour of the same rows: substr counts
// characters from 1 (https://sqlite.org/lang_corefunc.html#substr), so 1-13
// of an RFC3339 UTC stamp is YYYY-MM-DDTHH.
func peakPerHourQuery(match string) string {
return `SELECT COALESCE(MAX(bucket_count), 0) FROM (
SELECT COUNT(DISTINCT queue_id) AS bucket_count FROM send_log
WHERE ` + match + ` AND status != ? AND created_at >= ?
GROUP BY substr(created_at, 1, 13)
)`
}
// sendStats counts the rows that match, a condition with one placeholder
// taking ref.
@@ -97,27 +121,13 @@ func (s *Store) sendStats(match, ref string, since time.Time, hours float64) (Se
sinceStr := since.UTC().Format(time.RFC3339)
var total int64
err := s.db.QueryRow(
`SELECT COUNT(DISTINCT queue_id) FROM send_log
WHERE `+match+` AND status != ? AND created_at >= ?`,
ref, StatusRejected, sinceStr,
).Scan(&total)
err := s.db.QueryRow(countMessagesQuery(match), ref, StatusRejected, sinceStr).Scan(&total)
if err != nil {
return SendStats{}, fmt.Errorf("send stats total %q: %w", ref, err)
}
// The busiest UTC hour: substr counts characters from 1
// (https://sqlite.org/lang_corefunc.html#substr), so 1-13 of an RFC3339
// UTC stamp is YYYY-MM-DDTHH.
var peak int64
err = s.db.QueryRow(
`SELECT COALESCE(MAX(bucket_count), 0) FROM (
SELECT COUNT(DISTINCT queue_id) AS bucket_count FROM send_log
WHERE `+match+` AND status != ? AND created_at >= ?
GROUP BY substr(created_at, 1, 13)
)`,
ref, StatusRejected, sinceStr,
).Scan(&peak)
err = s.db.QueryRow(peakPerHourQuery(match), ref, StatusRejected, sinceStr).Scan(&peak)
if err != nil {
return SendStats{}, fmt.Errorf("send stats peak %q: %w", ref, err)
}