logtail: count the message a hung sender check defers in cleanup (audit M13)

Seen on the e2e stand, the panel frozen with SIGSTOP once DATA was answered: the client gets 451 4.7.1 after 30 s, and the warning that names the socket is cleanup's, not smtpd's: 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 ... 4.7.1 Service unavailable - try again later; ... The counter read smtpd lines only, so Health's "messages deferred" missed the one case that tells a hung panel from a stopped one. milterLineRe now takes smtpd and cleanup; cleanup's "milter unix:<socket>:" warning counts a message each time (one cleanup process serves message after message, and the first warning ends the message); smtpd keeps once per connection. The composed fixture is replaced by the seen lines, with two messages through one cleanup process and OpenDKIM hung in cleanup (not counted). e2e panel_hung_mid_message_is_counted: freezes the panel after DATA's 354, wants a 4xx at the end of DATA, logs what mail.log says, and waits for Health's today count to grow. kill through sh -c: the image has no kill(1). CHANGELOG [Unreleased], audit plan line ticked, roadmap 13/61. Evidence on the test server for this tree (with the next commit's docs): go vet clean, go test ./... 23 packages ok, make e2e exit 0 - renewed_certificate_picked_up 1.2 s, panel_hung_mid_message_is_counted 31.7 s. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 14:42:01 +03:00
parent 7af37654a1
commit db36aa2c0e
7 changed files with 185 additions and 30 deletions
@@ -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
@@ -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
@@ -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
@@ -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:<socket>: 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,6 +126,12 @@ func (c *deferredCounter) handle(line string, now time.Time, catchingUp bool) {
 			c.failed = make(map[string]bool)
 		}
 		c.failed[pid] = true
+		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
 	}
@@ -118,5 +141,4 @@ func (c *deferredCounter) handle(line string, now time.Time, catchingUp bool) {
 	if err := c.st.AddSenderCheckDeferred(at, 1); err != nil {
 		log.Printf("log-tailer: sender check statistics: %v", err)
 	}
-	}
 }
@@ -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=<a@sender.e2e.test> to=<b@sink.e2e.test> proto=ESMTP helo=<x>`,
+		`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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>`,
+		`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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>`,
+
+		// 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)
 	}
 }

@@ -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)
 	})
@@ -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(`<tr><td>Today</td><td>([^<]*)</td><td>(\d+)</td></tr>`).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)
+	}
+}