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}}