audit 5: findings of the two reviews
- The e2e's numeric-settings test ran a container that passed every gate
and never ended: the good values are checked beside a bad one after
them; each run is named, bounded to a minute and removed.
- The gates refuse a value under the parameter's minimum (a zero window
kills anvil, a zero milter timeout smtpd) and one past an int, in
seconds for a time value (src/global/conv_time.c, src/anvil/anvil.c).
- OpenDKIM waits, five seconds at most, for the relay's socket.
- The relay marks its lines `syslog: `, writes control characters out,
reads into a queue at once and drops past 200 lines a second, saying
how many (security F1, F2; a stuck relay would hold OpenDKIM in
syslog(3)).
- smtp_tls_mandatory_protocols >=TLSv1.2 too.
- extract-cert.sh keeps the old files' group and sets its trap before
mktemp.
- crashexit spares cert-reload; architecture.md "four times running" and
what else exits the container; security.md the restart after five panel
exits and the /dev/log socket.
- Measured against the technical review: smtpd has the selfpost group
(Groups 104 998), so it did reach the supervisor socket before this
stage.
Accepted, reasons in the plan: the logrotate state file in the postfix
user's directory, envdoc_test's reading of `${VAR:-}` only, crashexit's
window pruning untested.
Tested on the test server: go vet + go test of 27 packages, make e2e (all
pass, 592 s) on this tree.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
+66
-24
@@ -2,32 +2,51 @@
|
||||
"""Supervisor event listener: bring the container down on unrecoverable failure.
|
||||
|
||||
If a managed program of the mail path exhausts its restart retries and
|
||||
enters FATAL, this listener signals supervisord (its parent) to terminate, so
|
||||
the whole container exits and Docker's `restart` policy starts it again —
|
||||
rather than lingering "alive" with a dead Postfix/OpenDKIM/panel. logrotate is
|
||||
not on the mail path: its FATAL (a config it would ignore) stays on
|
||||
Server > Health, and mail keeps flowing (assumptions C-V5).
|
||||
enters FATAL, or keeps crashing - CRASH_LIMIT unexpected exits within
|
||||
CRASH_WINDOW seconds - this listener signals supervisord (its parent) to
|
||||
terminate, so the whole container exits and Docker's `restart` policy starts it
|
||||
again, rather than lingering "alive" with a dead Postfix/OpenDKIM/panel.
|
||||
FATAL alone did not cover the second: a program reaches FATAL only through
|
||||
exits before its startsecs, and one that crashed after it was restarted for
|
||||
ever (audit 2026-10-12, L32; supervisor 4.2.5, supervisor/process.py,
|
||||
Subprocess.finish()). logrotate is not on the mail path: its FATAL (a config
|
||||
it would ignore) stays on Server > Health, and mail keeps flowing
|
||||
(assumptions C-V5).
|
||||
|
||||
Communication with supervisord uses the event listener protocol over stdin and
|
||||
stdout, so stdout must carry only protocol tokens.
|
||||
|
||||
supervisor 4.2.5, docs/events.rst, "Event Listener Notification Protocol": the
|
||||
listener writes READY\\n, reads one header line of key:value tokens whose len
|
||||
is the payload's length, reads the payload, and answers "RESULT 2\\nOK".
|
||||
A PROCESS_STATE_FATAL payload is a token set, "processname:cat groupname:cat
|
||||
from_state:BACKOFF" (docs/events.rst; supervisor/events.py,
|
||||
ProcessStateEvent.payload()).
|
||||
is the payload's length and eventname the event's type, reads the payload, and
|
||||
answers "RESULT 2\\nOK". A PROCESS_STATE_FATAL payload is a token set,
|
||||
"processname:cat groupname:cat from_state:BACKOFF"; a PROCESS_STATE_EXITED one
|
||||
adds "expected:0" for an exit code the program's exitcodes do not list, "1"
|
||||
otherwise (docs/events.rst; supervisor/events.py, ProcessStateEvent.payload()).
|
||||
supervisord starts the listener as its own child, and on SIGTERM it shuts down
|
||||
(docs/running.rst, "Signals"); it is PID 1 here (build/entrypoint.sh, exec).
|
||||
|
||||
CRASHEXIT_DRYRUN=1 writes "crashexit: would shut down" instead of signalling,
|
||||
for the test (build/crashexit_test.go).
|
||||
"""
|
||||
import os
|
||||
import signal
|
||||
import sys
|
||||
import time
|
||||
|
||||
# Programs whose FATAL does not take the container down (build/supervisord.conf):
|
||||
# logrotate is not on the mail path, and postfix-reload runs on demand - a
|
||||
# reload it could not start is reported to whoever asked for it.
|
||||
SPARED = {"logrotate", "postfix-reload"}
|
||||
# Programs whose failure does not take the container down
|
||||
# (build/supervisord.conf): logrotate is not on the mail path, postfix-reload
|
||||
# runs on demand - a reload it could not start is reported to whoever asked for
|
||||
# it - syslog-relay carries OpenDKIM's log lines, not mail, and cert-reload
|
||||
# looks for a renewed certificate once a day (a crash of it leaves the one
|
||||
# Postfix serves).
|
||||
SPARED = {"logrotate", "postfix-reload", "syslog-relay", "cert-reload"}
|
||||
|
||||
# CRASH_LIMIT unexpected exits of one program within CRASH_WINDOW seconds are a
|
||||
# program that does not stay up. A program on the mail path restarts in
|
||||
# seconds; five times in ten minutes is no passing fault.
|
||||
CRASH_LIMIT = 5
|
||||
CRASH_WINDOW = 600
|
||||
|
||||
|
||||
def write_stdout(s):
|
||||
@@ -35,7 +54,20 @@ def write_stdout(s):
|
||||
sys.stdout.flush()
|
||||
|
||||
|
||||
def say(s):
|
||||
sys.stderr.write("crashexit: " + s + "\n")
|
||||
sys.stderr.flush()
|
||||
|
||||
|
||||
def shut_down():
|
||||
if os.environ.get("CRASHEXIT_DRYRUN") == "1":
|
||||
say("would shut down")
|
||||
return
|
||||
os.kill(os.getppid(), signal.SIGTERM)
|
||||
|
||||
|
||||
def main():
|
||||
crashes = {} # program -> times of its unexpected exits in the window
|
||||
while True:
|
||||
# Tell supervisord we are ready for the next event.
|
||||
write_stdout("READY\n")
|
||||
@@ -50,22 +82,32 @@ def main():
|
||||
pair.split(":", 1) for pair in payload.split() if ":" in pair
|
||||
)
|
||||
name = tokens.get("processname", "")
|
||||
event = headers.get("eventname", "PROCESS_STATE_FATAL")
|
||||
|
||||
# We only subscribe to PROCESS_STATE_FATAL, so any event means a managed
|
||||
# program can no longer be restarted.
|
||||
if name in SPARED:
|
||||
sys.stderr.write(
|
||||
"crashexit: %s entered FATAL; it is not on the mail path, the "
|
||||
"container stays up\n" % name
|
||||
if event == "PROCESS_STATE_EXITED":
|
||||
if name not in SPARED and tokens.get("expected") == "0":
|
||||
now = time.monotonic()
|
||||
times = [t for t in crashes.get(name, []) if now - t < CRASH_WINDOW]
|
||||
times.append(now)
|
||||
crashes[name] = times
|
||||
if len(times) >= CRASH_LIMIT:
|
||||
say(
|
||||
"%s exited unexpectedly %d times in %d seconds; shutting down container"
|
||||
% (name, len(times), CRASH_WINDOW)
|
||||
)
|
||||
shut_down()
|
||||
crashes[name] = []
|
||||
elif name in SPARED:
|
||||
say(
|
||||
"%s entered FATAL; it is not on the mail path, the container stays up"
|
||||
% name
|
||||
)
|
||||
sys.stderr.flush()
|
||||
else:
|
||||
sys.stderr.write(
|
||||
"crashexit: %s entered FATAL; shutting down container\n"
|
||||
say(
|
||||
"%s entered FATAL; shutting down container"
|
||||
% (name or "a managed process")
|
||||
)
|
||||
sys.stderr.flush()
|
||||
os.kill(os.getppid(), signal.SIGTERM)
|
||||
shut_down()
|
||||
|
||||
write_stdout("RESULT 2\nOK")
|
||||
|
||||
|
||||
@@ -0,0 +1,95 @@
|
||||
// Package build holds the image's scripts; this file tests crashexit.py, the
|
||||
// supervisor event listener that takes the container down.
|
||||
package build
|
||||
|
||||
import (
|
||||
"fmt"
|
||||
"os"
|
||||
"os/exec"
|
||||
"runtime"
|
||||
"strings"
|
||||
"testing"
|
||||
)
|
||||
|
||||
// event is one event as supervisord writes it to a listener's stdin
|
||||
// (supervisor 4.2.5, docs/events.rst: a header line whose len is the
|
||||
// payload's length, then the payload).
|
||||
func event(name, payload string) string {
|
||||
return fmt.Sprintf("ver:3.0 server:supervisor serial:1 pool:crashexit poolserial:1 eventname:%s len:%d\n%s", name, len(payload), payload)
|
||||
}
|
||||
|
||||
// runListener feeds events to crashexit.py in dry run and returns what it
|
||||
// wrote to stderr.
|
||||
func runListener(t *testing.T, events ...string) string {
|
||||
t.Helper()
|
||||
// python3 on Linux; on Windows "python3" may be the Store's stub, which
|
||||
// runs nothing.
|
||||
names := []string{"python3", "python"}
|
||||
if runtime.GOOS == "windows" {
|
||||
names = []string{"python", "python3"}
|
||||
}
|
||||
python := ""
|
||||
for _, n := range names {
|
||||
if p, err := exec.LookPath(n); err == nil {
|
||||
python = p
|
||||
break
|
||||
}
|
||||
}
|
||||
if python == "" {
|
||||
t.Skip("no python")
|
||||
}
|
||||
cmd := exec.Command(python, "crashexit.py")
|
||||
cmd.Env = append(os.Environ(), "CRASHEXIT_DRYRUN=1")
|
||||
cmd.Stdin = strings.NewReader(strings.Join(events, ""))
|
||||
var stderr strings.Builder
|
||||
cmd.Stderr = &stderr
|
||||
out, err := cmd.Output()
|
||||
if err != nil {
|
||||
t.Fatalf("crashexit.py: %v\n%s", err, stderr.String())
|
||||
}
|
||||
// Python on Windows writes its text stdout with \r\n.
|
||||
if n := strings.Count(strings.ReplaceAll(string(out), "\r\n", "\n"), "RESULT 2\nOK"); n != len(events) {
|
||||
t.Errorf("answered %d of %d events:\n%q", n, len(events), out)
|
||||
}
|
||||
return stderr.String()
|
||||
}
|
||||
|
||||
// A program on the mail path that keeps crashing after its startsecs - never
|
||||
// FATAL - takes the container down at the fifth unexpected exit (audit
|
||||
// 2026-10-12, L32); expected exits, spared programs and fewer crashes do not.
|
||||
func TestCrashexitCountsCrashes(t *testing.T) {
|
||||
exit := func(name, expected string) string {
|
||||
return event("PROCESS_STATE_EXITED", "processname:"+name+" groupname:"+name+" from_state:RUNNING expected:"+expected+" pid:7")
|
||||
}
|
||||
var four []string
|
||||
for i := 0; i < 4; i++ {
|
||||
four = append(four, exit("panel", "0"))
|
||||
}
|
||||
if got := runListener(t, four...); strings.Contains(got, "would shut down") {
|
||||
t.Errorf("four crashes shut down:\n%s", got)
|
||||
}
|
||||
if got := runListener(t, append(four, exit("panel", "0"))...); !strings.Contains(got, "panel exited unexpectedly 5 times") || !strings.Contains(got, "would shut down") {
|
||||
t.Errorf("five crashes did not shut down:\n%s", got)
|
||||
}
|
||||
var calm []string
|
||||
for i := 0; i < 6; i++ {
|
||||
calm = append(calm, exit("panel", "1"), exit("logrotate", "0"))
|
||||
}
|
||||
calm = append(calm, exit("opendkim", "0"), exit("opendkim", "0"), exit("opendkim", "0"))
|
||||
if got := runListener(t, calm...); strings.Contains(got, "would shut down") {
|
||||
t.Errorf("expected exits, spared programs and three crashes of another shut down:\n%s", got)
|
||||
}
|
||||
}
|
||||
|
||||
// FATAL of a mail-path program shuts down at once; of a spared one, not.
|
||||
func TestCrashexitFatal(t *testing.T) {
|
||||
fatal := func(name string) string {
|
||||
return event("PROCESS_STATE_FATAL", "processname:"+name+" groupname:"+name+" from_state:BACKOFF")
|
||||
}
|
||||
if got := runListener(t, fatal("postfix")); !strings.Contains(got, "postfix entered FATAL; shutting down") || !strings.Contains(got, "would shut down") {
|
||||
t.Errorf("postfix FATAL:\n%s", got)
|
||||
}
|
||||
if got := runListener(t, fatal("logrotate"), fatal("syslog-relay")); strings.Contains(got, "would shut down") {
|
||||
t.Errorf("a spared program's FATAL shut down:\n%s", got)
|
||||
}
|
||||
}
|
||||
+13
-8
@@ -17,16 +17,21 @@
|
||||
# path anew (src/postlogd/postlogd.c, logwriter_open_or_die()).
|
||||
#
|
||||
# logrotate itself only rotates once the configured "daily" period has elapsed
|
||||
# (tracked in /var/lib/logrotate/status), so it is safe to invoke this more
|
||||
# often than daily — polling merely bounds how late a legitimate rotation runs.
|
||||
# (logrotate 3.21.0-1: debian/rules, --with-state-file-path=/var/lib/logrotate/
|
||||
# status. That file is in the container's own filesystem: a recreated container
|
||||
# starts without it, and logrotate.c, newState(), records a log it has no state
|
||||
# for as rotated today, so the first rotation after a recreate comes a day
|
||||
# later.)
|
||||
# (tracked in its state file), so it is safe to invoke this more often than
|
||||
# daily — polling merely bounds how late a legitimate rotation runs. The state
|
||||
# file is beside the log, under /data, not at the default
|
||||
# /var/lib/logrotate/status (logrotate 3.21.0-1: debian/rules,
|
||||
# --with-state-file-path) in the container's own filesystem: a recreated
|
||||
# container started without it, logrotate.c, newState(), records a log it has
|
||||
# no state for as rotated today, and so a host that recreates the container
|
||||
# daily - an .env change, an image bump - never rotated mail.log at all (audit
|
||||
# 2026-10-12, M19). (logrotate 3.21.0, logrotate.8.in: "-s, --state
|
||||
# statefile".) The directory is postfix:selfpost 2750 and logrotate runs as
|
||||
# root.
|
||||
set -eu
|
||||
|
||||
CONFIG=/etc/logrotate.d/mail
|
||||
STATE=/data/log/.logrotate.status
|
||||
INTERVAL="${LOGROTATE_INTERVAL_SECONDS:-21600}"
|
||||
|
||||
# logrotate refuses configs writable by group or others and exits 0 while
|
||||
@@ -56,7 +61,7 @@ if ! logrotate_config_ok; then
|
||||
fi
|
||||
|
||||
run_logrotate() {
|
||||
out=$(logrotate "$CONFIG" 2>&1) || {
|
||||
out=$(logrotate -s "$STATE" "$CONFIG" 2>&1) || {
|
||||
echo "$out" >&2
|
||||
return 1
|
||||
}
|
||||
|
||||
@@ -117,6 +117,64 @@ fi
|
||||
RATE_MSGS="${RATE_LIMIT_MESSAGES_PER_IP:-100}"
|
||||
RATE_WINDOW="${RATE_LIMIT_WINDOW_SECONDS:-3600}"
|
||||
|
||||
# The settings below reach main.cf and master.cf as numbers or time values.
|
||||
# A value that is neither, or one under the parameter's minimum, passes
|
||||
# `postfix check` and kills the daemon that reads it - every smtpd at its
|
||||
# first connection, or anvil and with it the rate limit (audit 2026-10-12,
|
||||
# L31; review of stage 5) - so the start stops here, saying which and why.
|
||||
# Counts and sizes are whole numbers from min up to 2147483647, an int's top
|
||||
# (Postfix 3.7.11 reads them with get_mail_conf_int*, src/global/
|
||||
# mail_conf_int.c: an int, held to the parameter's own minimum). A time value
|
||||
# is a whole number from 1 with an optional unit, s m h d or w, at most
|
||||
# 2147483647 seconds
|
||||
# (proto/postconf.proto: "Specify a non-zero time value (an integral value
|
||||
# plus an optional one-letter suffix ...). Time units: s (seconds), m
|
||||
# (minutes), h (hours), d (days), w (weeks)"; one unit - "1h30m" is read as
|
||||
# 1h, src/global/conv_time.c - so it is refused here).
|
||||
need_number() {
|
||||
case "$2" in
|
||||
'' | *[!0-9]*)
|
||||
echo "postfix-config: $1 must be a whole number, got '$2'" >&2
|
||||
exit 1
|
||||
;;
|
||||
esac
|
||||
if [ "${#2}" -gt 10 ] || [ "$2" -lt "$3" ] || [ "$2" -gt 2147483647 ]; then
|
||||
echo "postfix-config: $1 must be from $3 to 2147483647, got '$2'" >&2
|
||||
exit 1
|
||||
fi
|
||||
}
|
||||
need_time() {
|
||||
if ! printf '%s' "$2" | grep -Eq '^[1-9][0-9]{0,8}[smhdw]?$'; then
|
||||
echo "postfix-config: $1 must be a time value - a whole number from 1 with an optional s, m, h, d or w - got '$2'" >&2
|
||||
exit 1
|
||||
fi
|
||||
# conv_time multiplies by the unit and refuses what passes an int.
|
||||
n=${2%[smhdw]}
|
||||
case "$2" in
|
||||
*w) n=$((n * 604800)) ;;
|
||||
*d) n=$((n * 86400)) ;;
|
||||
*h) n=$((n * 3600)) ;;
|
||||
*m) n=$((n * 60)) ;;
|
||||
esac
|
||||
if [ "$n" -gt 2147483647 ]; then
|
||||
echo "postfix-config: $1 is more than 2147483647 seconds, got '$2'" >&2
|
||||
exit 1
|
||||
fi
|
||||
}
|
||||
# A rate of 0 is no limit, a size of 0 none (proto/postconf.proto,
|
||||
# smtpd_client_message_rate_limit, message_size_limit); the window is
|
||||
# anvil_rate_time_unit, at least 1 second (src/anvil/anvil.c, main(): its
|
||||
# time table's minimum 1).
|
||||
need_number RATE_LIMIT_MESSAGES_PER_IP "$RATE_MSGS" 0
|
||||
need_number RATE_LIMIT_WINDOW_SECONDS "$RATE_WINDOW" 1
|
||||
need_number INBOUND_RATE_LIMIT_MESSAGES_PER_IP "${INBOUND_RATE_LIMIT_MESSAGES_PER_IP:-20}" 0
|
||||
need_number INBOUND_MESSAGE_SIZE_LIMIT "${INBOUND_MESSAGE_SIZE_LIMIT:-26214400}" 0
|
||||
need_number DMARC_RATE_LIMIT_MESSAGES_PER_IP "${DMARC_RATE_LIMIT_MESSAGES_PER_IP:-20}" 0
|
||||
need_number DMARC_MESSAGE_SIZE_LIMIT "${DMARC_MESSAGE_SIZE_LIMIT:-5242880}" 0
|
||||
need_time MILTER_CONNECT_TIMEOUT "${MILTER_CONNECT_TIMEOUT:-15s}"
|
||||
need_time MILTER_COMMAND_TIMEOUT "${MILTER_COMMAND_TIMEOUT:-15s}"
|
||||
need_time MILTER_CONTENT_TIMEOUT "${MILTER_CONTENT_TIMEOUT:-30s}"
|
||||
|
||||
# Milter sockets: OpenDKIM (signing, strict), the panel's sender check
|
||||
# (strict) and its journal-milter (monitoring, fail-open). Fixed container
|
||||
# paths, matched by postfix-wrapper.sh.
|
||||
@@ -236,6 +294,22 @@ postconf -e \
|
||||
"smtpd_tls_auth_only=yes" \
|
||||
"smtpd_tls_loglevel=1"
|
||||
|
||||
# TLS 1.2 at least, opportunistic or required - and the client's too where an
|
||||
# inbound domain requires TLS to its upstream (smtp_tls_mandatory_protocols,
|
||||
# the security review of stage 5) (audit 2026-10-12, L31; Postfix
|
||||
# 3.7.11, proto/postconf.proto, smtpd_tls_protocols: since 3.6 the default is
|
||||
# ">=TLSv1", and a lower bound is written ">=version"). A sender that offers
|
||||
# less on port 25 sends in the clear, as one without TLS does. VRFY answers
|
||||
# no question about who is accepted on port 25 (relay_recipient_maps), and
|
||||
# the banner names no distribution (Debian's adds "(Debian/GNU)"; the
|
||||
# upstream default is "$myhostname ESMTP $mail_name").
|
||||
postconf -e \
|
||||
"smtpd_tls_protocols=>=TLSv1.2" \
|
||||
"smtpd_tls_mandatory_protocols=>=TLSv1.2" \
|
||||
"smtp_tls_mandatory_protocols=>=TLSv1.2" \
|
||||
"disable_vrfy_command=yes" \
|
||||
'smtpd_banner=$myhostname ESMTP'
|
||||
|
||||
# SASL: Cyrus with the local sasldb2 the panel maintains. The realm is left
|
||||
# implicit (smtpd_sasl_local_domain empty) so the authenticated name Postfix
|
||||
# uses for sender_login_maps is the BARE login the panel writes into the map;
|
||||
|
||||
+15
-9
@@ -9,13 +9,15 @@
|
||||
; pass, with no wait for a program to be ready.)
|
||||
;
|
||||
; If a managed process of the mail path exhausts its restart retries (FATAL),
|
||||
; the crashexit event listener brings the whole container down so Docker's
|
||||
; restart policy starts it again (the same container: docs.docker.com, "Start
|
||||
; containers automatically", restart policies), rather than lingering with a
|
||||
; dead component. A program reaches FATAL only through BACKOFF, by exits that
|
||||
; come before its startsecs (supervisor 4.2.5, supervisor/process.py,
|
||||
; Subprocess.finish() and transition()): an exit after it is EXITED and simply
|
||||
; restarted, for ever. logrotate's FATAL is left on Server > Health
|
||||
; or exits unexpectedly five times in ten minutes, the crashexit event listener
|
||||
; brings the whole container down so Docker's restart policy starts it again
|
||||
; (the same container: docs.docker.com, "Start containers automatically",
|
||||
; restart policies), rather than lingering with a dead component. A program
|
||||
; reaches FATAL only through BACKOFF, by exits that come before its startsecs
|
||||
; (supervisor 4.2.5, supervisor/process.py, Subprocess.finish() and
|
||||
; transition()): an exit after it is EXITED and simply restarted, for ever -
|
||||
; which the count of exits covers (audit 2026-10-12, L32). logrotate's,
|
||||
; postfix-reload's and syslog-relay's failures are left on Server > Health
|
||||
; (build/crashexit.py).
|
||||
|
||||
[supervisord]
|
||||
@@ -66,7 +68,11 @@ stderr_logfile=/dev/stderr
|
||||
stderr_logfile_maxbytes=0
|
||||
|
||||
[program:opendkim]
|
||||
command=/usr/sbin/opendkim -f -x /etc/opendkim.conf
|
||||
; It waits, five seconds at most, for the syslog relay's socket: supervisord
|
||||
; starts programs in priority order without waiting for one to be ready, and
|
||||
; OpenDKIM's start line would go nowhere (review of audit stage 5). exec keeps
|
||||
; the supervised pid OpenDKIM's.
|
||||
command=/bin/sh -c 'i=0; while [ ! -S /run/syslog/log ] && [ "$i" -lt 50 ]; do sleep 0.1; i=$((i+1)); done; exec /usr/sbin/opendkim -f -x /etc/opendkim.conf'
|
||||
priority=100
|
||||
autostart=true
|
||||
autorestart=true
|
||||
@@ -182,6 +188,6 @@ stderr_logfile_maxbytes=0
|
||||
; STOPPED (Subprocess.finish(), self.killing), which this listener never sees.
|
||||
[eventlistener:crashexit]
|
||||
command=/usr/local/bin/crashexit.py
|
||||
events=PROCESS_STATE_FATAL
|
||||
events=PROCESS_STATE_FATAL,PROCESS_STATE_EXITED
|
||||
stderr_logfile=/dev/stderr
|
||||
stderr_logfile_maxbytes=0
|
||||
|
||||
Reference in New Issue
Block a user