diff --git a/CHANGELOG.md b/CHANGELOG.md index e36cc63..c933d14 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -37,6 +37,13 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version key belong together, renews the copy and reloads Postfix; when nothing changed it no longer reloads (audit 2026-10-12, H2). +- **Health counts mail deferred by a panel that hangs mid-message.** The + figure "messages deferred" on the Sender check card read only smtpd's + lines, but once a message's DATA has begun it is cleanup that talks to the + check, and its warning was never counted - the very case that tells a hung + panel from a stopped one. Seen on the e2e stand with the panel frozen, and + now counted, once per message (audit 2026-10-12, M13). + ### Added - **The delivery log measures its own guesses** (migration `0007`). A table diff --git a/docs/audit-2026-10-12.md b/docs/audit-2026-10-12.md index de54fc1..9220892 100644 --- a/docs/audit-2026-10-12.md +++ b/docs/audit-2026-10-12.md @@ -633,7 +633,7 @@ has already run is never edited — the next file is added; the published to the copy and re-copies before `postfix reload` (atomically, same modes); e2e replaces the cert in the stand and reads the new serial off 465. — **Opus** -- [ ] **Deferred counter** (M13): on the stand, `kill -STOP` the panel mid-message +- [x] **Deferred counter** (M13): on the stand, `kill -STOP` the panel mid-message and record which program logs the warning; widen the matcher accordingly and replace the composed fixture with the seen lines. — **Opus** - [ ] Docs: architecture § Log tailer, § Queue reconcile (the measurement and diff --git a/docs/roadmap.md b/docs/roadmap.md index 2406a5c..3df32bf 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`; next stages 1+2 → `2.5.0`) | 12/61 | [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`; next stages 1+2 → `2.5.0`) | 13/61 | [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/internal/logtail/sendercheck.go b/internal/logtail/sendercheck.go index 526aac4..e75f743 100644 --- a/internal/logtail/sendercheck.go +++ b/internal/logtail/sendercheck.go @@ -27,11 +27,21 @@ import ( // // It is counted at the warning, which is the one line that names the socket. // The reject lines do not: the same words are written when OpenDKIM does not -// answer and when the journal milter refuses under a level-2 limit, and for a -// check that stops answering in the middle of a message they are written by -// cleanup, another process, under a queue id. The warning for that case is -// "milter unix:: can't read … reply packet header" (Postfix's -// milter8.c; not seen on the stand). +// answer and when the journal milter refuses under a level-2 limit. +// +// A check that is running and stops answering in the middle of a message - +// its socket accepts, nothing replies - is met by cleanup, not smtpd: past the +// DATA command it is cleanup that talks to the milters. Seen on the e2e stand +// with the panel frozen (SIGSTOP) once DATA was answered (2026-10-14): +// +// postfix/cleanup[1339]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_HEADER reply packet header: Connection timed out +// postfix/cleanup[1339]: 7BCAF3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from=<…> to=<…> proto=ESMTP helo=<…> +// +// One cleanup process serves message after message and the first warning +// ends the message, so each such warning is a message, counted on its own. +// Until 2.5.0 only smtpd's lines were read, and this case - the one that +// tells a hung panel from a stopped one - was never counted (audit +// 2026-10-12, M13). // SenderCheckStore is where the count goes, and where the time of the last // counted line is kept. *store.Store satisfies it. @@ -47,7 +57,7 @@ type SenderCheck struct { Socket string } -var smtpdLineRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?smtpd\[(\d+)\]: (.*)$`) +var milterLineRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?(smtpd|cleanup)\[(\d+)\]: (.*)$`) const ( // senderCheckPids bounds the processes remembered; smtpd processes are a @@ -89,11 +99,18 @@ func newDeferredCounter(sc *SenderCheck) *deferredCounter { // read to the end of the log for the first time. func (c *deferredCounter) handle(line string, now time.Time, catchingUp bool) { at, rest := lineTime(line, now) - m := smtpdLineRe.FindStringSubmatch(rest) + m := milterLineRe.FindStringSubmatch(rest) if m == nil { return } - pid, text := m[1], m[2] + program, pid, text := m[1], m[2], m[3] + 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) + } + return + } switch { case strings.HasPrefix(text, "connect from "): delete(c.failed, pid) @@ -109,14 +126,19 @@ func (c *deferredCounter) handle(line string, now time.Time, catchingUp bool) { c.failed = make(map[string]bool) } c.failed[pid] = true - if catchingUp && !at.After(c.last) { - return - } - if at.After(c.last) { - c.last = at - } - if err := c.st.AddSenderCheckDeferred(at, 1); err != nil { - log.Printf("log-tailer: sender check statistics: %v", err) - } + c.count(at, catchingUp) + } +} + +// count adds one deferred message at at, unless it is a line read again. +func (c *deferredCounter) count(at time.Time, catchingUp bool) { + if catchingUp && !at.After(c.last) { + return + } + if at.After(c.last) { + c.last = at + } + if err := c.st.AddSenderCheckDeferred(at, 1); 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 dfde2c3..8d19c8e 100644 --- a/internal/logtail/sendercheck_test.go +++ b/internal/logtail/sendercheck_test.go @@ -24,11 +24,11 @@ func (d *deferredStore) AddSenderCheckDeferred(at time.Time, n int64) error { } // The lines of process 1183 and of cleanup are as the e2e stand wrote them -// with the panel stopped and for a refused From: (2026-10-12; the stamps are -// put in ISO form). Around them are the lines of two other things that use -// the same words - a level-2 refusal of the journal milter, OpenDKIM not -// answering - and, composed from Postfix's source rather than seen, a check -// that stops answering in the middle of a message. +// with the panel stopped and for a refused From: (2026-10-12), and with the +// panel frozen in the middle of a message (cleanup 1339, 2026-10-14); the +// stamps are put in ISO form. Around them are the lines of two other things +// that use the same words - a level-2 refusal of the journal milter, OpenDKIM +// not answering. func TestDeferredCounter(t *testing.T) { st := &deferredStore{} c := newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"}) @@ -61,11 +61,17 @@ func TestDeferredCounter(t *testing.T) { `2026-10-12T16:24:00.100000+00:00 mail postfix/smtpd[1201]: warning: connect to Milter service unix:/run/opendkim/opendkim.sock: Connection refused`, `2026-10-12T16:24:00.200000+00:00 mail postfix/smtpd[1201]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`, - // The check stops answering in the middle of a message, the next day. + // The check stops answering in the middle of a message, the next day: + // cleanup meets it. Two messages through the same cleanup process are + // two messages. `2026-10-13T00:00:05.000000+00:00 mail postfix/smtpd[1300]: connect from unknown[10.77.0.1]`, - `2026-10-13T00:00:21.000000+00:00 mail postfix/smtpd[1300]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_EOH reply packet header: Connection timed out`, - `2026-10-13T00:00:21.050000+00:00 mail postfix/smtpd[1300]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_BODYEOB reply packet header: Connection timed out`, - `2026-10-13T00:00:21.100000+00:00 mail postfix/cleanup[1195]: 4XcB7k2Jm9z1: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from= to= proto=ESMTP helo=`, + `2026-10-13T00:00:35.000000+00:00 mail postfix/cleanup[1339]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`, + `2026-10-13T00:00:35.100000+00:00 mail postfix/cleanup[1339]: 7BCAF3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from= to= proto=ESMTP helo=`, + `2026-10-13T00:01:20.000000+00:00 mail postfix/cleanup[1339]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`, + `2026-10-13T00:01:20.100000+00:00 mail postfix/cleanup[1339]: 8C1D43C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from= to= proto=ESMTP helo=`, + + // OpenDKIM hung in the middle of a message: another socket. + `2026-10-13T00:01:30.000000+00:00 mail postfix/cleanup[1339]: warning: milter unix:/run/opendkim/opendkim.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`, // The check's own verdict is a refusal, not a deferral, and it is // cleanup that writes it. @@ -73,8 +79,8 @@ func TestDeferredCounter(t *testing.T) { } { c.handle(line, now, false) } - if len(st.days) != 2 || st.days["2026-10-12"] != 1 || st.days["2026-10-13"] != 1 { - t.Fatalf("deferred per day = %v, want one on each of the two days", st.days) + 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) } } diff --git a/test/e2e/main_test.go b/test/e2e/main_test.go index da36c21..f0aa33e 100644 --- a/test/e2e/main_test.go +++ b/test/e2e/main_test.go @@ -310,6 +310,9 @@ func TestE2E(t *testing.T) { run("panel_down_defers_mail", func(t *testing.T) { testPanelDownDefersMail(t, sc) }) + run("panel_hung_mid_message_is_counted", func(t *testing.T) { + testPanelHungMidMessage(t, sc) + }) run("session_survives_restart", func(t *testing.T) { testSessionSurvivesRestart(t, sc) }) diff --git a/test/e2e/sender_check_test.go b/test/e2e/sender_check_test.go index f1085ef..a4b14a7 100644 --- a/test/e2e/sender_check_test.go +++ b/test/e2e/sender_check_test.go @@ -1,8 +1,11 @@ package e2e import ( + "crypto/tls" "errors" "fmt" + "net" + "net/smtp" "net/textproto" "regexp" "strconv" @@ -187,3 +190,117 @@ func testPanelDownDefersMail(t *testing.T, sc *scenario) { t.Fatal(err) } } + +// senderCheckDeferredToday reads Server > Health's "Sender check" row for +// today: the messages deferred because the check did not answer. +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) + if m == nil { + return 0, fmt.Errorf("no Sender check row for today on Health") + } + return strconv.Atoi(m[2]) +} + +// testPanelHungMidMessage: a panel that is running and stops answering in the +// middle of a message - its socket still accepts, nothing replies. The +// message is deferred, and the count on Health sees it. Past the DATA +// command Postfix's cleanup, not smtpd, talks to the milters, so the warning +// that names the socket is cleanup's (audit 2026-10-12, M13: the counter read +// smtpd's lines only). The panel is frozen with SIGSTOP once DATA is +// answered, and thawed after the client has its reply. +func testPanelHungMidMessage(t *testing.T, sc *scenario) { + before, err := senderCheckDeferredToday(sc) + if err != nil { + t.Fatal(err) + } + pidOut, err := h.execIn("selfpost", "supervisorctl", "-c", "/etc/supervisor/supervisord.conf", "pid", "panel") + if err != nil { + t.Fatalf("panel pid: %v (%s)", err, pidOut) + } + pid := strings.TrimSpace(pidOut) + if _, err := strconv.Atoi(pid); err != nil { + t.Fatalf("panel pid: %q", pidOut) + } + signal := func(sig string) error { + // kill is the shell's: the image has no kill(1). + _, err := h.execIn("selfpost", "sh", "-c", "kill -"+sig+" "+pid) + return err + } + thawed := false + thaw := func() { + if !thawed { + thawed = true + _ = signal("CONT") + } + } + t.Cleanup(thaw) + + conn, err := tls.DialWithDialer(&net.Dialer{Timeout: 10 * time.Second}, "tcp", smtpsAddr, &tls.Config{ + InsecureSkipVerify: true, + ServerName: selfpostHostname, + }) + if err != nil { + t.Fatal(err) + } + _ = conn.SetDeadline(time.Now().Add(3 * time.Minute)) + c, err := smtp.NewClient(conn, selfpostHostname) + if err != nil { + t.Fatal(err) + } + defer c.Close() + from := "alerts@" + senderDomain + if err := c.Hello("e2e-client.e2e.test"); err != nil { + t.Fatal(err) + } + if err := c.Auth(smtp.PlainAuth("", sc.appLogin, sc.appPassword, selfpostHostname)); err != nil { + t.Fatal(err) + } + if err := c.Mail(from); err != nil { + t.Fatal(err) + } + if err := c.Rcpt(recipient); err != nil { + t.Fatal(err) + } + w, err := c.Data() + if err != nil { + t.Fatal(err) + } + if err := signal("STOP"); err != nil { + t.Fatalf("freeze the panel: %v", err) + } + started := time.Now() + _, err = w.Write([]byte(buildMessage(sendAttempt{from: from, to: recipient, subject: "e2e " + uniqueToken("panelhung"), body: "must be deferred"}))) + if err == nil { + err = w.Close() + } + t.Logf("end of DATA answered after %s: %v", time.Since(started).Round(time.Second), err) + thaw() + var reply *textproto.Error + if !errors.As(err, &reply) || reply.Code/100 != 4 { + t.Fatalf("want a temporary 4xx at the end of DATA with the panel frozen, got %v", err) + } + _ = c.Quit() + + // What Postfix wrote, so that the program and the wording are seen here + // and not assumed. + if out, err := h.execIn("selfpost", "sh", "-c", "grep -i 'milter' /data/log/mail.log | tail -n 8"); err == nil { + t.Logf("mail.log on the frozen panel:\n%s", out) + } + + if err := waitFor("Health to count the message deferred mid-message", 30*time.Second, 500*time.Millisecond, func() (bool, error) { + n, err := senderCheckDeferredToday(sc) + if err != nil { + return false, err + } + if n <= before { + return false, fmt.Errorf("messages deferred today: %d, as before", n) + } + return true, nil + }); err != nil { + t.Fatal(err) + } +}