From 508ac96c79e06fd3308c667d632fd83dbb1e5f8c Mon Sep 17 00:00:00 2001 From: Mix Date: Thu, 15 Oct 2026 10:10:52 +0300 Subject: [PATCH] audit 3: every per-message question of the send log has its index 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 --- CHANGELOG.md | 12 ++ docs/audit-2026-10-12.md | 18 ++- docs/roadmap.md | 2 +- docs/schema-migrations.md | 8 +- internal/store/deliverylog.go | 8 +- .../migrations/0010_send_log_indexes.sql | 22 ++++ internal/store/notify.go | 28 ++--- internal/store/notify_test.go | 20 +--- internal/store/queryplan_test.go | 110 ++++++++++++++++++ internal/store/ratelimits.go | 4 +- internal/store/schema_test.go | 11 +- internal/store/sendlog.go | 70 +++++++---- internal/store/stats.go | 44 ++++--- 13 files changed, 268 insertions(+), 89 deletions(-) create mode 100644 internal/store/migrations/0010_send_log_indexes.sql create mode 100644 internal/store/queryplan_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index c8c5482..beebb5d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -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 diff --git a/docs/audit-2026-10-12.md b/docs/audit-2026-10-12.md index f4d3823..e180741 100644 --- a/docs/audit-2026-10-12.md +++ b/docs/audit-2026-10-12.md @@ -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 diff --git a/docs/roadmap.md b/docs/roadmap.md index 795823e..140deb9 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -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 diff --git a/docs/schema-migrations.md b/docs/schema-migrations.md index ce70717..3af0aa1 100644 --- a/docs/schema-migrations.md +++ b/docs/schema-migrations.md @@ -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. diff --git a/internal/store/deliverylog.go b/internal/store/deliverylog.go index 285f159..ac20a82 100644 --- a/internal/store/deliverylog.go +++ b/internal/store/deliverylog.go @@ -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) } diff --git a/internal/store/migrations/0010_send_log_indexes.sql b/internal/store/migrations/0010_send_log_indexes.sql new file mode 100644 index 0000000..55a0d20 --- /dev/null +++ b/internal/store/migrations/0010_send_log_indexes.sql @@ -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 <> ''; diff --git a/internal/store/notify.go b/internal/store/notify.go index a44383b..52fd9aa 100644 --- a/internal/store/notify.go +++ b/internal/store/notify.go @@ -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 { diff --git a/internal/store/notify_test.go b/internal/store/notify_test.go index 083423e..dcf70a1 100644 --- a/internal/store/notify_test.go +++ b/internal/store/notify_test.go @@ -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, ¬used, &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. } diff --git a/internal/store/queryplan_test.go b/internal/store/queryplan_test.go new file mode 100644 index 0000000..974de68 --- /dev/null +++ b/internal/store/queryplan_test.go @@ -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, ¬used, &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? AND 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) + } + } +} diff --git a/internal/store/ratelimits.go b/internal/store/ratelimits.go index d24a625..1f83a15 100644 --- a/internal/store/ratelimits.go +++ b/internal/store/ratelimits.go @@ -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 { diff --git a/internal/store/schema_test.go b/internal/store/schema_test.go index 0449d24..497a1da 100644 --- a/internal/store/schema_test.go +++ b/internal/store/schema_test.go @@ -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) diff --git a/internal/store/sendlog.go b/internal/store/sendlog.go index 408f96b..4eff301 100644 --- a/internal/store/sendlog.go +++ b/internal/store/sendlog.go @@ -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) } diff --git a/internal/store/stats.go b/internal/store/stats.go index e9f01b7..c04ac6f 100644 --- a/internal/store/stats.go +++ b/internal/store/stats.go @@ -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) }