From 43841790d4df80329b07ef411058c677f1f4175a Mon Sep 17 00:00:00 2001 From: mixeme Date: Sat, 8 Aug 2026 10:22:29 +0300 Subject: [PATCH] feat(panel): lay a delivery's log lines out as a table MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The lines came out as one block of preformatted text, which is what the system log page does with a tail of mail.log — right there, where the lines are unrelated to each other and the block is the log itself. Here they are one message's six or seven lines, and what is read off them is the pace: the second between the connection and the banner, the ten between DATA and the reply. Run together, every line began with a different-width stamp and none of those numbers lined up. So they are two columns now, when and what, the same shape the send log itself has. logtail.SplitTimestamp takes the stamp off the head of a line: postlogd's format, which is what this server writes, and syslog's traditional one for a deployment that routes the log through syslogd instead. The stamp loses its microseconds and its offset — five decimal places are the widest part of the column and the least worth reading — but is not converted, so the page shows the log's own wall clock rather than a claim about which zone it was in. A line whose head is not a stamp either parser recognises keeps its whole text in the second column and leaves the first empty. The format is the log's, not ours; a line we cannot split is a line we must not drop, and the test says so. Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 7 ++- internal/logtail/logtail.go | 31 ++++++++++++++ internal/logtail/logtail_test.go | 61 +++++++++++++++++++++++++++ internal/web/handlers_monitor.go | 37 +++++++++++----- internal/web/handlers_monitor_test.go | 34 ++++++++++++--- internal/web/static/panel.css | 16 +++++++ internal/web/templates/delivery.html | 22 ++++++++-- 7 files changed, 187 insertions(+), 21 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index ef9a92c..d4c27d1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,7 +10,12 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version - A **Delivery log** on each delivery's page (`/deliveries/{id}`): the `mail.log` lines Postfix wrote about that message, oldest first — the connection to the receiving server, its reply, and the status that reply was - filed as. The queue id was printed on this page as something to go and search + filed as. It is a table of two columns, when and what, so the seconds between + the connection and the reply line up down one edge; the timestamp is the + log's own wall clock without its microseconds and offset, and a line whose + head is not a timestamp keeps its whole text under *Message* + (`logtail.SplitTimestamp`, which reads both postlogd's format and syslog's). + The queue id was printed on this page as something to go and search the system log for by hand; the search is done for the operator instead (`logtail.QueueLines`). The read is a bounded tail of the current log and matches only lines carrying this message's queue id, anchored so a shorter id diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index ebde67a..314efc3 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -280,6 +280,37 @@ func isQueueIDByte(b byte) bool { return b >= '0' && b <= '9' || b >= 'A' && b <= 'Z' || b >= 'a' && b <= 'z' } +// Timestamps at the head of a mail.log line. The first is what Postfix's own +// postlogd writes, which is what this server runs (maillog_file in +// build/postfix-config.sh) — RFC 3339 down to microseconds and with an offset. +// The second is syslog's traditional format, for a deployment that routes the +// log through syslogd instead; it carries no year and no zone, which is why it +// is not the one being matched first. +var ( + isoStampRe = regexp.MustCompile(`^(\d{4}-\d{2}-\d{2})T(\d{2}:\d{2}:\d{2})(?:\.\d+)?(?:Z|[+-]\d{2}:?\d{2})?\s`) + syslogStampRe = regexp.MustCompile(`^([A-Z][a-z]{2}\s+\d{1,2} \d{2}:\d{2}:\d{2})\s`) +) + +// SplitTimestamp separates the timestamp at the head of a mail.log line from +// the rest of it, so a page can put the two in their own columns. The stamp +// comes back without its fractional seconds and zone offset — five decimal +// places of microsecond are the widest part of the column and the least worth +// reading — but is otherwise the log's own wall clock, not converted: what is +// on the page is what is in the file. +// +// A line whose head is not a timestamp this recognises comes back whole, as +// rest, with an empty stamp. Nothing is ever dropped: the point of showing the +// log is that it says what it says. +func SplitTimestamp(line string) (stamp, rest string) { + if m := isoStampRe.FindStringSubmatch(line); m != nil { + return m[1] + " " + m[2], strings.TrimSpace(line[len(m[0]):]) + } + if m := syslogStampRe.FindStringSubmatch(line); m != nil { + return m[1], strings.TrimSpace(line[len(m[0]):]) + } + return "", line +} + // follow tails path line by line, calling handle for each complete line, until // 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 diff --git a/internal/logtail/logtail_test.go b/internal/logtail/logtail_test.go index 8325532..69eac1d 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -454,3 +454,64 @@ func TestQueueLinesReadsABoundedTail(t *testing.T) { t.Errorf("got %d lines, want only the one inside the budget:\n%s", len(lines), strings.Join(lines, "\n")) } } + +// The delivery page shows a message's lines as a table of when and what, so the +// timestamp has to come off the head of the line — in either of the two formats +// a mail log arrives in — and nothing may be lost doing it. +func TestSplitTimestamp(t *testing.T) { + cases := []struct { + name string + line string + stamp, rest string + }{ + { + name: "postlogd, which is what this server writes", + line: "2026-08-03T05:15:52.219218+00:00 mail postfix/smtp[26]: 4A1B2C3D: to=, status=sent (250 OK)", + stamp: "2026-08-03 05:15:52", + rest: "mail postfix/smtp[26]: 4A1B2C3D: to=, status=sent (250 OK)", + }, + { + name: "no fractional seconds, zone as Z", + line: "2026-08-03T05:15:52Z mail postfix/qmgr[10]: 4A1B2C3D: removed", + stamp: "2026-08-03 05:15:52", + rest: "mail postfix/qmgr[10]: 4A1B2C3D: removed", + }, + { + name: "no zone at all", + line: "2026-08-03T05:15:52 mail opendkim[30]: 4A1B2C3D: DKIM-Signature field added", + stamp: "2026-08-03 05:15:52", + rest: "mail opendkim[30]: 4A1B2C3D: DKIM-Signature field added", + }, + { + name: "syslog's traditional format, padded day", + line: "Aug 3 05:15:52 mail postfix/smtpd[20]: 4A1B2C3D: client=app.example.ru[203.0.113.4]", + stamp: "Aug 3 05:15:52", + rest: "mail postfix/smtpd[20]: 4A1B2C3D: client=app.example.ru[203.0.113.4]", + }, + { + name: "unrecognised head keeps the whole line", + line: "mail postfix/smtp[26]: 4A1B2C3D: to=, status=sent (250 OK)", + stamp: "", + rest: "mail postfix/smtp[26]: 4A1B2C3D: to=, status=sent (250 OK)", + }, + { + // A date-like run that is not the head of the line is not a stamp. + name: "date inside the text is left alone", + line: "mail postfix/smtp[26]: ABC: 220 mx.example.net ready at 2026-08-03T05:15:52+00:00", + stamp: "", + rest: "mail postfix/smtp[26]: ABC: 220 mx.example.net ready at 2026-08-03T05:15:52+00:00", + }, + } + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + stamp, rest := SplitTimestamp(c.line) + if stamp != c.stamp || rest != c.rest { + t.Errorf("SplitTimestamp(%q) = (%q, %q), want (%q, %q)", c.line, stamp, rest, c.stamp, c.rest) + } + // Whatever the split, the line's own text survives it whole. + if !strings.Contains(c.line, rest) { + t.Errorf("the text column is not part of the line it came from: %q", rest) + } + }) + } +} diff --git a/internal/web/handlers_monitor.go b/internal/web/handlers_monitor.go index c90b83d..ba1e808 100644 --- a/internal/web/handlers_monitor.go +++ b/internal/web/handlers_monitor.go @@ -85,7 +85,7 @@ func (s *Server) handleDelivery(w http.ResponseWriter, r *http.Request) { return } row.Subject = mailhdr.DecodeSubject(row.Subject) - lines, logNote := s.deliveryLog(row) + logRows, logNote := s.deliveryLog(row) s.render(w, http.StatusOK, "delivery", map[string]any{ "Title": "SelfPost — delivery", "User": currentUser(r), @@ -97,8 +97,8 @@ func (s *Server) handleDelivery(w http.ResponseWriter, r *http.Request) { "Events": deliveryEvents(row), // The mail.log lines for this message, and — when there are none — the // reason, which is a normal outcome rather than a failure. - "LogLines": lines, - "LogNote": logNote, + "LogRows": logRows, + "LogNote": logNote, // Where the row came from, so "Back" returns to the page and filters // the operator was looking at rather than the top of an unfiltered log. "BackURL": deliveriesBackURL(r), @@ -207,13 +207,23 @@ func deliveryEvents(row store.SendLogRow) []deliveryEvent { } } -// deliveryLog reads the mail.log lines Postfix wrote about one message. 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. -func (s *Server) deliveryLog(row store.SendLogRow) ([]string, string) { +// deliveryLogRow is one mail.log line split for the table on the delivery +// page: when it was written, and what it says. Time is empty for a line whose +// head is not a timestamp the log format recognises — the line still shows, in +// full, under Message. +type deliveryLogRow struct { + Time string + Text string +} + +// deliveryLog reads the mail.log lines Postfix wrote about one message and +// splits each into the two columns 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. +func (s *Server) deliveryLog(row store.SendLogRow) ([]deliveryLogRow, string) { if row.QueueID == "" { return nil, "This message never reached the queue, so Postfix wrote no delivery lines for it." } @@ -228,7 +238,12 @@ func (s *Server) deliveryLog(row store.SendLogRow) ([]string, string) { // left to show is the normal end state, not a fault. return nil, "Nothing for this queue id in the current mail log. Its lines have most likely been rotated away." } - return lines, "" + out := make([]deliveryLogRow, len(lines)) + for i, line := range lines { + stamp, rest := logtail.SplitTimestamp(line) + out[i] = deliveryLogRow{Time: stamp, Text: rest} + } + return out, "" } // deliveriesBackURL rebuilds the delivery-log URL a detail page was opened diff --git a/internal/web/handlers_monitor_test.go b/internal/web/handlers_monitor_test.go index ccd1c27..ec8d01b 100644 --- a/internal/web/handlers_monitor_test.go +++ b/internal/web/handlers_monitor_test.go @@ -143,24 +143,46 @@ func TestDeliveryPageMarksAQueuedMessageAsStillWaiting(t *testing.T) { // The queue id used to be printed as something to go and search the system log // for by hand; the page does that search now, and shows only this message's -// lines. +// lines — as a table of when and what, so the seconds between the connection +// and the reply line up down one edge. func TestDeliveryPageShowsThisMessagesLogLines(t *testing.T) { s, row := serverWithDelivery(t) s.cfg.MailLogPath = writeMailLog(t, - "host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]", - "host postfix/qmgr[10]: 99999999: from=, size=500, nrcpt=1 (queue active)", - "host postfix/smtp[26]: 4A1B2C3D: to=, dsn=2.0.0, status=sent (250 OK)", + "2026-08-03T05:15:52.219218+00:00 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]", + "2026-08-03T05:15:52.300000+00:00 host postfix/qmgr[10]: 99999999: from=, size=500, nrcpt=1 (queue active)", + "2026-08-03T05:16:03.884210+00:00 host postfix/smtp[26]: 4A1B2C3D: to=, dsn=2.0.0, status=sent (250 OK)", ) out := getBody(t, s.handleDelivery, "/deliveries/"+itoa(row.ID)) - if !strings.Contains(out, "client=mail.example.com") || !strings.Contains(out, "status=sent (250 OK)") { - t.Errorf("delivery page does not show this message's log lines:\n%s", out) + for _, want := range []string{ + "Time", "Message", + // The stamp is split off into its own cell, without the microseconds + // and the offset that make it the widest thing on the line. + `2026-08-03 05:15:52`, + `2026-08-03 05:16:03`, + "client=mail.example.com", "status=sent (250 OK)", + } { + if !strings.Contains(out, want) { + t.Errorf("delivery log table is missing %q:\n%s", want, out) + } } if strings.Contains(out, "99999999") { t.Errorf("delivery page shows another message's log line:\n%s", out) } } +// A line whose head is not a timestamp still has to show in full; the format is +// the log's, not ours, and a line we cannot split is a line we must not drop. +func TestDeliveryPageKeepsAnUnstampedLogLineWhole(t *testing.T) { + s, row := serverWithDelivery(t) + s.cfg.MailLogPath = writeMailLog(t, "host postfix/smtp[26]: 4A1B2C3D: to=, status=sent (250 OK)") + + out := getBody(t, s.handleDelivery, "/deliveries/"+itoa(row.ID)) + if !strings.Contains(out, "host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>, status=sent (250 OK)") { + t.Errorf("an unstamped log line did not survive the split into columns:\n%s", out) + } +} + // 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. func TestDeliveryPageExplainsAnEmptyDeliveryLog(t *testing.T) { diff --git a/internal/web/static/panel.css b/internal/web/static/panel.css index 8448a36..bddd573 100644 --- a/internal/web/static/panel.css +++ b/internal/web/static/panel.css @@ -468,6 +468,22 @@ h1.subject { overflow-wrap: anywhere; } .event-time { margin: 0; font-size: 0.75rem; color: #6b7280; } .event-title { display: flex; flex-wrap: wrap; align-items: center; gap: 0.4rem; margin: 0.15rem 0 0; font-weight: 600; } .event-detail { margin: 0.2rem 0 0; font-size: 0.9rem; } +/* A message's own mail.log lines, as a table of when and what. The time column + is sized to its content — width:1% is as narrow as the automatic layout will + take a column, which with the nowrap on td.time settles on exactly the stamp + — so everything left over goes to the text, which is the column that needs + it. */ +table.log { margin-top: 1rem; } +table.log th:first-child, table.log td.time { width: 1%; } +/* The log's own text: monospace, because it is full of addresses, response + codes and identifiers that are compared character by character rather than + read as words. pre-wrap keeps the spacing a server's reply was written with + while still letting a long line wrap inside the cell instead of widening it + (the th/td rule above allows the break). */ +table.log td.log-text { + font-family: ui-monospace, SFMono-Regular, Menlo, monospace; + font-size: 0.8rem; white-space: pre-wrap; +} /* Compact outlined button: same affordance as the filled one but quiet enough that several can sit together without shouting — the Copy buttons beside a value, the controls of a table row or of an application block. Sign out diff --git a/internal/web/templates/delivery.html b/internal/web/templates/delivery.html index 1796b13..f03fccb 100644 --- a/internal/web/templates/delivery.html +++ b/internal/web/templates/delivery.html @@ -98,9 +98,25 @@ message's queue id are shown; the whole log is on the System log page.

- {{if .LogLines}} - {{range .LogLines}}{{.}} -{{end}} + {{if .LogRows}} + {{/* Two columns, the way the send log itself is a table: the times down one + edge are what the message's pace is read off — the seconds between the + connection and the reply — and lining them up is what makes that + readable. A line whose head was not a timestamp keeps its whole text in + the second column and leaves the first empty. */}} + + + + + + {{range .LogRows}} + + + + + {{end}} + +
TimeMessage
{{if .Time}}{{.Time}}{{else}}—{{end}}{{.Text}}
{{else}}

{{.LogNote}}

{{end}}