diff --git a/CHANGELOG.md b/CHANGELOG.md index 759fbe9..6137f52 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -17,8 +17,19 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version the tailer reads it; after an unclean stop a line read twice is stored once. Lines whose queue id has no send-log row - the row was pruned, or the message never had one (inbound relay mail, bounces) - are deleted once they - are an hour old, with every send-log sweep and hourly between. No page reads - them yet. + are an hour old, with every send-log sweep and hourly between. + +### Changed + +- **A message's page keeps its delivery log after `mail.log` rotates.** The + *Delivery log* box on Outbound › Log › a message was filled by searching + the current `mail.log`, which is rotated daily, so it was empty for anything + not sent today while the row itself lives for ninety days. The page now + reads the lines the tailer stored: they are there for as long as the row + is. Postfix reuses queue ids, so a row is given only the lines dated within + its own queue lifetime. A message accepted before this version shows its + lines only while they are still in the current file, as before; the note + shown when there are none and the *Outbound log* help topic say so. ## [2.1.0] - 2026-10-12 diff --git a/docs/plans/delivery-log-storage.md b/docs/plans/delivery-log-storage.md index 0505e0b..ce0c690 100644 --- a/docs/plans/delivery-log-storage.md +++ b/docs/plans/delivery-log-storage.md @@ -145,7 +145,7 @@ Target version cut: **`2.2.0`** (MINOR). One commit per step; - [x] Migration `0003_send_log_lines.sql`, store methods (insert, insert once, lines of a row, prune) and their tests — **Opus** - [x] Log tailer: store queue-id lines, write once while catching up, prune with the send-log sweep and hourly — **Opus** - [x] The two texts, mockup first: the *Outbound log* help topic and the empty note (`design:` commit) — **Opus** (the help topic is in the mockups; the empty note is not drawn there - the `out-message` mockup shows a message with lines - and changes with the page) -- [ ] Message page reads the table, falls back to the current `mail.log`; help text in `help.go` — **Opus** +- [x] Message page reads the table, falls back to the current `mail.log`; help text in `help.go` — **Opus** - [ ] [architecture.md](../architecture.md), [guide.md](../guide.md), [schema-migrations.md](../schema-migrations.md) — **Opus** - [ ] `go vet`, `go test`, e2e: a message's page still lists its lines after a forced rotation — **Opus** - [ ] Technical review — **Opus** diff --git a/docs/roadmap.md b/docs/roadmap.md index 81978ae..303d506 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -36,7 +36,7 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md). | structured-logging | `log/slog` with levels and fields | candidate | — | — | | review-2026-08-followups | Remaining findings of the 2026-08-19 code review | candidate | — | — | | panel-notifications | E-mail notifications about important events | candidate | — | — | -| delivery-log-storage | Keep a message's `mail.log` lines with its send-log row | in progress | 3/8 | [plans/delivery-log-storage.md](plans/delivery-log-storage.md) | +| delivery-log-storage | Keep a message's `mail.log` lines with its send-log row | in progress | 4/8 | [plans/delivery-log-storage.md](plans/delivery-log-storage.md) | | password-reset | Password reset by e-mail | candidate | — | — | | phone-desktop-mode | A phone browser in "desktop site" mode gets the phone navigation | candidate | — | — | | panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) | diff --git a/internal/postfix/retry.go b/internal/postfix/retry.go index 662ace4..7354518 100644 --- a/internal/postfix/retry.go +++ b/internal/postfix/retry.go @@ -129,6 +129,16 @@ func (p RetryPolicy) BackoffCap() string { return FormatDuration(p.MaximalBackoff) } +// LongestLifetime is how long Postfix may go on working on a message: the +// larger of the queue lifetime for mail and for the bounces it generates. It +// bounds which stored log lines can be about a send-log row (store.SendLogLines). +func (p RetryPolicy) LongestLifetime() time.Duration { + if p.BounceQueueLifetime > p.MaximalQueueLifetime { + return p.BounceQueueLifetime + } + return p.MaximalQueueLifetime +} + // QueueLifetime is the human string for maximal_queue_lifetime. func (p RetryPolicy) QueueLifetime() string { return FormatDuration(p.MaximalQueueLifetime) diff --git a/internal/web/handlers/handlers_monitor.go b/internal/web/handlers/handlers_monitor.go index 5d68b66..05de697 100644 --- a/internal/web/handlers/handlers_monitor.go +++ b/internal/web/handlers/handlers_monitor.go @@ -183,25 +183,46 @@ func deliveryEvents(row store.SendLogRow, policy postfix.RetryPolicy) []view.Ste } } -// deliveryLog reads the mail.log lines Postfix wrote about one message and -// splits each into the time and the text the page shows it in. The second -// return value is what to say when there are none: every reason for an empty -// result here is an ordinary one — the message never reached the queue, or its -// lines have aged out of the log — so none of them is an error on the page. Only -// a log that cannot be read at all is reported as a fault, and that one is -// logged for the operator as well. +// deliveryLogMargin is added to the queue lifetime when asking which stored +// lines are a row's: Postfix expires a message on a queue run after the +// lifetime has passed, not at the second it does, and logs the bounce after +// that. +const deliveryLogMargin = 24 * time.Hour + +// deliveryLog returns the mail.log lines Postfix wrote about one message, each +// split into the time and the text the page shows it in. They come from the +// database, where the log tailer keeps them for as long as the row lives +// (architecture.md § Log tailer). A row with none stored is searched for in +// the current mail.log, as every row was before 2.2.0: that is what shows a +// message accepted before the lines were kept. +// +// The second return value is what to say when there are none: every reason for +// an empty result here is an ordinary one — the message never reached the +// queue, or it predates the stored lines and the log has rotated — so none of +// them is an error on the page. Only lines that cannot be read at all are +// reported as a fault, and that one is logged for the operator as well. func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) { if row.QueueID == "" { return nil, "This message never reached the queue, so Postfix wrote no delivery lines for it." } - lines, err := logtail.QueueLines(h.cfg.MailLogPath, row.QueueID, deliveryLogLines) - if err != nil && !errors.Is(err, fs.ErrNotExist) { + stored, err := h.store.SendLogLines(row, h.cfg.RetryPolicy.LongestLifetime()+deliveryLogMargin, deliveryLogLines) + if err != nil { logf("panel: delivery log %s: %v", row.QueueID, err) - return nil, "Could not read the mail log." + return nil, "Could not read the stored delivery log." + } + lines := make([]string, len(stored)) + for i, l := range stored { + lines[i] = l.Line } if len(lines) == 0 { - days := h.sendLogRetentionDays() - return nil, fmt.Sprintf("Nothing for this queue id in the current mail log. Its lines have most likely been rotated away (send-log rows are kept for %d days).", days) + lines, err = logtail.QueueLines(h.cfg.MailLogPath, row.QueueID, deliveryLogLines) + if err != nil && !errors.Is(err, fs.ErrNotExist) { + logf("panel: delivery log %s: %v", row.QueueID, err) + return nil, "Could not read the mail log." + } + } + if len(lines) == 0 { + return nil, "Nothing is stored for this queue id and nothing is in the current mail log. Lines are kept with the row since version 2.2.0; a message accepted before that had them only in mail.log, which has since rotated." } out := make([]view.LogLine, len(lines)) for i, line := range lines { diff --git a/internal/web/handlers/handlers_monitor_test.go b/internal/web/handlers/handlers_monitor_test.go index 0a390c6..5aa40bc 100644 --- a/internal/web/handlers/handlers_monitor_test.go +++ b/internal/web/handlers/handlers_monitor_test.go @@ -188,23 +188,53 @@ func TestDeliveryPageKeepsAnUnstampedLogLineWhole(t *testing.T) { } } -// Rows outlive mail.log, and a message the milter refused never reached the -// queue at all. Neither is a fault, so neither may render as an error. +// The lines are kept in the database as the tailer reads them, so a message's +// page shows them when mail.log no longer holds any - the ordinary case for +// anything sent before the last daily rotation, and the reason they are kept. +// Only this message's lines: another queue id's are not, nor those of an +// earlier message that had the same queue id. +func TestDeliveryPageShowsStoredLogLinesAfterRotation(t *testing.T) { + h, row := serverWithDelivery(t) + h.cfg.RetryPolicy = postfix.DefaultRetryPolicy() + h.cfg.MailLogPath = writeMailLog(t, "2026-08-04T00:00:01.000000+00:00 host postfix/qmgr[10]: 99999999: removed") + for _, l := range []store.SendLogLine{ + {QueueID: row.QueueID, At: row.CreatedAt.AddDate(0, 0, -40), Line: "2026-06-24T05:00:00.000000+00:00 host postfix/qmgr[10]: 4A1B2C3D: an earlier message under the same id"}, + {QueueID: row.QueueID, At: row.CreatedAt.Add(-time.Second), Line: "2026-08-03T05:15:52.219218+00:00 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]"}, + {QueueID: "99999999", At: row.CreatedAt, Line: "2026-08-03T05:15:52.300000+00:00 host postfix/qmgr[10]: 99999999: from=, size=500, nrcpt=1 (queue active)"}, + {QueueID: row.QueueID, At: row.CreatedAt.Add(11 * time.Second), Line: "2026-08-03T05:16:03.884210+00:00 host postfix/smtp[26]: 4A1B2C3D: to=, dsn=2.0.0, status=sent (250 OK)"}, + } { + if err := h.store.InsertSendLogLine(l); err != nil { + t.Fatalf("InsertSendLogLine: %v", err) + } + } + + out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID)) + for _, want := range []string{ + `2026-08-03 05:15:52 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`, + `2026-08-03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>`, + } { + if !strings.Contains(out, want) { + t.Errorf("delivery log is missing %q:\n%s", want, out) + } + } + for _, not := range []string{"99999999", "an earlier message"} { + if strings.Contains(out, not) { + t.Errorf("delivery page shows a line that is not this message's (%q):\n%s", not, out) + } + } +} + +// A message accepted before the lines were kept has them only in mail.log, and +// a message the milter refused never reached the queue at all. Neither is a +// fault, so neither may render as an error. func TestDeliveryPageExplainsAnEmptyDeliveryLog(t *testing.T) { h, row := serverWithDelivery(t) - h.cfg.SendLogRetentionEnvDefault = 60 - if err := h.store.SetSendLogRetentionDays(60); err != nil { - t.Fatalf("SetSendLogRetentionDays: %v", err) - } h.cfg.MailLogPath = filepath.Join(t.TempDir(), "mail.log") // never created out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID)) - if !strings.Contains(out, "rotated away") { + if !strings.Contains(out, "Nothing is stored for this queue id") || !strings.Contains(out, "since version 2.2.0") { t.Errorf("delivery page does not explain the empty delivery log:\n%s", out) } - if !strings.Contains(out, "kept for 60 days") { - t.Errorf("delivery page does not show configured retention:\n%s", out) - } if strings.Contains(out, `class="error"`) || strings.Contains(out, "Could not read the mail log") { t.Errorf("an aged-out delivery log is reported as a failure:\n%s", out) } diff --git a/internal/web/view/help.go b/internal/web/view/help.go index a0d121c..03d7615 100644 --- a/internal/web/view/help.go +++ b/internal/web/view/help.go @@ -162,7 +162,7 @@ var outboundTopics = []HelpTopic{ }}, {ID: HelpLog, Title: "Outbound log", Body: []Text{ Rich("One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out) and rejected (refused before queueing under a level-2 rate limit, so it never reached Postfix). A message's page lists these steps and the lines Postfix wrote about it in ", - Code("mail.log"), ", found by queue id; that file is rotated daily and about two weeks are kept, so an old message may show none. Rows are deleted after the retention set in Server › Settings, 90 days by default. A domain administrator sees only the rows of their own domains."), + Code("mail.log"), ", found by queue id. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains."), }}, {ID: HelpQueue, Title: "Queue and retries", Body: []Text{ Rich("The page lists, as ", Code("postqueue -p"), " prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged."), diff --git a/internal/web/view/outbound_log.go b/internal/web/view/outbound_log.go index bab4fea..80ceb7b 100644 --- a/internal/web/view/outbound_log.go +++ b/internal/web/view/outbound_log.go @@ -189,7 +189,7 @@ type OutMessage struct { Delivery Box LogLines []LogLine // LogEmpty says why there are no lines: a message that never reached the - // queue, or whose lines have been rotated away, is an ordinary outcome. + // queue, or that predates the stored lines, is an ordinary outcome. LogEmpty EmptyState }