base-trixie: the image on Debian trixie, Postfix 3.10.13; Received: hidden on 465/587
test / test (push) Canceled after 0s

The runtime base is debian:trixie-slim, the build stage golang:1.26-trixie:
Postfix 3.10.13 with upstream's 2026 security fixes up to the August
batch, libmilter 8.18.1, OpenSSL 3.5. Every citation of another program in
code, scripts and documents was re-read against the trixie sources
(dev/upstream; bookworm's kept in dev/upstream-bookworm) and updated;
development.md's cited-package table holds the trixie versions.

What the re-reading changed in behaviour:
- logtail: reject lines with sasl_method/sasl_username/sasl_sender
  (smtpd_check.c:1019-1026); cleanup's "removed (canceled)" forgets a
  port-25 id (cleanup_api.c:363-364).
- internal/postfix/retry.go reads postconf's stdout only: since 3.9 a
  deprecated-parameter warning on stderr made one value too many and the
  panel fell back to the compiled-in retry policy.
- logrotate-loop.sh: logrotate 3.22 exits 1 when it ignores a config;
  the loop refuses on that output whatever the status.
- postfix-config.sh: cyrus_sasl_config_path set explicitly (bookworm's
  07_sasl_config.diff is gone); maillog_file_permissions=0640; mynetworks
  explicit; Dockerfile: SYNC_CHROOT= in /etc/default/postfix,
  opendkim-tools dropped, openssl named, systemd-standalone-sysusers so
  cron does not bring the whole of systemd.
- The selfpost group is 10998, outside the system range 100-999: in
  trixie a package took 998 and the build failed (owner's decision:
  a conflict-free id, the distribution's own ids untouched). The
  entrypoint hands /data back by name when the user or the group differs.
  Guide, backup refusal text, help (design commit 68ec8b2), e2e.
- smtpd_hide_client_session=yes on smtps and submission (owner's
  decision): Received: names no client, TLS, login or protocol; port 25
  keeps the full header. e2e checks both.
- test/upstream/opendkim-probe.sh makes keys with openssl genrsa.

Tests: on the server, make e2e exit 0 (674 s, the image built on trixie),
go vet + go test 27 packages ok. CHANGELOG [Unreleased], guide,
architecture.md, security.md, roadmap.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
mix
2026-10-15 19:31:35 +03:00
co-authored by Claude Opus 5.5
parent 68ec8b274c
commit 1c6e04b7d3
80 changed files with 970 additions and 454 deletions
+28 -16
View File
@@ -45,11 +45,15 @@ type Inbound struct {
// so it counts only for a queue id the port-25 smtpd was seen to open
// (inboundClientRe).
//
// Postfix 3.7.11: smtpd's refusal is src/smtpd/smtpd_check.c, log_whatsup():
// Postfix 3.10.13: smtpd's refusal is src/smtpd/smtpd_check.c, log_whatsup():
// "%s: %s: %s from %s: %s;" then " from=<..>", " to=<..>", " proto=",
// " helo=<..>", nothing after; a milter's at smtpd is src/smtpd/smtpd.c,
// " helo=<..>", then - new in 3.10 (RELEASE_NOTES, [Incompat 20241023]) -
// " sasl_method=%s", " sasl_username=%s" and " sasl_sender=%s" for a session
// that has them, nothing after; a milter's at smtpd is src/smtpd/smtpd.c,
// check_milter_reply(), whose smtpd_whatsup() appends " sasl_username=<..>"
// only to an authenticated session (SASL is off on port 25). "name[addr]" is
// only to an authenticated session. SASL is off on port 25
// (build/postfix-config.sh, smtpd_sasl_auth_enable=no), so neither tail is
// written there; the pattern takes the 3.10 one all the same. "name[addr]" is
// state->namaddr, the address without "IPv6:" (smtpd.h,
// SMTPD_BUILD_NAMADDRPORT). cleanup's is src/cleanup/cleanup_milter.c,
// cleanup_milter_apply(); smtpd hands it to the one cleanup service
@@ -64,21 +68,29 @@ type Inbound struct {
// journal rows.
//
// For the same reason the reply is the shortest text before "; from=<", and
// the HELO name - the last thing on the line, which Postfix logs as the client
// wrote it, spaces and brackets included - is whatever is left. Taking the
// longest reply instead would let a HELO name that itself spells
// the HELO name - the last thing on the line but the SASL fields above, which
// Postfix logs as the client wrote it, spaces and brackets included - is
// whatever is left. Taking the longest reply instead would let a HELO name
// that itself spells
// "; from=<…> to=<…> proto=…" supply the sender, the recipient and the reply
// of the row (security review, 2026-10-12).
var (
inboundRejectRe = regexp.MustCompile(`^\S+ postfix/(inbound/smtpd|cleanup)\[\d+\]: ([0-9A-Za-z]+): (reject|milter-reject|milter-discard): \S+ from [^\[\s]*\[([0-9A-Fa-f:.]+)\]: (.*?); from=<([^>]*)> to=<([^>]*)> proto=\S+(?: helo=<.*>)?$`)
inboundRejectRe = regexp.MustCompile(`^\S+ postfix/(inbound/smtpd|cleanup)\[\d+\]: ([0-9A-Za-z]+): (reject|milter-reject|milter-discard): \S+ from [^\[\s]*\[([0-9A-Fa-f:.]+)\]: (.*?); from=<([^>]*)> to=<([^>]*)> proto=\S+(?: helo=<.*>)?(?: sasl_(?:method|username|sender)=.*)?$`)
inboundClientRe = regexp.MustCompile(`^\S+ postfix/inbound/smtpd\[\d+\]: ([0-9A-Za-z]+): client=`)
// A queue id stops being port 25's when the message is queued (qmgr takes
// it: the filter let it through) or when another listener opens a message
// under the same id - Postfix reuses ids. Postfix 3.7.11,
// it: the filter let it through), when cleanup removes the queue file of
// a message it did not queue, or when another listener opens a message
// under the same id - Postfix reuses ids. Postfix 3.10.13,
// src/qmgr/qmgr_message.c, qmgr_message_read() calls opened()
// (src/global/opened.c: "%s: from=<%s>, size=%ld, nrcpt=%d") for a queue
// file cleanup has committed, each time it enters the active queue.
inboundForgetRe = regexp.MustCompile(`^\S+ postfix/(?:qmgr\[\d+\]: ([0-9A-Za-z]+): from=|(?:[a-z0-9-]+/)?smtpd\[\d+\]: ([0-9A-Za-z]+): client=)`)
// file cleanup has committed, each time it enters the active queue;
// src/cleanup/cleanup_api.c, cleanup_flush(): "%s: removed (%s)", with
// "canceled" or "discarded", once the queue file of a refused, discarded
// or unfinished message is gone (new in 3.10, HISTORY 20241112) - after
// the verdict line, which cleanup_milter_inspect() writes earlier in
// cleanup_flush(). Without it, the id of a message whose client went away
// in DATA stayed until inboundQueueIDs pushed it out.
inboundForgetRe = regexp.MustCompile(`^\S+ postfix/(?:qmgr\[\d+\]: ([0-9A-Za-z]+): from=|(?:[a-z0-9-]+/)?smtpd\[\d+\]: ([0-9A-Za-z]+): client=|cleanup\[\d+\]: ([0-9A-Za-z]+): removed \()`)
)
// A row holds one line of reason; Postfix's reply text carries the far end's
@@ -95,7 +107,7 @@ const inboundQueueIDs = 4096
// journal cut back to its row cap, without waiting for the six-hourly prune.
// Refusals are written at the rate strangers send RCPT TO. Postfix's one
// limit on that, smtpd_client_recipient_rate_limit, is per client address and
// off by default (postconf(5), Postfix 3.7.11) and not set here, so between
// off by default (postconf(5), Postfix 3.10.13) and not set here, so between
// two prunes the journal would otherwise grow as fast as someone cared to
// make it.
const inboundPruneEvery = 500
@@ -140,7 +152,7 @@ func (j *inboundJournal) handle(line string, now time.Time, catchingUp bool) {
return
}
if m := inboundForgetRe.FindStringSubmatch(rest); m != nil {
delete(j.port25, m[1]+m[2])
delete(j.port25, m[1]+m[2]+m[3])
return
}
m := inboundRejectRe.FindStringSubmatch(rest)
@@ -150,7 +162,7 @@ func (j *inboundJournal) handle(line string, now time.Time, catchingUp bool) {
program, queueID, kind, clientIP, reason, from, to := m[1], m[2], m[3], m[4], m[5], m[6], m[7]
// The sender's address is his own text too, and with a quoted local part it
// may hold "> to=<…> proto=…" - which would end the sender early and supply
// the recipient (Postfix 3.7.11 logs addresses in external form, the local
// the recipient (Postfix 3.10.13 logs addresses in external form, the local
// part quoted when it holds spaces or specials: postconf(5)
// info_log_address_format, src/global/info_log_addr_form.c). Such a line
// shows it: the sender is left with an unclosed quote. An address with a
@@ -198,7 +210,7 @@ func (j *inboundJournal) handle(line string, now time.Time, catchingUp bool) {
e.Engine = store.SpamEnginePostfix
}
// "450 4.7.1 …" from Postfix, "4.7.1 …" from a milter: either way a reply
// that starts with 4 asks the sender to come back. Postfix 3.7.11:
// that starts with 4 asks the sender to come back. Postfix 3.10.13:
// smtpd_check_reject() logs smtpd's whole "%d %s ..." reply through
// log_whatsup(); cleanup_milter_apply() logs a
// milter's from its fifth byte (text = resp + 4), so the enhanced code
@@ -263,7 +275,7 @@ func printable(s string, max int) string {
// tailer got to it: after the panel was down the two are hours apart. The
// syslog format carries neither year nor zone - the year is taken from now
// (a stamp that would then lie in the future is last year's), the zone is the
// container's. Postfix 3.7.11, src/util/msg_logger.c, msg_logger_print(): the
// container's. Postfix 3.10.13, src/util/msg_logger.c, msg_logger_print(): the
// stamp is made by the process that logs, with localtime(), and postlogd
// writes it unchanged (src/postlogd/postlogd.c, postlogd_service()); that
// process has the container's zone (TZ is in import_environment,
+53 -10
View File
@@ -53,8 +53,9 @@ func inboundFixture() (*inboundJournal, *fakeInboundStore) {
var tailNow = time.Date(2026, 10, 11, 18, 0, 0, 0, time.UTC)
// The mail.log lines in this file are composed by hand, after
// src/smtpd/smtpd_check.c log_whatsup() and src/cleanup/cleanup_milter.c
// cleanup_milter_apply() (Postfix 3.7.11), with the stamp Postfix 3.7 writes
// src/smtpd/smtpd_check.c log_whatsup(), src/cleanup/cleanup_milter.c
// cleanup_milter_apply() and src/cleanup/cleanup_api.c cleanup_flush()
// (Postfix 3.10.13), with the stamp Postfix 3.10 writes
// (src/util/msg_logger.c, "%b %d %H:%M:%S").
const (
head = "Oct 11 12:00:05 mail "
@@ -89,6 +90,26 @@ func TestInboundTempfailByPostfix(t *testing.T) {
}
}
// Postfix 3.10's log_whatsup() appends " sasl_method=%s", " sasl_username=%s"
// and " sasl_sender=%s" after the HELO name for a session that has them
// (src/smtpd/smtpd_check.c; RELEASE_NOTES, [Incompat 20241023]). Port 25 has
// SASL off, so it never writes them there; a line that had them, with the
// HELO name or without it, is still read for what comes before. Composed
// from that format.
func TestInboundRejectTakesTheSASLTail(t *testing.T) {
for name, line := range map[string]string{
"after the HELO name": head + "postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from mx.example.net[203.0.113.9]: 550 5.1.1 <nobody@in.example.com>: Recipient address rejected: User unknown in relay recipient table; from=<a@example.net> to=<nobody@in.example.com> proto=ESMTP helo=<mx.example.net> sasl_method=PLAIN sasl_username=u sasl_sender=s",
"with no HELO name": head + "postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from mx.example.net[203.0.113.9]: 550 5.1.1 <nobody@in.example.com>: Recipient address rejected: User unknown in relay recipient table; from=<a@example.net> to=<nobody@in.example.com> proto=ESMTP sasl_method=PLAIN sasl_username=u",
} {
j, st := inboundFixture()
j.handle(line, tailNow, false)
if len(st.rows) != 1 || st.rows[0].From != "a@example.net" || st.rows[0].To != "nobody@in.example.com" ||
st.rows[0].Detail != "550 5.1.1 <nobody@in.example.com>: Recipient address rejected: User unknown in relay recipient table" {
t.Errorf("%s: rows = %+v", name, st.rows)
}
}
}
// The filter's verdict is written by cleanup, under one name for every
// listener: it is the journal's only for a queue id port 25 opened.
func TestInboundMilterVerdictNeedsAPort25QueueID(t *testing.T) {
@@ -137,7 +158,7 @@ func TestInboundIgnores(t *testing.T) {
for name, line := range map[string]string{
"another domain (relay access denied)": head + "postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from x[203.0.113.9]: 554 5.7.1 <c@elsewhere.example>: Relay access denied; from=<a@example.net> to=<c@elsewhere.example> proto=ESMTP helo=<x>",
"no recipient (size limit at MAIL)": head + "postfix/inbound/smtpd[41]: NOQUEUE: reject: MAIL from x[203.0.113.9]: 552 5.3.4 Message size exceeds fixed limit; proto=ESMTP helo=<x>",
"a submission port": head + "postfix/smtpd[20]: NOQUEUE: reject: RCPT from x[203.0.113.9]: 553 5.7.1 <b@in.example.com>: Sender address rejected: not owned by user app; from=<a@example.net> to=<b@in.example.com> proto=ESMTP helo=<x>",
"a submission port": head + "postfix/smtpd[20]: NOQUEUE: reject: RCPT from x[203.0.113.9]: 553 5.7.1 <b@in.example.com>: Sender address rejected: not owned by user app; from=<a@example.net> to=<b@in.example.com> proto=ESMTP helo=<x> sasl_method=PLAIN sasl_username=app",
"a delivery line": head + "postfix/smtp[26]: 41E862C00D9E: to=<b@in.example.com>, relay=mx[203.0.113.9]:25, dsn=2.0.0, status=sent (250 OK)",
"a connect line": head + "postfix/inbound/smtpd[41]: connect from mx.example.net[203.0.113.9]",
// The HELO name is the sender's; a line cannot be started from inside one.
@@ -176,11 +197,28 @@ func TestInboundLookupFailureLeavesNoRow(t *testing.T) {
// A message the filter holds goes on to the inbound journal milter, which
// writes its row; a second one from the log would be the same message twice.
func TestInboundHoldIsTheMiltersRow(t *testing.T) {
j, st := inboundFixture()
j.handle(head+"postfix/inbound/smtpd[41]: Q1: client=mx.example.net[203.0.113.9]", tailNow, false)
j.handle(head+"postfix/cleanup[52]: Q1: milter-hold: END-OF-MESSAGE from mx.example.net[203.0.113.9]: milter triggers HOLD action; from=<a@example.net> to=<b@in.example.com> proto=ESMTP helo=<mx.example.net>", tailNow, false)
if len(st.rows) != 0 {
t.Errorf("rows = %+v", st.rows)
// Postfix 3.10.13 logs a quarantine with the milter's reason, or
// "default_action" when milter_default_action asked for it, where 3.7
// wrote "milter triggers HOLD action" (src/cleanup/cleanup_milter.c,
// cleanup_milter_apply(), and src/smtpd/smtpd.c, check_milter_reply():
// text = reply[1] ? reply + 1 : "milter triggers HOLD action";
// src/milter/milter8.c, SMFIR_QUARANTINE "H%.*s" and milter8_comm_error()
// "Hdefault_action"). Whatever the reason says, the line is a hold.
// Composed from those formats.
for _, hold := range []string{
"postfix/cleanup[52]: Q1: milter-hold: END-OF-MESSAGE from mx.example.net[203.0.113.9]: milter triggers HOLD action; from=<a@example.net> to=<b@in.example.com> proto=ESMTP helo=<mx.example.net>",
"postfix/cleanup[52]: Q1: milter-hold: END-OF-MESSAGE from mx.example.net[203.0.113.9]: Gtube pattern; from=<a@example.net> to=<b@in.example.com> proto=ESMTP helo=<mx.example.net>",
"postfix/cleanup[52]: Q1: milter-hold: END-OF-MESSAGE from mx.example.net[203.0.113.9]: default_action; from=<a@example.net> to=<b@in.example.com> proto=ESMTP helo=<mx.example.net>",
// A reason that spells a reject is still the reason of a hold.
"postfix/cleanup[52]: Q1: milter-hold: END-OF-MESSAGE from mx.example.net[203.0.113.9]: x: milter-reject: END-OF-MESSAGE from y[192.0.2.1]: 5.7.1 no; from=<a@example.net> to=<b@in.example.com> proto=ESMTP helo=<mx.example.net>",
"postfix/inbound/smtpd[41]: Q1: milter-hold: RCPT from mx.example.net[203.0.113.9]: held for review; from=<a@example.net> to=<b@in.example.com> proto=ESMTP helo=<mx.example.net>",
} {
j, st := inboundFixture()
j.handle(head+"postfix/inbound/smtpd[41]: Q1: client=mx.example.net[203.0.113.9]", tailNow, false)
j.handle(head+hold, tailNow, false)
if len(st.rows) != 0 {
t.Errorf("%s: rows = %+v", hold, st.rows)
}
}
}
@@ -216,13 +254,18 @@ func TestInboundHeloCannotWriteTheRow(t *testing.T) {
}
}
// A queue id is port 25's only until the message is queued or the id is
// opened again by another listener - Postfix reuses ids.
// A queue id is port 25's only until the message is queued, cleanup removes
// it unqueued, or the id is opened again by another listener - Postfix reuses
// ids.
func TestInboundQueueIDIsForgotten(t *testing.T) {
const verdict = "postfix/cleanup[52]: Q1: milter-reject: END-OF-MESSAGE from app[203.0.113.4]: 4.7.1 Service unavailable - try again later; from=<a@example.net> to=<b@in.example.com> proto=ESMTP helo=<app>"
for name, forget := range map[string]string{
"queued": "postfix/qmgr[58]: Q1: from=<a@example.net>, size=600, nrcpt=1 (queue active)",
"reused by the submission port": "postfix/smtpd[20]: Q1: client=app.example.com[203.0.113.4], sasl_method=PLAIN, sasl_username=app",
// Postfix 3.10's cleanup_flush(): "%s: removed (%s)", for a message
// whose client went away in DATA, or that was discarded.
"canceled by cleanup": "postfix/cleanup[52]: Q1: removed (canceled)",
"discarded by cleanup": "postfix/cleanup[52]: Q1: removed (discarded)",
} {
j, st := inboundFixture()
j.handle(head+"postfix/inbound/smtpd[41]: Q1: client=mx.example.net[203.0.113.9]", tailNow, false)
+19 -9
View File
@@ -3,6 +3,7 @@ package logtail
import (
"log"
"regexp"
"strings"
"time"
"github.com/mixeme/selfpost/internal/store"
@@ -28,7 +29,7 @@ import (
// enable_long_queue_ids, digits and letters without vowels; neither word is
// either.
//
// Postfix 3.7.11, src/global/mail_queue.c, mail_queue_enter(), with
// Postfix 3.10.13, src/global/mail_queue.c, mail_queue_enter(), with
// src/global/mail_queue.h MQID_*: a short id is "%05X" of the microseconds
// and "%lX" of the inode (6 to 21 characters); a long one is the seconds (6+)
// and microseconds (4) in src/global/safe_ultostr.c's vowel-less alphabet, 'z',
@@ -38,7 +39,7 @@ var queueLineRe = regexp.MustCompile(`^\S+ ([^\s\[]+)\[\d+\]: ([0-9A-F]{6,24}|[0
// smtpdProgramRe tells an smtpd from the other programs, whatever listener it
// serves: "postfix/smtpd", "postfix/submission/smtpd", "postfix/inbound/smtpd".
// Postfix 3.7.11, src/global/mail_task.c, mail_task(): the tag is
// Postfix 3.10.13, src/global/mail_task.c, mail_task(): the tag is
// "<syslog_name>/<process name>"; a master.cf "-o syslog_name=" reaches it
// through mail_params_init() (src/global/mail_params.c) before
// single_server_main() calls maillog_client_init() again.
@@ -55,7 +56,7 @@ const (
// logged when it arrives and its row is written at end-of-message; an hour
// is a message body sent slowly. Postfix sets no such bound: smtpd_timeout
// limits each read, not the message (postconf(5) smtpd_timeout,
// smtpd_per_request_deadline, Postfix 3.7.11) - assumptions A-34.
// smtpd_per_request_deadline, Postfix 3.10.13) - assumptions A-34.
lineGrace = time.Hour
// lineBatch is how many lines are held before they are written without
@@ -80,13 +81,21 @@ type lineKeeper struct {
// port25 holds the queue ids the port-25 smtpd opened: mail offered by
// strangers, which never gets a send-log row. Its lines are not kept - what
// a stranger can make Postfix log is not something to store on his say-so
// and prune later. An id leaves when qmgr removes the message or when
// another listener opens a message under it (Postfix reuses ids).
// Postfix 3.7.11: smtpd writes "<id>: client=..." when it opens the queue
// and prune later. An id leaves when qmgr removes the message, when
// cleanup removes a message it did not queue, or when another listener
// opens a message under it (Postfix reuses ids).
// Postfix 3.10.13: smtpd writes "<id>: client=..." when it opens the queue
// file (src/smtpd/smtpd.c, mail_open_stream()); qmgr writes "<id>: removed"
// when it deletes it (src/qmgr/qmgr_active.c, qmgr_active_done_3_generic());
// short ids repeat (postconf(5) enable_long_queue_ids: the long ones are
// the "non-repeating" kind).
// cleanup writes "<id>: removed (canceled)" or "<id>: removed (discarded)"
// when it deletes the queue file of a message it refused, discarded or
// was not given in full (src/cleanup/cleanup_api.c, cleanup_flush(),
// msg_info("%s: removed (%s)"), new in 3.10: HISTORY 20241112), after its
// milter verdict line (cleanup_milter_inspect() runs earlier in
// cleanup_flush()) and after smtpd's line about a connection lost in DATA
// (src/smtpd/smtpd.c, smtpd_proto(), logs it before mail_reset() closes the
// cleanup stream); short ids repeat (postconf(5) enable_long_queue_ids:
// the long ones are the "non-repeating" kind).
port25 map[string]struct{}
}
@@ -121,7 +130,8 @@ func (k *lineKeeper) add(line string, now time.Time, catchingUp bool) {
}
}
if _, inbound := k.port25[queueID]; inbound {
if program == "postfix/qmgr" && text == "removed" {
if program == "postfix/qmgr" && text == "removed" ||
program == "postfix/cleanup" && strings.HasPrefix(text, "removed (") {
delete(k.port25, queueID)
}
return
+41
View File
@@ -24,6 +24,15 @@ func TestQueueLineHead(t *testing.T) {
{"port-25 smtpd", "mail postfix/inbound/smtpd[41]: 4A1B2C3D: client=mx.example.net[203.0.113.9]", "4A1B2C3D"},
{"cleanup", "mail postfix/cleanup[52]: 41E862C00D9E: message-id=<1@example.com>", "41E862C00D9E"},
{"qmgr removes it", "mail postfix/qmgr[10]: 41E862C00D9E: removed", "41E862C00D9E"},
// Postfix 3.10.13: src/cleanup/cleanup_api.c, cleanup_flush(), "%s:
// removed (%s)"; src/smtpd/smtpd.c, smtpd_proto(), "%s: %s after %s
// (%lu bytes) from %s" with the queue id or "NOQUEUE".
{"cleanup removes an unqueued message", "mail postfix/cleanup[52]: 41E862C00D9E: removed (canceled)", "41E862C00D9E"},
{"a connection lost in DATA", "mail postfix/submission/smtpd[10]: 41E862C00D9E: lost connection after DATA (5420 bytes) from unknown[203.0.113.7]", "41E862C00D9E"},
{"a connection lost before a queue id", "mail postfix/smtpd[10]: NOQUEUE: lost connection after EHLO from unknown[203.0.113.7]", ""},
// The same function's "%s: %s after %s from %s" for the other reasons.
{"too many errors with a queue id", "mail postfix/submission/smtpd[10]: 41E862C00D9E: too many errors after RCPT from unknown[203.0.113.7]", "41E862C00D9E"},
{"a timeout before a queue id", "mail postfix/smtpd[10]: NOQUEUE: timeout after MAIL from unknown[203.0.113.7]", ""},
{"a bounce is sent: the id at the head, not the new message's", "mail postfix/bounce[30]: 41E862C00D9E: sender non-delivery notification: 5F00AA12", "41E862C00D9E"},
{"long queue id", "mail postfix/qmgr[10]: 3sJ8Xh2Cgqz4Xy1: removed", "3sJ8Xh2Cgqz4Xy1"},
{"refused before queueing", "mail postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from mx.example.net[203.0.113.9]: 550 5.1.1 <n@in.example.com>: Recipient address rejected; from=<a@example.net> to=<n@in.example.com> proto=ESMTP helo=<mx.example.net>", ""},
@@ -162,6 +171,38 @@ func TestLineKeeperLeavesOutPort25Mail(t *testing.T) {
}
}
// A port-25 message that is never queued - refused at end-of-message, or its
// client gone in DATA - ends with cleanup's "removed (canceled)" rather than
// qmgr's "removed", and its id is anybody's again from there. Postfix 3.10.13:
// src/smtpd/smtpd.c, smtpd_proto(), logs the lost connection before
// mail_reset() closes the cleanup stream; src/cleanup/cleanup_api.c,
// cleanup_flush(), logs "%s: removed (%s)" after the milter verdict. The
// lines are composed from those formats.
func TestLineKeeperForgetsPort25AtCleanupRemoval(t *testing.T) {
cs := &captureStore{}
k := newLineKeeper(cs)
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
const bounce = "host postfix/cleanup[52]: 4A1B2C3D: message-id=<20261012180000.4A1B2C3D@mail.example.com>"
for _, line := range []string{
"host postfix/inbound/smtpd[41]: 4A1B2C3D: client=mx.example.net[198.51.100.9]",
"host postfix/inbound/smtpd[41]: 4A1B2C3D: lost connection after DATA (5420 bytes) from mx.example.net[198.51.100.9]",
"host postfix/cleanup[52]: 4A1B2C3D: removed (canceled)",
// The id comes round for a bounce Postfix generates, which has no smtpd.
bounce,
} {
k.add(line, now, false)
}
k.flush()
if got := cs.kept(); len(got) != 1 || got[0] != "4A1B2C3D|"+bounce {
t.Errorf("kept %v, want only the bounce's line", got)
}
if len(k.port25) != 0 {
t.Errorf("port-25 ids still remembered: %v", k.port25)
}
}
// The tailer keeps queue-id lines as it follows the log, and after an unclean
// stop - its saved place lies before lines it had already read - it does not
// keep them a second time.
+19 -18
View File
@@ -62,7 +62,7 @@ func RetentionInterval() time.Duration {
}
// queueIDs lists the messages Postfix currently holds, for the reconcile sweep.
// It is a var so tests can answer without a running Postfix. Postfix 3.7.11,
// It is a var so tests can answer without a running Postfix. Postfix 3.10.13,
// src/showq/showq.c, showq_service(): the listing covers the maildrop,
// active, incoming, deferred and hold queues.
var queueIDs = postfix.QueueIDs
@@ -91,7 +91,7 @@ type RetentionDays func() int
// postfix/smtp[26]: 41E862C00D9E: to=<a@example.net>, relay=…, dsn=2.0.0, status=sent (250 OK)
//
// The "<queue-id>: to=<addr>, …, status=<word>" shape is the per-recipient
// result line: Postfix 3.7.11, src/global/log_adhoc.c, log_adhoc() writes
// result line: Postfix 3.10.13, src/global/log_adhoc.c, log_adhoc() writes
// "%s: to=<%s>", ", orig_to=<%s>" (only when the address was rewritten),
// ", relay=%s", then ", dsn=%s, status=%s (%s)". It is called from sent(),
// defer_append() and bounce_append() in whichever process decides - the
@@ -150,7 +150,7 @@ func parseDelivery(line string) (queueID, recipient, status string, ok bool) {
//
// postfix/qmgr[93]: 41E862C00D9E: from=<app@example.org>, status=expired, returned to sender
//
// Postfix 3.7.11, src/qmgr/qmgr_active.c, qmgr_active_done_25_generic():
// Postfix 3.10.13, src/qmgr/qmgr_active.c, qmgr_active_done_25_generic():
// msg_info("%s: from=<%s>, status=%s, returned to sender") with "expired"
// once the queue lifetime has passed, "force-expired" after postsuper -e.
// It is the only line about the expiry, one per message, and no recipient is
@@ -253,7 +253,7 @@ func reconcileLoop(ctx context.Context, st StatusStore, caughtUp <-chan struct{}
}
// A message Postfix still works on stays queued until its first retry after
// the queue lifetime, which can be a whole backoff later. Postfix 3.7.11,
// the queue lifetime, which can be a whole backoff later. Postfix 3.10.13,
// src/qmgr/qmgr_active.c: expiry is decided when an attempt ends
// (qmgr_active_done_25_generic()), and a deferred message waits at most
// maximal_backoff_time (qmgr_active_done_3_generic()). The deferred queue
@@ -361,7 +361,7 @@ func reconcile(st StatusStore, cutoff time.Time, path string) {
// message's expiry line. A deferred line is not one: a deferred row has one
// by definition. Rows reach the sweep minutes after they were written, so
// the end of those two files is where such a line would be.
// logrotate 3.21.0, logrotate.c, prerotateSingleLog(): the first rotated
// logrotate 3.22.0, logrotate.c, prerotateSingleLog(): the first rotated
// name is "<log>.1", without the compression suffix under delaycompress
// (build/logrotate-mail.conf).
func resultInLog(path string, row store.QueuedDelivery) bool {
@@ -556,11 +556,11 @@ func QueueLines(path, queueID string, n int) ([]string, error) {
// mentionsQueueID reports whether a mail.log line is about queueID. Postfix
// writes the id followed by a colon ("… postfix/smtp[26]: 41E862C00D9E: to=…";
// Postfix 3.7.11 "%s: ..." in log_adhoc(), smtpd's "%s: client=", qmgr's
// "%s: removed"),
// and the match is anchored on the character before it so a shorter id is not
// found inside a longer one — queue ids are hexadecimal, and one being the tail
// of another is ordinary, not unlikely.
// Postfix 3.10.13 "%s: ..." in log_adhoc(), smtpd's "%s: client=", qmgr's
// "%s: removed", cleanup's "%s: removed (%s)"), and the match is anchored on
// the character before it so a shorter id is not found inside a longer one —
// queue ids are hexadecimal, and one being the tail of another is ordinary,
// not unlikely.
func mentionsQueueID(line, queueID string) bool {
needle := queueID + ":"
for i := 0; i <= len(line)-len(needle); {
@@ -582,16 +582,17 @@ func isQueueIDByte(b byte) bool {
}
// syslogStampRe is the timestamp at the head of a mail.log line (maillog_file
// in build/postfix-config.sh), the one format Postfix 3.7 writes. Postfix 3.7.11,
// src/util/msg_logger.c, msg_logger_print(): every record is stamped
// in build/postfix-config.sh), the one format Postfix 3.10 writes. Postfix
// 3.10.13, src/util/msg_logger.c, msg_logger_print(): every record is stamped
// strftime("%b %d %H:%M:%S ") in the logging process's local time (the day
// zero-padded), then the first label of the host name, and postlogd writes it
// as received (src/postlogd/postlogd.c, postlogd_service()). It carries no
// year and no zone, so the stamp shown is a wall clock and nothing more,
// which is all this column claims to be. An RFC 3339 stamp once matched
// here too, for a maillog_file_format parameter said to arrive in Postfix
// 3.9; there is none in 3.7.11, nor in the 3.12 snapshot of 2026-09-25
// (proto/postconf.proto; msg_logger.c keeps the strftime) - assumptions A-12.
// 3.9; there is none in 3.7.11, nor in 3.10.13, nor in the 3.12 snapshot of
// 2026-09-25 (proto/postconf.proto; msg_logger.c keeps the strftime) -
// assumptions A-12.
var syslogStampRe = regexp.MustCompile(`^([A-Z][a-z]{2}\s+\d{1,2} \d{2}:\d{2}:\d{2})\s`)
// SplitTimestamp separates the timestamp at the head of a mail.log line from
@@ -615,7 +616,7 @@ func SplitTimestamp(line string) (stamp, rest string) {
// first ever run); it reopens the file when it is rotated, so nothing is missed.
// The inode changes under logrotate's create, which build/logrotate-mail.conf
// uses; a file shorter than the read position is taken as truncation.
// logrotate 3.21.0, logrotate.c, rotateSingleLog(): without copytruncate the
// logrotate 3.22.0, logrotate.c, rotateSingleLog(): without copytruncate the
// file is rename()d and, with create, a new one made by createOutputFile();
// with copytruncate it is copied and truncated, which that config does not use.
//
@@ -817,14 +818,14 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
}
// rotatedTail is mail.log just rotated away, still open: postlogd writes to
// it until "postfix reload" makes it exit. Postfix 3.7.11,
// it until "postfix reload" makes it exit. Postfix 3.10.13,
// src/postlogd/postlogd.c, pre_jail_init(): maillog_file is opened once per
// postlogd process; src/master/master_service.c, master_restart_service(),
// closes the service's status pipe at a reload (master_status_cleanup()),
// and src/master/dgram_server.c, dgram_server_abort(), exits when it reads
// its end - the next postlogd opens the new file. logrotate runs the reload
// right after the rename and create (build/logrotate-mail.conf, postrotate;
// logrotate 3.21.0, logrotate.c, rotateLogSet(): the postrotate script runs
// logrotate 3.22.0, logrotate.c, rotateLogSet(): the postrotate script runs
// right after rotateSingleLog() has renamed and created), so the gap is short;
// rotatedGrace is far longer than it.
type rotatedTail struct {
@@ -845,7 +846,7 @@ const rotatedGrace = time.Minute
// lost to a restart and lands on the days it covered. A stretch shorter than
// blindMin is not counted: a rotation leaves the name missing for a tick
// between rename and create, and that loses nothing - the new file is read
// from its start. logrotate 3.21.0, logrotate.c, rotateSingleLog(): the
// from its start. logrotate 3.22.0, logrotate.c, rotateSingleLog(): the
// rename() and createOutputFile() follow each other in one pass, with no
// script or wait between them (postrotate runs after).
type blindness struct {
+26 -4
View File
@@ -15,12 +15,12 @@ import (
)
// The mail.log lines in this file are composed by hand, after the formats the
// code cites (Postfix 3.7.11, src/global/log_adhoc.c and the others), unless a
// code cites (Postfix 3.10.13, src/global/log_adhoc.c and the others), unless a
// comment says where one was seen; some carry no stamp, which the parsers
// take as they come. One shape Postfix does not write here: opendkim lines in
// mail.log (OpenDKIM logs through syslog(3), to the container log - build/opendkim.conf).
// qmgr's expiry line, as Postfix 3.7.11 writes it (src/qmgr/qmgr_active.c,
// qmgr's expiry line, as Postfix 3.10.13 writes it (src/qmgr/qmgr_active.c,
// qmgr_active_done_25_generic(): "%s: from=<%s>, status=%s, returned to
// sender"); composed by hand after that format. The sender is the client's
// text, so a line only resembles one when it ends as qmgr's does.
@@ -36,6 +36,11 @@ func TestParseExpiry(t *testing.T) {
// qmgr's ordinary from= line, whose sender carries the text.
{"Oct 14 09:01:02 relay postfix/qmgr[93]: 41E862C00D9E: from=<x>, status=expired, returned to sender>, size=500, nrcpt=1 (queue active)", ""},
{"Oct 14 09:01:02 relay postfix/qmgr[93]: 41E862C00D9E: removed", ""},
// cleanup's removal of a message it did not queue (Postfix 3.10.13,
// src/cleanup/cleanup_api.c, cleanup_flush(): "%s: removed (%s)")
// says nothing of what became of a queued one.
{"Oct 14 09:01:02 relay postfix/cleanup[52]: 41E862C00D9E: removed (canceled)", ""},
{"Oct 14 09:01:02 relay postfix/cleanup[52]: 41E862C00D9E: removed (discarded)", ""},
} {
id, ok := parseExpiry(c.line)
if ok != (c.id != "") || id != c.id {
@@ -194,7 +199,8 @@ func TestParseDelivery(t *testing.T) {
status: store.StatusSent,
},
{
// The stamp Postfix 3.7's postlogd writes, as on the stand.
// The stamp postlogd writes, as on the stand (Postfix 3.7;
// 3.10.13's msg_logger_print() keeps the format).
name: "syslog stamp",
line: "Oct 14 11:05:51 mail postfix/smtp[26]: 41E862C00D9E: to=<a@example.net>, relay=x, dsn=2.0.0, status=sent (250 OK)",
wantOK: true,
@@ -221,6 +227,22 @@ func TestParseDelivery(t *testing.T) {
line: "Oct 14 11:05:51 mail postfix/smtpd[10]: 5B4A2C1D3E: client=unknown[203.0.113.7], sasl_username=41E862C00D9E: to=<victim@example.net>, status=sent",
wantOK: false,
},
{
// Postfix 3.10.13, src/cleanup/cleanup_api.c, cleanup_flush():
// "%s: removed (%s)" for a transaction cleanup did not queue. It
// is no result for any recipient. Composed from that format.
name: "cleanup's removed (canceled) is not one",
line: "Oct 14 11:05:51 mail postfix/cleanup[52]: 41E862C00D9E: removed (canceled)",
wantOK: false,
},
{
// Postfix 3.10.13, src/smtpd/smtpd.c, smtpd_proto(): "%s: %s after
// %s (%lu bytes) from %s", the queue id first since 3.10. Composed
// from that format.
name: "smtpd's lost connection with a queue id is not one",
line: "Oct 14 11:05:51 mail postfix/submission/smtpd[10]: 41E862C00D9E: lost connection after DATA (5420 bytes) from unknown[203.0.113.7]",
wantOK: false,
},
}
for _, c := range cases {
t.Run(c.name, func(t *testing.T) {
@@ -920,7 +942,7 @@ func TestSplitTimestamp(t *testing.T) {
stamp, rest string
}{
{
// An RFC 3339 stamp is not one Postfix 3.7 writes (assumptions
// An RFC 3339 stamp is not one Postfix 3.10 writes (assumptions
// A-12): it is not taken off.
name: "RFC 3339 is not a stamp Postfix writes",
line: "2026-08-03T05:15:52.219218+00:00 mail postfix/qmgr[10]: 4A1B2C3D: removed",
+1 -1
View File
@@ -7,7 +7,7 @@ import (
)
// TestMain reads mail.log stamps in UTC, whatever the zone of the machine the
// tests run on: Postfix 3.7 writes "%b %d %H:%M:%S" in the logging process's
// tests run on: Postfix 3.10 writes "%b %d %H:%M:%S" in the logging process's
// local time (src/util/msg_logger.c, msg_logger_print()) and lineTime reads it
// in time.Local, which in the container is the zone the fixtures are written
// in.
+2 -2
View File
@@ -17,7 +17,7 @@ import (
const (
// fingerprintSize is how many bytes from the head of the log identify it.
// Postfix writes a timestamped line per event (Postfix 3.7.11,
// Postfix writes a timestamped line per event (Postfix 3.10.13,
// src/util/msg_logger.c, msg_logger_print(): "%b %d %H:%M:%S" on every
// record), so the first 512 bytes are
// effectively unique per log generation — enough to tell "the file we were
@@ -130,7 +130,7 @@ func (t *tracker) resume(f *os.File) int64 {
// readRotated reads, when the log was rotated while the panel was down, the
// rest of the file the saved place belongs to: logrotate renamed it to
// mail.log.1 (delaycompress leaves it plain - logrotate 3.21.0, logrotate.c,
// mail.log.1 (delaycompress leaves it plain - logrotate 3.22.0, logrotate.c,
// prerotateSingleLog()), and what Postfix wrote there
// between the panel's stop and the rotation - deliveries, refusals, deferrals -
// was otherwise never read (audit 2026-10-12, stage 2b). It is read from the
+11 -8
View File
@@ -18,14 +18,17 @@ import (
//
// postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from=<billing@sender.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test> sasl_username=<l2app>
//
// Postfix 3.7.11, src/smtpd/smtpd.c, check_milter_reply(): "%s: %s: %s from
// Postfix 3.10.13, src/smtpd/smtpd.c, check_milter_reply(): "%s: %s: %s from
// %s: %s;%s" with "NOQUEUE" before the queue file is opened, and
// smtpd_whatsup() for the rest: " from=<..>", " to=<..>", " proto=..",
// " helo=<..>", then " sasl_username=<..>" when the session authenticated
// (assumptions A-20, A-21). The login is read at the end of the line, where
// Postfix puts it last; a line without one is no application's refusal - the
// journal milter refuses at MAIL FROM only an authenticated session
// (milter/ratelimit.go). The HELO name before it is the client's text and can
// (assumptions A-20, A-21). smtpd's own refusals are another function,
// src/smtpd/smtpd_check.c, log_whatsup(), whose line says "reject:", not
// "milter-reject:", and since 3.10 ends in " sasl_method=%s sasl_username=%s"
// without the brackets; it is not one of these. The login is read at the end
// of the line, where Postfix puts it last; a line without one is no
// application's refusal - the journal milter refuses at MAIL FROM only an
// authenticated session (milter/ratelimit.go). The HELO name before it is the client's text and can
// end in what looks like the field, but only in a session that has no login,
// and so no refused row to take the line; a row must also be of the line's
// client address and sender, within minutes.
@@ -52,7 +55,7 @@ type RefusalStore interface {
// The From: line as the check printed it runs to the last " - " before the
// first semicolon; the reason after it holds neither, and the check prints no
// ";" of the client's (sender.go printable), so that semicolon is Postfix's
// and what follows it - the envelope - is Postfix's own text. Postfix 3.7.11,
// and what follows it - the envelope - is Postfix's own text. Postfix 3.10.13,
// src/cleanup/cleanup_milter.c, cleanup_milter_apply(): "%s: %s: %s from
// %s[%s]: %s;" with the reply from its fifth byte (the "550 " dropped), then
// " from=<..>", " to=<..>" - the last recipient only (assumptions A-15).
@@ -60,7 +63,7 @@ var fromRefusalRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?cleanup\[\d
// clientLoginRe is smtpd's line naming the login a queue id was submitted
// under: "<id>: client=host[addr], sasl_method=PLAIN, sasl_username=<login>".
// Postfix 3.7.11, src/smtpd/smtpd.c, mail_open_stream(): ", sasl_sender=.."
// Postfix 3.10.13, src/smtpd/smtpd.c, mail_open_stream(): ", sasl_sender=.."
// follows when the client gave AUTH= on MAIL FROM, then ", orig_queue_id=.."
// and ", orig_client=.." for XFORWARD; the login ends at the comma (a login
// holds none - internal/postfix assertMapSafe; assumptions A-23).
@@ -148,7 +151,7 @@ func (r *refusalLines) handle(line string, now time.Time, start Place) {
return
}
// The address in "name[addr]" is smtpd's state->addr, which has no
// "IPv6:" (Postfix 3.7.11, src/smtpd/smtpd_peer.c, smtpd_peer_init();
// "IPv6:" (Postfix 3.10.13, src/smtpd/smtpd_peer.c, smtpd_peer_init();
// assumptions A-24).
ip := net.ParseIP(m[2])
if ip == nil {
+4 -3
View File
@@ -31,8 +31,9 @@ func (r *refusalProbe) AttachRefusalLine(clientIP, login, from string, _ time.Ti
// The mail.log lines in this file are composed by hand, with the e2e stand's
// names and addresses (smtpd.c check_milter_reply(), mail_open_stream();
// cleanup_milter.c cleanup_milter_apply(), Postfix 3.7.11), with the stamp
// Postfix 3.7 writes (src/util/msg_logger.c, "%b %d %H:%M:%S").
// smtpd_check.c log_whatsup(); cleanup_milter.c cleanup_milter_apply(),
// Postfix 3.10.13), with the stamp Postfix 3.10 writes
// (src/util/msg_logger.c, "%b %d %H:%M:%S").
//
// The NOQUEUE line of a refusal at MAIL FROM goes on its row; a line whose
// row is not written yet waits and is tried again; port 25's and other
@@ -45,7 +46,7 @@ func TestRefusalLines(t *testing.T) {
for _, other := range []string{
`Oct 14 12:00:00 mail postfix/inbound/smtpd[372]: NOQUEUE: milter-reject: MAIL from unknown[203.0.113.7]: 451 4.7.1 Service unavailable - try again later; from=<a@stranger.example> proto=ESMTP helo=<x>`,
`Oct 14 12:00:00 mail postfix/smtpd[11]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`,
`Oct 14 12:00:00 mail postfix/smtpd[11]: NOQUEUE: reject: RCPT from unknown[10.77.0.1]: 553 5.7.1 <a@x>: Sender address rejected: not owned by user app1; from=<a@x> to=<b@y> proto=ESMTP helo=<x>`,
`Oct 14 12:00:00 mail postfix/smtpd[11]: NOQUEUE: reject: RCPT from unknown[10.77.0.1]: 553 5.7.1 <a@x>: Sender address rejected: not owned by user app1; from=<a@x> to=<b@y> proto=ESMTP helo=<x> sasl_method=PLAIN sasl_username=app1`,
// No login: no application's refusal (the panel down refuses every
// session, an unauthenticated one too).
`Oct 14 12:00:00 mail postfix/smtpd[12]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from=<billing@sender.e2e.test> proto=ESMTP helo=<x>`,
+2 -2
View File
@@ -29,7 +29,7 @@ import (
// 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.
//
// Postfix 3.7.11, src/milter/milter8.c: milter8_connect() warns "connect to
// Postfix 3.10.13, src/milter/milter8.c: milter8_connect() warns "connect to
// Milter service %s: %m" with the milter's configured name; then
// milter8_comm_error() answers, for default_action=tempfail, "451 4.7.1
// Service unavailable - try again later" - the very text milter8_event()
@@ -50,7 +50,7 @@ import (
//
// 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.
// Postfix 3.7.11, src/milter/milter8.c, milter8_read_resp(): "milter %s:
// Postfix 3.10.13, src/milter/milter8.c, milter8_read_resp(): "milter %s:
// can't read %s reply packet header: %m", then milter8_comm_error(), which
// closes the milter's stream and leaves it in the error state for the rest of
// that message.
+1 -1
View File
@@ -39,7 +39,7 @@ func (d *deferredStore) AddSenderCheckDeferred(at time.Time, n int64, place stri
// that use the same words - a level-2 refusal of the journal milter, OpenDKIM
// not answering. Those - smtpd 1149, 1190 and 1201, the second client of
// 1183, smtpd 1300 and the OpenDKIM warning of cleanup 1339 - are composed,
// after src/smtpd/smtpd.c and src/milter/milter8.c (Postfix 3.7.11).
// after src/smtpd/smtpd.c and src/milter/milter8.c (Postfix 3.10.13).
func TestDeferredCounter(t *testing.T) {
st := &deferredStore{}
c := newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"})