feat: implement B.2 — rotate mail.log by rename + postfix reload

Replaces copytruncate with rename + `postfix reload` (the same mechanism
`postfix logrotate` itself uses), closing the up-to-one-second window where
copytruncate could drop in-flight delivery lines and leave a send-log row
stuck at "queued" forever.

logrotate-mail.conf keeps `create 0644 root root` rather than `nocreate` as
originally planned: verified on a live container that Postfix recreates the
file itself only lazily, on the next write after reload, and at mode 0600 —
unreadable by the unprivileged panel process. `create` hands the file back at
0644 immediately after rename, before Postfix ever touches it.

logtail.follow() re-drains the old file descriptor once more right before
switching to the rotated file, closing the residual gap between the last
poll's drain and the rotation check. readLogTail() treats a momentarily
missing mail.log as an empty screen rather than a logged error.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
2026-08-02 23:45:15 +03:00
parent 82ec287ba1
commit 8c95192a7a
8 changed files with 64 additions and 13 deletions
+12
View File
@@ -5,6 +5,18 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version
## [Unreleased] ## [Unreleased]
- ops: `mail.log` rotation switched from `copytruncate` to rename +
`postfix reload` (the same mechanism `postfix logrotate` itself uses),
eliminating the up-to-one-second window in which `copytruncate` could drop
in-flight delivery lines — a lost line meant a send-log row stuck at
`queued` forever. `logrotate-mail.conf` keeps `create 0644 root root`
rather than `nocreate`: verified on a live container that letting Postfix
recreate the file itself on reload produces `0600`, which the unprivileged
panel process cannot read, breaking the mail-log view until the next
restart. The panel's log-tailer (`internal/logtail`) re-drains the old file
descriptor once more right before switching to the rotated one, closing a
similar small window between polls; a missing `mail.log` right after
rotation is now a normal empty screen rather than a logged error.
- panel: login sessions now persist in SQLite instead of memory, so an - panel: login sessions now persist in SQLite instead of memory, so an
administrator's login survives a container restart or redeploy. Only the administrator's login survives a container restart or redeploy. Only the
SHA-256 of the session token is stored, never the token itself. The SHA-256 of the session token is stored, never the token itself. The
+9 -6
View File
@@ -1,10 +1,13 @@
#!/bin/sh #!/bin/sh
# Periodic logrotate for /var/log/mail.log (spec 9, 10). Postfix's maillog_file # Periodic logrotate for /var/log/mail.log (spec 9, 10). Rotation renames the
# is written by postlogd, which keeps the file open for the life of the # file, recreates it (`create 0644 root root`, matching a cold container
# process — there is no daemon to signal on rotation, so the logrotate.d config # start), then runs `postfix reload` (the same mechanism `postfix logrotate`
# uses copytruncate (a brief truncation race can drop the last few in-flight # uses): postlogd keeps writing to the renamed inode until reload, and the
# lines, which is an acceptable trade for not having to reload Postfix on every # panel's log-tailer holds its own descriptor on that inode, so nothing
# rotation). # 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.
# #
# logrotate itself only rotates once the configured "daily" period has elapsed # 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 # (tracked in /var/lib/logrotate/status), so it is safe to invoke this more
+4 -1
View File
@@ -5,5 +5,8 @@
notifempty notifempty
compress compress
delaycompress delaycompress
copytruncate create 0644 root root
postrotate
/usr/sbin/postfix reload
endscript
} }
+3 -3
View File
@@ -37,15 +37,15 @@
- **миллисекунды между «`cp` дочитал до EOF» и `truncate`** — эти строки не попадают никуда; для `copytruncate` устранить нельзя. - **миллисекунды между «`cp` дочитал до EOF» и `truncate`** — эти строки не попадают никуда; для `copytruncate` устранить нельзя.
**Решение** — ротация переименованием, ровно та механика, которую применяет сам Postfix в `postfix logrotate` (`mv`, затем `HUP` мастеру): rename атомарен, postlogd продолжает писать в переименованный inode до перезапуска, а тейлер держит дескриптор на том же inode и дочитывает хвост перед переключением на новый файл. Не теряется ничего ни на стороне записи, ни на стороне чтения. Правки: **Решение** — ротация переименованием, ровно та механика, которую применяет сам Postfix в `postfix logrotate` (`mv`, затем `HUP` мастеру): rename атомарен, postlogd продолжает писать в переименованный inode до перезапуска, а тейлер держит дескриптор на том же inode и дочитывает хвост перед переключением на новый файл. Не теряется ничего ни на стороне записи, ни на стороне чтения. Правки:
- [build/logrotate-mail.conf](../build/logrotate-mail.conf): убрать `copytruncate`, добавить `nocreate` и `postrotate /usr/sbin/postfix reload endscript`. `rotate 14`/`compress`/`delaycompress` остаются: удержание N файлов (ТЗ 9) — за logrotate, поэтому берётся не сам `postfix logrotate` (у него нет retention, он лишь переименовывает с меткой времени и жмёт), а его механика; - [build/logrotate-mail.conf](../build/logrotate-mail.conf): убрать `copytruncate`, добавить `postrotate /usr/sbin/postfix reload endscript`. `rotate 14`/`compress`/`delaycompress` остаются: удержание N файлов (ТЗ 9) — за logrotate, поэтому берётся не сам `postfix logrotate` (у него нет retention, он лишь переименовывает с меткой времени и жмёт), а его механика. **`create 0644 root root`, не `nocreate`** — см. стендовую проверку ниже, предположение о `nocreate` не подтвердилось;
- `follow()` в [internal/logtail/logtail.go](../internal/logtail/logtail.go): при обнаружении смены inode дочитать старый дескриптор ещё раз перед закрытием — иначе остаётся микроокно между `drain()` и проверкой смены файла. Проверка `ni.Size() < pos` сохраняется как страховка от обрезания посторонней схемой ротации, но перестаёт быть основным механизмом; - `follow()` в [internal/logtail/logtail.go](../internal/logtail/logtail.go): при обнаружении смены inode дочитать старый дескриптор ещё раз перед закрытием — иначе остаётся микроокно между `drain()` и проверкой смены файла. Проверка `ni.Size() < pos` сохраняется как страховка от обрезания посторонней схемой ротации, но перестаёт быть основным механизмом;
- `readLogTail()` в [internal/web/handlers_monitor.go](../internal/web/handlers_monitor.go): `fs.ErrNotExist` — не ошибка, а пустой экран. После rename файла нет, пока Postfix не запишет в него первую строку (порядка секунды в сутки), и баннер ошибки в этот момент — шум. - `readLogTail()` в [internal/web/handlers_monitor.go](../internal/web/handlers_monitor.go): `fs.ErrNotExist` — не ошибка, а пустой экран. После rename файла нет, пока Postfix не запишет в него первую строку (порядка секунды в сутки), и баннер ошибки в этот момент — шум.
**Цена:** один `postfix reload` в сутки — ровно то, что уже делает [postfix-cert-reload.sh](../build/postfix-cert-reload.sh) ради сертификатов, никакой новой машинерии. **Цена:** один `postfix reload` в сутки — ровно то, что уже делает [postfix-cert-reload.sh](../build/postfix-cert-reload.sh) ради сертификатов, никакой новой машинерии.
**Проверено на живом 1.0.0 до принятия решения:** Postfix 3.7.11 (команда `postfix logrotate` есть начиная с 3.4, её реализация в `postfix-script` — это `mv` + `master -t || kill -HUP` + `sleep 1` + компрессор); postlogd работает под uid `postfix`, `/var/log` принадлежит root, `/var/log/mail.log``root:root 0644` и пользователю `postfix` на запись недоступен; в образе файла нет — значит создаёт его привилегированная сторона. Отсюда и `nocreate`: после rename состояние ровно такое же, как при холодном старте контейнера, который заведомо работает. **Проверено на живом 1.0.0 до принятия решения:** Postfix 3.7.11 (команда `postfix logrotate` есть начиная с 3.4, её реализация в `postfix-script` — это `mv` + `master -t || kill -HUP` + `sleep 1` + компрессор); postlogd работает под uid `postfix`, `/var/log` принадлежит root, `/var/log/mail.log``root:root 0644` и пользователю `postfix` на запись недоступен; в образе файла нет — значит создаёт его привилегированная сторона.
**Обязательная проверка на стенде при реализации:** после `postfix reload` новый `/var/log/mail.log` действительно создаётся и логирование продолжается. Если нет — вернуть создание файла logrotate'у (`create 0644 root root`), он и так работает под root. **Стендовая проверка при реализации (обязательная по плану) обнаружила, что предположение о `nocreate` неверно.** На живом контейнере (`selfpost.mixfed.ru`, тестовый образ) после `mv` + `postfix reload` файл действительно появляется — но не сразу и не на `0644`: сам HUP лог не пересоздаёт, это происходит лениво при следующей фактической записи, и создаётся он с режимом `0600` — непривилегированная панель (свой uid) такой файл читать не может, то есть просмотр `mail.log` в панели остаётся сломан до следующего холодного старта контейнера (там `0644` берётся из другого, не связанного с этим, пути создания). Решение — то, что план заранее указал как запасной вариант: `create 0644 root root` вместо `nocreate`. logrotate создаёт пустой файл на 644 сразу после `mv`, ещё до запуска `postrotate`, и Postfix при следующей записи просто открывает и дозаписывает уже существующий файл, не трогая его режим. Проверено многократно на стенде: после ротации файл сразу (без окна) читаем непривилегированным uid панели, и остаётся на 644 после того, как в него попадает новый трафик.
**Смежное, не решённое (тот же класс потерь, вариантом выше не лечится):** при рестарте панели `follow()` стартует с конца файла, поэтому строки, записанные пока она не читала, пропускаются; при редеплое `mail.log` исчезает вместе с контейнером — `/var/log` не в volume. В обоих случаях статусы писем, бывших в полёте, остаются `queued` навсегда — вероятно, чаще, чем при ротации. Кандидаты, если решим закрывать: переживать рестарт (запоминать позицию), вынести лог в `/data`, либо досверять зависшие строки по `postqueue`. **Смежное, не решённое (тот же класс потерь, вариантом выше не лечится):** при рестарте панели `follow()` стартует с конца файла, поэтому строки, записанные пока она не читала, пропускаются; при редеплое `mail.log` исчезает вместе с контейнером — `/var/log` не в volume. В обоих случаях статусы писем, бывших в полёте, остаются `queued` навсегда — вероятно, чаще, чем при ротации. Кандидаты, если решим закрывать: переживать рестарт (запоминать позицию), вынести лог в `/data`, либо досверять зависшие строки по `postqueue`.
3. **Поведение при незаданном `SELFPOST_HOSTNAME` — решено: фатальная проверка в [entrypoint.sh](../build/entrypoint.sh) с развёрнутым текстом ошибки.** Прежнее предложение («предупреждать громко в лог, но не падать») отклонено: оба отказа мягкого fallback'а тихие и отложенные, а предупреждение в лог для таких отказов не работает — оно печатается при старте, а последствие проявляется через часы и в другом месте. 3. **Поведение при незаданном `SELFPOST_HOSTNAME` — решено: фатальная проверка в [entrypoint.sh](../build/entrypoint.sh) с развёрнутым текстом ошибки.** Прежнее предложение («предупреждать громко в лог, но не падать») отклонено: оба отказа мягкого fallback'а тихие и отложенные, а предупреждение в лог для таких отказов не работает — оно печатается при старте, а последствие проявляется через часы и в другом месте.
+2 -1
View File
@@ -39,7 +39,8 @@
- **Выполнено и принято:** базовый линейный план 0→11 (v1.0; аудит безопасности ТЗ 7.6 — полное соответствие), Фаза 12 (UI/UX), Фаза 13 (страница `/status`, DNS-проверки домена) и Фаза 14 (security-заголовки, проверка origin, cookie `__Host-` + обнаружение дублей, документация про `/data/setup-token`). Что именно сделано — в `git log` и `CHANGELOG.md`, здесь не дублируется. - **Выполнено и принято:** базовый линейный план 0→11 (v1.0; аудит безопасности ТЗ 7.6 — полное соответствие), Фаза 12 (UI/UX), Фаза 13 (страница `/status`, DNS-проверки домена) и Фаза 14 (security-заголовки, проверка origin, cookie `__Host-` + обнаружение дублей, документация про `/data/setup-token`). Что именно сделано — в `git log` и `CHANGELOG.md`, здесь не дублируется.
- **B.1 реализован** (не выкачен на прод): сессии переехали в SQLite (`internal/store/migrations/0002_sessions.sql`, `internal/store/sessions.go`, `internal/web/session.go`) — хранится SHA-256 токена, не сам токен; скользящий срок бездействия `PANEL_SESSION_IDLE_DAYS` (по умолчанию 7 дней, без абсолютного потолка); запись в БД продлевается не чаще раза в час (`renewThreshold`); опросы мониторинга (`GET` с `HX-Request`) продление не триггерят (`isSessionActivity` в `internal/web/middleware.go`); `Max-Age` cookie выставляется тем же значением при логине и при продлении (`setSessionCookie`); смена пароля разлогинивает все сессии кроме текущей (уже было, теперь через БД). Проверено на стенде: логин → рестарт процесса панели → сессия жива по старой cookie; HX-Request-опрос и повторный GET внутри часового окна не шлют `Set-Cookie`. `go vet`/`go test ./...`/`gofmt -l .` чистые. - **B.1 реализован** (не выкачен на прод): сессии переехали в SQLite (`internal/store/migrations/0002_sessions.sql`, `internal/store/sessions.go`, `internal/web/session.go`) — хранится SHA-256 токена, не сам токен; скользящий срок бездействия `PANEL_SESSION_IDLE_DAYS` (по умолчанию 7 дней, без абсолютного потолка); запись в БД продлевается не чаще раза в час (`renewThreshold`); опросы мониторинга (`GET` с `HX-Request`) продление не триггерят (`isSessionActivity` в `internal/web/middleware.go`); `Max-Age` cookie выставляется тем же значением при логине и при продлении (`setSessionCookie`); смена пароля разлогинивает все сессии кроме текущей (уже было, теперь через БД). Проверено на стенде: логин → рестарт процесса панели → сессия жива по старой cookie; HX-Request-опрос и повторный GET внутри часового окна не шлют `Set-Cookie`. `go vet`/`go test ./...`/`gofmt -l .` чистые.
- **Решено, но ещё не реализовано:** пункты **B.2**, **B.3** и **C.4** плана, именно в этом порядке. B.2 — ротация `mail.log` уходит с `copytruncate` на «переименовать + `postfix reload`» (правки в `logrotate-mail.conf`, `follow()` в `internal/logtail`, `readLogTail()` в `internal/web`; на стенде проверить, что после reload новый `mail.log` создаётся). B.3 — незаданный `SELFPOST_HOSTNAME` роняет контейнер в `entrypoint.sh` с развёрнутым текстом ошибки плюс синтаксическая проверка значения. C.4 — герметичный контейнерный e2e отдельным Go-модулем `test/e2e/` поверх поставляемого compose, гейт перед публикацией образа по тегу, нативная матрица amd64/arm64 вместо qemu в `release.yml`; делается **после** B.1–B.3, стендовые проверки B.1/B.3 переезжают в него регрессиями. Замыкает очередь **D.5** — предрелизная проверка на уязвимости моделью Fable по всему дифу от `v1.0.0` плюс повторный проход по ТЗ 7.6; вместе с e2e это гейт перед тегом. - **B.2 реализован** (не выкачен на прод): ротация `mail.log` ушла с `copytruncate` на «переименовать + `postfix reload`» `build/logrotate-mail.conf` (`nocreate` заменён на `create 0644 root root` **не по плану, а по стендовой проверке**: после reload Postfix пересоздаёт лог сам только в момент следующей фактической записи и с режимом `0600`, недоступным непривилегированной панели, — `create` в logrotate закрывает это, отдавая файл ей же на 644 сразу после переименования); `follow()` в `internal/logtail/logtail.go` при обнаружении смены inode дочитывает старый дескриптор ещё раз перед переключением; `readLogTail()` в `internal/web/handlers_monitor.go` считает отсутствующий файл пустым экраном, а не ошибкой. Проверено на стенде (`selfpost.mixfed.ru`, отдельный контейнер `selfpost:b2test2`): цикл трафик → принудительная ротация → файл пуст и сразу читаем непривилегированным uid панели (0 читает `mail.log` сразу после rename, без окна недоступности) → новый трафик после ротации уходит в новый файл на 644, ничего не потеряно по обе стороны rename. `go vet`/`go test ./...`/`gofmt -l .` чистые (на dev-сервере; локально на Windows `TestFollowTailsAndRotates` падает — rename открытого файла запрещён ОС, к делу не относится).
- **Решено, но ещё не реализовано:** пункты **B.3** и **C.4** плана, именно в этом порядке. B.3 — незаданный `SELFPOST_HOSTNAME` роняет контейнер в `entrypoint.sh` с развёрнутым текстом ошибки плюс синтаксическая проверка значения. C.4 — герметичный контейнерный e2e отдельным Go-модулем `test/e2e/` поверх поставляемого compose, гейт перед публикацией образа по тегу, нативная матрица amd64/arm64 вместо qemu в `release.yml`; делается **после** B.1–B.3, стендовые проверки B.1/B.3 переезжают в него регрессиями. Замыкает очередь **D.5** — предрелизная проверка на уязвимости моделью Fable по всему дифу от `v1.0.0` плюс повторный проход по ТЗ 7.6; вместе с e2e это гейт перед тегом.
- **Дальше — то, что перечислено в `implementation-plan.md`:** открытые вопросы закрыты, раздел E теперь только указатель на объём 2.x (входящий релей O1+ и роль администратора домена; 2FA снята с рассмотрения); остаются принятые риски безопасности (переехали в [security.md](security.md): `POST` без `Sec-Fetch-Site`/`Origin` пропускается, CSRF-токенов нет) и опциональная **Фаза O1+** (входящий релей, линия 2.x.x, требует согласования). - **Дальше — то, что перечислено в `implementation-plan.md`:** открытые вопросы закрыты, раздел E теперь только указатель на объём 2.x (входящий релей O1+ и роль администратора домена; 2FA снята с рассмотрения); остаются принятые риски безопасности (переехали в [security.md](security.md): `POST` без `Sec-Fetch-Site`/`Origin` пропускается, CSRF-токенов нет) и опциональная **Фаза O1+** (входящий релей, линия 2.x.x, требует согласования).
- **Прод:** `selfpost.mixfed.ru`, реальный Let's Encrypt сертификат, живой e2e (DKIM/SPF pass). Контейнер там всё ещё на образе v1.0 — Фаза 14 в него не выкатывалась. При апгрейде: админа один раз разлогинит (сменилось имя cookie), а от reverse-proxy требуется передача исходного `Host` (Apache-фрагмент из `deploy/` это делает). - **Прод:** `selfpost.mixfed.ru`, реальный Let's Encrypt сертификат, живой e2e (DKIM/SPF pass). Контейнер там всё ещё на образе v1.0 — Фаза 14 в него не выкатывалась. При апгрейде: админа один раз разлогинит (сменилось имя cookie), а от reverse-proxy требуется передача исходного `Host` (Apache-фрагмент из `deploy/` это делает).
+5 -2
View File
@@ -245,8 +245,11 @@ func follow(ctx context.Context, path string, handle func(string)) error {
} }
pos, _ := f.Seek(0, io.SeekCurrent) pos, _ := f.Seek(0, io.SeekCurrent)
if !os.SameFile(info, ni) || ni.Size() < pos { if !os.SameFile(info, ni) || ni.Size() < pos {
// Rotated away or truncated: reopen from the start of the new // Rotated away or truncated: the old (renamed) inode may have
// file. Any tail of the old file was already drained above. // gained lines between the drain() above and this check, since
// Postfix keeps writing to it until it reloads. Drain it once
// more before switching so nothing in that gap is lost.
drain()
if err := openAt(0, io.SeekStart); err != nil { if err := openAt(0, io.SeekStart); err != nil {
log.Printf("log-tailer: reopen %s: %v", path, err) log.Printf("log-tailer: reopen %s: %v", path, err)
} }
+8
View File
@@ -1,6 +1,8 @@
package web package web
import ( import (
"errors"
"io/fs"
"net/http" "net/http"
"strconv" "strconv"
@@ -164,6 +166,12 @@ func (s *Server) handleLogTailBody(w http.ResponseWriter, r *http.Request) {
func (s *Server) readLogTail() ([]string, string) { func (s *Server) readLogTail() ([]string, string) {
lines, err := logtail.TailLines(s.cfg.MailLogPath, logTailLines) lines, err := logtail.TailLines(s.cfg.MailLogPath, logTailLines)
if err != nil { if err != nil {
if errors.Is(err, fs.ErrNotExist) {
// Rotation renamed the file away; Postfix recreates it on reload
// (within about a second), so this is a normal, brief gap rather
// than a failure worth alarming the operator about.
return nil, ""
}
logf("panel: tail %s: %v", s.cfg.MailLogPath, err) logf("panel: tail %s: %v", s.cfg.MailLogPath, err)
return nil, "Could not read the mail log." return nil, "Could not read the mail log."
} }
+21
View File
@@ -0,0 +1,21 @@
package web
import (
"path/filepath"
"testing"
)
// After log rotation renames mail.log away, Postfix takes about a second to
// recreate it on reload (spec B.2); a missing file in that window is a normal,
// transient gap, not an operator-facing failure.
func TestReadLogTailMissingFileIsNotAnError(t *testing.T) {
s := &Server{cfg: Config{MailLogPath: filepath.Join(t.TempDir(), "mail.log")}}
lines, errText := s.readLogTail()
if lines != nil {
t.Errorf("lines = %v, want nil", lines)
}
if errText != "" {
t.Errorf("errText = %q, want empty (missing file is not an error)", errText)
}
}