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] ## [Unreleased]
Migration `0010` (indexes only).
### Fixed ### 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 - **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 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 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 untouched, no `-wal`), a damaged key named; the domain import of a cut
plain export, a cut and an altered `.spde` (each refused, nothing plain export, a cut and an altered `.spde` (each refused, nothing
created). The CLI's `-decrypt -o` is step 3. 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`; on the id column stage 2 adds, replacing `idx_send_log_domain`;
partial `idx_send_log_queued (created_at) WHERE status = 'queued'`; partial `idx_send_log_queued (created_at) WHERE status = 'queued'`;
consider `(domain, id)` for the scoped page. Migration `0009` DDL only; consider `(domain, id)` for the scoped page. Migration `0009` DDL only;
`TestLimitRefusalsSince`-style EXPLAIN tests against the **real** query `TestLimitRefusalsSince`-style EXPLAIN tests against the **real** query
strings. — **Opus** 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 - [ ] **CLI backup**: open the source `mode=ro`, refuse a missing file; password
floor of 12 shared with the panel (`validate.MinSecretFilePasswordLen`); floor of 12 shared with the panel (`validate.MinSecretFilePasswordLen`);
`-decrypt -o` verifies the password (first chunk) before opening the `-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) | | 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) | | 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) | | 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 **Recommended order** (not binding; owner, 2026-10-09: feature order follows
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and 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 | | Field | Value |
|---|---| |---|---|
| Chain head | `user_version = 9` | | 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` | | 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") | | File mark | `PRAGMA application_id = 0x53503230` ("SP20") |
| Database file | `/data/selfpost.db` (bind mount) | | 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.** | | 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 `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 `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 `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 | | 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) | | 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) | | 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 **Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct
for operators upgrading from older 2.x images. 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 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" - // CountOpenOlderThan counts the rows still open - "queued" or "deferred" -
// that were accepted before cutoff. created_at is RFC3339 UTC, so the strings // that were accepted before cutoff. created_at is RFC3339 UTC, so the strings
// compare as times. // compare as times.
func (s *Store) CountOpenOlderThan(cutoff time.Time) (int64, error) { func (s *Store) CountOpenOlderThan(cutoff time.Time) (int64, error) {
var n int64 var n int64
err := s.db.QueryRow( err := s.db.QueryRow(countOpenQuery, cutoff.UTC().Format(time.RFC3339)).Scan(&n)
`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 { if err != nil {
return 0, fmt.Errorf("count queued send_log rows: %w", err) 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 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 // LimitRefusalsSince returns, per sending domain, the messages the journal
// milter refused under a level-2 limit at or after since. // 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 // address or its From: line is left out by that; a row from before has no
// reason and is still judged the old way. // reason and is still judged the old way.
func (s *Store) LimitRefusalsSince(since time.Time) ([]LimitRefusal, error) { func (s *Store) LimitRefusalsSince(since time.Time) ([]LimitRefusal, error) {
// The status is a literal so that the partial index of migration 0005 rows, err := s.db.Query(limitRefusalsQuery,
// 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`,
since.UTC().Format(time.RFC3339), since.UTC().Format(time.RFC3339),
) )
if err != nil { if err != nil {
+2 -18
View File
@@ -201,22 +201,6 @@ func TestLimitRefusalsSince(t *testing.T) {
t.Errorf("other.example = %+v", g) t.Errorf("other.example = %+v", g)
} }
// The question is answered from the index of the refused rows alone. // The question is answered from the index of the refused rows alone:
var plan []string // TestSendLogQueriesUseTheirIndexes.
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)
}
} }
+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 var n int64
// created_at is stored as RFC3339 UTC, so a lexical comparison against the // created_at is stored as RFC3339 UTC, so a lexical comparison against the
// same format is chronologically correct (as in DeleteSendLogBefore). // same format is chronologically correct (as in DeleteSendLogBefore).
err := s.db.QueryRow( err := s.db.QueryRow(countMessagesQuery(match),
`SELECT COUNT(DISTINCT queue_id) FROM send_log
WHERE `+match+` AND status != ? AND created_at >= ?`,
ref, StatusRejected, since.UTC().Format(time.RFC3339), ref, StatusRejected, since.UTC().Format(time.RFC3339),
).Scan(&n) ).Scan(&n)
if err != nil { if err != nil {
+6 -5
View File
@@ -107,7 +107,8 @@ func TestBaselineSchema(t *testing.T) {
wantIdx := []string{ wantIdx := []string{
"idx_applications_login_nocase", "idx_dmarc_report_records_report", "idx_dmarc_reports_domain", "idx_dmarc_reports_received", "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_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", "idx_sessions_expires_at",
} }
sort.Strings(wantIdx) sort.Strings(wantIdx)
@@ -116,8 +117,8 @@ func TestBaselineSchema(t *testing.T) {
} }
var version, appID int64 var version, appID int64
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 9 { if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 10 {
t.Errorf("user_version = %d, %v; want 9", version, err) t.Errorf("user_version = %d, %v; want 10", version, err)
} }
if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID { 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) t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID)
@@ -193,8 +194,8 @@ func TestOpenMigratesA20Database(t *testing.T) {
} }
defer st.Close() defer st.Close()
var version int var version int
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 9 { if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 10 {
t.Errorf("user_version = %d, %v; want 9", version, err) t.Errorf("user_version = %d, %v; want 10", version, err)
} }
if ok, err := st.UserExists(); err != nil || !ok { if ok, err := st.UserExists(); err != nil || !ok {
t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err) 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 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, // 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 // 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). // 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 // BINARY collation, memcmp() (https://sqlite.org/datatype3.html § 7), and
// time.RFC3339 of a UTC time is fixed-width, YYYY-MM-DDTHH:MM:SSZ. // time.RFC3339 of a UTC time is fixed-width, YYYY-MM-DDTHH:MM:SSZ.
func (s *Store) ListOpenOlderThan(cutoff time.Time) ([]QueuedDelivery, error) { func (s *Store) ListOpenOlderThan(cutoff time.Time) ([]QueuedDelivery, error) {
rows, err := s.db.Query( rows, err := s.db.Query(listOpenQuery, cutoff.UTC().Format(time.RFC3339))
`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),
)
if err != nil { if err != nil {
return nil, fmt.Errorf("list queued send_log rows: %w", err) return nil, fmt.Errorf("list queued send_log rows: %w", err)
} }
@@ -284,6 +293,23 @@ type SendLogRow struct {
UpdatedAt time.Time 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 // 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 // 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 // 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 // § 2); NOCASE folds ASCII only (datatype3.html § 7.1); ?1 is bound once and
// used twice (lang_expr.html § 4). // used twice (lang_expr.html § 4).
func (s *Store) AttachRefusalLine(clientIP, login, from string, at time.Time, line string) (bool, error) { func (s *Store) AttachRefusalLine(clientIP, login, from string, at time.Time, line string) (bool, error) {
res, err := s.db.Exec( res, err := s.db.Exec(attachRefusalLineQuery,
`UPDATE send_log SET refusal_line = ?1 WHERE id = ( line, ReasonLimit, ReasonClient, from, clientIP,
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,
at.Add(-refusalLineWindow).UTC().Format(time.RFC3339), at.Add(-refusalLineWindow).UTC().Format(time.RFC3339),
at.Add(refusalLineWindow).UTC().Format(time.RFC3339), at.Add(refusalLineWindow).UTC().Format(time.RFC3339),
at.UTC().Format(time.RFC3339), at.UTC().Format(time.RFC3339),
@@ -409,19 +426,24 @@ type SendLogFilter struct {
AllDomains bool 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 // QuerySendLog returns send-log rows matching filter, newest first, for the
// monitoring screen's server-side pagination (product.md's send-log view). // monitoring screen's server-side pagination (product.md's send-log view).
// The filter's authorization scope is mandatory: see SendLogFilter. // The filter's authorization scope is mandatory: see SendLogFilter.
func (s *Store) QuerySendLog(filter SendLogFilter, limit, offset int) ([]SendLogRow, error) { func (s *Store) QuerySendLog(filter SendLogFilter, limit, offset int) ([]SendLogRow, error) {
where, args := sendLogWhere(filter) where, args := sendLogWhere(filter)
args = append(args, limit, offset) args = append(args, limit, offset)
rows, err := s.db.Query( rows, err := s.db.Query(sendLogPageQuery(where), args...)
`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...,
)
if err != nil { if err != nil {
return nil, fmt.Errorf("query send_log: %w", err) 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 // 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 // v1.60.1, conn.go bind() and argFinder.find(): ?NNN takes argument NNN, a
// plain ? the argument of its number. // 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 // sendStats counts the rows that match, a condition with one placeholder
// taking ref. // 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) sinceStr := since.UTC().Format(time.RFC3339)
var total int64 var total int64
err := s.db.QueryRow( err := s.db.QueryRow(countMessagesQuery(match), ref, StatusRejected, sinceStr).Scan(&total)
`SELECT COUNT(DISTINCT queue_id) FROM send_log
WHERE `+match+` AND status != ? AND created_at >= ?`,
ref, StatusRejected, sinceStr,
).Scan(&total)
if err != nil { if err != nil {
return SendStats{}, fmt.Errorf("send stats total %q: %w", ref, err) 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 var peak int64
err = s.db.QueryRow( err = s.db.QueryRow(peakPerHourQuery(match), ref, StatusRejected, sinceStr).Scan(&peak)
`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)
if err != nil { if err != nil {
return SendStats{}, fmt.Errorf("send stats peak %q: %w", ref, err) return SendStats{}, fmt.Errorf("send stats peak %q: %w", ref, err)
} }