diff --git a/CHANGELOG.md b/CHANGELOG.md index cd56291..69b7a63 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,23 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version ## [Unreleased] +### Fixed + +- Log-tailer resumes where it stopped instead of jumping to end-of-file on + every start (phase 3, `docs/code-review.md`): the read position and a + fingerprint of the log's head are persisted (`logtail_state`, migration + `0003`), so delivery lines written while the panel was down are parsed and + their send-log rows no longer stay `queued` forever. A log that changed + identity while the panel was down is read from the start; a first-ever start, + with nothing stored, still begins at the end. Container recreate remains a + gap — `mail.log` is not in `/data` (`docs/security.md`). +- Level-2 rate limit no longer overshoots under concurrency: messages that + passed the check at MAIL FROM but have not reached the send log yet are + counted alongside the stored rows (`internal/milter/inflight.go`), so + parallel SMTP sessions cannot each spend the same last slot. Slots are + released at end-of-message, on ABORT, and after a 10-minute TTL, so a client + that drops mid-transaction cannot hold one — the limiter stays fail-open. + ### Changed - Phase 1 doc/code hygiene (`docs/code-review.md`): removed ~30 stale diff --git a/docs/architecture.md b/docs/architecture.md index 7a9c6ad..0d05215 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -81,7 +81,11 @@ One process, three roles: proxy only. 2. **journal-milter** — unix socket `JOURNAL_MILTER_SOCKET`; records From/To/ Subject/SASL user at DATA; enforces level-2 rate limits; **fail-open** - (`default_action=accept`) so milter failure does not stop mail. + (`default_action=accept`) so milter failure does not stop mail. The level-2 + count is the stored send-log rows plus the messages this process has admitted + but not yet written (`internal/milter/inflight.go`), so concurrent sessions + cannot each spend the same last slot; a reservation is released at + end-of-message, on ABORT, or after a 10-minute TTL. 3. **log-tailer** — follows `MAIL_LOG`, updates send-log delivery status by queue-id. Send-log `queued → sent` transitions depend on this goroutine alone (`UpdateStatus` is only called from [internal/logtail](../internal/logtail/logtail.go)). @@ -99,15 +103,23 @@ 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 an error. -**Known gaps (same class of loss, not fixed by rename rotation):** +**Read offset is persisted** (`logtail_state` table, migration `0003`): the +tailer stores its position plus a fingerprint of the log's first 512 bytes, and +on start resumes from it, parsing the tail written while the panel was down. If +the fingerprint no longer matches (rotated or recreated in the meantime) it reads +the current file from the start; re-parsing lines is harmless because +`UpdateStatus` writes the same status onto the same row. Only a first-ever start, +with nothing stored, begins at end-of-file, so installing the panel does not +replay a pre-existing log. + +**Remaining gap:** -- **Panel restart** — `follow()` starts at end-of-file; lines written while the - panel was down are never parsed; in-flight send-log rows may stay `queued`. - **Container recreate** — `/var/log` is ephemeral; the log is lost with the - container. + container, so the delivery lines for rows still `queued` are gone with it and + those rows stay `queued` forever. -Possible follow-ups if these become painful: persist read offset across restarts, -mount mail log under `/data`, or reconcile stuck rows via `postqueue`. +Possible follow-ups if this becomes painful: mount the mail log under `/data`, or +reconcile stuck rows via `postqueue`. --- @@ -158,7 +170,7 @@ cookie and idle timeout has not expired. | Path | Contents | |---|---| -| `selfpost.db` | SQLite: domains, apps, admin, sessions, send log, L2 limits | +| `selfpost.db` | SQLite: domains, apps, admin, sessions, send log, L2 limits, log-tailer offset | | `setup-token` | First-run setup token file | | `opendkim/` | DKIM keys + tables | | `sasl/sasldb2` | Application SASL credentials | diff --git a/docs/code-review.md b/docs/code-review.md index 62e27f7..f96406b 100644 --- a/docs/code-review.md +++ b/docs/code-review.md @@ -72,7 +72,7 @@ flowchart TB - **Layered / ports-and-adapters:** handlers → services (`domain`, `app`) → `store`; инфраструктура изолирована в адаптерах ([`internal/web/web.go`](../internal/web/web.go), [`internal/app/service.go`](../internal/app/service.go)). - **Composition root** в [`cmd/panel/main.go`](../cmd/panel/main.go): три роли (HTTP, journal-milter, log-tailer) в одном процессе — оправдано для single-container deployment. - **Interface seams** для тестов: `milter.Store`, `app.SenderMaps`, `logtail.StatusStore`. -- **Embedded migrations** ([`internal/store/store.go`](../internal/store/store.go)) — простой, надёжный подход для 2 миграций. +- **Embedded migrations** ([`internal/store/store.go`](../internal/store/store.go)) — простой, надёжный подход для 3 миграций. - **E2E как отдельный модуль** (`test/e2e/go.mod`) — не загрязняет основной модуль. ### Замечания (не блокеры) @@ -215,7 +215,7 @@ E2E покрывает: bootstrap, SMTP AUTH, DKIM, send-log lifecycle, negative | Gap | Описание | Документировано | |-----|----------|-----------------| -| Send-log `queued` forever | Log-tailer стартует с EOF; после restart пропущенный хвост не дочитывается | [security.md](security.md), [roadmap.md](roadmap.md) | +| Send-log `queued` forever | **Закрыто для рестарта:** Фаза 3 — offset персистится (`logtail_state`), хвост дочитывается. Остаётся пересоздание контейнера: `mail.log` не в `/data` | [security.md](security.md), [roadmap.md](roadmap.md) | | CSRF without tokens | POST без Origin/Sec-Fetch-Site пропускается | [security.md](security.md) | | Fail-open L2 rate limit | DB error → mail проходит | [`internal/milter/ratelimit.go`](../internal/milter/ratelimit.go) | | Shallow SPF check | Не следует `include:`/`redirect=` | README, `internal/dnscheck/spf.go` | @@ -235,8 +235,8 @@ E2E покрывает: bootstrap, SMTP AUTH, DKIM, send-log lifecycle, negative |---|----------|-----------|--------| | L1 | **Предрелизный security review** (§ D) — обязательный гейт | **P0** | **Fable** | | L2 | **Шифрование бэкапа и экспорта домена** (R13) — optional, checkbox + password — **выполнено** | P1 | **Opus** + Sonnet | -| L3 | Send-log gap mitigation — опционально | P2 | Opus | -| L4 | Transaction wrap для rate limit count+insert — опционально | P3 | Opus | +| L3 | Send-log gap mitigation — **выполнено** (persist offset, Фаза 3) | P2 | Opus | +| L4 | Rate limit count+insert — **выполнено** (учёт «в полёте», Фаза 3; транзакция как таковая неприменима) | P3 | Opus | --- @@ -246,6 +246,7 @@ E2E покрывает: bootstrap, SMTP AUTH, DKIM, send-log lifecycle, negative - [`0001_init.sql`](../internal/store/migrations/0001_init.sql) — initial schema - [`0002_sessions.sql`](../internal/store/migrations/0002_sessions.sql) — sessions (plan B.1) +- [`0003_logtail_state.sql`](../internal/store/migrations/0003_logtail_state.sql) — log-tailer read offset (Фаза 3) - Механизм: `PRAGMA user_version`, embedded FS, transactional apply — **чистый**, без legacy branches в коде. ### Архивная документация @@ -360,7 +361,7 @@ Go `html/template` + HTMX polling + [`panel.css`](../internal/web/static/panel.c |---|--------|--------| | R9 | Inbound relay (Phase O1) | **Opus** | | R10 | Domain-admin role | Opus | -| R11 | Send-log gap fix (persist offset) | Opus | +| R11 | Send-log gap fix (persist offset) — **выполнено в Фазе 3**, из 2.x снято | Opus | | R12 | Split internal/web subpackages | Sonnet/Opus | ### CI/infra @@ -423,10 +424,22 @@ Go `html/template` + HTMX polling + [`panel.css`](../internal/web/static/panel.c 2. Sonnet: CSS custom properties для dark mode 3. Haiku: consolidate main max-width rules -### Фаза 3 — Operational improvements (P2–P3, optional) +### Фаза 3 — Operational improvements (P2–P3, optional) — **выполнено 2026-08-06** -1. Opus: send-log read offset persistence -2. Opus: rate limit count transaction wrap +1. Opus: send-log read offset persistence — **сделано**: `logtail_state` + (миграция `0003`) хранит offset + отпечаток головы лога; при совпадении + отпечатка чтение продолжается, при несовпадении файл читается с начала, + первый запуск (записи нет) — с конца, как раньше. +2. Opus: rate limit count transaction wrap — **сделано иначе**: буквальная + транзакция невозможна, count живёт на MAIL FROM, insert — на end-of-message, + это разные стадии SMTP-транзакции. Overshoot закрыт учётом сообщений «в + полёте» (`internal/milter/inflight.go`): к счёту из БД добавляются + резервации, взятые прошедшими проверку сессиями и снимаемые после записи в + send-log, на ABORT или по TTL 10 минут. + +Остаток по send-log (не закрывается персистом offset): при пересоздании +контейнера `mail.log` теряется вместе с ним — принятый риск в +[security.md](security.md). --- diff --git a/docs/progress.md b/docs/progress.md index 7d3321b..00c227f 100644 --- a/docs/progress.md +++ b/docs/progress.md @@ -52,6 +52,7 @@ - **§ D выполнен (2026-08-06):** предрелизная ревизия безопасности моделью Fable — диф от аудита v1.0 (Фаза 11, `bd64e80`) до HEAD + полный проход по чек-листу [security.md](security.md) (бывшее ТЗ 7.6). Эксплуатируемых находок нет; одна правка defence-in-depth (`--` перед логином в argv `saslpasswd2`, `internal/app/sasl.go` + тест). Принятые риски не пополнились. Детали — [implementation-plan.md](implementation-plan.md) § D и CHANGELOG `[Unreleased]/Security`. Локально `go vet`/`go test ./internal/app/...` чистые; падения `internal/domain` (`TestWriteLoadPrivateKeyRoundtrip`, `TestRenderTables`) и `internal/logtail` (`TestFollowTailsAndRotates`) — Windows-специфика (права файлов/`\` в путях/rename открытого файла), на Linux CI зелено. - **Фаза 1 выполнена (2026-08-06)** ([code-review.md](code-review.md) § Фаза 1 — doc/code hygiene, P1): cleanup ~30 stale «Phase N» комментариев в коде и shell-скриптах; исправлен stale-комментарий в `handlers_domains.go`; ADR CSRF (Origin vs токены) добавлен в [security.md](security.md); known-limitations по log-tailer уже был в [architecture.md](architecture.md) § Log tailer — отдельного действия не потребовалось; `docs/logo` в [roadmap.md](roadmap.md) закрыт (каталога нет, критерию соответствует); `gofmt -l` добавлен в CI (`.github/workflows/test.yml`). `gofmt`/`go vet`/`go test ./...` чистые в обоих модулях (dev-server). - **Фаза 1.5 выполнена (2026-08-06)** ([code-review.md](code-review.md) § Фаза 1.5 — шифрование резервных копий, P1): новый пакет `internal/secretfile` — конверт `magic SELFPOST1 | type | scrypt-параметры | salt | nonce-prefix` + поток 64 KiB чанков AES-256-GCM, каждый с AAD `header+counter+last`, поэтому обрезка, перестановка и подмена не открываются (стриминг в обе стороны — полный бэкап не держится в памяти). Панель: чекбокс «Encrypt with a password» в форме полного бэкапа и экспорта домена (общий партиал `templates/encrypt_fields.html`, показ/очистка полей — `panel.js`, без inline-скриптов), импорт домена принимает `.spde` (шифрование определяется по magic, не по расширению) с полем пароля. CLI `selfpost-backup`: пишет `.spbk` при заданном пароле и умеет `-decrypt` (иначе зашифрованный бэкап нечем распаковать при restore); пароль — только `SELFPOST_BACKUP_PASSWORD` / `-password-file`, никогда argv. Умолчание не изменилось: галочка снята — прежние `.tar.gz` / `.json` байт в байт. Тесты: round-trip по размерам (0, границы чанка, несколько чанков), неверный пароль, обрезка, перестановка чанков, порча байта, чужие KDF-параметры; валидация формы пароля; round-trip CLI create→decrypt→tar. Docs: README § *Encrypting a backup or export*, [security.md](security.md) § «Резервная копия и экспорт домена» + принятый риск (шифрование опционально), [architecture.md](architecture.md) § Persistence. `gofmt`/`go vet`/`go test ./...` чистые (кроме известных Windows-падений `internal/domain`, `internal/logtail`). E2E-сценарий не добавлялся: в `test/e2e/` бэкапа не было и раньше, а прогнать новый тест локально нечем (нет Docker) — кандидат при следующем прогоне на dev-сервере. +- **Фаза 3 выполнена (2026-08-06)** ([code-review.md](code-review.md) § Фаза 3 — 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 локально) — кандидат на следующий прогон на dev-сервере. - **Дальше:** релизный гейт (Фаза 0) закрыт по существу — e2e C.4 и ревизия § D пройдены; остаются только шаги, которые делаются в момент резки версии (бамп тега образа + Codeberg URL, git tag) по явной команде пользователя. Остальные пункты из [code-review.md](code-review.md) — polish (фазы 2–3). - **Принятые риски** — [security.md](security.md). **Опционально v1.x / 2.x** — [roadmap.md](roadmap.md) (хвост документации, send-log gaps, Фаза O1+, роль администратора домена). - **Прод:** `selfpost.example.com`, реальный Let's Encrypt сертификат, живой e2e (DKIM/SPF pass). Контейнер там всё ещё на образе v1.0 — Фаза 14 в него не выкатывалась. При апгрейде: админа один раз разлогинит (сменилось имя cookie), а от reverse-proxy требуется передача исходного `Host` (Apache-фрагмент из `deploy/` это делает). diff --git a/docs/roadmap.md b/docs/roadmap.md index ef3bf91..40193af 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -60,11 +60,12 @@ CHANGELOG `[Unreleased]/Security`, а разделы B.1–B.3 и C.4 вырез (`docs/logo` уже отсутствует как каталог — критерию «либо содержит файлы, либо отсутствует» удовлетворяет; отдельного действия не требуется.) -**Send-log vs `mail.log` (опционально).** После рестарта панели или пересоздания -контейнера строки send-log могут навсегда остаться `queued` — log-tailer не -дочитывает пропущенный хвост, `mail.log` не в `/data`. Rename-ротация (B.2) -это не лечит. Кандидаты, если станет больно: persist позиции чтения, volume для -лога, сверка зависших строк через `postqueue`. As-built и принятый риск: +**Send-log vs `mail.log` (частично закрыто).** Persist позиции чтения сделан +(Фаза 3 [code-review.md](code-review.md), таблица `logtail_state`): после +рестарта панели log-tailer дочитывает пропущенный хвост. Остаётся пересоздание +контейнера — `mail.log` не в `/data` и теряется вместе с ним, такие строки +навсегда останутся `queued`. Кандидаты, если станет больно: volume для лога, +сверка зависших строк через `postqueue`. As-built и принятый риск: [architecture.md](architecture.md) § Log tailer, [security.md](security.md). --- diff --git a/docs/security.md b/docs/security.md index 295c4dd..3f5f587 100644 --- a/docs/security.md +++ b/docs/security.md @@ -118,10 +118,12 @@ Hardening сверх обязательного (security-заголовки, п безвозвратно нерасшифровываемый архив хуже незашифрованного: пароль SelfPost не хранит. Триггером сделать шифрование обязательным считать появление второго администратора (тогда «кто скачал» перестаёт быть одним человеком). -- **Send-log может навсегда остаться `queued` после рестарта панели или - пересоздания контейнера.** Log-tailer стартует с конца `mail.log`; файл не в - `/data` и теряется при recreate. Rename-ротация это не лечит. См. [architecture.md](architecture.md) - § Log tailer — known gaps. +- **Send-log может навсегда остаться `queued` после пересоздания контейнера.** + Рестарт панели это больше не вызывает: log-tailer сохраняет позицию чтения + (`logtail_state`, миграция `0003`) и после старта дочитывает хвост, написанный + пока панель лежала. Но `mail.log` живёт не в `/data` и теряется вместе с + контейнером — строки, чьи delivery-строки были только в нём, останутся + `queued`. См. [architecture.md](architecture.md) § Log tailer. ## ADR: CSRF через проверку Origin, без токенов diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index 70c2984..4829f3e 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -20,11 +20,14 @@ import ( "codeberg.org/mix/selfpost/internal/store" ) -// StatusStore is the slice of the store the log-tailer needs. *store.Store -// satisfies it. +// 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. type StatusStore interface { UpdateStatus(queueID, recipient, status string) (int64, error) DeleteSendLogBefore(cutoff time.Time) (int64, error) + LogtailState(path string) (store.LogtailState, bool, error) + SaveLogtailState(path string, st store.LogtailState) error } // pollInterval is how often the tail loop checks for new bytes / rotation. It @@ -73,12 +76,13 @@ func parseDelivery(line string) (queueID, recipient, status string, ok bool) { } // Run follows path and updates send-log statuses until ctx is cancelled, while -// a background sweep prunes rows older than retentionDays. It returns nil on a -// clean shutdown. +// a background sweep prunes rows older than retentionDays. Reading resumes at +// the offset the previous run persisted, so a restart parses the delivery lines +// written while the panel was down. It returns nil on a clean shutdown. func Run(ctx context.Context, path string, st StatusStore, retentionDays int) error { go retentionLoop(ctx, st, retentionDays) - return follow(ctx, path, func(line string) { + return follow(ctx, path, &tracker{st: st, path: path}, func(line string) { queueID, recipient, status, ok := parseDelivery(line) if !ok { return @@ -166,10 +170,11 @@ func TailLines(path string, n int) ([]string, error) { } // follow tails path line by line, calling handle for each complete line, until -// ctx is cancelled. It starts at end-of-file (so a restart does not reprocess -// history) and reopens the file when it is rotated (inode change from +// ctx is cancelled. Where it starts is tr's decision (a persisted offset, the +// 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, handle func(string)) error { +func follow(ctx context.Context, path string, tr *tracker, handle func(string)) error { var ( f *os.File r *bufio.Reader @@ -199,7 +204,7 @@ func follow(ctx context.Context, path string, handle func(string)) error { // The container may start before Postfix has created mail.log; wait for it. for { - if err := openAt(0, io.SeekEnd); err == nil { + if err := openAt(0, io.SeekStart); err == nil { break } select { @@ -208,6 +213,10 @@ func follow(ctx context.Context, path string, handle func(string)) error { case <-time.After(pollInterval): } } + if _, err := f.Seek(tr.resume(f), io.SeekStart); err != nil { + log.Printf("log-tailer: seek %s: %v", path, err) + } + r.Reset(f) // the reader buffered from the pre-seek position defer func() { if f != nil { f.Close() @@ -231,11 +240,20 @@ func follow(ctx context.Context, path string, handle func(string)) error { } } + // read returns how many bytes of the open file have actually been consumed: + // the descriptor position less the partial line bufio handed back at EOF, + // which is re-read (and completed) on the next drain or the next start. + read := func() int64 { + pos, _ := f.Seek(0, io.SeekCurrent) + return pos - int64(len(pending)) + } + ticker := time.NewTicker(pollInterval) defer ticker.Stop() for { select { case <-ctx.Done(): + tr.record(f, read(), true) // shutdown: the next start resumes here return nil case <-ticker.C: drain() @@ -252,8 +270,12 @@ func follow(ctx context.Context, path string, handle func(string)) error { drain() if err := openAt(0, io.SeekStart); err != nil { log.Printf("log-tailer: reopen %s: %v", path, err) + continue } + tr.adopt(f) + continue } + tr.record(f, read(), false) } } } diff --git a/internal/logtail/logtail_test.go b/internal/logtail/logtail_test.go index 6abaf1f..62c3d47 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -4,6 +4,7 @@ import ( "context" "os" "path/filepath" + "strings" "sync" "testing" "time" @@ -77,10 +78,16 @@ func TestParseDelivery(t *testing.T) { } } -// captureStore records UpdateStatus calls for the follow integration test. +// captureStore records UpdateStatus calls for the follow integration test and +// keeps the persisted read offset in memory, so a "restart" in a test is a +// second Run against the same captureStore. type captureStore struct { mu sync.Mutex calls []string + + state store.LogtailState + haveState bool + stateErr error } func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, error) { @@ -92,12 +99,37 @@ func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, e func (c *captureStore) DeleteSendLogBefore(time.Time) (int64, error) { return 0, nil } +func (c *captureStore) LogtailState(string) (store.LogtailState, bool, error) { + c.mu.Lock() + defer c.mu.Unlock() + if c.stateErr != nil { + return store.LogtailState{}, false, c.stateErr + } + return c.state, c.haveState, nil +} + +func (c *captureStore) SaveLogtailState(_ string, st store.LogtailState) error { + c.mu.Lock() + defer c.mu.Unlock() + if c.stateErr != nil { + return c.stateErr + } + c.state, c.haveState = st, true + return nil +} + func (c *captureStore) snapshot() []string { c.mu.Lock() defer c.mu.Unlock() return append([]string(nil), c.calls...) } +func (c *captureStore) reset() { + c.mu.Lock() + defer c.mu.Unlock() + c.calls = nil +} + // TestFollowTailsAndRotates writes delivery lines to a log file, then rotates // it (rename + fresh create, as logrotate does) and writes more, asserting the // tailer picks up lines from both the original and rotated file. @@ -142,6 +174,80 @@ func TestFollowTailsAndRotates(t *testing.T) { } } +// TestFollowResumesAfterRestart covers the persisted read offset: a restart +// must parse the delivery lines written while the tailer was down (rows that +// would otherwise stay "queued" forever), without re-parsing what it already +// read, and must fall back to reading the whole file when the log was rotated +// or recreated in the meantime. +func TestFollowResumesAfterRestart(t *testing.T) { + old := pollInterval + pollInterval = 10 * time.Millisecond + t.Cleanup(func() { pollInterval = old }) + + dir := t.TempDir() + path := filepath.Join(dir, "mail.log") + // A head longer than fingerprintSize, so the file stays identifiable across + // the restart; the lines themselves predate the first start and are ignored. + seed := strings.Repeat("host postfix/qmgr[1]: seed line, not a delivery\n", 20) + if err := os.WriteFile(path, []byte(seed), 0o644); err != nil { + t.Fatalf("seed log: %v", err) + } + + cs := &captureStore{} + stop := startRun(t, path, cs) + appendLine(t, path, "host postfix/smtp[1]: Q1: to=, dsn=2.0.0, status=sent (ok)") + waitFor(t, func() bool { return contains(cs.snapshot(), "Q1|a@example.net|sent") }) + stop() // persists the offset past Q1 + + // Down: Postfix keeps delivering. + appendLine(t, path, "host postfix/smtp[1]: Q2: to=, dsn=2.0.0, status=sent (ok)") + + cs.reset() + stop = startRun(t, path, cs) + waitFor(t, func() bool { return contains(cs.snapshot(), "Q2|b@example.net|sent") }) + if contains(cs.snapshot(), "Q1|a@example.net|sent") { + t.Fatal("resumed run re-parsed Q1: offset was not honoured") + } + stop() + + // Down again, and this time the log is replaced (logrotate + fresh create). + // The stored offset belongs to a file that no longer exists, so the new one + // must be read from the start. + if err := os.WriteFile(path, []byte(strings.Repeat("host postfix/qmgr[1]: fresh log after rotation\n", 20)+ + "host postfix/smtp[1]: Q3: to=, dsn=5.1.1, status=bounced (nope)\n"), 0o644); err != nil { + t.Fatalf("recreate log: %v", err) + } + + cs.reset() + stop = startRun(t, path, cs) + waitFor(t, func() bool { return contains(cs.snapshot(), "Q3|c@example.net|bounced") }) + stop() +} + +// startRun launches the tailer and returns a function that cancels it and waits +// for a clean return, the way a panel restart bookends a run. +func startRun(t *testing.T, path string, cs *captureStore) func() { + t.Helper() + ctx, cancel := context.WithCancel(context.Background()) + done := make(chan error, 1) + go func() { done <- Run(ctx, path, cs, 90) }() + // follow() opens and seeks on start; give it a moment before the caller + // appends, so the append is not raced by the initial open. + time.Sleep(50 * time.Millisecond) + return func() { + t.Helper() + cancel() + select { + case err := <-done: + if err != nil { + t.Fatalf("Run: %v", err) + } + case <-time.After(2 * time.Second): + t.Fatal("Run did not return after cancel") + } + } +} + func appendLine(t *testing.T, path, line string) { t.Helper() f, err := os.OpenFile(path, os.O_APPEND|os.O_WRONLY, 0o644) diff --git a/internal/logtail/offset.go b/internal/logtail/offset.go new file mode 100644 index 0000000..f8c8000 --- /dev/null +++ b/internal/logtail/offset.go @@ -0,0 +1,136 @@ +package logtail + +import ( + "crypto/sha256" + "encoding/hex" + "errors" + "io" + "log" + "os" + "time" + + "codeberg.org/mix/selfpost/internal/store" +) + +const ( + // fingerprintSize is how many bytes from the head of the log identify it. + // Postfix writes a timestamped line per event, so the first 512 bytes are + // effectively unique per log generation — enough to tell "the file we were + // reading" from "a fresh one created by logrotate while we were down", + // which os.SameFile cannot answer across a restart. + fingerprintSize = 512 + // persistInterval throttles the offset write. Losing up to this much + // progress on a crash only means re-parsing a few lines (UpdateStatus is + // idempotent), which is much cheaper than a database write per poll tick. + persistInterval = 5 * time.Second +) + +// tracker persists the tailer's read position so a restart resumes where the +// previous run stopped instead of jumping to end-of-file — the "send-log rows +// stay queued forever" gap (architecture.md § Log tailer). It is used from the +// follow loop only, so it needs no locking. +type tracker struct { + st StatusStore + path string + + fp string // fingerprint of the file currently open ("" if too short) + saved int64 // last offset written to the store + lastSave time.Time +} + +// resume returns the byte offset the tailer should start reading f at, having +// recorded f's fingerprint for later saves. +// +// The rules, in order: no stored state at all (first ever start) means start at +// the end, so installing the panel does not replay a pre-existing log; a stored +// state whose fingerprint still matches means continue from it, parsing the +// tail written while the panel was down; anything else means the file is not +// the one the offset referred to (rotated, recreated or truncated in the +// meantime), so read it from the start. Re-parsing lines already seen is +// harmless: UpdateStatus writes the same status onto the same row. +func (t *tracker) resume(f *os.File) int64 { + size, err := fileSize(f) + if err != nil { + log.Printf("log-tailer: stat %s: %v (reading from the start)", t.path, err) + return 0 + } + t.fp = fingerprintOf(f) + + prev, ok, err := t.st.LogtailState(t.path) + if err != nil { + log.Printf("log-tailer: read stored offset: %v (starting at end)", err) + return size + } + switch { + case !ok: + t.saved = size + return size + case prev.Fingerprint != "" && prev.Fingerprint == t.fp && prev.Offset <= size: + t.saved = prev.Offset + if prev.Offset < size { + log.Printf("log-tailer: resuming %s at offset %d (%d bytes to catch up)", + t.path, prev.Offset, size-prev.Offset) + } + return prev.Offset + default: + log.Printf("log-tailer: %s changed while the panel was down; reading from the start", t.path) + t.saved = 0 + return 0 + } +} + +// adopt re-fingerprints after the follow loop switched to a rotated-in file and +// persists the fresh start immediately, so a restart right after a rotation +// does not resume at the old file's offset. +func (t *tracker) adopt(f *os.File) { + t.fp = fingerprintOf(f) + t.saved = -1 // force the write below even if the old offset happened to be 0 + t.record(f, 0, true) +} + +// record persists offset, at most once per persistInterval unless force is set +// (rotation and shutdown, where the write must not be skipped). +func (t *tracker) record(f *os.File, offset int64, force bool) { + if offset == t.saved { + return + } + if !force && time.Since(t.lastSave) < persistInterval { + return + } + if t.fp == "" { + // The log was shorter than a fingerprint when we opened it; now that it + // has grown, an identifiable one may be available. + t.fp = fingerprintOf(f) + } + if err := t.st.SaveLogtailState(t.path, store.LogtailState{Fingerprint: t.fp, Offset: offset}); err != nil { + log.Printf("log-tailer: save offset: %v", err) + return + } + t.saved = offset + t.lastSave = time.Now() +} + +// fingerprintOf hashes the head of the file. It returns "" for a file too short +// to identify — the head would still change as Postfix appends, so such a +// fingerprint could not be compared meaningfully on the next start. +func fingerprintOf(f *os.File) string { + buf := make([]byte, fingerprintSize) + n, err := f.ReadAt(buf, 0) + if err != nil && !errors.Is(err, io.EOF) { + log.Printf("log-tailer: fingerprint read: %v", err) + return "" + } + if n < fingerprintSize { + return "" + } + sum := sha256.Sum256(buf) + return hex.EncodeToString(sum[:]) +} + +func fileSize(f *os.File) (int64, error) { + info, err := f.Stat() + if err != nil { + return 0, err + } + return info.Size(), nil +} diff --git a/internal/milter/inflight.go b/internal/milter/inflight.go new file mode 100644 index 0000000..78ca52b --- /dev/null +++ b/internal/milter/inflight.go @@ -0,0 +1,99 @@ +package milter + +import ( + "sync" + "time" +) + +// reservationTTL bounds how long a message may stay reserved. A reservation is +// released at end-of-message or on ABORT, but a client that simply drops the +// connection after MAIL FROM produces neither callback (go-milter has no +// connection-close hook), and a reservation that never expired would count +// against the limit forever — a fail-closed drift this milter must not have. +// The TTL is generously longer than any realistic DATA transfer, so a message +// still being received is never dropped from the count. +const reservationTTL = 10 * time.Minute + +// reservation is one message that passed the level-2 check and has not been +// written to the send log yet. +type reservation struct { + key string + at time.Time +} + +// inflight counts messages that are between the limit check (MAIL FROM) and the +// send-log insert (end-of-message). The stored count alone cannot see them, so +// without this several concurrent SMTP sessions each read the same pre-insert +// count, each conclude they are under the ceiling, and the limit is overshot by +// however many were in flight. Counting reservations closes that window without +// writing placeholder rows the operator would see in the UI. +// +// One instance is shared by every session of the process, hence the mutex. +// Methods tolerate a nil receiver so a session built without one (tests) simply +// behaves as it did before. +type inflight struct { + mu sync.Mutex + m map[string]map[*reservation]struct{} +} + +// count returns how many reservations for key were taken within the limit's +// window (at or after since), pruning any that outlived reservationTTL. +func (f *inflight) count(key string, since time.Time) int64 { + if f == nil { + return 0 + } + f.mu.Lock() + defer f.mu.Unlock() + + set := f.m[key] + cutoff := time.Now().Add(-reservationTTL) + var n int64 + for r := range set { + if r.at.Before(cutoff) { + delete(set, r) + continue + } + if !r.at.Before(since) { + n++ + } + } + if len(set) == 0 { + delete(f.m, key) + } + return n +} + +// reserve claims a slot for key until the message is recorded or released. +func (f *inflight) reserve(key string) *reservation { + if f == nil { + return nil + } + f.mu.Lock() + defer f.mu.Unlock() + + if f.m == nil { + f.m = make(map[string]map[*reservation]struct{}) + } + if f.m[key] == nil { + f.m[key] = make(map[*reservation]struct{}) + } + r := &reservation{key: key, at: time.Now()} + f.m[key][r] = struct{}{} + return r +} + +// release drops a reservation, either because the message reached the send log +// (where the stored count takes over) or because it never will. +func (f *inflight) release(r *reservation) { + if f == nil || r == nil { + return + } + f.mu.Lock() + defer f.mu.Unlock() + + set := f.m[r.key] + delete(set, r) + if len(set) == 0 { + delete(f.m, r.key) + } +} diff --git a/internal/milter/milter.go b/internal/milter/milter.go index 09dbcb9..2ae29d4 100644 --- a/internal/milter/milter.go +++ b/internal/milter/milter.go @@ -45,13 +45,18 @@ type Store interface { type session struct { milter.NoOpMilter rec Store + // flight is shared by every session of the process; it holds the messages + // that passed the level-2 check but are not in the send log yet. Nil is a + // valid zero value (no in-flight accounting). + flight *inflight clientIP string // captured once per connection - login string - from string - rcpts []string - subject string + login string + from string + rcpts []string + subject string + reserved []*reservation // level-2 slots held by the current message } // Connect captures the client IP, which comes from the addr parameter rather @@ -72,6 +77,7 @@ func (s *session) Connect(host, family string, port uint16, addr net.IP, m *milt // tempfail before recipients are even offered (spec 7.4). Enforcement is // fail-open — see overLimit. func (s *session) MailFrom(from string, m *milter.Modifier) (milter.Response, error) { + s.releaseReservations() // a previous transaction that ended without EOM/ABORT s.from = cleanAddress(from) s.login = macro(m, "auth_authen") s.rcpts = nil @@ -127,9 +133,22 @@ func decodeSubject(v string) string { // rows are written. We accept (this milter is done) without ever rejecting. func (s *session) Body(m *milter.Modifier) (milter.Response, error) { s.record(macro(m, "i")) + // The rows are in the send log now, so the stored count sees this message + // and its level-2 slots are no longer needed. + s.releaseReservations() return milter.RespAccept, nil } +// Abort ends the current transaction without an end-of-message (client RSET, or +// Postfix rejecting the message for its own reasons). No send-log row will be +// written, so the level-2 slots this message held must go back. +func (s *session) Abort(m *milter.Modifier) error { + s.releaseReservations() + s.rcpts = nil + s.subject = "" + return nil +} + // macro reads a milter macro, tolerating Postfix's convention of wrapping // multi-character macro names in curly braces (e.g. {auth_authen}) while // single-character names (e.g. i) arrive bare. go-milter stores whatever name @@ -191,8 +210,9 @@ func domainOf(addr string) string { // Serve runs the journal-milter on ln until ctx is cancelled. Each connection // gets a fresh session bound to rec. It returns nil on a clean shutdown. func Serve(ctx context.Context, ln net.Listener, rec Store) error { + flight := &inflight{} // shared: the level-2 window spans all connections srv := &milter.Server{ - NewMilter: func() milter.Milter { return &session{rec: rec} }, + NewMilter: func() milter.Milter { return &session{rec: rec, flight: flight} }, Actions: 0, // read-only: we make no message modifications Protocol: milter.OptNoBody, // the journal needs headers/EOM, not the body } diff --git a/internal/milter/milter_test.go b/internal/milter/milter_test.go index 999a43a..9474e6b 100644 --- a/internal/milter/milter_test.go +++ b/internal/milter/milter_test.go @@ -331,6 +331,130 @@ func TestRateLimitNoIPKeyDoesNotApply(t *testing.T) { } } +// mailFromIn is mailFrom with an explicit shared in-flight registry, so a test +// can play several concurrent SMTP sessions of one process against each other. +func mailFromIn(t *testing.T, rec Store, fl *inflight, ip, from, login string) (*session, milter.Response) { + t.Helper() + s := &session{rec: rec, flight: fl} + if _, err := s.Connect("h", "tcp4", 0, net.ParseIP(ip), mods(nil)); err != nil { + t.Fatalf("Connect: %v", err) + } + resp, err := s.MailFrom(from, mods(map[string]string{"auth_authen": login})) + if err != nil { + t.Fatalf("MailFrom: %v", err) + } + return s, resp +} + +func limitedRecorder(count int64) *fakeRecorder { + return &fakeRecorder{ + limits: map[string]store.RateLimit{ + store.RateLimitScopeDomain + "|example.com": activeLimit(limitIP), + }, + counts: map[string]int64{store.RateLimitScopeDomain + "|example.com": count}, + } +} + +// Messages between MAIL FROM and end-of-message are not in the send log yet, so +// counting the stored rows alone lets concurrent sessions each pass the same +// check and overshoot the ceiling. The last free slot may only be taken once. +func TestRateLimitCountsInFlightMessages(t *testing.T) { + rec := limitedRecorder(4) // one below the ceiling of 5 + fl := &inflight{} + + if _, resp := mailFromIn(t, rec, fl, limitIP, "a@example.com", "app1"); resp != milter.RespContinue { + t.Fatalf("first message = %v, want Continue (4/5 stored)", resp) + } + // Same window, nothing written yet: the first message holds the fifth slot. + if _, resp := mailFromIn(t, rec, fl, limitIP, "b@example.com", "app1"); resp != milter.RespTempFail { + t.Fatalf("concurrent message = %v, want TempFail (would overshoot)", resp) + } + if len(rec.rejected) != 1 { + t.Fatalf("want one rejected send-log row, got %+v", rec.rejected) + } +} + +// Once the message is recorded the stored count sees it, so its reservation +// must be given back — otherwise it would be counted twice and the ceiling +// would drift closed. +func TestReservationReleasedAtEndOfMessage(t *testing.T) { + rec := limitedRecorder(4) + fl := &inflight{} + + s, resp := mailFromIn(t, rec, fl, limitIP, "a@example.com", "app1") + if resp != milter.RespContinue { + t.Fatalf("first message = %v, want Continue", resp) + } + if _, err := s.Body(mods(map[string]string{"i": "Q1"})); err != nil { + t.Fatalf("Body: %v", err) + } + if n := fl.count(store.RateLimitScopeDomain+"|example.com", time.Now().Add(-time.Hour)); n != 0 { + t.Fatalf("in-flight count after EOM = %d, want 0", n) + } +} + +// A transaction the client abandons (RSET, or a Postfix-side rejection) never +// reaches the send log, so its slot must not stay claimed. +func TestReservationReleasedOnAbort(t *testing.T) { + rec := limitedRecorder(4) + fl := &inflight{} + + s, resp := mailFromIn(t, rec, fl, limitIP, "a@example.com", "app1") + if resp != milter.RespContinue { + t.Fatalf("first message = %v, want Continue", resp) + } + if err := s.Abort(mods(nil)); err != nil { + t.Fatalf("Abort: %v", err) + } + if _, resp := mailFromIn(t, rec, fl, limitIP, "b@example.com", "app1"); resp != milter.RespContinue { + t.Fatalf("after abort = %v, want Continue (slot released)", resp) + } +} + +// A refused message must not leave the slots it claimed for the limits checked +// before the one that tripped, or every refusal would tighten the ceiling. +func TestRefusalReleasesEarlierReservation(t *testing.T) { + rec := &fakeRecorder{ + limits: map[string]store.RateLimit{ + store.RateLimitScopeDomain + "|example.com": activeLimit(limitIP), + store.RateLimitScopeApp + "|app1": activeLimit(limitIP), + }, + counts: map[string]int64{ + store.RateLimitScopeDomain + "|example.com": 0, // domain: plenty of room + store.RateLimitScopeApp + "|app1": 5, // app: at the ceiling + }, + } + fl := &inflight{} + if _, resp := mailFromIn(t, rec, fl, limitIP, "a@example.com", "app1"); resp != milter.RespTempFail { + t.Fatalf("app over limit = %v, want TempFail", resp) + } + if n := fl.count(store.RateLimitScopeDomain+"|example.com", time.Now().Add(-time.Hour)); n != 0 { + t.Fatalf("domain reservation left behind after refusal: %d", n) + } +} + +// The in-flight count only covers the limit's own window: a reservation older +// than it (a session stuck mid-DATA for longer than the window) must not be +// counted against a window it no longer belongs to. +func TestInflightIgnoresReservationsOutsideWindow(t *testing.T) { + fl := &inflight{} + r := fl.reserve("domain|example.com") + r.at = time.Now().Add(-time.Minute) + + if n := fl.count("domain|example.com", time.Now().Add(-time.Hour)); n != 1 { + t.Fatalf("count inside window = %d, want 1", n) + } + if n := fl.count("domain|example.com", time.Now().Add(-time.Second)); n != 0 { + t.Fatalf("count outside window = %d, want 0", n) + } + // Past the TTL the reservation is dropped even for a wide window, so a + // client that vanished after MAIL FROM cannot hold a slot forever. + r.at = time.Now().Add(-2 * reservationTTL) + if n := fl.count("domain|example.com", time.Now().Add(-3*reservationTTL)); n != 0 { + t.Fatalf("expired reservation still counted: %d", n) + } +} + func TestDomainOf(t *testing.T) { cases := map[string]string{ "user@Example.COM": "example.com", diff --git a/internal/milter/ratelimit.go b/internal/milter/ratelimit.go index a2ad2fd..049c68a 100644 --- a/internal/milter/ratelimit.go +++ b/internal/milter/ratelimit.go @@ -17,6 +17,10 @@ import ( // can never block mail — Postfix's level-1 anvil limit (spec 5) remains the // backstop, and it does not depend on this milter at all. Only a clean count at // or above a configured ceiling returns true. +// +// A message that passes reserves a slot per applicable limit, released once it +// reaches the send log (or is abandoned) — see inflight for why the stored +// count alone is not enough. func (s *session) overLimit() bool { if s.clientIP == "" { return false // no client IP to key on; level-2 does not apply @@ -25,6 +29,7 @@ func (s *session) overLimit() bool { {store.RateLimitScopeDomain, domainOf(s.from)}, {store.RateLimitScopeApp, s.login}, } + var taken []*reservation for _, c := range checks { if c.ref == "" { continue @@ -45,15 +50,34 @@ func (s *session) overLimit() bool { log.Printf("journal-milter: rate-limit count %s %q: %v (fail-open)", c.scope, c.ref, err) continue } + key := c.scope + "|" + c.ref + n += s.flight.count(key, since) if n >= int64(rl.MaxMessages) { log.Printf("journal-milter: %s %q over limit: %d/%d in %ds from %s — refusing 4xx", c.scope, c.ref, n, rl.MaxMessages, rl.WindowSeconds, s.clientIP) + // The message is refused, so the slots claimed for the limits + // checked before this one must not stay claimed. + for _, r := range taken { + s.flight.release(r) + } return true } + taken = append(taken, s.flight.reserve(key)) } + s.reserved = append(s.reserved, taken...) return false } +// releaseReservations gives back every slot this message holds. It runs once +// the message is in the send log (where the stored count sees it), and whenever +// the transaction ends without getting there. +func (s *session) releaseReservations() { + for _, r := range s.reserved { + s.flight.release(r) + } + s.reserved = nil +} + // recordRejected writes a send-log row for a message refused by a level-2 limit // (spec 7.4, "опционально фиксирует ... для видимости в UI"), so the rejection // shows up in the monitoring screen. Only MAIL-stage fields are known; the write diff --git a/internal/store/logtail.go b/internal/store/logtail.go new file mode 100644 index 0000000..e9d1fc8 --- /dev/null +++ b/internal/store/logtail.go @@ -0,0 +1,54 @@ +package store + +import ( + "database/sql" + "errors" + "fmt" + "time" +) + +// LogtailState is the persisted read position of the mail.log tailer: how far +// into the log it had got, and a fingerprint of the file that offset refers to. +// It lets the tailer resume after a panel restart instead of jumping to +// end-of-file and losing the delivery lines written while it was down. +type LogtailState struct { + Fingerprint string + Offset int64 +} + +// LogtailState returns the stored read position for path. ok is false the first +// time a path is followed (nothing persisted yet), which the tailer treats as +// "start at the end". +func (s *Store) LogtailState(path string) (LogtailState, bool, error) { + var st LogtailState + err := s.db.QueryRow( + `SELECT fingerprint, read_offset FROM logtail_state WHERE path = ?`, + path, + ).Scan(&st.Fingerprint, &st.Offset) + if errors.Is(err, sql.ErrNoRows) { + return LogtailState{}, false, nil + } + if err != nil { + return LogtailState{}, false, fmt.Errorf("read logtail state for %q: %w", path, err) + } + return st, true, nil +} + +// SaveLogtailState records the tailer's read position for path, replacing any +// previous one. It is called on a timer while tailing, so it is a single small +// upsert rather than a transaction. +func (s *Store) SaveLogtailState(path string, st LogtailState) error { + _, err := s.db.Exec( + `INSERT INTO logtail_state (path, fingerprint, read_offset, updated_at) + VALUES (?, ?, ?, ?) + ON CONFLICT(path) DO UPDATE SET + fingerprint = excluded.fingerprint, + read_offset = excluded.read_offset, + updated_at = excluded.updated_at`, + path, st.Fingerprint, st.Offset, time.Now().UTC().Format(time.RFC3339), + ) + if err != nil { + return fmt.Errorf("save logtail state for %q: %w", path, err) + } + return nil +} diff --git a/internal/store/migrations/0003_logtail_state.sql b/internal/store/migrations/0003_logtail_state.sql new file mode 100644 index 0000000..c1ea93a --- /dev/null +++ b/internal/store/migrations/0003_logtail_state.sql @@ -0,0 +1,12 @@ +-- Log-tailer read position. Without it the tailer starts at end-of-file on +-- every start, so delivery lines written while the panel was down are never +-- parsed and their send-log rows stay "queued" forever. One row per followed +-- path; fingerprint identifies the file the offset belongs to (the head bytes +-- of the log), so a rotated or recreated mail.log is detected across a restart, +-- where os.SameFile cannot help. +CREATE TABLE logtail_state ( + path TEXT PRIMARY KEY, + fingerprint TEXT NOT NULL, + read_offset INTEGER NOT NULL, + updated_at TEXT NOT NULL +);