logtail, health, panel: cite the source of what they rely on (assumptions part A)

Comments only, no behaviour changed. Each place the log tailer, Health and
cmd/panel rely on another program now says where that is written, for the
version the image runs: Postfix 3.7.11 (log_adhoc(), msg_logger_print(),
smtpd_whatsup(), cleanup_milter.c, qmgr_active.c, postlogd.c, showq.c,
pipe.c), logrotate 3.21.0, supervisor 4.2.5, proc(5). Measurements stay
measurements and say where and when; test fixtures say whether they were
seen or composed.

Where the source contradicts the code the comment does not bless it but
names the register entry (A-8 expiry, A-12 the ISO stamp no Postfix writes,
A-15 the last recipient, A-21/A-23 sasl_username, A-33 postlogd's old
inode, A-38 a socket file is not a listener, A-65 the certificate served);
those are fixed in their own commits.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
mix
2026-10-14 19:36:11 +03:00
co-authored by Claude Opus 5.5
parent a8b6276b0d
commit ce363f48dd
25 changed files with 314 additions and 72 deletions
+16 -3
View File
@@ -34,7 +34,12 @@ func runDMARCIngestMode() error {
} }
// Not a report this relay keeps. It is dropped: deferring would have // 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 // 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 { if incrErr := st.IncrDMARCParseFailures(); incrErr != nil {
log.Printf("dmarc ingest: record failure: %v", incrErr) 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 // what a delivery command wrote - about a hundred bytes - into its own line
// for the message ("status=sent (delivered via dmarc-ingest service (...))"), // for the message ("status=sent (delivered via dmarc-ingest service (...))"),
// so the reason goes out first and bare: no prefix, no date, no recipient, // 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 // all of which that line already has. Postfix 3.7.11, src/pipe/pipe.c,
// the command without the group that may write to Postfix's log socket. // 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) { func logRejected(reason error) {
fmt.Fprintln(os.Stderr, "dropped: "+logSafe(strings.TrimPrefix(reason.Error(), dmarc.ErrRejected.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 // 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, // 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). // 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 // Without it the check that a report came to its own domain's address is
// skipped. // skipped.
func ingestRecipient(args []string) string { func ingestRecipient(args []string) string {
+3 -1
View File
@@ -99,7 +99,9 @@ func newPanel(cfg config, st *store.Store) (*web.Server, error) {
ms := newMailStack(cfg, st) ms := newMailStack(cfg, st)
// postfix-config.sh has already run (entrypoint). postconf -h is the // postfix-config.sh has already run (entrypoint). postconf -h is the
// effective config, including a manual override; the panel keeps this // 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() retryPolicy := postfix.LoadRetryPolicy()
return web.New(st, ms.Domains, ms.Apps, ms.Inbound, ms.Lists, ms.DMARC, web.Config{ return web.New(st, ms.Domains, ms.Apps, ms.Inbound, ms.Lists, ms.DMARC, web.Config{
Hostname: cfg.hostname, Hostname: cfg.hostname,
+6 -1
View File
@@ -54,7 +54,9 @@ func listenMilter(socketPath string) (net.Listener, error) {
return nil, err return nil, err
} }
// Clear a stale socket left behind by an unclean shutdown, otherwise the // 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) { if err := os.Remove(socketPath); err != nil && !errors.Is(err, os.ErrNotExist) {
return nil, err 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 // group access. The socket inherits group `selfpost` from the setgid parent
// dir entrypoint.sh prepares; make it group read/write so postfix can reach // 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). // 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 { if err := os.Chmod(socketPath, 0o660); err != nil {
ln.Close() ln.Close()
return nil, err return nil, err
+14 -2
View File
@@ -34,7 +34,12 @@ func main() {
log.SetPrefix("dmarc-ingest: ") log.SetPrefix("dmarc-ingest: ")
if err := runDMARCIngestMode(); err != nil { if err := runDMARCIngestMode(); err != nil {
log.Printf("ingest failed: %v", err) 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 return
} }
@@ -200,7 +205,14 @@ func antispamAction(raw string) string {
// saslRealm chooses the realm new SASL accounts live under. It mirrors the // 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 // 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 { func saslRealm() string {
if r := os.Getenv("SASL_REALM"); r != "" { if r := os.Getenv("SASL_REALM"); r != "" {
return r return r
+6 -1
View File
@@ -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 // 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 // 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 { if rebuilt, err := ms.Domains.EnsureServerSigned(); err != nil {
log.Printf("notifier: sign as %s: %v", cfg.hostname, err) log.Printf("notifier: sign as %s: %v", cfg.hostname, err)
} else if rebuilt { } else if rebuilt {
+11 -3
View File
@@ -19,8 +19,11 @@ import (
const aliveEvery = 2 * time.Second const aliveEvery = 2 * time.Second
// serveSenderCheck runs the sender check (internal/milter/sender.go) on a // serveSenderCheck runs the sender check (internal/milter/sender.go) on a
// socket of its own. Postfix attaches that socket strictly, so while this // socket of its own. Postfix attaches that socket strictly
// role is not serving, mail is deferred: what that costs is counted here and // (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 // by the log tailer, and shown on Server > Health
// (docs/plans/from-header-binding.md § Statistics). // (docs/plans/from-header-binding.md § Statistics).
func serveSenderCheck(ctx context.Context, cfg config, st *store.Store) error { 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 var postfixAskFor, postfixAskEvery = 30 * time.Second, 2 * time.Second
// postfixStarted asks supervisord since when Postfix has been running, again // 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 { func postfixStarted() postfixState {
deadline := time.Now().Add(postfixAskFor) deadline := time.Now().Add(postfixAskFor)
for { for {
+10 -1
View File
@@ -9,13 +9,22 @@ import (
) )
// certWarnDays is how close to expiry the certificate has to be before the // 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. // 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 const certWarnDays = 14
// Certificate is the state of the TLS certificate Postfix serves on 465/587 // Certificate is the state of the TLS certificate Postfix serves on 465/587
// (guide § Environment variables: TLS_CERT_FILE). The panel only reads it — // (guide § Environment variables: TLS_CERT_FILE). The panel only reads it —
// the file is supplied by the reverse proxy through a read-only mount. // 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 { type Certificate struct {
Path string Path string
Subject string Subject string
+8 -1
View File
@@ -33,7 +33,10 @@ func TestWorstPicksMostSevere(t *testing.T) {
} }
func TestParseProcesses(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 out := `opendkim RUNNING pid 21, uptime 0:04:10
panel RUNNING pid 22, uptime 0:04:09 panel RUNNING pid 22, uptime 0:04:09
postfix FATAL Exited too quickly (process log may have details) 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) { func TestLivenessFromParsedProcesses(t *testing.T) {
// Composed, in the columns of TestParseProcesses.
allRunning := `opendkim RUNNING pid 21, uptime 0:04:10 allRunning := `opendkim RUNNING pid 21, uptime 0:04:10
panel RUNNING pid 22, uptime 0:04:09 panel RUNNING pid 22, uptime 0:04:09
postfix RUNNING pid 23, uptime 0:04:08 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) { func TestUptime(t *testing.T) {
for detail, want := range map[string]time.Duration{ for detail, want := range map[string]time.Duration{
"pid 41, uptime 0:03:12": 3*time.Minute + 12*time.Second, "pid 41, uptime 0:03:12": 3*time.Minute + 12*time.Second,
+31 -11
View File
@@ -33,11 +33,14 @@ const (
// status page's answer to "is the server itself under strain", next to the // status page's answer to "is the server itself under strain", next to the
// component checks that answer "is mail flowing". // component checks that answer "is mail flowing".
// //
// The numbers come from the kernel's /proc filesystem, which a container shares // The numbers come from the kernel's /proc filesystem. /proc/stat and
// with its host unless it was started with its own namespaces — so CPU and // /proc/meminfo are system-wide and no namespace changes them (proc(5):
// memory describe the host, while /proc/net/dev describes whatever network // "kernel/system statistics", "statistics about memory usage on the
// namespace the container is in (its own veth under the default bridge, the // system"), so CPU and memory describe the host, while /proc/net/dev
// host's interfaces under network_mode: host). // 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 { type Machine struct {
CPU CPU CPU CPU
Memory Memory Memory Memory
@@ -276,7 +279,9 @@ func (c CPU) contextText() string {
// MemAvailable rather than MemFree: Linux spends every spare page on cache, so // 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 // 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 // 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 { func readMemory(root string) Memory {
var m Memory var m Memory
fields, err := readMeminfo(root) fields, err := readMeminfo(root)
@@ -398,11 +403,15 @@ func readCPUTimes(root string) (cpuTimes, int, error) {
continue continue
} }
if fields[0] != "cpu" { if fields[0] != "cpu" {
cores++ // cpu0, cpu1, … — one line per core cores++ // cpu0, cpu1, … — one line per online logical CPU
continue continue
} }
// user nice system idle iowait irq softirq steal (guest fields are // 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:] { for i, f := range fields[1:] {
if i >= 8 { if i >= 8 {
break break
@@ -428,7 +437,11 @@ func readCPUTimes(root string) (cpuTimes, int, error) {
// readCPUTopology returns physical core and logical thread counts from // readCPUTopology returns physical core and logical thread counts from
// /proc/cpuinfo. Zeroes mean the file was missing or empty; the caller falls // /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) { func readCPUTopology(root string) (cores, threads int) {
data, err := os.ReadFile(filepath.Join(root, "cpuinfo")) data, err := os.ReadFile(filepath.Join(root, "cpuinfo"))
if err != nil { if err != nil {
@@ -522,7 +535,9 @@ func isZeroLoad(load [3]float64) bool {
} }
// readMeminfo returns the /proc/meminfo entries this package uses, in bytes. // 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) { func readMeminfo(root string) (map[string]uint64, error) {
data, err := os.ReadFile(filepath.Join(root, "meminfo")) data, err := os.ReadFile(filepath.Join(root, "meminfo"))
if err != nil { 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 // readNetDev returns each interface's byte counters from /proc/net/dev, loopback
// excluded. Each line is " eth0: <rx bytes> <rx packets> … <tx bytes> …" — the // excluded. Each line is " eth0: <rx bytes> <rx packets> … <tx bytes> …" — the
// name is separated by a colon, which may or may not have a space after it, so // 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) { func readNetDev(root string) (map[string]netCounters, error) {
data, err := os.ReadFile(filepath.Join(root, "net", "dev")) data, err := os.ReadFile(filepath.Join(root, "net", "dev"))
if err != nil { if err != nil {
+3 -1
View File
@@ -9,7 +9,9 @@ import (
// fakeProc writes a /proc-shaped directory the sampler can be pointed at, so // 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 // 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 { func fakeProc(t *testing.T, stat, meminfo, loadavg, netdev string) string {
t.Helper() t.Helper()
dir := t.TempDir() dir := t.TempDir()
+3 -1
View File
@@ -16,7 +16,9 @@ import (
// add to a poll. // add to a poll.
const milterDialTimeout = time.Second 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 // 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 // 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 // a failure costs, as for CheckSocket: an error when mail stops without the
+12 -3
View File
@@ -38,7 +38,9 @@ type Process struct {
// The command takes fixed arguments and no user input, so it never goes through // 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 // 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 // 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) { func Processes() ([]Process, error) {
cmd := exec.Command("supervisorctl", "-c", supervisorConf, "status") cmd := exec.Command("supervisorctl", "-c", supervisorConf, "status")
out, err := cmd.CombinedOutput() out, err := cmd.CombinedOutput()
@@ -54,7 +56,8 @@ func Processes() ([]Process, error) {
// supervisorStates are the state words supervisord prints. Lines whose second // 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 // 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{ var supervisorStates = map[string]bool{
"STOPPED": true, "STOPPED": true,
"STARTING": true, "STARTING": true,
@@ -68,6 +71,10 @@ var supervisorStates = map[string]bool{
// parseProcesses turns supervisorctl's tabular output into Process values. Each // parseProcesses turns supervisorctl's tabular output into Process values. Each
// status line is "<name> <STATE> <detail...>", column-aligned with spaces. // status line is "<name> <STATE> <detail...>", column-aligned with spaces.
// supervisor 4.2.5, supervisor/supervisorctl.py, _show_statuses(): the
// template is "%(namespec)-<maxlen+3>s%(state)-10s%(desc)s" (maxlen at least
// 30, no state word longer than 8), and an unknown name prints
// "<name>: ERROR (no such process)".
func parseProcesses(out string) []Process { func parseProcesses(out string) []Process {
var procs []Process var procs []Process
for _, line := range strings.Split(out, "\n") { 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 // 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, // 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) { func Uptime(detail string) (time.Duration, bool) {
_, rest, found := strings.Cut(detail, "uptime ") _, rest, found := strings.Cut(detail, "uptime ")
if !found { if !found {
+11 -3
View File
@@ -18,9 +18,17 @@ type Socket struct {
} }
// CheckSocket stats a milter socket. required distinguishes the two milters: // CheckSocket stats a milter socket. required distinguishes the two milters:
// OpenDKIM runs with default_action=tempfail, so a missing socket stops mail // Postfix attaches OpenDKIM with default_action=tempfail, so a missing socket
// leaving the server, while the journal-milter fails open — mail still goes out, // stops mail leaving the server, while the journal-milter is attached with
// only the send log stops being written. // 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 { func CheckSocket(name, path string, required bool) Socket {
s := Socket{Name: name, Path: path} s := Socket{Name: name, Path: path}
if path == "" { if path == "" {
+3 -2
View File
@@ -9,8 +9,9 @@ import (
) )
// fileID names the file itself - its inode - which a rename keeps and a new // 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 // file does not share (rename(2): the file is moved, other hard links to it
// whose first bytes happen to match are still told apart. The device number // 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 // 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 // file systems), and the same log would then pass for a rotated one (review
// of stage 2b). // of stage 2b).
+38 -10
View File
@@ -45,6 +45,19 @@ type Inbound struct {
// so it counts only for a queue id the port-25 smtpd was seen to open // so it counts only for a queue id the port-25 smtpd was seen to open
// (inboundClientRe). // (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 // 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, // 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 // 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=`) 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 // 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 // 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=)`) 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 // 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. // 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 // Refusals are written at the rate strangers send RCPT TO. Postfix's one
// Postfix's counts, so between two prunes the journal would otherwise grow as // limit on that, smtpd_client_recipient_rate_limit, is per client address and
// fast as someone cared to make it. // 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 const inboundPruneEvery = 500
// inboundJournal is the per-run state of the inbound half. // 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] 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 // 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 // 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 // the recipient (Postfix 3.7.11 logs addresses in external form, the local
// quote. An address with a quote, a bracket or a space in it is not one the // part quoted when it holds spaces or specials: postconf(5)
// journal keeps. // 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, "\"<> ") { if strings.ContainsAny(from, "\"<> ") || strings.ContainsAny(to, "\"<> ") {
return return
} }
@@ -178,7 +198,12 @@ func (j *inboundJournal) handle(line string, now time.Time, catchingUp bool) {
e.Engine = store.SpamEnginePostfix e.Engine = store.SpamEnginePostfix
} }
// "450 4.7.1 …" from Postfix, "4.7.1 …" from a milter: either way a reply // "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") { if e.Decision == store.SpamDecisionReject && strings.HasPrefix(reason, "4") {
e.Decision = store.SpamDecisionTempfail 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 // 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 // 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 // (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 // container's. Postfix 3.7.11, src/util/msg_logger.c, msg_logger_print(): the
// stamp is dated now. // 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) { func lineTime(line string, now time.Time) (time.Time, string) {
if m := isoStampRe.FindStringSubmatch(line); m != nil { if m := isoStampRe.FindStringSubmatch(line); m != nil {
rest := strings.TrimSpace(line[len(m[0]):]) rest := strings.TrimSpace(line[len(m[0]):])
+4
View File
@@ -52,6 +52,10 @@ func inboundFixture() (*inboundJournal, *fakeInboundStore) {
var tailNow = time.Date(2026, 10, 11, 18, 0, 0, 0, time.UTC) 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 ( const (
head = "2026-10-11T12:00:05.123456+00:00 mail " 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 <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>" unknownRcp = 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>"
+19 -1
View File
@@ -27,10 +27,21 @@ import (
// "warning:" stand there too. A queue id is hexadecimal in capitals, or, with // "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 // enable_long_queue_ids, digits and letters without vowels; neither word is
// either. // 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}): (.*)`) 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 // smtpdProgramRe tells an smtpd from the other programs, whatever listener it
// serves: "postfix/smtpd", "postfix/submission/smtpd", "postfix/inbound/smtpd". // serves: "postfix/smtpd", "postfix/submission/smtpd", "postfix/inbound/smtpd".
// Postfix 3.7.11, 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.
var smtpdProgramRe = regexp.MustCompile(`^postfix/(?:[a-z0-9-]+/)?smtpd$`) var smtpdProgramRe = regexp.MustCompile(`^postfix/(?:[a-z0-9-]+/)?smtpd$`)
// port25Program is the smtpd of the inbound relay's listener, which // 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 // 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 // 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 // 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 lineGrace = time.Hour
// lineBatch is how many lines are held before they are written without // 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 // 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 // and prune later. An id leaves when qmgr removes the message or when
// another listener opens a message under it (Postfix reuses ids). // another listener opens a message under it (Postfix reuses ids).
// Postfix 3.7.11: 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).
port25 map[string]struct{} port25 map[string]struct{}
} }
+4
View File
@@ -9,6 +9,10 @@ import (
"time" "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 // 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. // at the head of the line and nothing the far end wrote further along it.
func TestQueueLineHead(t *testing.T) { func TestQueueLineHead(t *testing.T) {
+56 -19
View File
@@ -61,7 +61,9 @@ func RetentionInterval() time.Duration {
} }
// queueIDs lists the messages Postfix currently holds, for the reconcile sweep. // 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 var queueIDs = postfix.QueueIDs
// retryPolicy reads Postfix's queue lifetimes, for counting the rows left // retryPolicy reads Postfix's queue lifetimes, for counting the rows left
@@ -87,8 +89,14 @@ type RetentionDays func() int
// //
// postfix/smtp[26]: 41E862C00D9E: to=<a@example.net>, relay=…, dsn=2.0.0, status=sent (250 OK) // 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 specific to the // The "<queue-id>: to=<addr>, …, status=<word>" shape is the per-recipient
// delivery agents; qmgr/smtpd/cleanup lines do not match. // 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=, // 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 // 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 // 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 // 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 // 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+)`) 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. // 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 // 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() policy := retryPolicy()
overLifetime := policy.LongestLifetime() + policy.MaximalBackoff 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 // 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 // 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 // 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. // 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 // 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 // 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 // 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. // 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 "<log>.1", without the compression suffix under delaycompress
// (build/logrotate-mail.conf).
func deliveryInLog(path string, row store.QueuedDelivery) bool { func deliveryInLog(path string, row store.QueuedDelivery) bool {
if path == "" { if path == "" {
return false 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 // 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 // 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 // found inside a longer one — queue ids are hexadecimal, and one being the tail
// of another is ordinary, not unlikely. // 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' 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 // Timestamps at the head of a mail.log line (maillog_file in
// writes (maillog_file in build/postfix-config.sh). // 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 // syslogStampRe is the one that matches. Postfix 3.7.11,
// controlled by maillog_file_format, which arrived in Postfix 3.9, and the // src/util/msg_logger.c, msg_logger_print(): every record is stamped
// image is built on Debian's 3.7 — where the parameter does not exist and the // strftime("%b %d %H:%M:%S ") in the logging process's local time (the day
// only format is syslog's traditional one. It carries no year and no zone, so // zero-padded), then the first label of the host name, and postlogd writes it
// the stamp shown is a wall clock and nothing more, which is all this column // as received (src/postlogd/postlogd.c, postlogd_service()). It carries no
// claims to be. // 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 // isoStampRe was written for an RFC 3339 format said to come with a
// base image carries a Postfix new enough to offer it. Matching it first costs // maillog_file_format parameter of Postfix 3.9. No such parameter exists in
// one failed anchor per line and means the upgrade needs no change here. // 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 ( var (
isoStampRe = regexp.MustCompile(`^(\d{4}-\d{2}-\d{2})T(\d{2}:\d{2}:\d{2})(?:\.\d+)?(?:Z|[+-]\d{2}:?\d{2})?\s`) 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`) 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 // 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 // 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'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 // 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 // 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 // gained lines between the drain() above and this check, since
// Postfix keeps writing to it until it reloads. Drain it once // Postfix keeps writing to it until it reloads. Drain it once
// more before switching so nothing in that gap is lost. // 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() drain()
if err := openAt(0, io.SeekStart); err != nil { if err := openAt(0, io.SeekStart); err != nil {
log.Printf("log-tailer: reopen %s: %v", path, err) 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 // 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 // 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 // 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 { type blindness struct {
add func(from time.Time, d time.Duration) error add func(from time.Time, d time.Duration) error
since time.Time // start of the current stretch; zero when reading since time.Time // start of the current stretch; zero when reading
+9
View File
@@ -14,6 +14,13 @@ import (
"github.com/mixeme/selfpost/internal/store" "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) { func TestParseDelivery(t *testing.T) {
cases := []struct { cases := []struct {
name string name string
@@ -787,6 +794,8 @@ func TestSplitTimestamp(t *testing.T) {
// Copied off the live relay (Postfix 3.7, which has no // Copied off the live relay (Postfix 3.7, which has no
// maillog_file_format), so this is the shape the panel actually // maillog_file_format), so this is the shape the panel actually
// meets: zero-padded day, and the host is the container's name. // 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", 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", 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", stamp: "Aug 08 07:26:41",
+5 -2
View File
@@ -17,7 +17,9 @@ import (
const ( const (
// fingerprintSize is how many bytes from the head of the log identify it. // 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 // effectively unique per log generation — enough to tell "the file we were
// reading" from "a fresh one created by logrotate while we were down", // reading" from "a fresh one created by logrotate while we were down",
// which os.SameFile cannot answer across a restart. // 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 // 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 // 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 - // 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 // 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 // saved offset to its end, line by line through handle, before the new file
+19 -5
View File
@@ -13,12 +13,19 @@ import (
// Postfix's line about a message the journal milter refused at MAIL FROM - a // 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 // 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, // 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 // stage 2b). The refusal has no queue id; it is matched to its row by client
// matched to its row by client address, sender and time. As the stand writes // address, sender and time. As the stand writes it (e2e stand, date not
// it: // recorded):
// //
// 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> // 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>
// //
// 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=<login>" 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. // 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=<([^>]*)>`) 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 // 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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test> // 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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>
// //
// The From: line as the check printed it runs to the last " - " before the // 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 // 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 // ";" 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=<([^>]*)>`) 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 // clientLoginRe is smtpd's line naming the login a queue id was submitted
// under: "<id>: client=host[addr], sasl_method=PLAIN, sasl_username=<login>". // under: "<id>: client=host[addr], sasl_method=PLAIN, sasl_username=<login>".
// 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+)`) 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. // refusalLogins bounds the queue ids whose login is remembered.
+5
View File
@@ -29,6 +29,11 @@ func (r *refusalProbe) AttachRefusalLine(clientIP, from string, _ time.Time, lin
return true, nil 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 // 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 // row is not written yet waits and is tried again; port 25's and other
// lines are not refusals of an application. // lines are not refusals of an application.
+15
View File
@@ -29,6 +29,17 @@ import (
// The reject lines do not: the same words are written when OpenDKIM does not // 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. // 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 - // 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 // 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 // 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 // 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. // 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 // 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 // tells a hung panel from a stopped one - was never counted (audit
// 2026-10-12, M13). // 2026-10-12, M13).
+3 -1
View File
@@ -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 // 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 // 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 // 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) { func TestDeferredCounter(t *testing.T) {
st := &deferredStore{} st := &deferredStore{}
c := newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"}) c := newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"})