diff --git a/CHANGELOG.md b/CHANGELOG.md index 0caaf82..d7ac733 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -33,6 +33,17 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version the page shows it. A row refused before this says the line was not kept. A refusal's line is red for a permanent reply, amber for a temporary one (audit 2026-10-12, stage 2b). +- **The Sender check card counts connections and messages apart.** What was + one column, "Messages deferred", was two things: connections Postfix + turned away while the panel did not answer - refused before any message + is offered, so a client trying three times is three - and messages + deferred in the middle, when the panel stopped answering after a message + had begun. The card now has a column for each (the owner's decision). +- **A start at which supervisord does not answer still counts the downtime.** + The panel asks supervisord once at start since when Postfix runs; when it + did not answer, that start's downtime was not counted at all. It now asks + for half a minute, and then takes the time since its last sign of life - + an upper bound - and the card marks such a period with ≈. - **A refusal the panel did not get to write is written from the log.** The sender check answers 550 and writes the row a moment later; a panel that stopped in between - a rollout, a crash - left an application refused and diff --git a/cmd/panel/sendercheck.go b/cmd/panel/sendercheck.go index 0c6af41..5de8f50 100644 --- a/cmd/panel/sendercheck.go +++ b/cmd/panel/sendercheck.go @@ -39,10 +39,14 @@ func serveSenderCheck(ctx context.Context, cfg config, st *store.Store) error { if err := st.StartSenderCheckStats(now); err != nil { log.Printf("sender-check: statistics: %v", err) } - if down := senderCheckDowntime(mark, now, postfixStarted); down > 0 { - log.Printf("sender-check: was not answering for %s while Postfix was running", down.Round(time.Second)) + if down, estimated := senderCheckDowntime(mark, now, postfixStarted); down > 0 { + if estimated { + log.Printf("sender-check: was not answering for at most %s (supervisord did not say since when Postfix ran)", down.Round(time.Second)) + } else { + log.Printf("sender-check: was not answering for %s while Postfix was running", down.Round(time.Second)) + } for _, part := range byDay(now.Add(-down), now) { - if err := st.AddSenderCheckDown(part.day, part.down); err != nil { + if err := st.AddSenderCheckDown(part.day, part.down, estimated); err != nil { log.Printf("sender-check: statistics: %v", err) } } @@ -57,28 +61,40 @@ func serveSenderCheck(ctx context.Context, cfg config, st *store.Store) error { return milter.ServeSender(ctx, ln, bind, signers, st) } +// postfixState is what supervisord said about Postfix: since when it runs, if +// it does; known is false when supervisord did not answer. +type postfixState struct { + started time.Time + running, known bool +} + // senderCheckDowntime is for how long the check was not serving before now // while Postfix was: the time since the mark at path was last set, or since // Postfix started if that was later. No mark means the container is new, and // a Postfix that is not running means mail was stopped for another reason - -// a rollout, a reboot - and neither is the check's downtime. -func senderCheckDowntime(path string, now time.Time, postfixStarted func() (time.Time, bool)) time.Duration { +// a rollout, a reboot - and neither is the check's downtime. When supervisord +// could not say, the time since the mark is taken and estimated is true: an +// upper bound, since Postfix may not have been running all of it (audit +// 2026-10-12, stage 2b - until then such a start counted nothing). +func senderCheckDowntime(path string, now time.Time, ask func() postfixState) (down time.Duration, estimated bool) { fi, err := os.Stat(path) if err != nil { - return 0 + return 0, false } from := fi.ModTime() - started, running := postfixStarted() - if !running { - return 0 - } - if started.After(from) { - from = started + p := ask() + switch { + case !p.known: + estimated = true + case !p.running: + return 0, false + case p.started.After(from): + from = p.started } if d := now.Sub(from); d > 0 { - return d + return d, estimated } - return 0 + return 0, false } // dayPart is the part of a stretch of downtime that fell on one UTC day. @@ -103,23 +119,34 @@ func byDay(from, to time.Time) []dayPart { return parts } -// postfixStarted asks supervisord since when Postfix has been running. -func postfixStarted() (time.Time, bool) { - procs, err := health.Processes() - if err != nil { - // Said aloud: the downtime of this start is then not counted. - log.Printf("sender-check: statistics: when Postfix started is not known: %v", err) - return time.Time{}, false - } - for _, p := range procs { - if p.Name != "postfix" || p.State != "RUNNING" { - continue +// postfixAskFor is how long postfixStarted keeps asking a supervisord that +// does not answer - at the container's start it may not be listening yet. +var postfixAskFor, postfixAskEvery = 30 * time.Second, 2 * time.Second + +// postfixStarted asks supervisord since when Postfix has been running, again +// and again for postfixAskFor while it does not answer. +func postfixStarted() postfixState { + deadline := time.Now().Add(postfixAskFor) + for { + procs, err := health.Processes() + if err == nil { + for _, p := range procs { + if p.Name != "postfix" || p.State != "RUNNING" { + continue + } + if up, ok := health.Uptime(p.Detail); ok { + return postfixState{started: time.Now().Add(-up), running: true, known: true} + } + } + return postfixState{known: true} } - if up, ok := health.Uptime(p.Detail); ok { - return time.Now().Add(-up), true + if time.Now().After(deadline) { + // Said aloud: this start's downtime is then an estimate. + log.Printf("sender-check: statistics: when Postfix started is not known: %v", err) + return postfixState{} } + time.Sleep(postfixAskEvery) } - return time.Time{}, false } // keepAlive sets the mark until ctx ends, and once a day drops the days of diff --git a/cmd/panel/sendercheck_test.go b/cmd/panel/sendercheck_test.go index ebb599e..a2f6452 100644 --- a/cmd/panel/sendercheck_test.go +++ b/cmd/panel/sendercheck_test.go @@ -23,25 +23,31 @@ func TestSenderCheckDowntime(t *testing.T) { t.Fatal(err) } } - postfix := func(started time.Time, running bool) func() (time.Time, bool) { - return func() (time.Time, bool) { return started, running } + postfix := func(started time.Time, running bool) func() postfixState { + return func() postfixState { return postfixState{started: started, running: running, known: true} } } + silent := func() postfixState { return postfixState{} } + down := func(ask func() postfixState) (time.Duration, bool) { return senderCheckDowntime(mark, now, ask) } - if d := senderCheckDowntime(mark, now, postfix(now.Add(-time.Hour), true)); d != 0 { + if d, _ := down(postfix(now.Add(-time.Hour), true)); d != 0 { t.Errorf("no mark: %s", d) } set(now.Add(-40 * time.Second)) - if d := senderCheckDowntime(mark, now, postfix(now.Add(-time.Hour), true)); d != 40*time.Second { - t.Errorf("Postfix up throughout: %s, want 40s", d) + if d, est := down(postfix(now.Add(-time.Hour), true)); d != 40*time.Second || est { + t.Errorf("Postfix up throughout: %s %v, want 40s, not estimated", d, est) } - if d := senderCheckDowntime(mark, now, postfix(now.Add(-10*time.Second), true)); d != 10*time.Second { + if d, _ := down(postfix(now.Add(-10*time.Second), true)); d != 10*time.Second { t.Errorf("Postfix started within the gap: %s, want 10s", d) } - if d := senderCheckDowntime(mark, now, postfix(time.Time{}, false)); d != 0 { + if d, _ := down(postfix(time.Time{}, false)); d != 0 { t.Errorf("Postfix not running: %s", d) } + // supervisord did not answer: the time since the mark, an estimate. + if d, est := down(silent); d != 40*time.Second || !est { + t.Errorf("supervisord silent: %s %v, want 40s, estimated", d, est) + } set(now.Add(time.Minute)) // a clock set back - if d := senderCheckDowntime(mark, now, postfix(now.Add(-time.Hour), true)); d != 0 { + if d, _ := down(postfix(now.Add(-time.Hour), true)); d != 0 { t.Errorf("a mark in the future: %s", d) } } diff --git a/docs/audit-2026-10-12.md b/docs/audit-2026-10-12.md index 4dca15d..042d63e 100644 --- a/docs/audit-2026-10-12.md +++ b/docs/audit-2026-10-12.md @@ -805,7 +805,7 @@ order - each stands on the one before. flush of the buffer at shutdown would not. Done when the e2e refuses a message, kills the panel before the row is written, and finds the row after the restart, once. - **Opus** -- [ ] **Downtime is counted when supervisord does not answer at start** +- [x] **Downtime is counted when supervisord does not answer at start** (owner, 2026-10-13, from the Not done list of from-header-binding). The panel asks supervisord once since when Postfix runs ([sendercheck.go](../cmd/panel/sendercheck.go), `postfixStarted`); an @@ -816,7 +816,7 @@ order - each stands on the one before. and the day is marked as estimated (a column in `sender_check_days`, the next migration), which the card shows. The mark on the card is drawn in the mockup with the renamed column above (one `design:` commit). - **Opus** -- [ ] **The Sender check card names what it counts** (owner, 2026-10-13, from +- [x] **The Sender check card names what it counts** (owner, 2026-10-13, from the Not done list of from-header-binding): the column *Messages deferred* becomes *Connections turned away*. Postfix refuses from the connection on while the check does not answer, before any message is offered, so a diff --git a/docs/roadmap.md b/docs/roadmap.md index d0a6d88..9478831 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -42,7 +42,7 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md). | from-header-binding | Hold a message's `From:` header against the application that sends it | shipped `2.4.0` | 9/9 | [plans/from-header-binding.md](plans/from-header-binding.md) | | panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) | | schema-squash | Squash SQLite migrations into a 2.x baseline | built in panel-redesign (stage 1) | — | [plans/panel-redesign.md](plans/panel-redesign.md) | -| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`, stages 1+2 `2.5.0`; next stage 2b → `2.5.1`) | 26/62 | [audit-2026-10-12.md](audit-2026-10-12.md) | +| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`, stages 1+2 `2.5.0`; next stage 2b → `2.5.1`) | 28/62 | [audit-2026-10-12.md](audit-2026-10-12.md) | **Recommended order** (not binding; owner, 2026-10-09: feature order follows development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and diff --git a/docs/schema-migrations.md b/docs/schema-migrations.md index d37ada3..ce70717 100644 --- a/docs/schema-migrations.md +++ b/docs/schema-migrations.md @@ -83,7 +83,7 @@ audit (`2.5.0`). | 6 | `0006_sender_check.sql` | 2.4.0 | DDL | `send_log.reason` and `send_log.header_from` (both default `''`: a row refused earlier keeps no reason), and `sender_check_days` | | 7 | `0007_delivery_log_days.sql` | 2.5.0 | DDL | `delivery_log_days`: what the reconcile sweep and the log tailer did, a row per UTC day, kept a year, shown nowhere - the measurement that decides the sweep's fate (audit 2026-10-12, stage 1). `send_log.reason` gains the values `reconcile` and `reconcile-contradicted` without a schema change | | 8 | `0008_tenant_boundary.sql` | 2.5.0 | DDL + data | `idx_applications_login_nocase`: an application login is unique without regard to case (audit 2026-10-12, H4). `send_log.domain_id` and `inbound_spam_log.inbound_domain_id` (`ON DELETE SET NULL`), each with an index, filled once by name from the registry as it was then: a row belongs to a domain by id, and a domain deleted and added again starts with an empty log (L12) | -| 9 | `0009_refusal_line.sql` | 2.5.1 | DDL | `send_log.refusal_line`: Postfix's line about a refusal at MAIL FROM (a level-2 limit, a client address off the list), which has no queue id; the log tailer puts it on the row; and `send_log.recovered`, a refusal row the tailer wrote from `mail.log` because the panel stopped before writing it (audit 2026-10-12, stage 2b) | +| 9 | `0009_refusal_line.sql` | 2.5.1 | DDL | `send_log.refusal_line`: Postfix's line about a refusal at MAIL FROM (a level-2 limit, a client address off the list), which has no queue id; the log tailer puts it on the row; `send_log.recovered`, a refusal row the tailer wrote from `mail.log` because the panel stopped before writing it; `sender_check_days.messages` (messages deferred mid-message, counted apart from the connections turned away) and `sender_check_days.estimated` (a day whose downtime is an upper bound) (audit 2026-10-12, stage 2b) | **Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct for operators upgrading from older 2.x images. diff --git a/internal/logtail/sendercheck.go b/internal/logtail/sendercheck.go index 0d68c73..bc292c3 100644 --- a/internal/logtail/sendercheck.go +++ b/internal/logtail/sendercheck.go @@ -48,7 +48,7 @@ import ( type SenderCheckStore interface { // AddSenderCheckDeferred counts and saves the place in the log reached, // in one transaction. - AddSenderCheckDeferred(at time.Time, n int64, place string) error + AddSenderCheckDeferred(at time.Time, n int64, place string, message bool) error SenderCheckDeferredAt() (time.Time, error) SenderCheckCountedPlace() (string, error) } @@ -118,7 +118,7 @@ func (c *deferredCounter) handle(line string, now time.Time, catchingUp bool, pl if program == "cleanup" { // A message cleanup could not finish because the check did not reply. if strings.HasPrefix(text, c.broken) { - c.count(at, catchingUp, place) + c.count(at, catchingUp, place, true) } return } @@ -137,13 +137,14 @@ func (c *deferredCounter) handle(line string, now time.Time, catchingUp bool, pl c.failed = make(map[string]bool) } c.failed[pid] = true - c.count(at, catchingUp, place) + c.count(at, catchingUp, place, false) } } -// count adds one deferred message at at, the line ending at place, unless it -// is a line read again. -func (c *deferredCounter) count(at time.Time, catchingUp bool, place Place) { +// count adds, at at, one connection turned away - or, with message, one +// message deferred in the middle - the line ending at place, unless it is a +// line read again. +func (c *deferredCounter) count(at time.Time, catchingUp bool, place Place, message bool) { if catchingUp && c.countedAlready(at, place) { return } @@ -151,7 +152,7 @@ func (c *deferredCounter) count(at time.Time, catchingUp bool, place Place) { c.last = at } c.counted = place - if err := c.st.AddSenderCheckDeferred(at, 1, place.String()); err != nil { + if err := c.st.AddSenderCheckDeferred(at, 1, place.String(), message); err != nil { log.Printf("log-tailer: sender check statistics: %v", err) } } diff --git a/internal/logtail/sendercheck_test.go b/internal/logtail/sendercheck_test.go index c64e5ff..4de1141 100644 --- a/internal/logtail/sendercheck_test.go +++ b/internal/logtail/sendercheck_test.go @@ -6,7 +6,8 @@ import ( ) type deferredStore struct { - days map[string]int64 + days map[string]int64 // connections turned away + msgs map[string]int64 // messages deferred in the middle last time.Time place string } @@ -15,12 +16,16 @@ func (d *deferredStore) SenderCheckDeferredAt() (time.Time, error) { return d.la func (d *deferredStore) SenderCheckCountedPlace() (string, error) { return d.place, nil } -func (d *deferredStore) AddSenderCheckDeferred(at time.Time, n int64, place string) error { +func (d *deferredStore) AddSenderCheckDeferred(at time.Time, n int64, place string, message bool) error { d.place = place if d.days == nil { - d.days = make(map[string]int64) + d.days, d.msgs = make(map[string]int64), make(map[string]int64) + } + if message { + d.msgs[at.UTC().Format("2006-01-02")] += n + } else { + d.days[at.UTC().Format("2006-01-02")] += n } - d.days[at.UTC().Format("2006-01-02")] += n if at.After(d.last) { d.last = at } @@ -83,8 +88,8 @@ func TestDeferredCounter(t *testing.T) { } { c.handle(line, now, false, Place{}) } - if len(st.days) != 2 || st.days["2026-10-12"] != 1 || st.days["2026-10-13"] != 2 { - t.Fatalf("deferred per day = %v, want one on the first day and two on the second", st.days) + if st.days["2026-10-12"] != 1 || st.days["2026-10-13"] != 0 || st.msgs["2026-10-13"] != 2 || len(st.msgs) != 1 { + t.Fatalf("connections %v, messages %v; want one connection on the first day and two messages on the second", st.days, st.msgs) } } diff --git a/internal/store/migrations/0009_refusal_line.sql b/internal/store/migrations/0009_refusal_line.sql index 1c81092..6b8de49 100644 --- a/internal/store/migrations/0009_refusal_line.sql +++ b/internal/store/migrations/0009_refusal_line.sql @@ -13,3 +13,12 @@ ALTER TABLE send_log ADD COLUMN refusal_line TEXT NOT NULL DEFAULT ''; -- none - is written by the log tailer from Postfix's line about it, and marked -- so: recovered = 1. ALTER TABLE send_log ADD COLUMN recovered INTEGER NOT NULL DEFAULT 0; + +-- The Sender check card counts two things apart (the owner, 2026-10-14): +-- deferred stays the connections Postfix turned away while the check did not +-- answer, and messages are those deferred in the middle, when the check +-- stopped answering after a message had begun (cleanup's warning). estimated +-- marks a day whose downtime was taken from the alive mark alone, because +-- supervisord could not say at start since when Postfix ran: an upper bound. +ALTER TABLE sender_check_days ADD COLUMN messages INTEGER NOT NULL DEFAULT 0; +ALTER TABLE sender_check_days ADD COLUMN estimated INTEGER NOT NULL DEFAULT 0; diff --git a/internal/store/schema_test.go b/internal/store/schema_test.go index 4d885e6..27af04e 100644 --- a/internal/store/schema_test.go +++ b/internal/store/schema_test.go @@ -59,7 +59,7 @@ func TestBaselineSchema(t *testing.T) { "inbound_spam_list": "id list_type entry_type value note created_at", "send_log_lines": "id queue_id logged_at line", "notify_state": "key phase count mark since sent_at", - "sender_check_days": "day down_seconds deferred", + "sender_check_days": "day down_seconds deferred messages estimated", "delivery_log_days": "day reconcile_closed reconcile_missed reconcile_contradicted tailer_blind_seconds queued_over_lifetime", } rows, err := st.db.Query("SELECT name FROM sqlite_master WHERE type = 'table' AND name NOT LIKE 'sqlite_%' ORDER BY name") diff --git a/internal/store/sendercheck.go b/internal/store/sendercheck.go index d30cc5f..e767004 100644 --- a/internal/store/sendercheck.go +++ b/internal/store/sendercheck.go @@ -43,7 +43,11 @@ const dayLayout = "2006-01-02" // SenderCheckTotals is what the strict sender check has cost over a period. type SenderCheckTotals struct { Down time.Duration // the panel not answering while Postfix was running - Deferred int64 // messages Postfix deferred because of it + Deferred int64 // connections Postfix turned away because of it + Messages int64 // messages deferred in the middle because of it + // Estimated: a day of the period had its downtime taken from the alive + // mark alone - at most what it was. + Estimated bool } // SenderCheckStats is the card of Server > Health. @@ -65,16 +69,18 @@ func (s *Store) StartSenderCheckStats(now time.Time) error { } // AddSenderCheckDown adds to the day of at the time the panel did not answer -// while Postfix was running. -func (s *Store) AddSenderCheckDown(at time.Time, d time.Duration) error { +// while Postfix was running; estimated marks the day when that time is an +// upper bound (supervisord could not say since when Postfix ran). +func (s *Store) AddSenderCheckDown(at time.Time, d time.Duration, estimated bool) error { secs := int64(d / time.Second) if secs <= 0 { return nil } _, err := s.db.Exec( - `INSERT INTO sender_check_days (day, down_seconds) VALUES (?, ?) - ON CONFLICT (day) DO UPDATE SET down_seconds = down_seconds + excluded.down_seconds`, - at.UTC().Format(dayLayout), secs, + `INSERT INTO sender_check_days (day, down_seconds, estimated) VALUES (?, ?, ?) + ON CONFLICT (day) DO UPDATE SET down_seconds = down_seconds + excluded.down_seconds, + estimated = MAX(estimated, excluded.estimated)`, + at.UTC().Format(dayLayout), secs, estimated, ) if err != nil { return fmt.Errorf("sender check downtime: %w", err) @@ -87,7 +93,10 @@ func (s *Store) AddSenderCheckDown(at time.Time, d time.Duration) error { // place - where in mail.log the counted line ends - in the same transaction: // a count without its place, or the other way round, would be counted again // or lost at the next start (audit 2026-10-12, stage 2b). -func (s *Store) AddSenderCheckDeferred(at time.Time, n int64, place string) error { +// +// message says which of the two it is: a message deferred in the middle +// (cleanup's warning) rather than a connection turned away (smtpd's). +func (s *Store) AddSenderCheckDeferred(at time.Time, n int64, place string, message bool) error { if n <= 0 { return nil } @@ -96,9 +105,13 @@ func (s *Store) AddSenderCheckDeferred(at time.Time, n int64, place string) erro return fmt.Errorf("sender check deferred: %w", err) } defer tx.Rollback() - if _, err := tx.Exec( - `INSERT INTO sender_check_days (day, deferred) VALUES (?, ?) - ON CONFLICT (day) DO UPDATE SET deferred = deferred + excluded.deferred`, + column := "deferred" + if message { + column = "messages" + } + if _, err := tx.Exec(fmt.Sprintf( + `INSERT INTO sender_check_days (day, %[1]s) VALUES (?, ?) + ON CONFLICT (day) DO UPDATE SET %[1]s = %[1]s + excluded.%[1]s`, column), at.UTC().Format(dayLayout), n, ); err != nil { return fmt.Errorf("sender check deferred: %w", err) @@ -149,16 +162,18 @@ func (s *Store) SenderCheckStats(now time.Time) (SenderCheckStats, error) { now = now.UTC() var out SenderCheckStats sum := func(days int) (SenderCheckTotals, error) { - var secs, deferred int64 + var secs, deferred, messages, estimated int64 err := s.db.QueryRow( - `SELECT COALESCE(SUM(down_seconds), 0), COALESCE(SUM(deferred), 0) + `SELECT COALESCE(SUM(down_seconds), 0), COALESCE(SUM(deferred), 0), COALESCE(SUM(messages), 0), + COALESCE(MAX(estimated), 0) FROM sender_check_days WHERE day > ? AND day <= ?`, now.AddDate(0, 0, -days).Format(dayLayout), now.Format(dayLayout), - ).Scan(&secs, &deferred) + ).Scan(&secs, &deferred, &messages, &estimated) if err != nil { return SenderCheckTotals{}, fmt.Errorf("sender check stats: %w", err) } - return SenderCheckTotals{Down: time.Duration(secs) * time.Second, Deferred: deferred}, nil + return SenderCheckTotals{Down: time.Duration(secs) * time.Second, Deferred: deferred, + Messages: messages, Estimated: estimated > 0}, nil } var err error if out.Today, err = sum(1); err != nil { diff --git a/internal/store/sendercheck_test.go b/internal/store/sendercheck_test.go index a0683ab..33829f5 100644 --- a/internal/store/sendercheck_test.go +++ b/internal/store/sendercheck_test.go @@ -39,16 +39,16 @@ func TestSenderCheckStats(t *testing.T) { t.Fatal(err) } } - must(st.AddSenderCheckDown(now, 3*time.Second)) - must(st.AddSenderCheckDown(now, 1500*time.Millisecond)) // whole seconds: one - must(st.AddSenderCheckDown(now, 400*time.Millisecond)) // nothing - must(st.AddSenderCheckDeferred(now.Add(-time.Hour), 2, "")) - must(st.AddSenderCheckDown(day(10), 30*time.Second)) - must(st.AddSenderCheckDeferred(day(10), 1, "")) - must(st.AddSenderCheckDown(day(29), time.Minute)) - must(st.AddSenderCheckDown(day(30), time.Hour)) // the 31st day back: the year's only - must(st.AddSenderCheckDeferred(day(200), 5, "")) - must(st.AddSenderCheckDown(day(365), 24*time.Hour)) // a year and a day: nobody's + must(st.AddSenderCheckDown(now, 3*time.Second, false)) + must(st.AddSenderCheckDown(now, 1500*time.Millisecond, false)) // whole seconds: one + must(st.AddSenderCheckDown(now, 400*time.Millisecond, false)) // nothing + must(st.AddSenderCheckDeferred(now.Add(-time.Hour), 2, "", false)) + must(st.AddSenderCheckDown(day(10), 30*time.Second, false)) + must(st.AddSenderCheckDeferred(day(10), 1, "", false)) + must(st.AddSenderCheckDown(day(29), time.Minute, false)) + must(st.AddSenderCheckDown(day(30), time.Hour, false)) // the 31st day back: the year's only + must(st.AddSenderCheckDeferred(day(200), 5, "", false)) + must(st.AddSenderCheckDown(day(365), 24*time.Hour, false)) // a year and a day: nobody's got, err = st.SenderCheckStats(now) if err != nil { @@ -118,10 +118,10 @@ func TestRefusedRowKeepsItsReason(t *testing.T) { func TestSenderCheckDeferredSavesItsPlace(t *testing.T) { st := openTestStore(t) later := time.Date(2026, 10, 14, 12, 0, 1, 0, time.UTC) - if err := st.AddSenderCheckDeferred(later, 1, "abc:1.2@100"); err != nil { + if err := st.AddSenderCheckDeferred(later, 1, "abc:1.2@100", false); err != nil { t.Fatal(err) } - if err := st.AddSenderCheckDeferred(later.Add(-time.Hour), 1, "abc:1.2@200"); err != nil { + if err := st.AddSenderCheckDeferred(later.Add(-time.Hour), 1, "abc:1.2@200", false); err != nil { t.Fatal(err) } if p, err := st.SenderCheckCountedPlace(); err != nil || p != "abc:1.2@200" { @@ -131,3 +131,29 @@ func TestSenderCheckDeferredSavesItsPlace(t *testing.T) { t.Fatalf("last deferral = %s, %v; want %s", at, err, later) } } + +// Connections turned away and messages deferred in the middle are counted +// apart (the owner, 2026-10-14), and a period holding a day whose downtime is +// an estimate says so. +func TestSenderCheckCountsConnectionsAndMessagesApart(t *testing.T) { + st := openTestStore(t) + now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC) + must := func(err error) { + t.Helper() + if err != nil { + t.Fatal(err) + } + } + must(st.AddSenderCheckDeferred(now, 3, "", false)) + must(st.AddSenderCheckDeferred(now, 1, "", true)) + must(st.AddSenderCheckDown(now.AddDate(0, 0, -3), 20*time.Second, true)) + must(st.AddSenderCheckDown(now.AddDate(0, 0, -3), 5*time.Second, false)) + got, err := st.SenderCheckStats(now) + must(err) + if got.Today.Deferred != 3 || got.Today.Messages != 1 || got.Today.Estimated { + t.Errorf("today = %+v, want 3 connections, 1 message, not estimated", got.Today) + } + if got.Month.Down != 25*time.Second || !got.Month.Estimated { + t.Errorf("the month = %+v, want 25 s, estimated", got.Month) + } +} diff --git a/internal/web/handlers/handlers_status.go b/internal/web/handlers/handlers_status.go index f7607bb..ca87b50 100644 --- a/internal/web/handlers/handlers_status.go +++ b/internal/web/handlers/handlers_status.go @@ -152,7 +152,7 @@ func (h *Handlers) healthView(r *http.Request, flash string) *view.Health { if err != nil { // Zeros that were not read are not zeros. for i := range rows { - rows[i].Down, rows[i].Deferred = "—", "—" + rows[i].Down, rows[i].Deferred, rows[i].Messages = "—", "—", "—" } status = string(health.StatusUnknown) } @@ -160,11 +160,17 @@ func (h *Handlers) healthView(r *http.Request, flash string) *view.Health { } // senderCheckCard is the Sender check card from its statistics. It warns when -// a message was deferred in the last 24 hours: that is mail an application had -// to send again. Downtime that deferred nothing is only shown. +// a connection was turned away or a message deferred in the last 24 hours: +// that is mail an application had to send again. Downtime that deferred +// nothing is only shown. func senderCheckCard(s store.SenderCheckStats, now time.Time) (rows []view.SenderCheckRow, since, status string) { row := func(period string, t store.SenderCheckTotals) view.SenderCheckRow { - return view.SenderCheckRow{Period: period, Down: view.Downtime(t.Down), Deferred: strconv.FormatInt(t.Deferred, 10)} + down := view.Downtime(t.Down) + if t.Estimated { + down = "≈ " + down + } + return view.SenderCheckRow{Period: period, Down: down, + Deferred: strconv.FormatInt(t.Deferred, 10), Messages: strconv.FormatInt(t.Messages, 10)} } rows = []view.SenderCheckRow{row("Today", s.Today), row("Last 30 days", s.Month), row("Last 12 months", s.Year)} if !s.Since.IsZero() { diff --git a/internal/web/view/fixtures_test.go b/internal/web/view/fixtures_test.go index 79a1e25..71ae1c8 100644 --- a/internal/web/view/fixtures_test.go +++ b/internal/web/view/fixtures_test.go @@ -96,9 +96,9 @@ func healthFixture(refresh bool) *Health { h.AsFragment() } h.WithSenderCheck([]SenderCheckRow{ - {Period: "Today", Down: "0 s", Deferred: "0"}, - {Period: "Last 30 days", Down: "4 s", Deferred: "0"}, - {Period: "Last 12 months", Down: "41 s", Deferred: "3"}, + {Period: "Today", Down: "0 s", Deferred: "0", Messages: "0"}, + {Period: "Last 30 days", Down: "4 s", Deferred: "0", Messages: "0"}, + {Period: "Last 12 months", Down: "≈ 41 s", Deferred: "3", Messages: "1"}, }, "2026-10-13", "ok") h.Machine.End = Verdict("ok") h.MachineRows = []MachineRow{ diff --git a/internal/web/view/health.go b/internal/web/view/health.go index 54a5c01..8f1a3d7 100644 --- a/internal/web/view/health.go +++ b/internal/web/view/health.go @@ -24,8 +24,9 @@ type Health struct { ProcessError bool // SenderCheck is what the strict check of the From: line has cost: for how - // long the panel did not answer while Postfix was running, and how many - // messages were deferred for it. SenderNote is the line under its table. + // long the panel did not answer while Postfix was running, how many + // connections Postfix turned away and how many messages it deferred in + // the middle for it. SenderNote is the line under its table. SenderCheck Box SenderRows []SenderCheckRow SenderNote Text @@ -57,8 +58,9 @@ type Health struct { // SenderCheckRow is one period of the Sender check table. type SenderCheckRow struct { Period string - Down string - Deferred string + Down string // with "≈ " in front when the period holds an estimate + Deferred string // connections turned away + Messages string // messages deferred in the middle } // MachineRow is one line of the Machine table. A row that is a level (CPU, @@ -173,7 +175,7 @@ func (h *Health) WithSenderCheck(rows []SenderCheckRow, since, status string) *H h.SenderCheck.End = Verdict(status) h.SenderRows = rows h.SenderNote = Rich("The panel holds each message's ", Code("From:"), - " against the application that sends it. While the panel does not answer, Postfix defers mail instead of accepting it unchecked. Time is counted only while Postfix itself was running.") + " against the application that sends it. While the panel does not answer, Postfix defers mail instead of accepting it unchecked. Time is counted only while Postfix itself was running; ≈ marks a period with a start at which that could not be asked, and its time is at most what is shown.") if since != "" { h.SenderNote = append(h.SenderNote, Rich(" Counted since ", Mono(since), ".")...) } diff --git a/internal/web/view/help.go b/internal/web/view/help.go index 97211fc..5186ebb 100644 --- a/internal/web/view/help.go +++ b/internal/web/view/help.go @@ -171,13 +171,13 @@ var outboundTopics = []HelpTopic{ Code("From:"), " - another of your domains, the server's own name, an address somewhere else, or none at all - is refused for good with ", Code("550 5.7.1"), ". It is a rejected row of the Outbound log, and its page says which address was refused. This is what keeps one application from getting mail signed with another domain's key.", Br(), Br(), - "The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running, and how many messages were deferred because of it. The card warns when a message was deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own."), + "The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, at most what Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own."), }}, {ID: HelpLimits, Title: "Rate limits", Body: []Text{ Rich("Level 1 is a per-IP ceiling set in ", Code(".env"), ". Level 2 is optional, per domain and per application, entered by hand or computed from the last 30 days of sending, and can never exceed level 1. An application's own limit replaces its domain's."), }}, {ID: HelpLog, Title: "Outbound log", Body: []Text{ - Rich("One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out) and rejected (refused before queueing, so it never reached the queue: under a level-2 rate limit, from a client address the application does not allow, or for a ", Code("From:"), " line that is not the application's - the message's page says which). A message's page lists these steps and the lines Postfix wrote about it in ", + Rich("One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out; or closed by the panel when Postfix no longer held the message and ", Code("mail.log"), " never said what became of it) and rejected (refused before queueing, so it never reached the queue: under a level-2 rate limit, from a client address the application does not allow, or for a ", Code("From:"), " line that is not the application's - the message's page says which). A message's page lists these steps and the lines Postfix wrote about it in ", Code("mail.log"), ", found by queue id. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains."), }}, {ID: HelpQueue, Title: "Queue and retries", Body: []Text{ diff --git a/internal/web/view/pages_test.go b/internal/web/view/pages_test.go index f9acc76..1a72925 100644 --- a/internal/web/view/pages_test.go +++ b/internal/web/view/pages_test.go @@ -177,7 +177,7 @@ func TestHealthShowsEveryCheckAndBothActions(t *testing.T) { t.Errorf("Health is missing %s", want) } } - pageHas(t, "Health", out, `Last 12 months41 s3`, + pageHas(t, "Health", out, `Last 12 months≈ 41 s31`, `Counted since 2026-10-13.`, `href="/help#sender-check"`) // The Configuration box is outside the polled stack: a refresh must not re-render a control. if strings.Contains(out[strings.Index(out, `id="health-stack"`):strings.Index(out, `id="sockets"`)], `action="/server/health/reload"`) { diff --git a/internal/web/view/templates/health_body.html b/internal/web/view/templates/health_body.html index 485b539..2577703 100644 --- a/internal/web/view/templates/health_body.html +++ b/internal/web/view/templates/health_body.html @@ -29,9 +29,9 @@ {{template "box_close"}} {{template "box_open" .SenderCheck}}
- + {{range .SenderRows}} - {{end}} + {{end}}
PeriodPanel not answeringMessages deferred
PeriodPanel not answeringConnections turned awayMessages deferred
{{.Period}}{{.Down}}{{.Deferred}}
{{.Period}}{{.Down}}{{.Deferred}}{{.Messages}}
{{template "body_open"}} diff --git a/test/e2e/sender_check_test.go b/test/e2e/sender_check_test.go index 4d461af..25d171d 100644 --- a/test/e2e/sender_check_test.go +++ b/test/e2e/sender_check_test.go @@ -177,7 +177,8 @@ func testPanelDownDefersMail(t *testing.T, sc *scenario) { } // Server > Health, "Sender check", today: some downtime, one message. - today := regexp.MustCompile(`Today([^<]*)(\d+)`) + // Today: downtime, connections turned away, messages deferred mid-message. + today := regexp.MustCompile(`Today([^<]*)(\d+)(\d+)`) if err := waitFor("Health to show the downtime and the deferred message", 20*time.Second, 500*time.Millisecond, func() (bool, error) { _, body, err := sc.panel.get("/server/health") if err != nil { @@ -201,17 +202,18 @@ func testPanelDownDefersMail(t *testing.T, sc *scenario) { } // senderCheckDeferredToday reads Server > Health's "Sender check" row for -// today: the messages deferred because the check did not answer. +// today: the messages deferred in the middle because the check stopped +// answering (the last column; connections turned away are the one before). func senderCheckDeferredToday(sc *scenario) (int, error) { _, body, err := sc.panel.get("/server/health") if err != nil { return 0, err } - m := regexp.MustCompile(`Today([^<]*)(\d+)`).FindStringSubmatch(body) + m := regexp.MustCompile(`Today([^<]*)(\d+)(\d+)`).FindStringSubmatch(body) if m == nil { return 0, fmt.Errorf("no Sender check row for today on Health") } - return strconv.Atoi(m[2]) + return strconv.Atoi(m[3]) } // testPanelHungMidMessage: a panel that is running and stops answering in the