package logtail import ( "log" "regexp" "strings" "time" ) // The sender check is attached to Postfix strictly: while the panel does not // answer on its socket, mail is deferred (docs/plans/from-header-binding.md). // How many submissions that happened to is read here, from what Postfix // writes about it, and shown on Server > Health. It is the figure that also // sees a panel which is running and not answering. // // Postfix says it in lines of one smtpd process - why, then what (seen on // the e2e stand, 2026-10-12): // // postfix/smtpd[1183]: warning: connect to Milter service unix:/run/selfpost/sender.sock: No such file or directory // postfix/smtpd[1183]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP // postfix/smtpd[1183]: NOQUEUE: milter-reject: EHLO from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP helo= // // and the client, told "454 4.3.0 Try again later" at AUTH, goes away without // a line of its own. So what is counted is the connection Postfix turned // away, once: a client brings a message when it connects, and it will bring // it again. // // 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. // // 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. 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 // given for the check (SENDER_CHECK_SOCKET), as a path. type SenderCheck struct { Store SenderCheckStore Socket string } var milterLineRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?(smtpd|cleanup)\[(\d+)\]: (.*)$`) const ( // senderCheckPids bounds the processes remembered; smtpd processes are a // few dozen, and a log that names more is not kept track of. senderCheckPids = 1024 ) // deferredCounter is the per-run state of the count. type deferredCounter struct { st SenderCheckStore // The two warnings, up to and including the socket's name: nobody // 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 + ":", failed: make(map[string]bool), } } // 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 := milterLineRe.FindStringSubmatch(rest) if m == nil { return } 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) case strings.HasPrefix(text, c.connect) || strings.HasPrefix(text, c.broken): // Postfix's own two sentences, from their first word: a warning also // quotes what a client sent ("Illegal address syntax ... in MAIL // command: "), and a client can send the socket's name. // Once for the connection, however many warnings it draws. if c.failed[pid] { return } if len(c.failed) >= senderCheckPids { 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 } 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) } }