diff --git a/CHANGELOG.md b/CHANGELOG.md index 8d68825..b7d9e43 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,36 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version ## [Unreleased] +### Added + +- 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 + 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 + is not found inside a longer one. Send-log rows outlive `mail.log` — retention + is ninety days, rotation keeps fourteen files — so a message with no lines + left says so rather than reporting a failure. +- A **History** block on the same page: the journal's two timestamps stated as + the steps they stand for — accepted and queued, then delivered, deferred, + bounced, or refused before queueing — each with the status it reached in the + panel's own ok/warn/error/unknown badge vocabulary. A message still queued + shows the delivery report it is waiting for as a step that has not happened. + +### Changed + +- The delivery page is laid out in two columns: what the journal recorded on + the left, what happened to the message on the right, and the delivery log at + full width under both. The facts the page used to stack one per line — domain, + application, queue id, journal id and the two timestamps — are a grid of tiles + instead, since a page of mostly empty rows was what the full-width stack came + to for six short values. The subject heads the page and the sender, recipient + and outcome are the line under it, so what the message was and how it ended + are both on the first line. The page takes the whole column rather than the + reading measure, as the other three monitoring pages already did. + ## [0.6.0] - 2026-08-08 ### Added diff --git a/README.md b/README.md index cf2c50b..63a69a4 100644 --- a/README.md +++ b/README.md @@ -213,9 +213,13 @@ service healthy and will mail be accepted?" time, sender, recipient, subject and status `queued` (accepted, not yet delivered), `sent` (handed off successfully), or `rejected` (refused — for example by a level-2 rate limit); *Details* opens that row's own page - (`/deliveries/{id}`) with the sending domain, the application it was - submitted under, the Postfix queue id to search the system log for, and when - the status was last reported. Retention is controlled by + (`/deliveries/{id}`). That page carries the sending domain, the application it + was submitted under, the Postfix queue id and the journal id, beside the + message's history — when it was accepted and what Postfix later reported for + the recipient — and, under both, the `mail.log` lines for its queue id: the + connection to the receiving server, the server's reply, and the status that + reply was filed as. Rows outlive `mail.log`, so an older message's lines may + have rotated away; the page says so. Retention is controlled by `SEND_LOG_RETENTION_DAYS`. - **Mail queue** (`/mail-queue`) — live view of messages Postfix is still trying to deliver or deferring. diff --git a/docs/architecture.md b/docs/architecture.md index 5e2bfce..96f88c7 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -121,6 +121,16 @@ replay a pre-existing log. Possible follow-ups if this becomes painful: mount the mail log under `/data`, or reconcile stuck rows via `postqueue`. +**Two one-shot reads** sit beside the follow loop and are unrelated to it, both +serving panel pages on request: `TailLines` (the last *n* lines, for +`/system-log`) and `QueueLines` (the lines carrying one queue-id, for +`/deliveries/{id}`). `QueueLines` scans a bounded tail of the current file — +finding a message's lines means reading rather than seeking — and matches the id +anchored on the character before it, since queue ids are hexadecimal runs and a +shorter one is regularly the tail of a longer one. Send-log rows outlive the log +(retention 90 days, rotation 14 files), so an empty result is the expected end +state for an older message and the page reports it as such, not as a failure. + --- ## Panel HTTP surface @@ -136,7 +146,7 @@ unless noted. | `/status` | Process, cert, socket, PTR checks; machine CPU/memory/network | | `/domains`, `/domains/*` | Domain and application CRUD, DKIM, L2 limits | | `/deliveries` | Send log with filters | -| `/deliveries/{id}` | One send-log row in full | +| `/deliveries/{id}` | One send-log row in full, with its `mail.log` lines | | `/mail-queue` | Postfix queue view | | `/system-log` | `mail.log` tail | | `/reload` | Reload OpenDKIM + Postfix maps | diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index 77590e8..ebde67a 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -176,6 +176,110 @@ func TailLines(path string, n int) ([]string, error) { return lines, nil } +// queueScanBytes bounds how far back QueueLines reads. A message's own lines +// are a handful, but they are scattered through everything else the mail path +// logged around them, so finding them means reading rather than seeking. The +// budget is what keeps that read bounded on a log that has grown for a day: +// beyond it the answer is "not in the part of the log still on disk", which is +// the same answer rotation gives and is reported the same way. It is a var so +// tests can shrink it, the way pollInterval above is. +var queueScanBytes int64 = 4 << 20 + +// QueueLines returns the mail.log lines Postfix wrote about one queue id, +// oldest first and at most n of them, for a single delivery's page +// (architecture.md § Panel HTTP surface). It reads the tail of the log the way +// TailLines does — one-shot, on request, unrelated to the follow loop above — +// but keeps only the lines belonging to this message instead of the last n of +// everything. +// +// A message older than the tail scanned, or older than the current log file, +// comes back empty rather than as an error: send-log rows outlive mail.log +// (retention is ninety days by default, rotation keeps fourteen files), so a +// row with nothing left to show for it is expected. +func QueueLines(path, queueID string, n int) ([]string, error) { + // No queue-id, no lines: a message the milter refused was never queued, so + // there is nothing to match on and every line would be someone else's. + if queueID == "" || n <= 0 { + return nil, nil + } + + f, err := os.Open(path) + if err != nil { + return nil, err + } + defer f.Close() + + info, err := f.Stat() + if err != nil { + return nil, err + } + + // Forward from the start of the budget rather than backwards in chunks: + // the lines are wanted oldest first, and the whole budget is read either + // way, so reading it in order costs nothing and keeps them in order. + start := info.Size() - queueScanBytes + if start < 0 { + start = 0 + } + if _, err := f.Seek(start, io.SeekStart); err != nil { + return nil, err + } + + sc := bufio.NewScanner(f) + // A Postfix line carrying a long remote reply can pass the scanner's default + // 64KB token; without a bigger ceiling that one line would end the scan and + // silently truncate the answer. + sc.Buffer(make([]byte, 0, 64*1024), 1<<20) + // Reading into the middle of the file lands mid-line; that fragment is + // dropped rather than reported as a line of its own. + if start > 0 && sc.Scan() { + _ = sc.Text() + } + + var lines []string + for sc.Scan() { + line := sc.Text() + if !mentionsQueueID(line, queueID) { + continue + } + lines = append(lines, line) + // Keep the latest n rather than stopping at the first n: what a message + // did last is what its page is opened for. + if len(lines) > n { + lines = lines[1:] + } + } + if err := sc.Err(); err != nil { + return nil, err + } + return lines, nil +} + +// mentionsQueueID reports whether a mail.log line is about queueID. Postfix +// writes the id followed by a colon ("… postfix/smtp[26]: 41E862C00D9E: to=…"), +// and the match is anchored on the character before it so a shorter id is not +// found inside a longer one — queue ids are hexadecimal, and one being the tail +// of another is ordinary, not unlikely. +func mentionsQueueID(line, queueID string) bool { + needle := queueID + ":" + for i := 0; i <= len(line)-len(needle); { + j := strings.Index(line[i:], needle) + if j < 0 { + return false + } + j += i + if j == 0 || !isQueueIDByte(line[j-1]) { + return true + } + i = j + 1 + } + return false +} + +func isQueueIDByte(b byte) bool { + return b >= '0' && b <= '9' || b >= 'A' && b <= 'Z' || b >= 'a' && b <= 'z' +} + // 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 5f6554b..8325532 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -4,6 +4,7 @@ import ( "context" "os" "path/filepath" + "strconv" "strings" "sync" "testing" @@ -333,3 +334,123 @@ func waitFor(t *testing.T, cond func() bool) { } t.Fatal("condition not met within timeout") } + +// A delivery's page shows what Postfix wrote about that one message, so the +// read has to pick its queue-id's lines out of everything else the mail path +// logged around them — and only its own: queue ids are hexadecimal runs, and a +// shorter one is regularly the tail of a longer one. +func TestQueueLinesPicksOutOneMessage(t *testing.T) { + path := writeLog(t, + "host postfix/smtpd[20]: 41E862C00D9E: client=mail.example.com[203.0.113.4]", + "host postfix/qmgr[10]: 5900C2C00D9E: from=, size=500, nrcpt=1 (queue active)", + "host postfix/cleanup[15]: 41E862C00D9E: message-id=", + // Same run of characters, longer id: not this message. + "host postfix/smtp[26]: FF41E862C00D9E: to=, status=sent (250 OK)", + "host opendkim[30]: 41E862C00D9E: DKIM-Signature field added (s=mail d=example.com)", + "host postfix/smtp[26]: 41E862C00D9E: to=, relay=mx.example.net[203.0.113.9]:25, dsn=2.0.0, status=sent (250 OK)", + ) + + lines, err := QueueLines(path, "41E862C00D9E", 200) + if err != nil { + t.Fatalf("QueueLines: %v", err) + } + if len(lines) != 4 { + t.Fatalf("got %d lines, want 4:\n%s", len(lines), strings.Join(lines, "\n")) + } + // Oldest first: the page reads the message's history downwards. + if !strings.Contains(lines[0], "client=") || !strings.Contains(lines[3], "status=sent") { + t.Errorf("lines are not in the order they were logged:\n%s", strings.Join(lines, "\n")) + } + for _, line := range lines { + if strings.Contains(line, "FF41E862C00D9E") || strings.Contains(line, "5900C2C00D9E") { + t.Errorf("another message's line came back: %q", line) + } + } +} + +// A message the milter refused has no queue id, so there is nothing to match +// on — every line in the log would be someone else's. +func TestQueueLinesWithoutAQueueIDMatchesNothing(t *testing.T) { + path := writeLog(t, "host postfix/smtp[26]: 41E862C00D9E: to=, status=sent (250 OK)") + + lines, err := QueueLines(path, "", 200) + if err != nil { + t.Fatalf("QueueLines: %v", err) + } + if lines != nil { + t.Errorf("got %v, want no lines", lines) + } +} + +// The cap keeps the newest lines, not the first ones: what a message did last +// is what its page is opened for. +func TestQueueLinesCapKeepsTheLatest(t *testing.T) { + var log []string + for i := 0; i < 10; i++ { + log = append(log, "host postfix/smtp[26]: ABC123: attempt "+itoa(i)) + } + path := writeLog(t, log...) + + lines, err := QueueLines(path, "ABC123", 3) + if err != nil { + t.Fatalf("QueueLines: %v", err) + } + if len(lines) != 3 || !strings.HasSuffix(lines[0], "attempt 7") || !strings.HasSuffix(lines[2], "attempt 9") { + t.Errorf("cap did not keep the last three:\n%s", strings.Join(lines, "\n")) + } +} + +// Send-log rows outlive mail.log — retention is ninety days and rotation keeps +// fourteen files — so a message whose lines are gone, or a log that is between +// rotations and absent altogether, is an empty answer for the page to explain, +// not an error for it to report. +func TestQueueLinesOnAMessageWithNoLinesLeft(t *testing.T) { + path := writeLog(t, "host postfix/smtp[26]: 5900C2C00D9E: to=, status=sent (250 OK)") + + lines, err := QueueLines(path, "41E862C00D9E", 200) + if err != nil { + t.Fatalf("QueueLines: %v", err) + } + if lines != nil { + t.Errorf("got %v, want no lines", lines) + } +} + +// writeLog creates a mail.log holding the given lines and returns its path. +func writeLog(t *testing.T, lines ...string) string { + t.Helper() + path := filepath.Join(t.TempDir(), "mail.log") + body := "" + for _, line := range lines { + body += line + "\n" + } + if err := os.WriteFile(path, []byte(body), 0o644); err != nil { + t.Fatalf("write log: %v", err) + } + return path +} + +func itoa(n int) string { return strconv.Itoa(n) } + +// The read is bounded, so on a log that has grown all day it starts in the +// middle of a line. That fragment is not a line and must not come back as one, +// and anything before the budget is out of reach — which the page reports the +// same way as a message whose lines have rotated away. +func TestQueueLinesReadsABoundedTail(t *testing.T) { + old := queueScanBytes + queueScanBytes = 120 + t.Cleanup(func() { queueScanBytes = old }) + + path := writeLog(t, + "host postfix/smtp[26]: ABC123: too far back to reach, padded out past the budget with this run of filler text", + "host postfix/smtp[26]: ABC123: within the budget", + ) + + lines, err := QueueLines(path, "ABC123", 200) + if err != nil { + t.Fatalf("QueueLines: %v", err) + } + if len(lines) != 1 || !strings.HasSuffix(lines[0], "within the budget") { + t.Errorf("got %d lines, want only the one inside the budget:\n%s", len(lines), strings.Join(lines, "\n")) + } +} diff --git a/internal/web/handlers_monitor.go b/internal/web/handlers_monitor.go index a141f46..c90b83d 100644 --- a/internal/web/handlers_monitor.go +++ b/internal/web/handlers_monitor.go @@ -6,6 +6,7 @@ import ( "net/http" "net/url" "strconv" + "time" "github.com/mixeme/selfpost/internal/logtail" "github.com/mixeme/selfpost/internal/mailhdr" @@ -15,10 +16,12 @@ import ( // sendLogPageSize bounds each send-log page (product.md's monitoring screens // call for pagination); logTailLines bounds how much of mail.log the log view -// shows per refresh. +// shows per refresh, and deliveryLogLines how many of one message's own lines +// its page shows. const ( - sendLogPageSize = 50 - logTailLines = 200 + sendLogPageSize = 50 + logTailLines = 200 + deliveryLogLines = 200 ) // handleDeliveries renders the Deliveries page over the send log: server-side @@ -57,6 +60,13 @@ func (s *Server) handleDeliveriesRows(w http.ResponseWriter, r *http.Request) { // how it ended — and every remaining field (domain, application, queue id, when // the status was last reported) lives here, one page per row, so widening the // journal never costs the table a column. +// +// The page answers the question the log raises rather than restating it: what +// the journal recorded, in what order it happened, and what Postfix itself +// wrote about the message. So it is three blocks — the message's own facts and +// its history side by side, and the mail.log lines for its queue id under both. +// The queue id used to be printed here as something to go and search the system +// log for by hand; the search is done for the operator instead. func (s *Server) handleDelivery(w http.ResponseWriter, r *http.Request) { id, err := strconv.ParseInt(r.PathValue("id"), 10, 64) if err != nil || id <= 0 { @@ -75,17 +85,152 @@ func (s *Server) handleDelivery(w http.ResponseWriter, r *http.Request) { return } row.Subject = mailhdr.DecodeSubject(row.Subject) + lines, logNote := s.deliveryLog(row) s.render(w, http.StatusOK, "delivery", map[string]any{ "Title": "SelfPost — delivery", "User": currentUser(r), "Active": "deliveries", "Row": row, + // The status in the panel's own badge vocabulary, so the headline reads + // the same way as every other health signal in the panel. + "Level": deliveryLevel(row.Status), + "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, // 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), }) } +// deliveryLevel maps a send-log status onto the ok/warn/error/unknown badge +// vocabulary the status page and the DNS checks already use (see .st in +// panel.css), so a colour means the same thing on every page: delivered is the +// good outcome, deferred is not settled yet, and the two refusals are failures. +// A queued row is "unknown" rather than "warn" — nothing has gone wrong, it is +// simply that nothing has been reported. +func deliveryLevel(status string) string { + switch status { + case store.StatusSent: + return "ok" + case store.StatusDeferred: + return "warn" + case store.StatusBounced, store.StatusRejected: + return "error" + default: + return "unknown" + } +} + +// deliveryEvent is one step of a message's history, as the timeline on the +// delivery page draws it. At is zero for the step that has not happened yet — +// the delivery report a queued message is still waiting for. +type deliveryEvent struct { + At time.Time + Level string // ok / warn / error / unknown, as deliveryLevel returns + Status string // the send-log status value this step reached + Title string + Detail string +} + +// deliveryEvents turns a row's two timestamps into the history the page shows. +// The journal keeps no event table — a row is created when the message is +// accepted and updated once when Postfix reports the attempt — so the two +// timestamps *are* the history, and stating them as steps is what makes a row +// whose created_at and updated_at differ by six hours legible as "queued for +// six hours, then delivered" rather than as two dates in a list of fields. +func deliveryEvents(row store.SendLogRow) []deliveryEvent { + // A rejected message has no second step, and its first one is not an + // acceptance: the journal-milter refused it, so Postfix never queued it. + if row.Status == store.StatusRejected { + return []deliveryEvent{{ + At: row.CreatedAt, + Level: "error", + Status: store.StatusRejected, + Title: "Refused before queueing", + Detail: "The journal-milter refused the message under a rate limit. It was never queued, so there is no queue id and Postfix never attempted delivery.", + }} + } + + events := []deliveryEvent{{ + At: row.CreatedAt, + Level: "unknown", + Status: store.StatusQueued, + Title: "Accepted and queued", + Detail: "Postfix accepted the message over an authenticated submission and the journal-milter recorded it. Delivery to the recipient had not been attempted yet.", + }} + + switch row.Status { + case store.StatusQueued: + // The step that has not happened. Drawn as an open dot with no time. + return append(events, deliveryEvent{ + Level: "unknown", + Status: store.StatusQueued, + Title: "Waiting for a delivery report", + Detail: "Postfix has not reported an attempt for this recipient yet. The Mail queue page shows what it is still holding.", + }) + case store.StatusSent: + return append(events, deliveryEvent{ + At: row.UpdatedAt, + Level: "ok", + Status: store.StatusSent, + Title: "Delivered", + Detail: "The receiving server accepted the message. That is as far as this server can see — what the recipient's mailbox then did with it is not reported back.", + }) + case store.StatusDeferred: + return append(events, deliveryEvent{ + At: row.UpdatedAt, + Level: "warn", + Status: store.StatusDeferred, + Title: "Deferred, will be retried", + Detail: "The receiving server could not take the message yet. Postfix keeps it queued and retries until it is delivered or the queue lifetime runs out.", + }) + case store.StatusBounced: + return append(events, deliveryEvent{ + At: row.UpdatedAt, + Level: "error", + Status: store.StatusBounced, + Title: "Bounced", + Detail: "Delivery failed for good: the receiving server refused the message permanently, or Postfix gave up after the queue lifetime. The reason is in the delivery log below.", + }) + default: + // A status the log-tailer learns to write before this switch does. + return append(events, deliveryEvent{ + At: row.UpdatedAt, + Level: deliveryLevel(row.Status), + Status: row.Status, + Title: "Status reported", + Detail: "The last state Postfix reported for this recipient.", + }) + } +} + +// 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) { + if row.QueueID == "" { + return nil, "This message never reached the queue, so Postfix wrote no delivery lines for it." + } + lines, err := logtail.QueueLines(s.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 { + // Send-log rows outlive mail.log: retention is ninety days by default + // and rotation keeps fourteen files, so an older message having nothing + // 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, "" +} + // deliveriesBackURL rebuilds the delivery-log URL a detail page was opened // from. Only the log's own parameters are carried over, and each is re-encoded // by url.Values, so nothing a visitor appends to the link can travel back into diff --git a/internal/web/handlers_monitor_test.go b/internal/web/handlers_monitor_test.go index 47afc7a..ccd1c27 100644 --- a/internal/web/handlers_monitor_test.go +++ b/internal/web/handlers_monitor_test.go @@ -3,6 +3,7 @@ package web import ( "net/http" "net/http/httptest" + "os" "path/filepath" "strconv" "strings" @@ -90,6 +91,91 @@ func TestDeliveryPageShowsWhatTheLogOmits(t *testing.T) { } } +// The page's second column is the message's history: the two timestamps the +// journal holds, stated as the steps they stand for, so a row is readable as +// what happened to the message rather than as a list of fields. +func TestDeliveryPageTellsTheMessagesHistory(t *testing.T) { + s, row := serverWithDelivery(t) + + out := getBody(t, s.handleDelivery, "/deliveries/"+itoa(row.ID)) + for _, want := range []string{ + "Accepted and queued", "Delivered", + row.CreatedAt.Format("2006-01-02 15:04:05"), + row.UpdatedAt.Format("2006-01-02 15:04:05"), + // A delivered message is "ok" in the panel's own badge vocabulary, the + // same one the status page and the DNS checks use. + `class="st st-ok"`, + } { + if !strings.Contains(out, want) { + t.Errorf("delivery page is missing %q:\n%s", want, out) + } + } + // Accepted comes before delivered: a history read in the wrong order is + // worse than none. + if strings.Index(out, "Accepted and queued") > strings.Index(out, "Delivered") { + t.Errorf("the history is not in the order it happened:\n%s", out) + } +} + +// A queued message has no second timestamp to state, so the step it is waiting +// for is drawn as one that has not happened rather than dated with the moment +// the row was written. +func TestDeliveryPageMarksAQueuedMessageAsStillWaiting(t *testing.T) { + s, _ := serverWithDelivery(t) + if err := s.store.InsertQueued(store.SendLogEntry{ + QueueID: "7F7F7F7F", Domain: "bs.example.ru", AppLogin: "Queuer3C", + From: "noreply@bs.example.ru", To: "waiting@example.ru", Subject: "Still going", + }); err != nil { + t.Fatalf("insert: %v", err) + } + rows, err := s.store.QuerySendLog(store.SendLogFilter{}, 1, 0) + if err != nil || len(rows) != 1 { + t.Fatalf("query: %v (%d rows)", err, len(rows)) + } + + out := getBody(t, s.handleDelivery, "/deliveries/"+itoa(rows[0].ID)) + for _, want := range []string{"Waiting for a delivery report", "pending", "not yet"} { + if !strings.Contains(out, want) { + t.Errorf("delivery page does not mark the message as still waiting (%q):\n%s", want, out) + } + } +} + +// 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. +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)", + ) + + 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) + } + if strings.Contains(out, "99999999") { + t.Errorf("delivery page shows another message's log line:\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) { + s, row := serverWithDelivery(t) + s.cfg.MailLogPath = filepath.Join(t.TempDir(), "mail.log") // never created + + out := getBody(t, s.handleDelivery, "/deliveries/"+itoa(row.ID)) + if !strings.Contains(out, "rotated away") { + t.Errorf("delivery page does not explain the empty delivery log:\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) + } +} + // Send-log rows are pruned on the retention window, so a bookmarked delivery // that no longer exists is a 404, not a 500. func TestDeliveryPageNotFound(t *testing.T) { @@ -159,3 +245,14 @@ func getBody(t *testing.T, h http.HandlerFunc, target string) string { } func itoa(n int64) string { return strconv.FormatInt(n, 10) } + +// writeMailLog creates a mail.log holding the given lines and returns its path, +// for the pages that read the log rather than the journal. +func writeMailLog(t *testing.T, lines ...string) string { + t.Helper() + path := filepath.Join(t.TempDir(), "mail.log") + if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")+"\n"), 0o644); err != nil { + t.Fatalf("write mail.log: %v", err) + } + return path +} diff --git a/internal/web/static/panel.css b/internal/web/static/panel.css index 0e1f51f..8448a36 100644 --- a/internal/web/static/panel.css +++ b/internal/web/static/panel.css @@ -81,12 +81,14 @@ main { flex: 1 1 auto; min-width: 0; width: 100%; max-width: 64rem; } floating in the middle — the misalignment that gave login and setup their own narrow column (main.page-login further down). */ main > * { max-width: 48rem; margin-left: auto; margin-right: auto; } -/* The three monitoring pages are the ones that opt out: six columns of send - log, and raw mail.log lines that are long by nature, which at the measure - left Subject and Status fighting over the last inch and wrapped every second - log line. The class is declared by the page itself (the "wide" block in - layout.html) rather than derived from the page name, since a delivery's own - page is prose and shares the send log's name in the navigation. */ +/* The four monitoring pages are the ones that opt out: six columns of send + log, raw mail.log lines that are long by nature — which at the measure left + Subject and Status fighting over the last inch and wrapped every second log + line — and a single delivery's page, which stands two cards side by side over + a block of those same log lines. The class is declared by the page itself + (the "wide" block in layout.html) rather than derived from the page name: a + page's name is the navigation entry it belongs under, which several pages + share, and how wide a page needs to be is a property of that page alone. */ main.wide > * { max-width: none; } /* Longhands, not the margin shorthand: the shorthand would re-zero the auto side margins above and pin the heading to the column's edge, a measure's @@ -390,6 +392,82 @@ meter { width: 5rem; height: 0.7rem; vertical-align: middle; margin-right: 0.4re .metric { white-space: nowrap; } .code-row { display: flex; align-items: flex-start; gap: 0.5rem; } .code-row .code { flex: 1; min-width: 0; } + +/* Two cards abreast, on the one page that has a pair of them worth reading + together (a delivery's facts beside its history). auto-fit with a minimum + rather than a media query: the pair falls into one column exactly when a + column would drop below the width its content needs, which is also what + happens inside the narrow column the navigation lies down at. */ +.split { + display: grid; grid-template-columns: repeat(auto-fit, minmax(22rem, 1fr)); + gap: 1.2rem; margin-top: 1.2rem; +} +/* The gap already spaces the cards inside the grid; the general .card + .card + rule would add a second gap's worth on top of it, and only to the second + card, which in one column reads as an uneven stack. The blocks around the + grid keep their spacing from it instead. */ +.split > .card + .card { margin-top: 0; } +.split + .card { margin-top: 1.2rem; } +/* The subject heads a delivery's page, and it is the one heading in the panel + whose text we do not control: it may be a hundred characters with nothing to + break on. It wraps to as many lines as it needs (this is the page's name, not + a table cell to clip) but never widens the column. */ +h1.subject { overflow-wrap: anywhere; } +/* The line under it: sender, recipient and outcome. Wrapping rather than + clipping, since either address may be long and both are the point. The + vertical margins are longhands for the reason given at the h1 rule above — + the shorthand would re-zero the auto side margins that keep a page's blocks + centred on the measure. It sits close under the heading: the two are one + statement of what this page is about. */ +.route { + display: flex; flex-wrap: wrap; align-items: center; gap: 0.4rem; + margin-top: -0.5rem; margin-bottom: 1rem; +} +.route .addr { font-family: ui-monospace, SFMono-Regular, Menlo, monospace; font-size: 0.9rem; overflow-wrap: anywhere; } +.route .arrow { color: #6b7280; } +/* A card's short facts, as a grid of tiles rather than the label-over-value + stack the rest of the panel uses. That stack is right for the pages where a + value is a DNS record or a password to copy — one per line, full width — and + wrong for six values of a few characters each, which down a narrow column + would be a page of mostly empty rows. Same auto-fit as .split: as many + columns as fit, and one when nothing else does. */ +.facts { display: grid; grid-template-columns: repeat(auto-fit, minmax(9.5rem, 1fr)); gap: 0.5rem; margin-top: 1rem; } +.fact { min-width: 0; padding: 0.5rem 0.7rem; border-radius: 8px; background: var(--surface-bg); } +.fact-label { + display: block; font-size: 0.7rem; font-weight: 700; + text-transform: uppercase; letter-spacing: 0.04em; color: #6b7280; +} +/* Nothing here is guaranteed to have a space in it — domains, logins and queue + ids are all one run — so a value may break mid word rather than push its tile + wider than the column it shares. */ +.fact-value { display: block; margin-top: 0.1rem; overflow-wrap: anywhere; } +.fact-value.mono { font-family: ui-monospace, SFMono-Regular, Menlo, monospace; font-size: 0.85rem; } +/* A message's history: the steps down a line, each with the time it happened, + the status it reached and what that means. The line is the list's own left + border and the dots sit on top of it, so nothing has to be positioned against + a fixed row height — a step's text is two lines or five depending on what + there is to say about it. */ +.timeline { list-style: none; display: flex; flex-direction: column; gap: 1.1rem; + margin: 1rem 0 0; padding: 0.2rem 0 0.2rem 1.4rem; border-left: 2px solid var(--border); } +.event { position: relative; min-width: 0; } +.event::before { + content: ""; position: absolute; left: -1.85rem; top: 0.3rem; + width: 0.65rem; height: 0.65rem; border-radius: 50%; + background: var(--card-bg); border: 2px solid var(--control-border); +} +/* The dot carries the step's own verdict, in the same four colours as the badge + beside it — so the shape of the history is readable down the line alone. */ +.event.lvl-ok::before { border-color: var(--st-ok-fg); background: var(--st-ok-bg); } +.event.lvl-warn::before { border-color: var(--st-warn-fg); background: var(--st-warn-bg); } +.event.lvl-error::before { border-color: var(--st-error-fg); background: var(--st-error-bg); } +/* The step that has not happened yet — a queued message's delivery report — is + the one hollow dot, and its text is quiet: it is what to expect, not a record + of anything. */ +.event.pending { opacity: 0.7; } +.event.pending::before { background: var(--card-bg); border-style: dashed; } +.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; } /* 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/deliveries.html b/internal/web/templates/deliveries.html index 6a510ff..7930e51 100644 --- a/internal/web/templates/deliveries.html +++ b/internal/web/templates/deliveries.html @@ -1,7 +1,8 @@ {{/* The send log is six columns of addresses, subjects and timestamps, so this page takes the whole column rather than the reading measure (see the "wide" - block in layout.html). A single delivery's page carries prose and keeps the - measure, which is why this is declared per page and not per page name. */}} + block in layout.html). It is declared per page rather than per page name + because how wide a page needs to be is a property of that page, not of the + navigation entry several pages share. */}} {{define "wide"}}wide{{end}} {{define "content"}} diff --git a/internal/web/templates/delivery.html b/internal/web/templates/delivery.html index 14f84d8..1796b13 100644 --- a/internal/web/templates/delivery.html +++ b/internal/web/templates/delivery.html @@ -1,55 +1,108 @@ +{{/* One message's page. It takes the whole column rather than the reading + measure (see the "wide" block in layout.html): the two cards below stand + side by side, and under them are raw mail.log lines, which are long by + nature and were the reason the send log opted out too. */}} +{{define "wide"}}wide{{end}} + {{define "content"}} -

Delivery

+{{/* The subject is the page's name — it is what the message was about, and + what an operator arriving from the log is holding in their head. The route + under it is the other half of the identity: who it was from and who it was + for, with the outcome badged on the end so the answer is on the first line + of the page rather than somewhere in the cards below. */}} +

{{if .Row.Subject}}{{.Row.Subject}}{{else}}(no subject){{end}}

+

+ {{.Row.From}} + + {{if .Row.To}}{{.Row.To}}{{else}}—{{end}} + {{.Row.Status}} +

← Back to deliveries -
-

Message

-

One recipient of one message, as the journal-milter recorded - it when Postfix accepted it. The delivery log lists these; everything the list - has no room for is here.

+{{/* The two columns: what was recorded on the left, in what order it happened + on the right. They are a pair — the facts are only worth reading against + the history and the history only means anything for a known message — so + they are read together rather than one after the other (.split in + panel.css lays them down into one column when there is no room). */}} +
+
+

Message

+

What the journal recorded as Postfix accepted this + message. The delivery log lists only what identifies a row at a glance; + everything the table has no column for is here.

- - {{.Row.CreatedAt.Format "2006-01-02 15:04:05"}} UTC +
+
+ Domain + {{if .Row.Domain}}{{.Row.Domain}}{{else}}—{{end}} +
+
+ Application + {{if .Row.AppLogin}}{{.Row.AppLogin}}{{else}}—{{end}} +
+
+ Accepted + {{.Row.CreatedAt.Format "2006-01-02 15:04:05"}} UTC +
+
+ Status reported + {{.Row.UpdatedAt.Format "2006-01-02 15:04:05"}} UTC +
+ {{/* The queue id is monospace because it is an identifier to compare + character by character against a log line, not a word to read. */}} +
+ Queue id + {{if .Row.QueueID}}{{.Row.QueueID}}{{else}}—{{end}} +
+
+ Journal id + {{.Row.ID}} +
+
- - {{.Row.From}} + {{if not .Row.QueueID}} +

A message with no queue id was refused before Postfix + queued it — under a level-2 rate limit — so it has no delivery attempt to + show.

+ {{end}} +
- - {{if .Row.To}}{{.Row.To}}{{else}}—{{end}} +
+

History

+

A row is written when the message is accepted and updated + once when Postfix reports the attempt for this recipient, so these are the + two moments the journal knows about — not a trace of the SMTP conversation, + which is in the delivery log below.

- - {{if .Row.Subject}}{{.Row.Subject}}{{else}}—{{end}} - - - {{.Row.Status}} +
    + {{range .Events}} +
  1. +

    {{if .At.IsZero}}not yet{{else}}{{.At.Format "2006-01-02 15:04:05"}} UTC{{end}}

    +

    {{.Status}} {{.Title}}

    +

    {{.Detail}}

    +
    2. + {{end}} +
+
-
-

Origin

-

Which sending domain and which application's SASL account the - message was submitted under — the two filters the delivery log offers.

+{{/* Under both, at the column's full width: what Postfix itself wrote. The + queue id used to be printed on this page as something to go and search the + system log for by hand — this is that search, already done. */}} +
+

Delivery log

+

The lines Postfix wrote about this message in + mail.log, oldest first — the connection to the receiving server, + its reply, and the status that reply was filed as. Only lines carrying this + message's queue id are shown; the whole log is on the + System log page.

- - {{if .Row.Domain}}{{.Row.Domain}}{{else}}—{{end}} - - - {{if .Row.AppLogin}}{{.Row.AppLogin}}{{else}}—{{end}} -
- -
-

Handling

-

Postfix's own identifiers for this message. The queue id is - what to search the system log for; a rejected message never got one, because - it was refused before it was queued.

- - - {{if .Row.QueueID}}{{.Row.QueueID}}{{else}}—{{end}} - - - {{.Row.UpdatedAt.Format "2006-01-02 15:04:05"}} UTC - - - {{.Row.ID}} + {{if .LogLines}} + {{range .LogLines}}{{.}} +{{end}} + {{else}} +

{{.LogNote}}

+ {{end}}
{{end}} diff --git a/internal/web/templates_test.go b/internal/web/templates_test.go index 8e2bbbd..c176e33 100644 --- a/internal/web/templates_test.go +++ b/internal/web/templates_test.go @@ -225,7 +225,7 @@ func TestOnlyThePagesMadeOfDataDeclareThemselvesWide(t *testing.T) { if err != nil { t.Fatalf("loadTemplates: %v", err) } - wide := map[string]bool{"deliveries": true, "mail_queue": true, "system_log": true} + wide := map[string]bool{"deliveries": true, "delivery": true, "mail_queue": true, "system_log": true} for name, page := range tmpl.pages { var buf bytes.Buffer if err := page.ExecuteTemplate(&buf, "wide", nil); err != nil { @@ -236,7 +236,7 @@ func TestOnlyThePagesMadeOfDataDeclareThemselvesWide(t *testing.T) { case wide[name] && got != "wide": t.Errorf("page %q no longer declares itself wide (%q); its data falls back to the reading measure", name, got) case !wide[name] && got != "": - t.Errorf("page %q declares itself %q; only the pages that are tables of data or raw log lines take the whole column", name, got) + t.Errorf("page %q declares itself %q; only the pages that are tables of data, raw log lines or side-by-side cards take the whole column", name, got) } } }