sender check: connections and messages counted apart; downtime estimated when supervisord is silent (stage 2b)

Following the design commit df96690. - Two columns (owner, 2026-10-14): sender_check_days.messages (migration 0009, not deployed) holds the messages deferred mid-message, from cleanup's warning; deferred stays the connections smtpd turned away. AddSenderCheckDeferred takes which; the counter passes cleanup's as a message. The card has "Connections turned away" and "Messages deferred"; it warns on either within 24 hours (one mark, as before). - Supervisord silent at start: postfixStarted asks again every 2 s for 30 s (postfixState: started, running, known). With no answer the downtime is the time since the alive mark - an upper bound - booked with estimated = 1 (sender_check_days.estimated, MAX over a day); the card prefixes such a period's time with "≈ " and its note says what ≈ means. Before, such a start counted nothing and the number the owner decides by read low. - Help topic sender-check and the log topic word for word as the mockup (help.go). Tests: store (connections and messages apart, a period with an estimated day); logtail (cleanup's warnings are messages); cmd/panel (supervisord silent: the time since the mark, estimated); view fixture and the Health page at four columns with ≈; e2e reads the row's two counts (panel down: connections; panel hung: messages). Schema at 0009 with the columns. schema-migrations row 9, CHANGELOG [Unreleased], audit plan lines ticked (two), roadmap 28/62. Evidence: go vet ./... clean; go test of store, view, cmd/panel ok locally, logtail but for the Windows-only test; the server run follows before the push. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 17:16:02 +03:00
parent df96690ba6
commit ac985d03a8
19 changed files with 211 additions and 101 deletions
@@ -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
@@ -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)
 	}
 }