From 9d6d89c79d6072962854c0f9ada772dccf0db497 Mon Sep 17 00:00:00 2001 From: mixeme Date: Sat, 8 Aug 2026 11:35:27 +0300 Subject: [PATCH] fix(logtail): keep mail.log in /data and reconcile stuck rows (v1.x closure phase 2) Move the delivery log from the ephemeral /var/log to /data/log/mail.log so the lines that resolve a queued send-log row survive a container recreate. postlogd writes it as postfix, the panel reads it through the selfpost group (dir 2750, file 0640, normalised every start); backups exclude log/. Close the residual gap with a queue sweep: rows queued for over two minutes whose id postqueue -p no longer lists are marked bounced. The sweep waits until the tailer has read the log to its end and does nothing when the queue cannot be listed, so a message in flight is never touched. Co-Authored-By: Claude Opus 5 Co-authored-by: Cursor --- CHANGELOG.md | 24 +++++++ README.md | 3 +- build/entrypoint.sh | 23 ++++++- build/logrotate-loop.sh | 10 +-- build/logrotate-mail.conf | 10 ++- build/postfix-config.sh | 10 ++- build/supervisord.conf | 2 +- cmd/panel/envdoc_test.go | 1 + cmd/panel/main.go | 5 +- deploy/docker-compose.yml | 3 + docs/architecture.md | 45 +++++++++---- docs/guide.md | 20 ++++-- docs/progress.md | 3 +- docs/roadmap.md | 17 +++-- docs/security.md | 25 ++++++-- docs/v1.x-closure-plan.md | 39 +++++++----- internal/backup/backup.go | 11 ++-- internal/backup/backup_test.go | 9 ++- internal/logtail/logtail.go | 106 +++++++++++++++++++++++++++++-- internal/logtail/logtail_test.go | 78 +++++++++++++++++++++++ internal/postfix/queue.go | 41 ++++++++++++ internal/postfix/queue_test.go | 43 +++++++++++++ internal/store/sendlog.go | 39 ++++++++++++ internal/store/sendlog_test.go | 52 +++++++++++++++ test/e2e/mail_helpers.go | 2 +- 25 files changed, 549 insertions(+), 72 deletions(-) create mode 100644 internal/postfix/queue_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 45a4877..371e66c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -28,8 +28,32 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version panel's own ok/warn/error/unknown badge vocabulary. A message still queued shows the delivery report it is waiting for as a step that has not happened. +### Fixed + +- A send-log row could stay `queued` forever after the container was recreated. + `mail.log` moved from the ephemeral `/var/log` into the data volume + (`/data/log/mail.log`, `./data/log/` on the host), so the delivery lines that + resolve a queued row now outlive the container the same way the journal does. + `postlogd` writes the file as user `postfix` and the unprivileged panel reads + it through the shared `selfpost` group (directory `2750`, file `0640`, + re-normalised on every start); logrotate creates each new file the same way. + Existing deployments need no action beyond the upgrade — the directory is + created on first start — but the log written by the previous image is gone + with its container, and the tailer starts the new file from its end. +- A row whose delivery lines are gone for good is no longer left `queued` + indefinitely: every five minutes the tailer compares rows still queued from + more than two minutes ago against `postqueue -p`, and marks `bounced` those + whose message Postfix no longer holds — it will never report on them again. + The sweep waits until the tailer has read the log to its end (on a restart the + log itself holds the answer) and does nothing at all if the queue cannot be + listed, so a message merely in flight, or a `postqueue` that fails, never + closes a row. + ### Changed +- Full backups no longer carry `/data/log`. It is Postfix's raw log plus its + fourteen rotated copies — diagnostic output rather than state to restore, and + otherwise by far the largest thing in the archive. - Monitoring screens (status, mail queue, system log, deliveries) use adaptive HTMX polling: 5 s while the operator is active on the page, 30 s when the tab is visible but idle, and no requests while the tab is hidden. Scheduling diff --git a/README.md b/README.md index 61cb432..bc4fd20 100644 --- a/README.md +++ b/README.md @@ -52,7 +52,8 @@ missing PTR record for you. Details: [Operator guide](docs/guide.md). - Docker + Compose v2 on the host - A reverse proxy in front of the panel (SelfPost never terminates HTTPS itself) - Rough sizing: **1 vCPU**, **512 MB–1 GB RAM**, **8–10 GB disk** (send log and - rotated `mail.log` are the main growth drivers) + rotated `mail.log` are the main growth drivers; both sit in the `./data` + volume, and both are capped — 90 days and 14 files by default) ### Network and IP diff --git a/build/entrypoint.sh b/build/entrypoint.sh index 779f92e..b0087a5 100644 --- a/build/entrypoint.sh +++ b/build/entrypoint.sh @@ -11,8 +11,10 @@ set -e chown panel:panel /data # Restored backups or previously-created state may contain panel-owned files # under /data; make sure they stay writable without disturbing anything that a -# later phase deliberately hands to another service. -find /data -mindepth 1 -maxdepth 1 ! -user panel -exec chown -R panel:panel {} + +# later phase deliberately hands to another service. /data/log is exempt: it is +# deliberately owned by postfix (postlogd writes the delivery log there) and is +# normalised on its own below. +find /data -mindepth 1 -maxdepth 1 ! -user panel ! -name log -exec chown -R panel:panel {} + # DKIM key tree (spec 6, 9). The panel (user `panel`) generates keys and writes # the OpenDKIM tables; OpenDKIM (user `opendkim`) must read them. Normalise the @@ -51,6 +53,23 @@ chown -R panel:selfpost /data/postfix chmod 2750 /data/postfix chmod 0640 /data/postfix/sender_login_maps +# Delivery log (architecture.md § Log tailer). postlogd writes it as user +# `postfix`; the panel reads it for the log-tailer and the System log page. It +# lives under /data — not the ephemeral /var/log — so the delivery lines that +# resolve a "queued" send-log row survive a container recreate. +# +# postlogd creates a missing log itself, but at 0600, which the unprivileged +# panel cannot read; so create it here (and re-normalise an existing one, plus +# whatever logrotate left behind) at 0640 owned postfix:selfpost. The setgid +# directory keeps the shared group on anything created inside it later, and +# 2750 keeps it group-traversable but not group-writable — logrotate refuses to +# rotate a log whose directory is writable by a non-root group. +mkdir -p /data/log +[ -e /data/log/mail.log ] || : > /data/log/mail.log +chown -R postfix:selfpost /data/log +chmod 2750 /data/log +find /data/log -type f -exec chmod 0640 {} + + # Milter socket directories (spec 5 p.3, 7.3). Postfix (user `postfix`) must # actually CONNECT to both milter sockets — OpenDKIM's and the panel's # journal-milter — not just probe them at start-up. The sockets are diff --git a/build/logrotate-loop.sh b/build/logrotate-loop.sh index e016a6c..c934d21 100644 --- a/build/logrotate-loop.sh +++ b/build/logrotate-loop.sh @@ -1,13 +1,13 @@ #!/bin/sh -# Periodic logrotate for /var/log/mail.log (spec 9, 10). Rotation renames the -# file, recreates it (`create 0644 root root`, matching a cold container +# Periodic logrotate for /data/log/mail.log (spec 9, 10). Rotation renames the +# file, recreates it (`create 0640 postfix selfpost`, matching a cold container # start), then runs `postfix reload` (the same mechanism `postfix logrotate` # uses): postlogd keeps writing to the renamed inode until reload, and the # panel's log-tailer holds its own descriptor on that inode, so nothing # written before the reload is lost. `create` (rather than `nocreate`) matters -# here beyond timing: a reload-triggered recreate lands the file at 0600, -# which the unprivileged panel process cannot read — confirmed on a live -# container — so logrotate must be the one to create it at 0644. +# here beyond timing: a postlogd-triggered recreate lands the file at 0600 +# owned by postfix, which the unprivileged panel process cannot read — +# confirmed on a live container — so logrotate must be the one to create it. # # logrotate itself only rotates once the configured "daily" period has elapsed # (tracked in /var/lib/logrotate/status), so it is safe to invoke this more diff --git a/build/logrotate-mail.conf b/build/logrotate-mail.conf index 5f4e402..9912d40 100644 --- a/build/logrotate-mail.conf +++ b/build/logrotate-mail.conf @@ -1,11 +1,17 @@ -/var/log/mail.log { +# The delivery log lives under the persistent /data, not the ephemeral +# /var/log, so the lines that resolve a "queued" send-log row outlive the +# container (architecture.md § Log tailer). Path and ownership match +# build/postfix-config.sh (maillog_file) and build/entrypoint.sh: postlogd +# writes it as user postfix, the unprivileged panel reads it through the shared +# selfpost group, hence create 0640 postfix selfpost rather than 0644 root root. +/data/log/mail.log { daily rotate 14 missingok notifempty compress delaycompress - create 0644 root root + create 0640 postfix selfpost postrotate /usr/sbin/postfix reload endscript diff --git a/build/postfix-config.sh b/build/postfix-config.sh index 61578f4..3bd634e 100644 --- a/build/postfix-config.sh +++ b/build/postfix-config.sh @@ -45,10 +45,18 @@ SASLDB_PATH="${SASL_DB_PATH:-/data/sasl/sasldb2}" # when a client library needs STARTTLS on 587 instead of implicit TLS on 465). SUBMISSION_ENABLE="${SUBMISSION_ENABLE:-false}" +# Delivery log, written by postlogd and read by the panel's log-tailer. It lives +# under the persistent /data (not the ephemeral /var/log) so the delivery lines +# for messages still marked "queued" survive a container recreate — without +# them those rows could never be resolved (architecture.md § Log tailer). The +# default must match cmd/panel/main.go's MAIL_LOG; entrypoint.sh creates the +# directory and the file with the ownership postlogd writes and the panel reads. +MAIL_LOG_PATH="${MAIL_LOG:-/data/log/mail.log}" + # --- main.cf ----------------------------------------------------------------- postconf -e \ "myhostname=${HOSTNAME_VALUE}" \ - "maillog_file=/var/log/mail.log" \ + "maillog_file=${MAIL_LOG_PATH}" \ "mydestination=" \ "relayhost=" \ "inet_interfaces=all" \ diff --git a/build/supervisord.conf b/build/supervisord.conf index 9b15635..99b3234 100644 --- a/build/supervisord.conf +++ b/build/supervisord.conf @@ -103,7 +103,7 @@ stdout_logfile_maxbytes=0 stderr_logfile=/dev/stderr stderr_logfile_maxbytes=0 -; Periodic logrotate for /var/log/mail.log (spec 9, 10: daily, 7-14 files kept +; Periodic logrotate for /data/log/mail.log (spec 9, 10: daily, 7-14 files kept ; in the image). Runs as root so logrotate can read/rotate the log; never exits ; non-zero, so it neither trips the crashexit listener nor needs restarting. [program:logrotate] diff --git a/cmd/panel/envdoc_test.go b/cmd/panel/envdoc_test.go index 1e580c4..2cb1b6a 100644 --- a/cmd/panel/envdoc_test.go +++ b/cmd/panel/envdoc_test.go @@ -82,6 +82,7 @@ var buildScriptKeys = []string{ "RATE_LIMIT_WINDOW_SECONDS", "OPENDKIM_SOCKET", "JOURNAL_MILTER_SOCKET", + "MAIL_LOG", "POSTFIX_SENDER_LOGIN_MAPS", "SASL_DB_PATH", "SUBMISSION_ENABLE", diff --git a/cmd/panel/main.go b/cmd/panel/main.go index a2ea695..dfae2f1 100644 --- a/cmd/panel/main.go +++ b/cmd/panel/main.go @@ -81,7 +81,10 @@ func loadConfig() config { return config{ httpAddr: envDefault("PANEL_HTTP_ADDR", ":8080"), journalSocket: envDefault("JOURNAL_MILTER_SOCKET", "/run/selfpost/journal.sock"), - mailLog: envDefault("MAIL_LOG", "/var/log/mail.log"), + // Postfix's delivery log, under /data so the lines that resolve a + // "queued" send-log row outlive the container. The default must match + // maillog_file in build/postfix-config.sh. + mailLog: envDefault("MAIL_LOG", "/data/log/mail.log"), // Send-log retention window (architecture.md § Persistence). // Non-positive/invalid falls back to the 90-day default inside the // log-tailer. diff --git a/deploy/docker-compose.yml b/deploy/docker-compose.yml index 3b8e68a..dca15a1 100644 --- a/deploy/docker-compose.yml +++ b/deploy/docker-compose.yml @@ -54,6 +54,9 @@ services: # All persistent state lives under /data (spec 9): SQLite DB, DKIM keys, # sasldb2, sender map, setup token. Back this up (panel button or the # selfpost-backup CLI) before you touch it directly. + # Postfix's mail.log is here too (./data/log, rotated daily, 14 files + # kept) so the delivery lines that resolve a queued send-log row survive + # a container recreate; it is diagnostics and is left out of backups. - ./data:/data # Read-only: SelfPost only ever reads certificates, never manages them # (spec 10 p.2). Point this at wherever your reverse-proxy/certbot diff --git a/docs/architecture.md b/docs/architecture.md index 965893e..db44a53 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -94,10 +94,20 @@ Milter chain in Postfix: OpenDKIM (tempfail) then journal (accept on failure). ### Log tailer and `mail.log` rotation -`mail.log` lives under `/var/log` (not in `/data`). Rotation uses rename + -`postfix reload` ([build/logrotate-mail.conf](../build/logrotate-mail.conf)), not -`copytruncate` — the latter can drop `status=sent` lines and leave send-log rows -stuck at `queued`. After rename, logrotate runs `create 0644 root root` (Postfix +`mail.log` lives at `/data/log/mail.log` — inside the persistent bind mount, so +the delivery lines that resolve a `queued` send-log row are not lost when the +container is recreated. `postlogd` writes it as user `postfix`; the panel reads +it through the shared `selfpost` group (directory `2750 postfix:selfpost`, file +`0640`, both normalised on every start by +[build/entrypoint.sh](../build/entrypoint.sh)). The path is one default in two +places, `maillog_file` in [build/postfix-config.sh](../build/postfix-config.sh) +and `MAIL_LOG` in [cmd/panel/main.go](../cmd/panel/main.go). Backups exclude +`log/`: it is diagnostic output, not state to restore. + +Rotation uses rename + `postfix reload` +([build/logrotate-mail.conf](../build/logrotate-mail.conf)), not `copytruncate` — +the latter can drop `status=sent` lines and leave send-log rows stuck at +`queued`. After rename, logrotate runs `create 0640 postfix selfpost` (postlogd recreates the file lazily on first write as mode `0600`, which the unprivileged panel user cannot read). `follow()` drains the old inode once more before switching descriptors; the panel treats a missing log file as an empty tail, not @@ -112,14 +122,20 @@ the current file from the start; re-parsing lines is harmless because with nothing stored, begins at end-of-file, so installing the panel does not replay a pre-existing log. -**Remaining gap:** - -- **Container recreate** — `/var/log` is ephemeral; the log is lost with the - container, so the delivery lines for rows still `queued` are gone with it and - those rows stay `queued` forever. - -Possible follow-ups if this becomes painful: mount the mail log under `/data`, or -reconcile stuck rows via `postqueue`. +**Queue reconcile** is the backstop for what the log cannot explain at all: a +row still `queued` more than two minutes after it was accepted, whose queue id +`postqueue -p` no longer lists, is marked `bounced` (swept every five minutes, +[internal/logtail](../internal/logtail/logtail.go), +[postfix.QueueIDs](../internal/postfix/queue.go)). Postfix having dropped the +message means nothing more will ever be reported about it, so the row can only +be closed on an assumption, and it is closed as a failure because a delivery the +panel cannot evidence must not be shown as one. Three things keep the sweep from +guessing where it need not: it starts only after the tailer has read to +end-of-file once (on a restart the log itself holds the answer), the two-minute +grace covers messages merely in flight, and a `postqueue` that cannot be read +leaves every row untouched rather than closing them all. Now that the log +survives the container, reaching this path means the lines are gone for good — +rotated past fourteen files while the panel was down, or deleted. **Two one-shot reads** sit beside the follow loop and are unrelated to it, both serving panel pages on request: `TailLines` (the last *n* lines, for @@ -250,6 +266,7 @@ single-connection trade-off that follows from it. | `opendkim/` | DKIM keys + tables | | `sasl/sasldb2` | Application SASL credentials | | `postfix/sender_login_maps` | Login → From binding | +| `log/mail.log` | Postfix delivery log + rotated copies (excluded from backups) | | `manifest.json` | Backup version stamp (consumed on restore) | Not in `/data`: TLS certificates (reverse-proxy mount), Postfix queue @@ -260,8 +277,8 @@ Not in `/data`: TLS certificates (reverse-proxy mount), Postfix queue `postfix reload` in `postrotate` — see § Log tailer above). **Backup:** panel button or `selfpost-backup` CLI — SQLite snapshot + tar of -`/data` tree; version check on restore. Stopped-container `tar` of `./data` is -safe (see guide). +`/data` tree, minus `log/`, the setup token and any `tls/`; version check on +restore. Stopped-container `tar` of `./data` is safe (see guide). **Optional encryption** of the two secret-bearing downloads ([internal/secretfile](../internal/secretfile/secretfile.go)): password → diff --git a/docs/guide.md b/docs/guide.md index 62bf790..221675a 100644 --- a/docs/guide.md +++ b/docs/guide.md @@ -109,7 +109,9 @@ supported configuration: (`/data/selfpost.db`), `SELFPOST_SETUP_TOKEN_FILE` (`/data/setup-token`), `PANEL_HTTP_ADDR` (`:8080`), `JOURNAL_MILTER_SOCKET` (`/run/selfpost/journal.sock`), `MAIL_LOG` - (`/var/log/mail.log`), `PANEL_COOKIE_SECURE` (`true`), `OPENDKIM_SOCKET` + (`/data/log/mail.log` — read by the panel and written by Postfix, so a change + here has to be matched in `build/postfix-config.sh`), + `PANEL_COOKIE_SECURE` (`true`), `OPENDKIM_SOCKET` (`/run/opendkim/opendkim.sock`), `OPENDKIM_DIR` (`/data/opendkim`), `DKIM_SELECTOR_DEFAULT` (`selfpost`), `SASL_DB_PATH` (`/data/sasl/sasldb2`), `SASL_REALM` (defaults to `SELFPOST_HOSTNAME`), @@ -191,8 +193,9 @@ service healthy and will mail be accepted?" - **Deliveries** (`/deliveries`) — searchable send log with server-side filters by domain and application. A row identifies its message and nothing more — time, sender, recipient, subject and status `queued` (accepted, not yet - delivered), `sent` (handed off successfully), or `rejected` (refused — for - example by a level-2 rate limit); *Details* opens that row's own page + delivered), `sent` (handed off successfully), `deferred` (Postfix is retrying), + `bounced` (final failure), or `rejected` (refused — for example by a level-2 + rate limit); *Details* opens that row's own page (`/deliveries/{id}`). That page carries the sending domain, the application it was submitted under, the Postfix queue id and the journal id, beside the message's history — when it was accepted and what Postfix later reported for @@ -203,10 +206,12 @@ service healthy and will mail be accepted?" `SEND_LOG_RETENTION_DAYS`. - **Mail queue** (`/mail-queue`) — live view of messages Postfix is still trying to deliver or deferring. -- **System log** (`/system-log`) — tail of `/var/log/mail.log` (Postfix and +- **System log** (`/system-log`) — tail of `/data/log/mail.log` (Postfix and related daemon lines). The log rotates daily (14 files kept) with a `postfix reload` after each rotation; a background loop checks every six - hours. + hours. It lives in the data volume, so it survives a container recreate along + with the rest of the state — `./data/log/` on the host — but it is *not* + included in backups: it is diagnostics, not state. - **Backup** (`/backup`) — download a full-server backup or import a single-domain export. See [Backup, restore, and moving a single domain](#backup-restore-and-moving-a-single-domain). - **Account** (`/account`) — change the administrator username and/or password. @@ -288,7 +293,10 @@ Two related but distinct operations — spec 7.5: **Alternative: archive `./data` while stopped.** If the service can be taken offline, `docker compose down` then `tar czf selfpost-data.tar.gz ./data` on - the host is safe — nothing is writing to SQLite. Do **not** tar `./data` while + the host is safe — nothing is writing to SQLite. Unlike the panel/CLI backup + this sweeps in `./data/log/` too, which is Postfix's raw log and usually the + bulk of the archive; add `--exclude=./data/log` if you only want the state. + Do **not** tar `./data` while the container is running: the database uses WAL mode and a naive copy can capture an inconsistent snapshot. The panel/CLI backup remains preferable when you cannot afford downtime because it takes a consistent SQLite snapshot via diff --git a/docs/progress.md b/docs/progress.md index 8862805..0fac5d9 100644 --- a/docs/progress.md +++ b/docs/progress.md @@ -55,7 +55,8 @@ - **Фаза 3 плана ревизии выполнена (2026-08-06)** (operational improvements, P2–P3): (1) log-tailer сохраняет позицию чтения — таблица `logtail_state` (миграция `0003`, `internal/store/logtail.go`) хранит offset + отпечаток первых 512 байт лога, `internal/logtail/offset.go` решает откуда стартовать: отпечаток совпал → продолжаем с offset (дочитывается хвост, написанный пока панель лежала); не совпал (лог сменился/пересоздан) → читаем файл с начала (повторный разбор безвреден, `UpdateStatus` идемпотентен); записи нет вовсе (первый запуск) → с конца, как раньше. Запись offset — не чаще раза в 5 с, плюс форс при ротации и на выключении; сохраняется позиция *потреблённых* байт (минус недочитанная частичная строка). (2) L2-лимит перестал промахиваться при параллельных сессиях: между проверкой на MAIL FROM и вставкой строки на end-of-message сообщение не видно в БД, поэтому N одновременных сессий пропускали друг друга — теперь к счёту из БД добавляются «в полёте» (`internal/milter/inflight.go`, общий на процесс реестр резерваций); резервация освобождается после записи в send-log, на ABORT и по TTL 10 минут (у go-milter нет колбэка на закрытие соединения, а вечная резервация — это fail-closed-дрейф, которого у лимитера быть не должно). Транзакция «count+insert», как предлагал review, невозможна буквально: эти два шага разнесены по разным стадиям SMTP-транзакции. Тесты: restart/rotation-resume для tailer'а, четыре сценария резерваций для лимита. `gofmt`/`go vet` чистые; `go test ./...` — падения только известные Windows-специфичные (`internal/domain`, `TestFollowTailsAndRotates`). Не проверено на стенде (нет Docker локально) — кандидат на следующий прогон на стенде. - **Добор по плану ревизии выполнен (2026-08-06):** (1) проект переехал на единственную площадку — GitHub (Codeberg уходит): вместе с URL, лицензионными шапками SVG/HTML и docs переехал путь Go-модуля на `github.com/mixeme/selfpost` (`go.mod`, `test/e2e/go.mod`, все импорты, `MODULE` в Makefile, `-ldflags` в Dockerfile и development.md) — оставлять импорты на исчезающем хосте нельзя, `go get`/`go install` сломались бы; (2) ссылки на архивную спецификацию убраны из кода целиком — не только «spec 7.x», как просило ревью, но и «spec 4/5/6/8/9», страдавшие тем же, каждая заменена на живой документ с секцией там, где документ большой; (3) [architecture.md](architecture.md) § Code layers — диаграмма слоёв (A2); (4) `TestParseDelivery` расширен экзотикой mail.log — и **вскрыл реальный баг**: шаблон брал `status=` жадно, то есть последнее вхождение в строке, а Postfix дописывает ответ удалённого сервера дословно, поэтому отказ с `status=sent` в тексте ответа попадал в журнал как доставленный (исправлено на ленивый разбор); (5) `CONTRIBUTING.md` перенесён в 2.x, бамп тега образа и git-тег оставлены в [roadmap.md](roadmap.md) § v1.x. `gofmt`/`go vet` чистые в обоих модулях, `go test ./...` — падения только известные Windows-специфичные (`internal/domain`, `TestFollowTailsAndRotates`). На стенде не проверялось (нет Docker локально). - **v1.x-closure Фаза 1 выполнена (2026-08-08)** (адаптивный опрос мониторинга): четыре HTMX-фрагмента (`status_body`, `mail_queue_body`, `system_log_body`, `deliveries_rows`) несут `data-poll` и `hx-trigger="load"` только для первого запроса; `panel.js` планирует следующий опрос после `htmx:afterSwap` / `htmx:responseError` — 5 s при активности оператора на странице, 30 s при видимой, но простаивающей вкладке, 0 при скрытой (`beforeRequest` + сброс таймеров на `visibilitychange`). Без `hx-trigger="every … [expr]"` (CSP / `unsafe-eval`). Docs: `architecture.md`, `roadmap.md`, CHANGELOG. На стенде не проверялось. -- **Дальше:** v1.x-closure [v1.x-closure-plan.md](v1.x-closure-plan.md) — **Фаза 1 закрыта** (адаптивный опрос мониторинга: 5 s / 30 s / 0 при скрытой вкладке, `data-poll` в `panel.js`). Следующий шаг — **Фаза 2** (mail.log в `/data` + postqueue reconcile). Релизный гейт по коду закрыт; бамп тега образа и git tag — по явной команде (Фазы 4–5). +- **v1.x-closure Фаза 2 выполнена (2026-08-08)** (send-log vs `mail.log`): (1) лог переехал из эфемерного `/var/log` в `/data/log/mail.log` — `maillog_file` в `postfix-config.sh` и `MAIL_LOG` в `cmd/panel/main.go` берут один и тот же дефолт, `entrypoint.sh` создаёт каталог `2750 postfix:selfpost` и нормализует файлы в `0640` на каждом старте (пишет `postlogd` от `postfix`, читает панель по общей группе; postlogd сам создал бы файл в `0600`, поэтому создаём его мы, а logrotate — `create 0640 postfix selfpost`), каталог исключён из общего `chown … panel` в начале entrypoint и из архива бэкапа (`internal/backup`, диагностика, а не состояние). (2) Строки, чьи delivery-строки потеряны безвозвратно, больше не висят `queued` вечно: `postfix.QueueIDs` разбирает `postqueue -p`, `store.ListQueuedOlderThan` отдаёт кандидатов, `internal/logtail` раз в 5 минут закрывает как `bounced` те, чьего queue-id в очереди уже нет (grace 2 мин). Три предохранителя: sweep стартует только после того, как tailer впервые дочитал лог до конца (на рестарте ответ лежит в самом логе), grace покрывает письмо «в полёте», нечитаемый `postqueue` не трогает ничего. Ложно-отрицательный `bounced` — новый принятый риск в [security.md](security.md). Тесты: парсер очереди (включая строку-причину deferred и «Mail queue is empty»), `ListQueuedOlderThan`, три сценария sweep, исключение `log/` из бэкапа. `gofmt`/`go vet` чистые в обоих модулях, `go test ./...` — падения только известные Windows-специфичные (`internal/domain`, `TestFollowTailsAndRotates`). **На стенде не проверялось (нет Docker локально): образ не собирался, контейнер не стартовал** — права на `/data/log`, чтение лога панелью, прокрутка logrotate и `postqueue -p` из-под `panel` подлежат проверке при выкате. +- **Дальше:** v1.x-closure [v1.x-closure-plan.md](v1.x-closure-plan.md) — **Фазы 1–2 закрыты**. Следующий шаг — **Фаза 3** (docs: development.md, README, удаление планов и `docs/archive/`). Релизный гейт по коду закрыт; бамп тега образа и git tag — по явной команде (Фазы 4–5). - **Принятые риски** — [security.md](security.md). **Опционально v1.x / 2.x** — [roadmap.md](roadmap.md) (хвост документации, send-log gaps, Фаза O1+, роль администратора домена). - **Прод:** инстанс с реальным Let's Encrypt сертификатом и живым deliverability (DKIM/SPF pass). Контейнер там всё ещё на образе v1.0 — Фаза 14 в него не выкатывалась. При апгрейде: админа один раз разлогинит (сменилось имя cookie), а от reverse-proxy требуется передача исходного `Host` (Apache-фрагмент из `deploy/` это делает). diff --git a/docs/roadmap.md b/docs/roadmap.md index e45a282..b2bfa7a 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -81,13 +81,16 @@ git-тег `vX.Y.Z`; `implementation-plan.md` в `docs/archive/`, ссылок осознанно не делать.~~ **Закрыто (v1.x-closure Фаза 1):** адаптивный интервал 5 с / 30 с / 0 (скрытая вкладка) в `panel.js` через `data-poll`. -**Send-log vs `mail.log` (частично закрыто).** Persist позиции чтения сделан -(таблица `logtail_state`, миграция `0003`): после -рестарта панели log-tailer дочитывает пропущенный хвост. Остаётся пересоздание -контейнера — `mail.log` не в `/data` и теряется вместе с ним, такие строки -навсегда останутся `queued`. Кандидаты, если станет больно: volume для лога, -сверка зависших строк через `postqueue`. As-built и принятый риск: -[architecture.md](architecture.md) § Log tailer, [security.md](security.md). +**Send-log vs `mail.log`.** ~~Persist позиции чтения сделан (таблица +`logtail_state`, миграция `0003`): после рестарта панели log-tailer дочитывает +пропущенный хвост. Остаётся пересоздание контейнера — `mail.log` не в `/data` и +теряется вместе с ним, такие строки навсегда останутся `queued`. Кандидаты, если +станет больно: volume для лога, сверка зависших строк через `postqueue`.~~ +**Закрыто (v1.x-closure Фаза 2):** сделаны оба кандидата — `mail.log` переехал в +`/data/log/`, а строки, чьи delivery-строки потеряны безвозвратно, закрываются +сверкой с `postqueue -p` (grace 2 мин → `bounced`). As-built и оставшийся риск +(ложный `bounced`): [architecture.md](architecture.md) § Log tailer, +[security.md](security.md). --- diff --git a/docs/security.md b/docs/security.md index 3f5f587..e94b15e 100644 --- a/docs/security.md +++ b/docs/security.md @@ -118,12 +118,25 @@ Hardening сверх обязательного (security-заголовки, п безвозвратно нерасшифровываемый архив хуже незашифрованного: пароль SelfPost не хранит. Триггером сделать шифрование обязательным считать появление второго администратора (тогда «кто скачал» перестаёт быть одним человеком). -- **Send-log может навсегда остаться `queued` после пересоздания контейнера.** - Рестарт панели это больше не вызывает: log-tailer сохраняет позицию чтения - (`logtail_state`, миграция `0003`) и после старта дочитывает хвост, написанный - пока панель лежала. Но `mail.log` живёт не в `/data` и теряется вместе с - контейнером — строки, чьи delivery-строки были только в нём, останутся - `queued`. См. [architecture.md](architecture.md) § Log tailer. +- **Строка журнала, оставшаяся без delivery-строк, закрывается как `bounced`, а + не как есть.** Риск «вечный `queued`» снят: `mail.log` переехал в + `/data/log/` и переживает пересоздание контейнера, а log-tailer сохраняет + позицию чтения (`logtail_state`, миграция `0003`), так что после старта хвост + дочитывается. Остаток — строки, delivery-строки которых потеряны + безвозвратно (лог провернулся дальше 14 файлов, пока панель лежала, либо был + удалён): сверка с `postqueue -p` видит, что письма в очереди нет, и через + 2 минуты grace ставит `bounced`. Если письмо на самом деле ушло, статус + окажется ложно-отрицательным. Принято сознательно: доставка, которую панель + не может подтвердить, не должна показываться как подтверждённая, а вечный + `queued` не отличим от «висит прямо сейчас». Сверка не срабатывает, пока + tailer не дочитал лог до конца, и не трогает ничего, если `postqueue` не + читается. См. [architecture.md](architecture.md) § Log tailer. +- **Доступ к `mail.log` из-под непривилегированной панели.** Каталог + `/data/log` — `2750 postfix:selfpost`, файл — `0640`: пишет `postlogd` + (пользователь `postfix`), читает панель по общей группе `selfpost`, миру файл + недоступен. Лог содержит envelope-адреса и IP клиентов, но не тела и не + заголовки писем; в бэкап он не попадает (`log/` исключён), чтобы выгрузка + оставалась состоянием, а не диагностикой. ## ADR: CSRF через проверку Origin, без токенов diff --git a/docs/v1.x-closure-plan.md b/docs/v1.x-closure-plan.md index a9aaaa1..7d0ae96 100644 --- a/docs/v1.x-closure-plan.md +++ b/docs/v1.x-closure-plan.md @@ -36,7 +36,7 @@ ## Общий чек-лист прогресса - [x] **Фаза 1** — адаптивный опрос мониторинга -- [ ] **Фаза 2** — mail.log в `/data` + postqueue reconcile +- [x] **Фаза 2** — mail.log в `/data` + postqueue reconcile - [ ] **Фаза 3** — docs: development.md, README, удаление планов и `docs/archive/` - [ ] **Фаза 4** — релизный коммит `1.0.0` (по явной команде) - [ ] **Фаза 5** — tag `v1.0.0` + push (по явной команде) @@ -76,26 +76,35 @@ ### 2.1 `mail.log` → `/data/log/mail.log` -- [ ] `build/postfix-config.sh` — `maillog_file` -- [ ] `build/logrotate-mail.conf` — путь -- [ ] `build/entrypoint.sh` — `mkdir`, права (postfix write, panel read) -- [ ] `cmd/panel/main.go` — default `MAIL_LOG` -- [ ] `test/e2e/mail_helpers.go` — путь в контейнере -- [ ] `guide.md` — `MAIL_LOG`, рост диска `/data/log` -- [ ] `envdoc_test` — при изменении env +- [x] `build/postfix-config.sh` — `maillog_file` из `MAIL_LOG` +- [x] `build/logrotate-mail.conf` — путь + `create 0640 postfix selfpost` +- [x] `build/entrypoint.sh` — `mkdir`, права (`2750 postfix:selfpost`, файл `0640`), + исключение `/data/log` из общего `chown` на `panel` +- [x] `cmd/panel/main.go` — default `MAIL_LOG` +- [x] `internal/backup` — исключить `log/` из архива (+ тест) +- [x] `test/e2e/mail_helpers.go` — путь в контейнере +- [x] `guide.md` — `MAIL_LOG`, System log, бэкап `./data`; README — рост диска +- [x] `envdoc_test` — `MAIL_LOG` в `buildScriptKeys` ### 2.2 Postqueue reconcile -- [ ] `internal/postfix` — парсер queue-id из `postqueue -p` + тест -- [ ] `internal/store` — `ListQueuedOlderThan(grace)` -- [ ] `internal/logtail` — periodic sweep, grace ~2 min → `bounced` -- [ ] Тесты reconcile +- [x] `internal/postfix` — `QueueIDs` / парсер queue-id из `postqueue -p` + тест +- [x] `internal/store` — `ListQueuedOlderThan(cutoff)` +- [x] `internal/logtail` — periodic sweep (5 min), grace 2 min → `bounced`, + старт только после того, как tailer дочитал лог до конца +- [x] Тесты reconcile ### 2.3 Документация и риски -- [ ] `architecture.md` — `/data/log`, reconcile; убрать gap «container recreate» -- [ ] `security.md` — снять принятый риск «вечный queued» -- [ ] CHANGELOG `[Unreleased]` +- [x] `architecture.md` — `/data/log`, reconcile; gap «container recreate» убран +- [x] `security.md` — риск «вечный queued» снят; на его месте — ложный `bounced` + и права на лог +- [x] CHANGELOG `[Unreleased]` + +**Стенд (остаток, для оператора):** Docker на машине разработки недоступен — +сборка образа и старт контейнера не проверены. Проверить при выкате: `/data/log` +создаётся с нужными правами, панель читает `mail.log`, logrotate проворачивает +файл, `postqueue -p` читается из-под `panel`. --- diff --git a/internal/backup/backup.go b/internal/backup/backup.go index d1bf4f8..2c2c6aa 100644 --- a/internal/backup/backup.go +++ b/internal/backup/backup.go @@ -63,10 +63,12 @@ type Params struct { // The live database files are replaced by a consistent VACUUM INTO snapshot // written under the canonical name; the setup token is transient bootstrap // state; a stale manifest from a previous restore must not be re-captured (a -// fresh one is written instead); and a "tls" directory holds the reverse -// proxy's certificates, which are explicitly out of scope for a SelfPost -// backup (architecture.md § Persistence) — excluding it keeps that guarantee -// even when an operator points TLS_CERT_FILE inside /data. +// fresh one is written instead); a "tls" directory holds the reverse proxy's +// certificates, which are explicitly out of scope for a SelfPost backup +// (architecture.md § Persistence) — excluding it keeps that guarantee even when +// an operator points TLS_CERT_FILE inside /data; and "log" is Postfix's raw +// delivery log plus its fourteen rotated files, which is diagnostic output, not +// state to restore, and by far the largest thing under /data. var excludedFromArchive = map[string]bool{ "selfpost.db": true, "selfpost.db-wal": true, @@ -74,6 +76,7 @@ var excludedFromArchive = map[string]bool{ "selfpost.db-journal": true, "setup-token": true, "tls": true, + "log": true, ManifestName: true, } diff --git a/internal/backup/backup_test.go b/internal/backup/backup_test.go index 7545f72..f7c99bc 100644 --- a/internal/backup/backup_test.go +++ b/internal/backup/backup_test.go @@ -39,6 +39,10 @@ func seedDataDir(t *testing.T) (dataDir, dbPath string) { writeFile(t, filepath.Join(dataDir, "setup-token"), "secret-token") writeFile(t, filepath.Join(dataDir, "selfpost.db-wal"), "wal") writeFile(t, filepath.Join(dataDir, "selfpost.db-shm"), "shm") + // Postfix's delivery log and its rotated files: diagnostic output, not + // state, and the bulkiest thing under /data. + writeFile(t, filepath.Join(dataDir, "log", "mail.log"), "Aug 8 07:26:41 mail postfix/smtp[1]: ABC: to=, status=sent (ok)") + writeFile(t, filepath.Join(dataDir, "log", "mail.log.1"), "older") return dataDir, dbPath } @@ -104,7 +108,10 @@ func TestCreateIncludesStateExcludesTransient(t *testing.T) { } } // Excluded. - for _, name := range []string{"setup-token", "selfpost.db-wal", "selfpost.db-shm"} { + for _, name := range []string{ + "setup-token", "selfpost.db-wal", "selfpost.db-shm", + "log/mail.log", "log/mail.log.1", + } { if _, ok := files[name]; ok { t.Errorf("archive should not contain %s", name) } diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index aa322c6..bc3ffad 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -16,16 +16,20 @@ import ( "os" "regexp" "strings" + "sync" "time" + "github.com/mixeme/selfpost/internal/postfix" "github.com/mixeme/selfpost/internal/store" ) // StatusStore is the slice of the store the log-tailer needs: advancing -// delivery statuses, pruning the retention window, and remembering how far into -// mail.log it has read. *store.Store satisfies it. +// delivery statuses, finding the rows still waiting for one, pruning the +// retention window, and remembering how far into mail.log it has read. +// *store.Store satisfies it. type StatusStore interface { UpdateStatus(queueID, recipient, status string) (int64, error) + ListQueuedOlderThan(cutoff time.Time) ([]store.QueuedDelivery, error) DeleteSendLogBefore(cutoff time.Time) (int64, error) LogtailState(path string) (store.LogtailState, bool, error) SaveLogtailState(path string, st store.LogtailState) error @@ -35,6 +39,10 @@ type StatusStore interface { // is a var so tests can shorten it. var pollInterval = time.Second +// queueIDs lists the messages Postfix currently holds, for the reconcile sweep. +// It is a var so tests can answer without a running Postfix. +var queueIDs = postfix.QueueIDs + const ( // retentionInterval is how often the retention sweep runs (also once at // startup). The window itself is configurable; the cadence need not be. @@ -42,6 +50,13 @@ const ( // defaultRetentionDays applies when the configured value is unset/invalid // (guide § Environment variables: SEND_LOG_RETENTION_DAYS). defaultRetentionDays = 90 + // reconcileInterval is how often the sweep compares stuck rows against the + // Postfix queue, and reconcileGrace how long a row is left alone first. + // The grace covers the ordinary lag between the milter writing the row and + // Postfix logging the result — seconds, generously rounded up — so a + // message merely in flight is never touched. + reconcileInterval = 5 * time.Minute + reconcileGrace = 2 * time.Minute ) // deliveryRe matches a Postfix delivery line and captures queue-id, recipient @@ -89,7 +104,14 @@ func parseDelivery(line string) (queueID, recipient, status string, ok bool) { func Run(ctx context.Context, path string, st StatusStore, retentionDays int) error { go retentionLoop(ctx, st, retentionDays) - return follow(ctx, path, &tracker{st: st, path: path}, func(line string) { + // The reconcile sweep must not run against a backlog the tailer has not + // read yet: on a restart the log holds the very lines that resolve the rows + // the sweep would otherwise close. follow() closes this once it has read to + // end-of-file for the first time. + caughtUp := make(chan struct{}) + go reconcileLoop(ctx, st, caughtUp) + + return follow(ctx, path, &tracker{st: st, path: path}, caughtUp, func(line string) { queueID, recipient, status, ok := parseDelivery(line) if !ok { return @@ -100,6 +122,75 @@ func Run(ctx context.Context, path string, st StatusStore, retentionDays int) er }) } +// reconcileLoop periodically closes send-log rows Postfix has stopped working +// on (architecture.md § Log tailer). It starts only once the tailer has caught +// up with the log, and then leaves the first sweep a full interval away, so a +// restart resolves rows from the log — the accurate source — before the sweep +// gets to guess at whatever the log could not explain. +func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{}) { + select { + case <-ctx.Done(): + return + case <-caughtUp: + } + + t := time.NewTicker(reconcileInterval) + defer t.Stop() + for { + select { + case <-ctx.Done(): + return + case <-t.C: + reconcile(st, time.Now().UTC().Add(-reconcileGrace)) + } + } +} + +// reconcile marks as bounced every row still "queued" from before cutoff whose +// message Postfix no longer holds. +// +// A row reaches this state only when its delivery lines are gone for good — the +// log rotated past its fourteen files while the panel was down, or was deleted +// — since the log itself now outlives the container. Postfix having dropped the +// message means it will never report anything more about it, so the row can +// only be closed on an assumption; it is closed as a failure rather than a +// success because a delivery the panel cannot evidence must not be shown as +// one. Rows whose message is still in the queue, and every row when the queue +// cannot be listed at all, are left exactly as they are. +func reconcile(st StatusStore, cutoff time.Time) { + rows, err := st.ListQueuedOlderThan(cutoff) + if err != nil { + log.Printf("log-tailer: reconcile: list queued rows: %v", err) + return + } + if len(rows) == 0 { + return + } + + held, err := queueIDs() + if err != nil { + // No listing is no information: closing rows now would be a guess made + // against nothing. + log.Printf("log-tailer: reconcile: read postfix queue: %v", err) + return + } + + var closed int + for _, row := range rows { + if _, still := held[row.QueueID]; still { + continue + } + if _, err := st.UpdateStatus(row.QueueID, row.To, store.StatusBounced); err != nil { + log.Printf("log-tailer: reconcile: close %s/%s: %v", row.QueueID, row.To, err) + continue + } + closed++ + } + if closed > 0 { + log.Printf("log-tailer: reconcile: closed %d row(s) Postfix no longer holds and never reported", closed) + } +} + // retentionLoop prunes expired send-log rows immediately and then periodically. func retentionLoop(ctx context.Context, st StatusStore, retentionDays int) { if retentionDays <= 0 { @@ -323,7 +414,11 @@ func SplitTimestamp(line string) (stamp, rest string) { // start of a file that changed while the panel was down, or end-of-file on a // first ever run); it reopens the file when it is rotated (inode change from // logrotate's create, or truncation from copytruncate) so nothing is missed. -func follow(ctx context.Context, path string, tr *tracker, handle func(string)) error { +// +// caughtUp is closed after the first read that reaches end-of-file, which is +// the point where every line the panel missed while it was down has been +// handled. +func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{}, handle func(string)) error { var ( f *os.File r *bufio.Reader @@ -397,6 +492,8 @@ func follow(ctx context.Context, path string, tr *tracker, handle func(string)) return pos - int64(len(pending)) } + var once sync.Once + ticker := time.NewTicker(pollInterval) defer ticker.Stop() for { @@ -406,6 +503,7 @@ func follow(ctx context.Context, path string, tr *tracker, handle func(string)) return nil case <-ticker.C: drain() + once.Do(func() { close(caughtUp) }) ni, err := os.Stat(path) if err != nil { continue // file briefly gone mid-rotation; try again next tick diff --git a/internal/logtail/logtail_test.go b/internal/logtail/logtail_test.go index def7e61..1273d48 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -2,6 +2,7 @@ package logtail import ( "context" + "errors" "os" "path/filepath" "strconv" @@ -142,6 +143,10 @@ type captureStore struct { state store.LogtailState haveState bool stateErr error + + // queued is what ListQueuedOlderThan returns, for the reconcile sweep. + queued []store.QueuedDelivery + queuedErr error } func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, error) { @@ -153,6 +158,12 @@ func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, e func (c *captureStore) DeleteSendLogBefore(time.Time) (int64, error) { return 0, nil } +func (c *captureStore) ListQueuedOlderThan(time.Time) ([]store.QueuedDelivery, error) { + c.mu.Lock() + defer c.mu.Unlock() + return c.queued, c.queuedErr +} + func (c *captureStore) LogtailState(string) (store.LogtailState, bool, error) { c.mu.Lock() defer c.mu.Unlock() @@ -335,6 +346,73 @@ func waitFor(t *testing.T, cond func() bool) { t.Fatal("condition not met within timeout") } +// stubQueue makes the reconcile sweep answer from a fixed list of queue ids +// instead of a running Postfix, or fail if err is non-nil. +func stubQueue(t *testing.T, err error, ids ...string) *int { + t.Helper() + calls := 0 + old := queueIDs + queueIDs = func() (map[string]struct{}, error) { + calls++ + if err != nil { + return nil, err + } + set := make(map[string]struct{}, len(ids)) + for _, id := range ids { + set[id] = struct{}{} + } + return set, nil + } + t.Cleanup(func() { queueIDs = old }) + return &calls +} + +// A row stays "queued" forever when its delivery lines are gone for good. The +// queue is what settles it: a message Postfix still holds is simply in flight +// and must be left alone, while one it no longer holds will never be reported +// on and is closed. +func TestReconcileClosesOnlyWhatPostfixNoLongerHolds(t *testing.T) { + stubQueue(t, nil, "STILLQ") + + cs := &captureStore{queued: []store.QueuedDelivery{ + {QueueID: "STILLQ", To: "inflight@example.net"}, + {QueueID: "GONEQ", To: "lost@example.net"}, + }} + reconcile(cs, time.Now().UTC()) + + got := cs.snapshot() + if len(got) != 1 || got[0] != "GONEQ|lost@example.net|"+store.StatusBounced { + t.Fatalf("got %v, want only the message Postfix dropped closed as bounced", got) + } +} + +// A queue that cannot be listed says nothing about any message — treating the +// failure as an empty queue would close every stale row at once. +func TestReconcileLeavesRowsAloneWhenTheQueueCannotBeRead(t *testing.T) { + stubQueue(t, errors.New("postqueue: Permission denied")) + + cs := &captureStore{queued: []store.QueuedDelivery{ + {QueueID: "GONEQ", To: "lost@example.net"}, + }} + reconcile(cs, time.Now().UTC()) + + if got := cs.snapshot(); len(got) != 0 { + t.Fatalf("got %v, want no row touched", got) + } +} + +// With nothing stale to explain there is no reason to shell out to postqueue at +// all — which is the normal state of a relay that is keeping up. +func TestReconcileSkipsTheQueueWhenNoRowIsStuck(t *testing.T) { + calls := stubQueue(t, nil) + + reconcile(&captureStore{}, time.Now().UTC()) + + if *calls != 0 { + t.Fatalf("queue listed %d time(s), want none", *calls) + } +} + // A delivery's page shows what Postfix wrote about that one message, so the // read has to pick its queue-id's lines out of everything else the mail path // logged around them — and only its own: queue ids are hexadecimal runs, and a diff --git a/internal/postfix/queue.go b/internal/postfix/queue.go index 039b41a..847eaac 100644 --- a/internal/postfix/queue.go +++ b/internal/postfix/queue.go @@ -3,6 +3,7 @@ package postfix import ( "fmt" "os/exec" + "regexp" "strings" ) @@ -20,3 +21,43 @@ func Queue() (string, error) { } return string(out), nil } + +// QueueIDs returns the set of queue ids Postfix is still holding — everything +// in the maildrop, incoming, active, deferred and hold queues. It answers the +// one question the log-tailer's reconcile sweep asks about a send-log row stuck +// at "queued": is Postfix still working on this message, or has it left the +// queue without the panel ever seeing a delivery line for it (architecture.md § +// Log tailer)? +// +// An error means the queue could not be listed and therefore says nothing about +// any message; the caller must treat it as "no information", never as an empty +// queue. +func QueueIDs() (map[string]struct{}, error) { + out, err := Queue() + if err != nil { + return nil, err + } + return parseQueueIDs(out), nil +} + +// queueEntryRe matches the first line of a `postqueue -p` entry, e.g. +// +// 3C5B04E6C1* 446 Thu Aug 7 10:12:31 app@example.com +// +// The id is at the start of the line, optionally flagged '*' (in the active +// queue) or '!' (on hold), and is followed by the message size. Requiring the +// size is what separates an entry from the listing's other left-margin lines: +// the '-Queue ID-' header, the '-- 5 Kbytes in 2 Requests.' trailer, a deferred +// entry's '(connect timed out)' reason, and 'Mail queue is empty'. Recipient +// lines are indented and never match. +var queueEntryRe = regexp.MustCompile(`^([0-9A-Za-z]+)[*!]?\s+\d+\s`) + +func parseQueueIDs(listing string) map[string]struct{} { + ids := make(map[string]struct{}) + for _, line := range strings.Split(listing, "\n") { + if m := queueEntryRe.FindStringSubmatch(line); m != nil { + ids[m[1]] = struct{}{} + } + } + return ids +} diff --git a/internal/postfix/queue_test.go b/internal/postfix/queue_test.go new file mode 100644 index 0000000..fbeb988 --- /dev/null +++ b/internal/postfix/queue_test.go @@ -0,0 +1,43 @@ +package postfix + +import "testing" + +// The reconcile sweep decides whether a message is still Postfix's problem, so +// the parser must pick queue ids out of a real listing and nothing else out of +// it: not the header, not the byte-count trailer, and above all not a deferred +// entry's reason line, which — unlike the recipient lines — starts at the left +// margin just as an entry does. +func TestParseQueueIDs(t *testing.T) { + listing := `-Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient------- +3C5B04E6C1* 446 Fri Aug 8 10:12:31 app@example.com + rcpt@example.net + +5B4A2C1D3E 446 Fri Aug 8 10:13:31 app@example.com +(connect to mx.example.net[203.0.113.9]:25: Connection timed out) + deferred@example.net + +A1B2C3D4E5F! 891 Fri Aug 8 10:14:31 app@example.com + held@example.net + +-- 1 Kbytes in 3 Requests. +` + ids := parseQueueIDs(listing) + want := []string{"3C5B04E6C1", "5B4A2C1D3E", "A1B2C3D4E5F"} + for _, id := range want { + if _, ok := ids[id]; !ok { + t.Errorf("queue id %s not found in %v", id, ids) + } + } + if len(ids) != len(want) { + t.Errorf("got %d ids %v, want exactly %v", len(ids), ids, want) + } +} + +// An empty queue must come back as an empty set, not as a phantom id parsed out +// of Postfix's prose — every stale row would otherwise be compared against a +// listing that claims to hold a message called "Mail". +func TestParseQueueIDsOnAnEmptyQueue(t *testing.T) { + if ids := parseQueueIDs("Mail queue is empty\n"); len(ids) != 0 { + t.Errorf("got %v, want no ids", ids) + } +} diff --git a/internal/store/sendlog.go b/internal/store/sendlog.go index 66f0054..6bb7e33 100644 --- a/internal/store/sendlog.go +++ b/internal/store/sendlog.go @@ -93,6 +93,45 @@ func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) { return n, nil } +// 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). +type QueuedDelivery struct { + QueueID string + To string +} + +// ListQueuedOlderThan returns the rows still marked "queued" that were accepted +// before cutoff — old enough that Postfix should long since have reported a +// result for them. Rows without a queue-id are skipped: the milter refused +// those before Postfix ever saw the message, so the queue has nothing to say +// about them. +// +// created_at is stored as RFC3339 UTC, so a lexical comparison against the same +// format is chronologically correct. +func (s *Store) ListQueuedOlderThan(cutoff time.Time) ([]QueuedDelivery, error) { + rows, err := s.db.Query( + `SELECT queue_id, to_addr FROM send_log + WHERE status = ? AND queue_id <> '' AND created_at < ? + ORDER BY id`, + StatusQueued, cutoff.UTC().Format(time.RFC3339), + ) + if err != nil { + return nil, fmt.Errorf("list queued send_log rows: %w", err) + } + defer rows.Close() + + var out []QueuedDelivery + for rows.Next() { + var d QueuedDelivery + if err := rows.Scan(&d.QueueID, &d.To); err != nil { + return nil, fmt.Errorf("scan queued send_log row: %w", err) + } + out = append(out, d) + } + return out, rows.Err() +} + // SendLogRow is one row as returned to the monitoring UI (architecture.md § // Persistence): a SendLogEntry plus the fields that only exist once a row has // been written (id, current status, timestamps). diff --git a/internal/store/sendlog_test.go b/internal/store/sendlog_test.go index 9947c80..0512ab2 100644 --- a/internal/store/sendlog_test.go +++ b/internal/store/sendlog_test.go @@ -95,6 +95,58 @@ func TestUpdateStatusRecipientCaseInsensitive(t *testing.T) { } } +// The reconcile sweep asks for the rows old enough that Postfix should have +// reported on them by now. A message accepted moments ago is simply in flight, +// and one the milter refused never reached the queue at all, so neither is the +// sweep's business. +func TestListQueuedOlderThan(t *testing.T) { + st := openTestStore(t) + + for _, e := range []SendLogEntry{ + {QueueID: "OLD1", To: "stale@example.net"}, + {QueueID: "NEW1", To: "fresh@example.net"}, + } { + if err := st.InsertQueued(e); err != nil { + t.Fatalf("InsertQueued: %v", err) + } + } + // A row the milter refused: no queue-id, and a status the sweep never sees. + if err := st.InsertRejected(SendLogEntry{To: "refused@example.net"}); err != nil { + t.Fatalf("InsertRejected: %v", err) + } + // A row that has already been delivered, aged the same as the stale one. + if err := st.InsertQueued(SendLogEntry{QueueID: "DONE1", To: "done@example.net"}); err != nil { + t.Fatalf("InsertQueued: %v", err) + } + if _, err := st.UpdateStatus("DONE1", "done@example.net", StatusSent); err != nil { + t.Fatalf("UpdateStatus: %v", err) + } + + cutoff := time.Now().UTC().Add(-2 * time.Minute) + backdate(t, st, "OLD1", cutoff.Add(-time.Hour)) + backdate(t, st, "DONE1", cutoff.Add(-time.Hour)) + + got, err := st.ListQueuedOlderThan(cutoff) + if err != nil { + t.Fatalf("ListQueuedOlderThan: %v", err) + } + if len(got) != 1 || got[0] != (QueuedDelivery{QueueID: "OLD1", To: "stale@example.net"}) { + t.Fatalf("got %+v, want only the stale queued row", got) + } +} + +// backdate rewrites a row's acceptance time, so a test can age it past a cutoff +// without waiting. +func backdate(t *testing.T, s *Store, queueID string, at time.Time) { + t.Helper() + if _, err := s.db.Exec( + `UPDATE send_log SET created_at = ? WHERE queue_id = ?`, + at.UTC().Format(time.RFC3339), queueID, + ); err != nil { + t.Fatalf("backdate %s: %v", queueID, err) + } +} + func TestUpdateStatusNoMatch(t *testing.T) { st := openTestStore(t) if err := st.InsertQueued(SendLogEntry{QueueID: "Q1", To: "a@example.net"}); err != nil { diff --git a/test/e2e/mail_helpers.go b/test/e2e/mail_helpers.go index 2ac9ba8..d125bcf 100644 --- a/test/e2e/mail_helpers.go +++ b/test/e2e/mail_helpers.go @@ -74,7 +74,7 @@ var connectFromPattern = regexp.MustCompile(`connect from [^\[]*\[([0-9a-fA-F.:] // lastSMTPClientIP reads mail.log inside the selfpost container and returns // the most recent address Postfix's smtpd logged a connection from. func lastSMTPClientIP(s *stack) (string, error) { - out, err := s.execIn("selfpost", "tail", "-n", "200", "/var/log/mail.log") + out, err := s.execIn("selfpost", "tail", "-n", "200", "/data/log/mail.log") if err != nil { return "", err }