diff --git a/cmd/panel/dmarc_ingest.go b/cmd/panel/dmarc_ingest.go index a324b9d..dddd701 100644 --- a/cmd/panel/dmarc_ingest.go +++ b/cmd/panel/dmarc_ingest.go @@ -34,7 +34,12 @@ func runDMARCIngestMode() error { } // Not a report this relay keeps. It is dropped: deferring would have // Postfix try it again for days, and a bounce would go to an envelope - // sender anyone can write - the report addresses are public. + // sender anyone can write - the report addresses are public. Postfix + // 3.7.11: exit 0 is PIPE_STAT_OK, logged "status=sent (delivered via + // ... service ...)" (src/global/pipe_command.c, pipe_command(); + // src/pipe/pipe.c, eval_command_status()); a 4.x.x status defers until + // maximal_queue_lifetime and a 5.x.x one bounces, either way a notice + // to the sender (src/qmgr/qmgr_active.c, src/global/bounce.c). if incrErr := st.IncrDMARCParseFailures(); incrErr != nil { log.Printf("dmarc ingest: record failure: %v", incrErr) } @@ -47,8 +52,13 @@ func runDMARCIngestMode() error { // what a delivery command wrote - about a hundred bytes - into its own line // for the message ("status=sent (delivered via dmarc-ingest service (...))"), // so the reason goes out first and bare: no prefix, no date, no recipient, -// all of which that line already has. postlog is no use here: pipe(8) starts -// the command without the group that may write to Postfix's log socket. +// all of which that line already has. Postfix 3.7.11, src/pipe/pipe.c, +// eval_command_status(): " (%.100s)" of the output, which +// src/global/pipe_command.c takes from stdout and stderr together. postlog is +// no use here: pipe(8) starts the command without the group that may write to +// Postfix's log socket (src/util/set_ugid.c, set_ugid(): setgroups() to the +// user's one group). Whether Debian's postlog is set-gid, which would bring +// the group with it, is not recorded - assumptions A-43. func logRejected(reason error) { fmt.Fprintln(os.Stderr, "dropped: "+logSafe(strings.TrimPrefix(reason.Error(), dmarc.ErrRejected.Error()+": "))) } @@ -73,6 +83,9 @@ func logSafe(s string) string { // ingestRecipient is the report address the message was delivered to. Postfix's // pipe(8) hands it over as an argument (${recipient} in the service's argv, // build/postfix-config.sh) - it sets no RECIPIENT variable, that is local(8). +// Postfix 3.7.11, src/pipe/pipe.c, deliver_message(): pipe_command() gets only +// CA_PIPE_CMD_EXPORT(export_environment), no extra environment; +// src/local/command.c sets "RECIPIENT". // Without it the check that a report came to its own domain's address is // skipped. func ingestRecipient(args []string) string { diff --git a/cmd/panel/httpserver.go b/cmd/panel/httpserver.go index de1fee1..afae6dd 100644 --- a/cmd/panel/httpserver.go +++ b/cmd/panel/httpserver.go @@ -99,7 +99,9 @@ func newPanel(cfg config, st *store.Store) (*web.Server, error) { ms := newMailStack(cfg, st) // postfix-config.sh has already run (entrypoint). postconf -h is the // effective config, including a manual override; the panel keeps this - // snapshot for the process lifetime (architecture.md). + // snapshot for the process lifetime (architecture.md). Postfix 3.7.11, + // postconf(1): without -d or -n it shows main.cf's value or the default, + // and -h drops the "name = " label; values are not $-expanded without -x. retryPolicy := postfix.LoadRetryPolicy() return web.New(st, ms.Domains, ms.Apps, ms.Inbound, ms.Lists, ms.DMARC, web.Config{ Hostname: cfg.hostname, diff --git a/cmd/panel/journal.go b/cmd/panel/journal.go index d84835f..36b9955 100644 --- a/cmd/panel/journal.go +++ b/cmd/panel/journal.go @@ -54,7 +54,9 @@ func listenMilter(socketPath string) (net.Listener, error) { return nil, err } // Clear a stale socket left behind by an unclean shutdown, otherwise the - // listen below fails with "address already in use". + // listen below fails with "address already in use" (unix(7): the socket + // file "must be deleted by the caller when it is no longer needed"; bind(2) + // EADDRINUSE). if err := os.Remove(socketPath); err != nil && !errors.Is(err, os.ErrNotExist) { return nil, err } @@ -67,6 +69,9 @@ func listenMilter(socketPath string) (net.Listener, error) { // group access. The socket inherits group `selfpost` from the setgid parent // dir entrypoint.sh prepares; make it group read/write so postfix can reach // it (connecting to a Unix socket needs write permission on the node). + // unix(7): "connecting to a stream socket object requires write + // permission on that socket"; inode(7): a file made in a set-group-ID + // directory takes the directory's group. if err := os.Chmod(socketPath, 0o660); err != nil { ln.Close() return nil, err diff --git a/cmd/panel/main.go b/cmd/panel/main.go index 002c1b0..3ed1fd8 100644 --- a/cmd/panel/main.go +++ b/cmd/panel/main.go @@ -34,7 +34,12 @@ func main() { log.SetPrefix("dmarc-ingest: ") if err := runDMARCIngestMode(); err != nil { log.Printf("ingest failed: %v", err) - os.Exit(75) // EX_TEMPFAIL — ask Postfix to defer + // EX_TEMPFAIL — ask Postfix to defer. Postfix 3.7.11, + // src/global/pipe_command.c, pipe_command(): a sysexits code maps + // to its DSN (src/global/sys_exits.c: 75 is "4.3.0") and a 4 defers, + // unless the output starts with a "D.S.N text" of its own - the + // log prefix above makes sure it does not. + os.Exit(75) } return } @@ -200,7 +205,14 @@ func antispamAction(raw string) string { // saslRealm chooses the realm new SASL accounts live under. It mirrors the // hostname Postfix's SASL layer uses so a client authenticating with a bare -// login resolves to the right account. +// login resolves to the right account. Postfix 3.7.11, +// src/xsasl/xsasl_cyrus_server.c, xsasl_cyrus_server_create(): serverFQDN is +// $myhostname (= SELFPOST_HOSTNAME, build/postfix-config.sh) and user_realm +// NULL while smtpd_sasl_local_domain is empty; Cyrus SASL 2.1.28, +// plugins/sasldb.c, sasldb_auxprop_lookup(), and common/plugin_common.c, +// _plug_parseuser(): a login +// without "@" is then looked up in the realm serverFQDN. A SASL_REALM other +// than SELFPOST_HOSTNAME does not follow that - assumptions A-48. func saslRealm() string { if r := os.Getenv("SASL_REALM"); r != "" { return r diff --git a/cmd/panel/notifier.go b/cmd/panel/notifier.go index 64531ce..80c7f6c 100644 --- a/cmd/panel/notifier.go +++ b/cmd/panel/notifier.go @@ -22,7 +22,12 @@ func runNotifier(ctx context.Context, cfg config, st *store.Store) error { // OpenDKIM's tables are rebuilt when a domain is added or deleted. On the // first start of a version that signs the server's own name they do not - // have its line yet. A failure here costs the signature, not the message. + // have its line yet. A failure here costs the signature, not the message: + // OpenDKIM 2.11.0~beta2, opendkim/opendkim.c, mlfi_eoh(): with no + // SigningTable match and Mode s (build/opendkim.conf) the message is + // accepted unsigned. A line whose key the KeyTable lacks or that does not + // load is another matter - dkimf_apply_signtable() < 0 there answers + // SMFIS_TEMPFAIL (assumptions A-47). if rebuilt, err := ms.Domains.EnsureServerSigned(); err != nil { log.Printf("notifier: sign as %s: %v", cfg.hostname, err) } else if rebuilt { diff --git a/cmd/panel/sendercheck.go b/cmd/panel/sendercheck.go index 05896ae..decd5b8 100644 --- a/cmd/panel/sendercheck.go +++ b/cmd/panel/sendercheck.go @@ -19,8 +19,11 @@ import ( const aliveEvery = 2 * time.Second // serveSenderCheck runs the sender check (internal/milter/sender.go) on a -// socket of its own. Postfix attaches that socket strictly, so while this -// role is not serving, mail is deferred: what that costs is counted here and +// socket of its own. Postfix attaches that socket strictly +// (default_action=tempfail in build/postfix-config.sh; Postfix 3.7.11, +// src/milter/milter8.c, milter8_comm_error(): "451 4.7.1 Service unavailable - +// try again later"), so while this role is not serving, mail is deferred: +// what that costs is counted here and // by the log tailer, and shown on Server > Health // (docs/plans/from-header-binding.md § Statistics). func serveSenderCheck(ctx context.Context, cfg config, st *store.Store) error { @@ -131,7 +134,12 @@ func byDay(from, to time.Time) []dayPart { 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. +// and again for postfixAskFor while it does not answer. supervisor 4.2.5, +// supervisor/rpcinterface.py, _interpretProcessInfo(): the uptime runs from +// the spawn of program "postfix", which is build/postfix-wrapper.sh; it waits +// for the milter sockets (up to MILTER_WAIT_TIMEOUT) before it execs +// "postfix start-fg", so the time given is up to that much early +// (assumptions A-46). func postfixStarted() postfixState { deadline := time.Now().Add(postfixAskFor) for { diff --git a/internal/health/cert.go b/internal/health/cert.go index 8831396..2be7b13 100644 --- a/internal/health/cert.go +++ b/internal/health/cert.go @@ -9,13 +9,22 @@ import ( ) // certWarnDays is how close to expiry the certificate has to be before the -// status page complains. Let's Encrypt renews at 30 days left, so two weeks is +// status page complains. certbot renews a 90-day certificate at 30 days left +// - a fixed 30 days before 4.0, a third of the lifetime from 4.0 (certbot +// docs, certbot/docs/using.rst, "Renewing certificates") - so two weeks is // comfortably past the point where automatic renewal should have happened. +// For a 45-day certificate a third is 15 days, one day ahead of this warning +// (assumptions A-64). const certWarnDays = 14 // Certificate is the state of the TLS certificate Postfix serves on 465/587 // (guide § Environment variables: TLS_CERT_FILE). The panel only reads it — // the file is supplied by the reverse proxy through a read-only mount. +// Postfix itself serves the copy build/postfix-config.sh makes in +// /etc/postfix/tls-internal, refreshed by build/postfix-cert-reload.sh up to +// TLS_RELOAD_INTERVAL_SECONDS later, and each smtpd loads it when it starts +// (Postfix 3.7.11, src/smtpd/smtpd.c, pre_jail_init(), TLS_SERVER_INIT) - so +// the mounted file can be newer than what is served (assumptions A-65). type Certificate struct { Path string Subject string diff --git a/internal/health/health_test.go b/internal/health/health_test.go index 3752bf5..94122fc 100644 --- a/internal/health/health_test.go +++ b/internal/health/health_test.go @@ -33,7 +33,10 @@ func TestWorstPicksMostSevere(t *testing.T) { } func TestParseProcesses(t *testing.T) { - // Real supervisorctl output: column-aligned, one line per program. + // Real supervisorctl output: column-aligned, one line per program. Where + // and when it was seen is not recorded; its columns are those of + // supervisor 4.2.5 supervisorctl.py _show_statuses() and its FATAL text + // supervisor/process.py's spawnerr. out := `opendkim RUNNING pid 21, uptime 0:04:10 panel RUNNING pid 22, uptime 0:04:09 postfix FATAL Exited too quickly (process log may have details) @@ -165,6 +168,7 @@ func writeCert(t *testing.T, path, cn string, validFor time.Duration) { } func TestLivenessFromParsedProcesses(t *testing.T) { + // Composed, in the columns of TestParseProcesses. allRunning := `opendkim RUNNING pid 21, uptime 0:04:10 panel RUNNING pid 22, uptime 0:04:09 postfix RUNNING pid 23, uptime 0:04:08 @@ -189,6 +193,9 @@ postfix FATAL Exited too quickly } } +// Composed, after supervisor 4.2.5 rpcinterface.py _interpretProcessInfo() +// (str() of a timedelta). "127:00:01" is not a form supervisor prints - it +// only shows that the parser takes hours past 24. func TestUptime(t *testing.T) { for detail, want := range map[string]time.Duration{ "pid 41, uptime 0:03:12": 3*time.Minute + 12*time.Second, diff --git a/internal/health/machine.go b/internal/health/machine.go index 0346b16..b7fdb47 100644 --- a/internal/health/machine.go +++ b/internal/health/machine.go @@ -33,11 +33,14 @@ const ( // status page's answer to "is the server itself under strain", next to the // component checks that answer "is mail flowing". // -// The numbers come from the kernel's /proc filesystem, which a container shares -// with its host unless it was started with its own namespaces — so CPU and -// memory describe the host, while /proc/net/dev describes whatever network -// namespace the container is in (its own veth under the default bridge, the -// host's interfaces under network_mode: host). +// The numbers come from the kernel's /proc filesystem. /proc/stat and +// /proc/meminfo are system-wide and no namespace changes them (proc(5): +// "kernel/system statistics", "statistics about memory usage on the +// system"), so CPU and memory describe the host, while /proc/net/dev +// describes whatever network namespace the container is in +// (network_namespaces(7) names /proc/net among what a network namespace +// isolates) - its own veth under the default bridge, the host's interfaces +// under network_mode: host. type Machine struct { CPU CPU Memory Memory @@ -276,7 +279,9 @@ func (c CPU) contextText() string { // MemAvailable rather than MemFree: Linux spends every spare page on cache, so // MemFree on a healthy machine is near zero and would report a permanent // emergency. MemAvailable is the kernel's own estimate of what a new workload -// could actually get. +// could actually get (proc(5), /proc/meminfo, MemAvailable "since Linux +// 3.14": "An estimate of how much memory is available for starting new +// applications, without swapping"). func readMemory(root string) Memory { var m Memory fields, err := readMeminfo(root) @@ -398,11 +403,15 @@ func readCPUTimes(root string) (cpuTimes, int, error) { continue } if fields[0] != "cpu" { - cores++ // cpu0, cpu1, … — one line per core + cores++ // cpu0, cpu1, … — one line per online logical CPU continue } // user nice system idle iowait irq softirq steal (guest fields are - // already counted inside user/nice, so they are left out). + // already counted inside user/nice, so they are left out). Field + // order: proc(5), /proc/stat. That guest time is in user/nice too: + // Linux kernel/sched/cputime.c, account_guest_time() adds it to + // CPUTIME_USER (or CPUTIME_NICE) as well as CPUTIME_GUEST (torvalds/ + // linux master read 2026-10-14; the kernel is the host's). for i, f := range fields[1:] { if i >= 8 { break @@ -428,7 +437,11 @@ func readCPUTimes(root string) (cpuTimes, int, error) { // readCPUTopology returns physical core and logical thread counts from // /proc/cpuinfo. Zeroes mean the file was missing or empty; the caller falls -// back to the cpuN count from /proc/stat. +// back to the cpuN count from /proc/stat. The keys are x86's: Linux +// arch/x86/kernel/cpu/proc.c, show_cpuinfo() prints "processor" and, on SMP, +// "physical id" and "core id" (show_cpuinfo_core(); torvalds/linux master +// read 2026-10-14). proc(5) says only that the items are architecture +// dependent; where they are missing each processor counts as a core. func readCPUTopology(root string) (cores, threads int) { data, err := os.ReadFile(filepath.Join(root, "cpuinfo")) if err != nil { @@ -522,7 +535,9 @@ func isZeroLoad(load [3]float64) bool { } // readMeminfo returns the /proc/meminfo entries this package uses, in bytes. -// The file reports kB (kibibytes, despite the label) for these fields. +// The file reports kB (kibibytes, despite the label) for these fields: Linux +// fs/proc/meminfo.c, show_val_kb() prints pages << (PAGE_SHIFT - 10) +// (torvalds/linux master read 2026-10-14). func readMeminfo(root string) (map[string]uint64, error) { data, err := os.ReadFile(filepath.Join(root, "meminfo")) if err != nil { @@ -557,7 +572,12 @@ func readMeminfo(root string) (map[string]uint64, error) { // readNetDev returns each interface's byte counters from /proc/net/dev, loopback // excluded. Each line is " eth0: … …" — the // name is separated by a colon, which may or may not have a space after it, so -// the split is on the colon and not on whitespace. +// the split is on the colon and not on whitespace. proc(5), /proc/net/dev: +// eight receive columns (bytes first), then the transmit ones (bytes first). +// Linux net/core/net-procfs.c, dev_seq_printf_stats(): "%6s: %7llu ..." in +// master read 2026-10-14; the host's kernel may be older, and the colon is +// all this relies on (net/core/dev.c, dev_valid_name() refuses ':' in a +// device name). func readNetDev(root string) (map[string]netCounters, error) { data, err := os.ReadFile(filepath.Join(root, "net", "dev")) if err != nil { diff --git a/internal/health/machine_test.go b/internal/health/machine_test.go index 219871f..48dc196 100644 --- a/internal/health/machine_test.go +++ b/internal/health/machine_test.go @@ -9,7 +9,9 @@ import ( // fakeProc writes a /proc-shaped directory the sampler can be pointed at, so // the parsing and the arithmetic are tested against known counters instead of -// whatever the machine running the tests happens to be doing. +// whatever the machine running the tests happens to be doing. The file +// contents in this test are composed, in the layouts proc(5) gives for +// /proc/stat, /proc/meminfo and /proc/net/dev. func fakeProc(t *testing.T, stat, meminfo, loadavg, netdev string) string { t.Helper() dir := t.TempDir() diff --git a/internal/health/milter.go b/internal/health/milter.go index 9985585..523e033 100644 --- a/internal/health/milter.go +++ b/internal/health/milter.go @@ -16,7 +16,9 @@ import ( // add to a poll. const milterDialTimeout = time.Second -// CheckMilter probes a milter address in the two forms Postfix takes: +// CheckMilter probes a milter address in the two forms build/postfix-config.sh +// lets INBOUND_ANTISPAM_MILTER take (Postfix 3.7.11, src/milter/milter8.c, +// milter8_connect(), also accepts "local:", which that script refuses): // unix:/path is stat-ed like any milter socket, and inet:host:port is dialled // and the connection closed at once, with nothing written. required says what // a failure costs, as for CheckSocket: an error when mail stops without the diff --git a/internal/health/processes.go b/internal/health/processes.go index ba89d4e..94805c2 100644 --- a/internal/health/processes.go +++ b/internal/health/processes.go @@ -38,7 +38,9 @@ type Process struct { // The command takes fixed arguments and no user input, so it never goes through // a shell (security.md). `supervisorctl status` deliberately exits non-zero when // some program is not running, so the output is parsed first and the exit status -// only matters when nothing could be parsed from it. +// only matters when nothing could be parsed from it. supervisor 4.2.5, +// supervisor/supervisorctl.py, do_status(): exit status 3 (NOT_RUNNING) when +// any program is in STOPPED_STATES, 4 when supervisord does not answer. func Processes() ([]Process, error) { cmd := exec.Command("supervisorctl", "-c", supervisorConf, "status") out, err := cmd.CombinedOutput() @@ -54,7 +56,8 @@ func Processes() ([]Process, error) { // supervisorStates are the state words supervisord prints. Lines whose second // field is not one of them are not status lines (banners, error text) and are -// skipped, so unexpected output cannot masquerade as a process. +// skipped, so unexpected output cannot masquerade as a process. supervisor +// 4.2.5, supervisor/states.py, ProcessStates. var supervisorStates = map[string]bool{ "STOPPED": true, "STARTING": true, @@ -68,6 +71,10 @@ var supervisorStates = map[string]bool{ // parseProcesses turns supervisorctl's tabular output into Process values. Each // status line is " ", column-aligned with spaces. +// supervisor 4.2.5, supervisor/supervisorctl.py, _show_statuses(): the +// template is "%(namespec)-s%(state)-10s%(desc)s" (maxlen at least +// 30, no state word longer than 8), and an unknown name prints +// ": ERROR (no such process)". func parseProcesses(out string) []Process { var procs []Process for _, line := range strings.Split(out, "\n") { @@ -89,7 +96,9 @@ func parseProcesses(out string) []Process { // Uptime reads for how long a running program has been up from the detail // supervisord prints for it: "pid 41, uptime 0:03:12", or with days in front, -// "pid 41, uptime 18 days, 3:02:11". +// "pid 41, uptime 18 days, 3:02:11". supervisor 4.2.5, +// supervisor/rpcinterface.py, _interpretProcessInfo(): 'pid %s, uptime %s' +// with Python's str() of a timedelta from the spawn time ("1 day, ..."). func Uptime(detail string) (time.Duration, bool) { _, rest, found := strings.Cut(detail, "uptime ") if !found { diff --git a/internal/health/socket.go b/internal/health/socket.go index b9ec922..3c0cd84 100644 --- a/internal/health/socket.go +++ b/internal/health/socket.go @@ -18,9 +18,17 @@ type Socket struct { } // CheckSocket stats a milter socket. required distinguishes the two milters: -// OpenDKIM runs with default_action=tempfail, so a missing socket stops mail -// leaving the server, while the journal-milter fails open — mail still goes out, -// only the send log stops being written. +// Postfix attaches OpenDKIM with default_action=tempfail, so a missing socket +// stops mail leaving the server, while the journal-milter is attached with +// default_action=accept and fails open — mail still goes out, only the send +// log stops being written (build/postfix-config.sh smtpd_milters; Postfix +// 3.7.11, src/milter/milter8.c, milter8_comm_error(): tempfail answers "451 +// 4.7.1 Service unavailable - try again later", accept answers nothing). +// +// A socket file that is there is reported as listening. It is not proof of +// it: a unix socket's file outlives the process that bound it unless that +// process unlinks it (unix(7)), so a killed OpenDKIM or panel leaves one that +// refuses every connection - assumptions A-38. func CheckSocket(name, path string, required bool) Socket { s := Socket{Name: name, Path: path} if path == "" { diff --git a/internal/logtail/fileid_unix.go b/internal/logtail/fileid_unix.go index 004dde3..3f8bc8d 100644 --- a/internal/logtail/fileid_unix.go +++ b/internal/logtail/fileid_unix.go @@ -9,8 +9,9 @@ import ( ) // fileID names the file itself - its inode - which a rename keeps and a new -// file does not share. It is part of the log's fingerprint, so two log files -// whose first bytes happen to match are still told apart. The device number +// file does not share (rename(2): the file is moved, other hard links to it +// are unaffected; st_ino in stat(2)). It is part of the log's fingerprint, so +// two log files whose first bytes happen to match are still told apart. The device number // is left out: it can change across a host's reboot (LVM, btrfs, network // file systems), and the same log would then pass for a rotated one (review // of stage 2b). diff --git a/internal/logtail/inbound.go b/internal/logtail/inbound.go index 95cf254..0bb71dc 100644 --- a/internal/logtail/inbound.go +++ b/internal/logtail/inbound.go @@ -45,6 +45,19 @@ 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(): +// "%s: %s: %s from %s: %s;" then " from=<..>", " to=<..>", " proto=", +// " helo=<..>", 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 +// 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 +// (cleanup_service_name, default "cleanup"; src/smtpd/smtpd.c, +// mail_open_stream()). Its to= is the last recipient cleanup saw, not every +// one (src/cleanup/cleanup_addr.c, cleanup_addr_recipient() overwrites +// state->recip) - assumptions A-15. +// // Both are matched from the head of the line, after the timestamp and host // name: the tail of such a line is the sender's own words (HELO name, // addresses), and a pattern that could start anywhere would let him write @@ -61,7 +74,10 @@ var ( 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. + // under the same id - Postfix reuses ids. Postfix 3.7.11, + // 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=)`) ) @@ -77,9 +93,11 @@ const inboundQueueIDs = 4096 // inboundPruneEvery is how many rows the tailer writes before it has the // journal cut back to its row cap, without waiting for the six-hourly prune. -// Refusals are written at the rate strangers send RCPT TO, which no limit of -// Postfix's counts, so between two prunes the journal would otherwise grow as -// fast as someone cared to make it. +// 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 +// two prunes the journal would otherwise grow as fast as someone cared to +// make it. const inboundPruneEvery = 500 // inboundJournal is the per-run state of the inbound half. @@ -132,9 +150,11 @@ 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. Such a line shows it: the sender is left with an unclosed - // quote. An address with a quote, a bracket or a space in it is not one the - // journal keeps. + // the recipient (Postfix 3.7.11 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 + // quote, a bracket or a space in it is not one the journal keeps. if strings.ContainsAny(from, "\"<> ") || strings.ContainsAny(to, "\"<> ") { return } @@ -178,7 +198,12 @@ 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. + // that starts with 4 asks the sender to come back. Postfix 3.7.11: + // 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 + // leads - when the milter sent one, which src/milter/milter8.c accepts + // either way for SMFIR_REPLYCODE (assumptions A-18). if e.Decision == store.SpamDecisionReject && strings.HasPrefix(reason, "4") { e.Decision = store.SpamDecisionTempfail } @@ -238,8 +263,11 @@ 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, which is what postlogd wrote it in. A line with no readable -// stamp is dated now. +// container's. Postfix 3.7.11, 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, +// src/global/mail_params.h). A line with no readable stamp is dated now. func lineTime(line string, now time.Time) (time.Time, string) { if m := isoStampRe.FindStringSubmatch(line); m != nil { rest := strings.TrimSpace(line[len(m[0]):]) diff --git a/internal/logtail/inbound_test.go b/internal/logtail/inbound_test.go index 22442ed..278964b 100644 --- a/internal/logtail/inbound_test.go +++ b/internal/logtail/inbound_test.go @@ -52,6 +52,10 @@ 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). Their ISO stamp is not a format +// Postfix writes (assumptions A-12); TestLineTime has the syslog one. const ( head = "2026-10-11T12:00:05.123456+00:00 mail " unknownRcp = head + "postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from mx.example.net[203.0.113.9]: 550 5.1.1 : Recipient address rejected: User unknown in relay recipient table; from= to= proto=ESMTP helo=" diff --git a/internal/logtail/lines.go b/internal/logtail/lines.go index f05699a..83f2c17 100644 --- a/internal/logtail/lines.go +++ b/internal/logtail/lines.go @@ -27,10 +27,21 @@ import ( // "warning:" stand there too. A queue id is hexadecimal in capitals, or, with // 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 +// 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', +// then the inode (12 to 23 characters). Program tag and "[pid]: ": +// src/util/msg_logger.c, msg_logger_print(). var queueLineRe = regexp.MustCompile(`^\S+ ([^\s\[]+)\[\d+\]: ([0-9A-F]{6,24}|[0-9B-DF-HJ-NP-TV-Zb-df-hj-np-tv-z]{10,24}): (.*)`) // 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 +// "/"; 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. var smtpdProgramRe = regexp.MustCompile(`^postfix/(?:[a-z0-9-]+/)?smtpd$`) // port25Program is the smtpd of the inbound relay's listener, which @@ -42,7 +53,9 @@ const ( // lineGrace is how old a line must be before the prune asks whether a // send-log row carries its queue id. The first lines of a message are // logged when it arrives and its row is written at end-of-message; an hour - // is a message body sent slowly. + // 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. lineGrace = time.Hour // lineBatch is how many lines are held before they are written without @@ -69,6 +82,11 @@ type lineKeeper struct { // 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 ": client=..." when it opens the queue + // file (src/smtpd/smtpd.c, mail_open_stream()); qmgr writes ": 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). port25 map[string]struct{} } diff --git a/internal/logtail/lines_test.go b/internal/logtail/lines_test.go index 6a9ccfd..152bd66 100644 --- a/internal/logtail/lines_test.go +++ b/internal/logtail/lines_test.go @@ -9,6 +9,10 @@ import ( "time" ) +// The mail.log lines in this file are composed by hand. "postfix/submission/ +// smtpd" is a tag this image never writes (build/postfix-config.sh sets +// syslog_name on port 25 only); it stands for any "-o syslog_name" listener. +// // Which lines are kept for a message's page, and under which queue id: the id // at the head of the line and nothing the far end wrote further along it. func TestQueueLineHead(t *testing.T) { diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index 8aee284..ae13e0a 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -61,7 +61,9 @@ 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. +// It is a var so tests can answer without a running Postfix. Postfix 3.7.11, +// src/showq/showq.c, showq_service(): the listing covers the maildrop, +// active, incoming, deferred and hold queues. var queueIDs = postfix.QueueIDs // retryPolicy reads Postfix's queue lifetimes, for counting the rows left @@ -87,8 +89,14 @@ type RetentionDays func() int // // postfix/smtp[26]: 41E862C00D9E: to=, relay=…, dsn=2.0.0, status=sent (250 OK) // -// The ": to=, …, status=" shape is specific to the -// delivery agents; qmgr/smtpd/cleanup lines do not match. +// The ": to=, …, status=" shape is the per-recipient +// result line: Postfix 3.7.11, 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 +// delivery agents, and qmgr too for recipients it defers or bounces itself +// (src/qmgr/qmgr_defer.c, qmgr_bounce.c); smtpd's and cleanup's own lines +// have no "to=<…>, relay=" after the id. // // The recipient runs to the ">, " that comes before relay= (and orig_to=, // when there is one): a quoted local part may hold a ">", and a recipient cut @@ -105,7 +113,8 @@ type RetentionDays func() int // server's reply verbatim, so a greedy match would take the *last* status= on // the line — and that one can come from the reply text, which the far end // controls. A bounce whose reply quoted "status=sent" would then be filed as a -// success. The real field is always the first one after to=<…>. +// success. The real field is always the first one after to=<…>: in +// log_adhoc() the reply is the "(%s)" after status=. var deliveryRe = regexp.MustCompile(`^\S+ [^\s\[]+\[\d+\]: ([0-9A-Za-z]+): to=<(.*?)>, (?:orig_to=<.*?>, )?relay=.*?\bstatus=(\w+)`) // parseDelivery extracts (queue-id, recipient, status) from a mail.log line. @@ -211,7 +220,12 @@ 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. + // the queue lifetime, which can be a whole backoff later. Postfix 3.7.11, + // 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 + // is scanned only every queue_run_delay (src/qmgr/qmgr.c), which this + // bound leaves out - assumptions A-30. policy := retryPolicy() overLifetime := policy.LongestLifetime() + policy.MaximalBackoff @@ -253,7 +267,11 @@ func countStuck(st StatusStore, now time.Time, overLifetime time.Duration) { // message means it will never report anything more about it, so the row can // only be closed on an assumption; it is closed as a failure rather than a // success because a delivery the panel cannot evidence must not be shown as -// one. Rows whose message is still in the queue, and every row when the queue +// one. Postfix does leave a recipient without a result line in a few cases of +// its own - postsuper -d (src/postsuper/postsuper.c logs only "removed"), a +// recipient cleanup dropped as a duplicate (src/cleanup/ +// cleanup_out_recipient.c, been_here()), one a milter deleted - assumptions +// A-31. Rows whose message is still in the queue, and every row when the queue // cannot be listed at all, are left exactly as they are. // // A closed row whose delivery line is in mail.log or mail.log.1 after all is @@ -308,6 +326,9 @@ func reconcile(st StatusStore, cutoff time.Time, path string) { // deliveryInLog says whether the current log or the one rotated last holds a // delivery line for row. 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 +// name is ".1", without the compression suffix under delaycompress +// (build/logrotate-mail.conf). func deliveryInLog(path string, row store.QueuedDelivery) bool { if path == "" { return false @@ -496,7 +517,9 @@ 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=…"), +// 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. @@ -520,19 +543,22 @@ func isQueueIDByte(b byte) bool { return b >= '0' && b <= '9' || b >= 'A' && b <= 'Z' || b >= 'a' && b <= 'z' } -// Timestamps at the head of a mail.log line, in the two formats postlogd -// writes (maillog_file in build/postfix-config.sh). +// Timestamps at the head of a mail.log line (maillog_file in +// build/postfix-config.sh): the one format postlogd writes, and an ISO one. // -// syslogStampRe is the one that matches in practice today: the format is -// controlled by maillog_file_format, which arrived in Postfix 3.9, and the -// image is built on Debian's 3.7 — where the parameter does not exist and the -// only format is syslog's traditional one. 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. +// syslogStampRe is the one that matches. Postfix 3.7.11, +// 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. // -// isoStampRe is for the RFC 3339 format that same parameter selects once the -// base image carries a Postfix new enough to offer it. Matching it first costs -// one failed anchor per line and means the upgrade needs no change here. +// isoStampRe was written for an RFC 3339 format said to come with a +// maillog_file_format parameter of Postfix 3.9. No such parameter exists in +// 3.7.11, nor in the 3.12 snapshot of 2026-09-25 (postconf.proto, and +// msg_logger.c still uses the same strftime) - assumptions A-12. No line +// Postfix writes matches it. var ( isoStampRe = regexp.MustCompile(`^(\d{4}-\d{2}-\d{2})T(\d{2}:\d{2}:\d{2})(?:\.\d+)?(?:Z|[+-]\d{2}:?\d{2})?\s`) syslogStampRe = regexp.MustCompile(`^([A-Z][a-z]{2}\s+\d{1,2} \d{2}:\d{2}:\d{2})\s`) @@ -563,6 +589,9 @@ func SplitTimestamp(line string) (stamp, rest string) { // start of a file that changed while the panel was down, or end-of-file on a // first ever run); it reopens the file when it is rotated (inode change from // logrotate's create, or truncation from copytruncate) so nothing is missed. +// logrotate 3.21.0, logrotate.c, rotateSingleLog(): without copytruncate the +// file is rename()d and, with create (build/logrotate-mail.conf), a new one +// made by createOutputFile(); with copytruncate it is copied and truncated. // // caughtUp is closed after the first read that reaches end-of-file, which is // the point where every line the panel missed while it was down has been @@ -685,6 +714,12 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{ // gained lines between the drain() above and this check, since // Postfix keeps writing to it until it reloads. Drain it once // more before switching so nothing in that gap is lost. + // Postfix 3.7.11, src/postlogd/postlogd.c, pre_jail_init(): + // maillog_file is opened once per postlogd process, which ends + // at "postfix reload" (README_FILES/MAILLOG_README) or after + // max_idle without a record (src/master/dgram_server.c). Lines + // it writes to the old inode after this switch and before the + // reload are not read - assumptions A-33. drain() if err := openAt(0, io.SeekStart); err != nil { log.Printf("log-tailer: reopen %s: %v", path, err) @@ -707,7 +742,9 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{ // 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. +// from its start. logrotate 3.21.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 { add func(from time.Time, d time.Duration) error since time.Time // start of the current stretch; zero when reading diff --git a/internal/logtail/logtail_test.go b/internal/logtail/logtail_test.go index 1b76228..9606ed7 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -14,6 +14,13 @@ import ( "github.com/mixeme/selfpost/internal/store" ) +// 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 +// comment says where one was seen. Some are shapes Postfix does not write: +// "to=..., status=expired" (qmgr logs expiry once per message as "from=<..>, +// status=expired, returned to sender" - assumptions A-8), ISO stamps +// (msg_logger.c writes "%b %d %H:%M:%S" - A-12), and opendkim lines in +// mail.log (build/opendkim.conf has Syslog no). func TestParseDelivery(t *testing.T) { cases := []struct { name string @@ -787,6 +794,8 @@ func TestSplitTimestamp(t *testing.T) { // Copied off the live relay (Postfix 3.7, which has no // maillog_file_format), so this is the shape the panel actually // meets: zero-padded day, and the host is the container's name. + // Seen on the live relay, date not recorded. The other cases + // here are composed. name: "syslog's traditional format as the live relay writes it", line: "Aug 08 07:26:41 selfpost postfix/master[231]: daemon started -- version 3.7.11, configuration /etc/postfix", stamp: "Aug 08 07:26:41", diff --git a/internal/logtail/offset.go b/internal/logtail/offset.go index 1221742..9fe0ac5 100644 --- a/internal/logtail/offset.go +++ b/internal/logtail/offset.go @@ -17,7 +17,9 @@ import ( const ( // fingerprintSize is how many bytes from the head of the log identify it. - // Postfix writes a timestamped line per event, so the first 512 bytes are + // Postfix writes a timestamped line per event (Postfix 3.7.11, + // 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 // reading" from "a fresh one created by logrotate while we were down", // which os.SameFile cannot answer across a restart. @@ -128,7 +130,8 @@ 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), and what Postfix wrote there +// mail.log.1 (delaycompress leaves it plain - logrotate 3.21.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 // saved offset to its end, line by line through handle, before the new file diff --git a/internal/logtail/refusals.go b/internal/logtail/refusals.go index a332c17..822e1cd 100644 --- a/internal/logtail/refusals.go +++ b/internal/logtail/refusals.go @@ -13,12 +13,19 @@ import ( // Postfix's line about a message the journal milter refused at MAIL FROM - a // level-2 limit, a client address off the application's list - is put on the // row the milter wrote, so the message's page shows it (audit 2026-10-12, -// stage 2b). The refusal has no queue id and the line no login; it is -// matched to its row by client address, sender and time. As the stand writes -// it: +// stage 2b). The refusal has no queue id; it is matched to its row by client +// address, sender and time. As the stand writes it (e2e stand, date not +// recorded): // // postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo= // +// Postfix 3.7.11, 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=<..>" first. smtpd_whatsup() also +// ends the line with " sasl_username=" on an authenticated session, +// which the quote above lacks and the regexp does not use (assumptions A-20, +// A-21). +// // Port 25's smtpd (postfix/inbound/smtpd) is a stranger's and has no such row. var refusalLineRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: NOQUEUE: milter-reject: MAIL from [^\[\s]*\[([^\]]+)\]: [45]\d\d .*?; from=<([^>]*)>`) @@ -33,18 +40,25 @@ type RefusalStore interface { } // fromRefusalRe is cleanup's line about a message the sender check refused -// for its From: line, as the stand writes it: +// for its From: line, as the stand writes it (e2e stand, 2026-10-12; the +// fixture in sendercheck_test.go): // // postfix/cleanup[1339]: E543D3C75DA0: 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= to= proto=ESMTP helo= // // 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. +// and what follows it - the envelope - is Postfix's own text. Postfix 3.7.11, +// 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). var fromRefusalRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?cleanup\[\d+\]: ([0-9A-Za-z]+): milter-reject: END-OF-MESSAGE from \S+: 5\.7\.1 From: ([^;]*) - ([^;]*); from=<([^>]*)> to=<([^>]*)>`) // clientLoginRe is smtpd's line naming the login a queue id was submitted // under: ": client=host[addr], sasl_method=PLAIN, sasl_username=". +// Postfix 3.7.11, src/smtpd/smtpd.c, mail_open_stream(): ", sasl_sender=<..>" +// follows when the client gave AUTH= on MAIL FROM, and "\S+" then takes +// "login," with the comma (assumptions A-23). var clientLoginRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: ([0-9A-Za-z]+): client=.*?, sasl_username=(\S+)`) // refusalLogins bounds the queue ids whose login is remembered. diff --git a/internal/logtail/refusals_test.go b/internal/logtail/refusals_test.go index da2b6f9..542d714 100644 --- a/internal/logtail/refusals_test.go +++ b/internal/logtail/refusals_test.go @@ -29,6 +29,11 @@ func (r *refusalProbe) AttachRefusalLine(clientIP, from string, _ time.Time, lin return true, nil } +// 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); their ISO stamp +// is not a format Postfix writes (assumptions A-12). +// // 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 // lines are not refusals of an application. diff --git a/internal/logtail/sendercheck.go b/internal/logtail/sendercheck.go index bc292c3..88699ae 100644 --- a/internal/logtail/sendercheck.go +++ b/internal/logtail/sendercheck.go @@ -29,6 +29,17 @@ 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 +// 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() +// gives a milter's own SMFIR_TEMPFAIL. smtpd writes "connect from %s" as it +// takes a client and only then connects to the milters, anew for each client +// (src/smtpd/smtpd.c, smtpd_service(), setup_milters(); milter8_create()), +// one client at a time (src/master/single_server.c); at AUTH a 4xx from the +// milters becomes "454 4.3.0 Try again later" with no line of its own +// (src/smtpd/smtpd_sasl_proto.c, smtpd_sasl_auth_cmd()). +// // 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 @@ -39,6 +50,10 @@ 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: +// 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. // 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). diff --git a/internal/logtail/sendercheck_test.go b/internal/logtail/sendercheck_test.go index 4de1141..6d0f964 100644 --- a/internal/logtail/sendercheck_test.go +++ b/internal/logtail/sendercheck_test.go @@ -37,7 +37,9 @@ func (d *deferredStore) AddSenderCheckDeferred(at time.Time, n int64, place stri // 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. +// 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). func TestDeferredCounter(t *testing.T) { st := &deferredStore{} c := newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"})