audit 3: every per-message question of the send log has its index
test / test (push) Canceled after 0s
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:
@@ -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
|
||||
|
||||
@@ -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
@@ -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
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -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
@@ -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 {
|
||||
|
||||
@@ -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.
|
||||
}
|
||||
|
||||
@@ -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<?)"}, 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)
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -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 {
|
||||
|
||||
@@ -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
@@ -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
@@ -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)
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user