delivery-log-storage: a message's page reads its stored lines

The Delivery log box on a message's page was filled by searching the current mail.log on every view; that file is rotated daily, so the box was empty for anything not sent today. deliveryLog now asks the store for the row's lines - its queue id, dated within the row's queue lifetime plus a day (RetryPolicy.LongestLifetime) - and shows the latest 200, oldest first. When nothing is stored the page still searches the current file, which is what shows a message accepted before 2.2.0. When that finds nothing either, the note no longer blames rotation for the ordinary case: it says lines are kept with the row since 2.2.0. The Outbound log help topic in help.go follows the mockup changed in fc184ec, word for word. Checked on Windows: go vet clean; go test ./internal/web/... ./internal/postfix ./internal/store pass, the guards among them. New test: lines shown from the table when mail.log holds none of them, without another queue id's lines and without those of an earlier message under the same id. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-12 10:15:26 +03:00
parent fc184ecc01
commit 1e6836b3c1
8 changed files with 100 additions and 28 deletions
@@ -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)
@@ -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 {
@@ -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=<other@example.ru>, 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=<public@example.ru>, 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{
+		`<span class="sp-d">2026-08-03 05:15:52</span> host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`,
+		`<span class="sp-d">2026-08-03 05:16:03</span> host postfix/smtp[26]: 4A1B2C3D: to=&lt;public@example.ru&gt;`,
+	} {
+		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)
 	}
@@ -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."),
@@ -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
 }