from-header-binding: what the reviews had left as found, and address extensions
test / test (push) Canceled after 0s
test / test (push) Canceled after 0s
The owner on the three things the reviews' commit left as found: can they be fixed? They can. - Downtime that crossed a UTC midnight was all booked on the day of the restart: it is cut at the midnights between (byDay). - A message with the null envelope sender - a bounce an application writes itself - left a refusal row without a domain, which no domain administrator would see: the row takes the domain the login is bound to. - A log read again after an unclean stop counted its deferrals again: while the tailer catches up, a warning no later than the last one counted is passed over. The mark is kept to the fraction of a second the log gives. And on the check being stricter than Postfix for an address with an extension (invoices+x@ passed in the envelope, was refused in the header): it makes Postfix's second try now, the address without its extension. recipient_delimiter was the distribution's default; it is set in postfix-config.sh, since the check depends on it. e2e sends one through. Test server, this tree: go vet ok, go test 23 packages ok, make e2e ok (339 s). Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
@@ -153,7 +153,7 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa
|
||||
journal.handle(line, now, catchingUp)
|
||||
}
|
||||
if deferred != nil {
|
||||
deferred.handle(line, now)
|
||||
deferred.handle(line, now, catchingUp)
|
||||
}
|
||||
keeper.add(line, now, catchingUp)
|
||||
queueID, recipient, status, ok := parseDelivery(line)
|
||||
|
||||
@@ -33,9 +33,11 @@ import (
|
||||
// "milter unix:<socket>: can't read … reply packet header" (Postfix's
|
||||
// milter8.c; not seen on the stand).
|
||||
|
||||
// SenderCheckStore is where the count goes. *store.Store satisfies it.
|
||||
// SenderCheckStore is where the count goes, and where the time of the last
|
||||
// counted line is kept. *store.Store satisfies it.
|
||||
type SenderCheckStore interface {
|
||||
AddSenderCheckDeferred(at time.Time, n int64) error
|
||||
SenderCheckDeferredAt() (time.Time, error)
|
||||
}
|
||||
|
||||
// SenderCheck turns the counting on: the store and the socket Postfix was
|
||||
@@ -60,10 +62,22 @@ type deferredCounter struct {
|
||||
// listening, and a reply that did not come.
|
||||
connect, broken string
|
||||
failed map[string]bool // smtpd pid -> its current client was counted already
|
||||
// last is the time of the latest line counted, by this run or an earlier
|
||||
// one. While the tailer catches up after a start it may be reading lines
|
||||
// it had read before an unclean stop; a warning no later than this was
|
||||
// counted then. mail.log's stamps are whole seconds, so a warning of the
|
||||
// very second of the last one counted can be passed over - once, at a
|
||||
// restart - which is the cheaper mistake than counting a stretch twice.
|
||||
last time.Time
|
||||
}
|
||||
|
||||
func newDeferredCounter(sc *SenderCheck) *deferredCounter {
|
||||
last, err := sc.Store.SenderCheckDeferredAt()
|
||||
if err != nil {
|
||||
log.Printf("log-tailer: sender check statistics: %v", err)
|
||||
}
|
||||
return &deferredCounter{
|
||||
last: last,
|
||||
st: sc.Store,
|
||||
connect: "warning: connect to Milter service unix:" + sc.Socket + ":",
|
||||
broken: "warning: milter unix:" + sc.Socket + ":",
|
||||
@@ -71,8 +85,9 @@ func newDeferredCounter(sc *SenderCheck) *deferredCounter {
|
||||
}
|
||||
}
|
||||
|
||||
// handle looks at one mail.log line.
|
||||
func (c *deferredCounter) handle(line string, now time.Time) {
|
||||
// handle looks at one mail.log line. catchingUp is true until the tailer has
|
||||
// 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)
|
||||
if m == nil {
|
||||
@@ -94,6 +109,12 @@ func (c *deferredCounter) handle(line string, now time.Time) {
|
||||
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)
|
||||
}
|
||||
|
||||
@@ -7,13 +7,19 @@ import (
|
||||
|
||||
type deferredStore struct {
|
||||
days map[string]int64
|
||||
last time.Time
|
||||
}
|
||||
|
||||
func (d *deferredStore) SenderCheckDeferredAt() (time.Time, error) { return d.last, nil }
|
||||
|
||||
func (d *deferredStore) AddSenderCheckDeferred(at time.Time, n int64) error {
|
||||
if d.days == nil {
|
||||
d.days = make(map[string]int64)
|
||||
}
|
||||
d.days[at.UTC().Format("2006-01-02")] += n
|
||||
if at.After(d.last) {
|
||||
d.last = at
|
||||
}
|
||||
return nil
|
||||
}
|
||||
|
||||
@@ -65,9 +71,41 @@ func TestDeferredCounter(t *testing.T) {
|
||||
// cleanup that writes it.
|
||||
`2026-10-13T00:01:00.000000+00:00 mail postfix/cleanup[1195]: B6B484831946: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: director@other.e2e.test - not an address this application sends as; from=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<x>`,
|
||||
} {
|
||||
c.handle(line, now)
|
||||
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)
|
||||
}
|
||||
}
|
||||
|
||||
// After an unclean stop the tailer reads again some lines it had read. What
|
||||
// was counted then is not counted now; what was written while the panel was
|
||||
// down - the very lines this count exists for - is.
|
||||
func TestDeferredCounterDoesNotCountALogReadAgain(t *testing.T) {
|
||||
st := &deferredStore{}
|
||||
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
|
||||
outage := func(pid, at string) []string {
|
||||
return []string{
|
||||
at + `0+00:00 mail postfix/smtpd[` + pid + `]: connect from unknown[10.77.0.1]`,
|
||||
at + `1+00:00 mail postfix/smtpd[` + pid + `]: warning: connect to Milter service unix:/run/selfpost/sender.sock: Connection refused`,
|
||||
}
|
||||
}
|
||||
first := append(outage("11", "2026-10-12T16:00:00.00000"), outage("12", "2026-10-12T16:00:05.00000")...)
|
||||
|
||||
c := newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"})
|
||||
for _, line := range first {
|
||||
c.handle(line, now, false)
|
||||
}
|
||||
if st.days["2026-10-12"] != 2 {
|
||||
t.Fatalf("first run counted %d, want 2", st.days["2026-10-12"])
|
||||
}
|
||||
|
||||
// A new run: the same lines again, then what the outage added.
|
||||
c = newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"})
|
||||
for _, line := range append(first, outage("13", "2026-10-12T16:00:09.00000")...) {
|
||||
c.handle(line, now, true)
|
||||
}
|
||||
if st.days["2026-10-12"] != 3 {
|
||||
t.Fatalf("after the restart the day has %d, want 3", st.days["2026-10-12"])
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user