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 <noreply@anthropic.com>
This commit is contained in:
+6
-1
@@ -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
|
- A **Delivery log** on each delivery's page (`/deliveries/{id}`): the
|
||||||
`mail.log` lines Postfix wrote about that message, oldest first — 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
|
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
|
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
|
(`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
|
matches only lines carrying this message's queue id, anchored so a shorter id
|
||||||
|
|||||||
@@ -280,6 +280,37 @@ func isQueueIDByte(b byte) bool {
|
|||||||
return b >= '0' && b <= '9' || b >= 'A' && b <= 'Z' || b >= 'a' && b <= 'z'
|
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
|
// 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
|
// 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
|
// start of a file that changed while the panel was down, or end-of-file on a
|
||||||
|
|||||||
@@ -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"))
|
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=<a@example.net>, status=sent (250 OK)",
|
||||||
|
stamp: "2026-08-03 05:15:52",
|
||||||
|
rest: "mail postfix/smtp[26]: 4A1B2C3D: to=<a@example.net>, 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=<a@example.net>, status=sent (250 OK)",
|
||||||
|
stamp: "",
|
||||||
|
rest: "mail postfix/smtp[26]: 4A1B2C3D: to=<a@example.net>, 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)
|
||||||
|
}
|
||||||
|
})
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|||||||
@@ -85,7 +85,7 @@ func (s *Server) handleDelivery(w http.ResponseWriter, r *http.Request) {
|
|||||||
return
|
return
|
||||||
}
|
}
|
||||||
row.Subject = mailhdr.DecodeSubject(row.Subject)
|
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{
|
s.render(w, http.StatusOK, "delivery", map[string]any{
|
||||||
"Title": "SelfPost — delivery",
|
"Title": "SelfPost — delivery",
|
||||||
"User": currentUser(r),
|
"User": currentUser(r),
|
||||||
@@ -97,8 +97,8 @@ func (s *Server) handleDelivery(w http.ResponseWriter, r *http.Request) {
|
|||||||
"Events": deliveryEvents(row),
|
"Events": deliveryEvents(row),
|
||||||
// The mail.log lines for this message, and — when there are none — the
|
// The mail.log lines for this message, and — when there are none — the
|
||||||
// reason, which is a normal outcome rather than a failure.
|
// reason, which is a normal outcome rather than a failure.
|
||||||
"LogLines": lines,
|
"LogRows": logRows,
|
||||||
"LogNote": logNote,
|
"LogNote": logNote,
|
||||||
// Where the row came from, so "Back" returns to the page and filters
|
// 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.
|
// the operator was looking at rather than the top of an unfiltered log.
|
||||||
"BackURL": deliveriesBackURL(r),
|
"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
|
// deliveryLogRow is one mail.log line split for the table on the delivery
|
||||||
// second return value is what to say when there are none: every reason for an
|
// page: when it was written, and what it says. Time is empty for a line whose
|
||||||
// empty result here is an ordinary one — the message never reached the queue,
|
// head is not a timestamp the log format recognises — the line still shows, in
|
||||||
// or its lines have aged out of the log — so none of them is an error on the
|
// full, under Message.
|
||||||
// page. Only a log that cannot be read at all is reported as a fault, and that
|
type deliveryLogRow struct {
|
||||||
// one is logged for the operator as well.
|
Time string
|
||||||
func (s *Server) deliveryLog(row store.SendLogRow) ([]string, 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 == "" {
|
if row.QueueID == "" {
|
||||||
return nil, "This message never reached the queue, so Postfix wrote no delivery lines for it."
|
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.
|
// 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 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
|
// deliveriesBackURL rebuilds the delivery-log URL a detail page was opened
|
||||||
|
|||||||
@@ -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
|
// 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
|
// 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) {
|
func TestDeliveryPageShowsThisMessagesLogLines(t *testing.T) {
|
||||||
s, row := serverWithDelivery(t)
|
s, row := serverWithDelivery(t)
|
||||||
s.cfg.MailLogPath = writeMailLog(t,
|
s.cfg.MailLogPath = writeMailLog(t,
|
||||||
"host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]",
|
"2026-08-03T05:15:52.219218+00:00 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]",
|
||||||
"host postfix/qmgr[10]: 99999999: from=<other@example.ru>, size=500, nrcpt=1 (queue active)",
|
"2026-08-03T05:15:52.300000+00:00 host postfix/qmgr[10]: 99999999: from=<other@example.ru>, size=500, nrcpt=1 (queue active)",
|
||||||
"host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>, dsn=2.0.0, status=sent (250 OK)",
|
"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)",
|
||||||
)
|
)
|
||||||
|
|
||||||
out := getBody(t, s.handleDelivery, "/deliveries/"+itoa(row.ID))
|
out := getBody(t, s.handleDelivery, "/deliveries/"+itoa(row.ID))
|
||||||
if !strings.Contains(out, "client=mail.example.com") || !strings.Contains(out, "status=sent (250 OK)") {
|
for _, want := range []string{
|
||||||
t.Errorf("delivery page does not show this message's log lines:\n%s", out)
|
"<th>Time</th>", "<th>Message</th>",
|
||||||
|
// The stamp is split off into its own cell, without the microseconds
|
||||||
|
// and the offset that make it the widest thing on the line.
|
||||||
|
`<td class="time muted">2026-08-03 05:15:52</td>`,
|
||||||
|
`<td class="time muted">2026-08-03 05:16:03</td>`,
|
||||||
|
"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") {
|
if strings.Contains(out, "99999999") {
|
||||||
t.Errorf("delivery page shows another message's log line:\n%s", out)
|
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=<public@example.ru>, 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
|
// 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.
|
// queue at all. Neither is a fault, so neither may render as an error.
|
||||||
func TestDeliveryPageExplainsAnEmptyDeliveryLog(t *testing.T) {
|
func TestDeliveryPageExplainsAnEmptyDeliveryLog(t *testing.T) {
|
||||||
|
|||||||
@@ -468,6 +468,22 @@ h1.subject { overflow-wrap: anywhere; }
|
|||||||
.event-time { margin: 0; font-size: 0.75rem; color: #6b7280; }
|
.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-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; }
|
.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
|
/* Compact outlined button: same affordance as the filled one but quiet enough
|
||||||
that several can sit together without shouting — the Copy buttons beside a
|
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
|
value, the controls of a table row or of an application block. Sign out
|
||||||
|
|||||||
@@ -98,9 +98,25 @@
|
|||||||
message's queue id are shown; the whole log is on the
|
message's queue id are shown; the whole log is on the
|
||||||
<a href="/system-log">System log</a> page.</p>
|
<a href="/system-log">System log</a> page.</p>
|
||||||
|
|
||||||
{{if .LogLines}}
|
{{if .LogRows}}
|
||||||
<span class="code">{{range .LogLines}}{{.}}
|
{{/* Two columns, the way the send log itself is a table: the times down one
|
||||||
{{end}}</span>
|
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. */}}
|
||||||
|
<table class="log">
|
||||||
|
<thead>
|
||||||
|
<tr><th>Time</th><th>Message</th></tr>
|
||||||
|
</thead>
|
||||||
|
<tbody>
|
||||||
|
{{range .LogRows}}
|
||||||
|
<tr>
|
||||||
|
<td class="time muted">{{if .Time}}{{.Time}}{{else}}—{{end}}</td>
|
||||||
|
<td class="log-text">{{.Text}}</td>
|
||||||
|
</tr>
|
||||||
|
{{end}}
|
||||||
|
</tbody>
|
||||||
|
</table>
|
||||||
{{else}}
|
{{else}}
|
||||||
<p class="muted">{{.LogNote}}</p>
|
<p class="muted">{{.LogNote}}</p>
|
||||||
{{end}}
|
{{end}}
|
||||||
|
|||||||
Reference in New Issue
Block a user