fix(logtail): keep mail.log in /data and reconcile stuck rows (v1.x closure phase 2)
test / test (push) Has been cancelled
test / test (push) Has been cancelled
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 <noreply@anthropic.com> Co-authored-by: Cursor <cursoragent@cursor.com>
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
|
||||
+21
-2
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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" \
|
||||
|
||||
@@ -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]
|
||||
|
||||
@@ -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",
|
||||
|
||||
+4
-1
@@ -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.
|
||||
|
||||
@@ -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
|
||||
|
||||
+31
-14
@@ -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 →
|
||||
|
||||
+14
-6
@@ -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
|
||||
|
||||
+2
-1
@@ -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/` это делает).
|
||||
|
||||
|
||||
+10
-7
@@ -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).
|
||||
|
||||
---
|
||||
|
||||
|
||||
+19
-6
@@ -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, без токенов
|
||||
|
||||
|
||||
+24
-15
@@ -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`.
|
||||
|
||||
---
|
||||
|
||||
|
||||
@@ -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,
|
||||
}
|
||||
|
||||
|
||||
@@ -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=<a@example.net>, 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)
|
||||
}
|
||||
|
||||
+102
-4
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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
|
||||
}
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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).
|
||||
|
||||
@@ -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 {
|
||||
|
||||
@@ -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
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user