From a59e3d4d6186c29cd2818bbf01a74da2992d1b5c Mon Sep 17 00:00:00 2001 From: Mix Date: Wed, 14 Oct 2026 14:42:02 +0300 Subject: [PATCH] docs: stage 1 of the audit - log tailer, reconcile, sender check, guide MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit architecture.md - § Log tailer: the rotation drain does not close the gap entirely (postlogd writes to the renamed file until the reload reaches it); the fix waits for the measurement. Delivery lines read at the head of the line (M12). - § Queue reconcile: reason "reconcile", the 4 MiB cap, the conditional close; the measurement (delivery_log_days, its four counters) and the decision rule written before the data. - § Sender check, what it costs: cleanup meets a check that hangs mid-message, with the warning seen on the stand; counted once per message. guide.md - § Outbound log: `bounced` is the panel's word when Postfix no longer holds a message and the log never said; it is counted. - § Overview and Health, Sender check: the message a hung panel deferred is counted too. Audit plan line ticked, roadmap 14/61. Stage 1's code items are done (the two deferred tailer fixes wait for the data, as planned). Co-Authored-By: Claude Opus 5.5 --- docs/architecture.md | 56 +++++++++++++++++++++++++++++++++------- docs/audit-2026-10-12.md | 2 +- docs/guide.md | 10 +++++-- docs/roadmap.md | 2 +- 4 files changed, 57 insertions(+), 13 deletions(-) diff --git a/docs/architecture.md b/docs/architecture.md index c717212..9eb5285 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -284,7 +284,14 @@ server itself. (the client is told `454 4.3.0` at `AUTH` and leaves), so what is counted is a connection turned away, once - a client brings a message when it connects. The reject line does not name the milter and the journal milter's - level-2 refusal reads the same, hence the warning. Both go into + level-2 refusal reads the same, hence the warning. A panel that is running + and stops answering in the middle of a message (its socket accepts, nothing + replies) is met by cleanup, not smtpd: past `DATA` it is cleanup that talks + to the milters, and after the content timeout it writes `warning: milter + unix:: can't read SMFIC_HEADER reply packet header` and refuses the + message with `4.7.1` (seen on the e2e stand with the panel frozen). One + cleanup process serves message after message, so each such warning is + counted as a message. Both go into `sender_check_days`, a row per UTC day kept a year, and Server › Health shows today, 30 days and 12 months. The second figure also sees a panel that is running and not @@ -375,7 +382,18 @@ the latter can drop `status=sent` lines and leave send-log rows stuck at 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 -an error. +an error. That drain does not close the gap entirely: postlogd keeps writing to +the renamed file until the reload reaches it, seconds later, and a line written +there after the drain is not read. Keeping the old file open until it has +stopped growing is the fix; it waits for the measurement below to say how +much it matters. + +**Delivery lines are read at the head of the line.** The pattern that turns a +line into a row's status (`deliveryRe`) is matched after the timestamp, the +host name and `program[pid]:`, at the queue id - like the stored lines' and the +inbound journal's. The tail of a line is the far end's words (a reply, a HELO +name), and a pattern that could start there let a stranger's HELO name file a +delivery (audit 2026-10-12, M12). **Read offset is persisted** (`logtail_state` table, in the baseline schema): the tailer stores its position plus a fingerprint of the log's first 512 bytes, and @@ -388,18 +406,38 @@ replay a pre-existing log. **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, +`postqueue -p` no longer lists, is marked `bounced` with the reason +`reconcile` (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 +panel cannot evidence must not be shown as one. What keeps 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. +end-of-file once (on a restart the log itself holds the answer); the two-minute +grace covers messages merely in flight; a `postqueue` that cannot be read, or +whose listing is over the 4 MiB cap, leaves every row untouched rather than +closing them all or those past the cut; and the close is conditional on the +row still being `queued`, so a status the log wrote in the meantime stands. +Now that the log survives the container, reaching this path should mean the +lines are gone for good — rotated past fourteen files while the panel was down, +or deleted — or that the tailer was not reading. + +Whether the sweep earns its place is measured, not argued (audit 2026-10-12, +H3). `delivery_log_days` (migration `0007`) keeps, per UTC day for a year: +`reconcile_closed`, the rows the sweep closed; `reconcile_contradicted`, those +of them a delivery line later spoke of - the log's status replaces the sweep's +and the reason is cleared, so a row counts once; `tailer_blind_seconds`, the +time `follow()` could not read `mail.log` (the file gone, reopening it failing; +stretches under three seconds - a rotation's tick between rename and create, +which loses nothing - are not counted); and `queued_over_lifetime`, the rows +still `queued` past the queue lifetime plus a maximal backoff, as the day's +last sweep saw them. No page shows the table: it is read off a copy of the +database. The rule, written before the data: `reconcile_closed = 0` for a month +→ remove the sweep; closed but never contradicted → keep it; contradicted → +each case explained by blind time means fix the tailer and keep the sweep, +otherwise mark such rows `lost` or remove the sweep. Decided after thirty days, +or sooner if `reconcile_contradicted` is ever non-zero. **Stored lines** (`send_log_lines`, since 2.2.0; [internal/logtail/lines.go](../internal/logtail/lines.go)). A send-log row diff --git a/docs/audit-2026-10-12.md b/docs/audit-2026-10-12.md index 9220892..a157f6d 100644 --- a/docs/audit-2026-10-12.md +++ b/docs/audit-2026-10-12.md @@ -636,7 +636,7 @@ has already run is never edited — the next file is added; the published - [x] **Deferred counter** (M13): on the stand, `kill -STOP` the panel mid-message and record which program logs the warning; widen the matcher accordingly and replace the composed fixture with the seen lines. — **Opus** -- [ ] Docs: architecture § Log tailer, § Queue reconcile (the measurement and +- [x] Docs: architecture § Log tailer, § Queue reconcile (the measurement and the rule), § Sender check "what it costs"; guide § Delivery log, § Health. — **Sonnet** diff --git a/docs/guide.md b/docs/guide.md index 3973331..b28a2e9 100644 --- a/docs/guide.md +++ b/docs/guide.md @@ -410,7 +410,8 @@ readings, in the order of what stops mail first: not counted: mail was stopped for another reason then. What is counted as a message is a connection Postfix turned away - it refuses before a message is offered - so a monitor that only connects during an outage is - counted too. Days are UTC days. The card warns when + counted too; and when the panel hangs instead of stopping, the message it + hung on. Days are UTC days. The card warns when a message was deferred in the last 24 hours. If these numbers do not stay at nothing, the panel is in the way of your mail more than it should be - report it. @@ -1257,7 +1258,12 @@ rows of their domains. It refreshes its rows without resetting a filter being chosen. A row identifies its message and nothing more — time, sender, recipient, subject and status `queued` (accepted, not yet delivered), `sent` (handed off successfully), `deferred` (Postfix is -retrying), `bounced` (final failure), or refused before it was queued. A +retrying), `bounced` (final failure), or refused before it was queued. +`bounced` is usually Postfix's word; it is the panel's when Postfix no longer +holds a message and `mail.log` never said what became of it (the log rotated +away while the panel was down, or was not readable) - the panel then closes +the row as a failure rather than show a delivery it cannot evidence, and +counts that it did. A refused row says why in its tag: `rate-limited` (a [level-2 rate limit](#rate-limiting--level-2-domain-and-application)), `wrong client` (the application's client IP list) or `wrong From` (see [Who an application may diff --git a/docs/roadmap.md b/docs/roadmap.md index 3df32bf..435b3e8 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -42,7 +42,7 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md). | from-header-binding | Hold a message's `From:` header against the application that sends it | shipped `2.4.0` | 9/9 | [plans/from-header-binding.md](plans/from-header-binding.md) | | panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) | | schema-squash | Squash SQLite migrations into a 2.x baseline | built in panel-redesign (stage 1) | — | [plans/panel-redesign.md](plans/panel-redesign.md) | -| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`; next stages 1+2 → `2.5.0`) | 13/61 | [audit-2026-10-12.md](audit-2026-10-12.md) | +| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`; next stages 1+2 → `2.5.0`) | 14/61 | [audit-2026-10-12.md](audit-2026-10-12.md) | **Recommended order** (not binding; owner, 2026-10-09: feature order follows development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and