From f2ad69947327b2337ac81e24a37458eb668aff93 Mon Sep 17 00:00:00 2001 From: Mix Date: Wed, 14 Oct 2026 23:49:25 +0300 Subject: [PATCH] supervision as supervisord does it: Postfix stopped, give-ups FATAL, reload's exit read C-P42. postfix-script's start-fg runs master as its child and master calls setsid() (Postfix 3.7.11, conf/postfix-script; src/master/master.c); supervisord signals the pid alone (supervisor 4.2.5, process.py, Subprocess.kill()). A stop of program postfix left master running - a restart then found "already running" - and a container stop cut Postfix off with SIGKILL. The wrapper now stays the parent of "postfix start-fg" and on TERM/INT runs "postfix stop", asking again while start-fg is still in its checks (master -t). stopwaitsecs=15. C-V6. The wrapper's give-up on the milter sockets came after the default startsecs, so it was EXITED and restarted for ever. startsecs is now MILTER_WAIT_TIMEOUT + 10, exported by the entrypoint as POSTFIX_STARTSECS and expanded by supervisord (options.py, processes_from_section(); a non-number MILTER_WAIT_TIMEOUT stops the start): a give-up is "Exited too quickly", BACKOFF, FATAL after startretries, crashexit. For those seconds after each start the program is STARTING (the healthcheck's 90 s start period covers it; the sender check counts no downtime then). C-V5. logrotate had startsecs=0, so a refused config restarted it every second for ever. startsecs=1: FATAL after startretries; crashexit reads the event's processname and leaves logrotate's FATAL on Server > Health. B-U2. "supervisorctl start" returns when a startsecs=0 program is RUNNING, not when it ends, and mapped "already started" to success. The panel now speaks supervisord's XML-RPC itself (internal/supervisor, RunOnce): startProcess without waiting, getProcessInfo until it leaves STARTING/RUNNING, exitstatus 0 or an error; a run in progress is waited out and one of its own follows. A failed reload while program postfix is not RUNNING is logged, not an error: the next master reads the files. C-V10: postfix-reload rests EXITED after a run; the e2e process check takes STOPPED or EXITED. C-P34: the dead "postfix set-permissions" branch goes - postfix check's create-missing builds the queue tree. Stand (2026-10-14, make e2e, exit 0; MILTER_WAIT_TIMEOUT=10 on the stand): new supervision_stops_postfix_and_gives_up - supervisorctl restart postfix writes postfix-script's "stopping the Postfix mail system" and leaves one master; with the panel's sockets removed, start answers "postfix: ERROR (spawn error)" (finish() sets spawnerr "Exited too quickly", onwait() reads it first) and Postfix comes up once the panel is back; a group-writable logrotate config ends FATAL with the container up; the panel's Reload configuration answers only after mail.log has "refreshing the Postfix mail system", postfix-reload EXITED. session_survives_restart sees the stop line for the container's restart. Measured: master's own "terminating on signal 15" never reaches mail.log (master TERMs its group, postlogd included, before it logs). go vet and go test ./... pass on the server (24 packages; new unit tests of RunOnce against a fake supervisord). Co-Authored-By: Claude Opus 5.5 --- build/crashexit.py | 43 +++-- build/entrypoint.sh | 24 ++- build/postfix-wrapper.sh | 53 +++++- build/supervisord.conf | 41 ++++- cmd/panel/sendercheck.go | 5 +- docs/architecture.md | 22 ++- internal/postfix/postfix.go | 22 ++- internal/supervisor/rpc.go | 280 ++++++++++++++++++++++++++++++ internal/supervisor/rpc_test.go | 156 +++++++++++++++++ internal/supervisor/supervisor.go | 15 -- test/e2e/compose.override.yml | 5 + test/e2e/main_test.go | 3 + test/e2e/negative_test.go | 8 + test/e2e/process_check.go | 13 +- test/e2e/supervision_test.go | 203 ++++++++++++++++++++++ 15 files changed, 834 insertions(+), 59 deletions(-) create mode 100644 internal/supervisor/rpc.go create mode 100644 internal/supervisor/rpc_test.go create mode 100644 test/e2e/supervision_test.go diff --git a/build/crashexit.py b/build/crashexit.py index 53cbfe7..445e5e9 100644 --- a/build/crashexit.py +++ b/build/crashexit.py @@ -1,10 +1,12 @@ #!/usr/bin/env python3 """Supervisor event listener: bring the container down on unrecoverable failure. -If any managed program 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 can recreate it cleanly — rather than -lingering "alive" with a dead Postfix/OpenDKIM/panel. +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). Communication with supervisord uses the event listener protocol over stdin and stdout, so stdout must carry only protocol tokens. @@ -12,6 +14,9 @@ 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()). 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). """ @@ -19,6 +24,9 @@ import os import signal import sys +# Programs whose FATAL does not take the container down (build/supervisord.conf). +SPARED = {"logrotate"} + def write_stdout(s): sys.stdout.write(s) @@ -35,16 +43,27 @@ def main(): return headers = dict(pair.split(":", 1) for pair in line.split()) payload_len = int(headers.get("len", 0)) - if payload_len: - sys.stdin.read(payload_len) + payload = sys.stdin.read(payload_len) if payload_len else "" + tokens = dict( + pair.split(":", 1) for pair in payload.split() if ":" in pair + ) + name = tokens.get("processname", "") # We only subscribe to PROCESS_STATE_FATAL, so any event means a managed - # program can no longer be restarted. Take the container down. - sys.stderr.write( - "crashexit: a managed process entered FATAL; shutting down container\n" - ) - sys.stderr.flush() - os.kill(os.getppid(), signal.SIGTERM) + # 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 + ) + sys.stderr.flush() + else: + sys.stderr.write( + "crashexit: %s entered FATAL; shutting down container\n" + % (name or "a managed process") + ) + sys.stderr.flush() + os.kill(os.getppid(), signal.SIGTERM) write_stdout("RESULT 2\nOK") diff --git a/build/entrypoint.sh b/build/entrypoint.sh index 0aecdaa..05e5930 100644 --- a/build/entrypoint.sh +++ b/build/entrypoint.sh @@ -177,11 +177,12 @@ rm -f /run/opendkim/*.sock /run/selfpost/*.sock /run/selfpost/*.alive # start the same way the /data normalisation above is. /usr/local/bin/postfix-config.sh -# Initialise the persistent queue tree on first start or after restore. postfix -# set-permissions reads queue_directory from main.cf (set by postfix-config.sh). -if [ ! -d /data/postfix/queue/active ]; then - postfix set-permissions -fi +# The queue tree, on a first start or after a restore, is already built here: +# postfix-config.sh ends with "postfix check", whose check-fatal runs +# "post-install create-missing" (Postfix 3.7.11, conf/postfix-script; +# conf/postfix-files, "$queue_directory/active:d:$mail_owner:-:700:ucr"). +# A "postfix set-permissions" for a missing active/ stood here and never ran +# (assumptions C-P34). chown -R postfix:postfix /data/postfix/queue # The recursive chown above would leave public/ and maildrop/ in group postfix. # Postfix keeps those two in its setgid group: postqueue and postdrop are setgid @@ -199,4 +200,17 @@ chgrp postdrop /data/postfix/queue/public /data/postfix/queue/maildrop # root".) chown root /data/postfix/queue /data/postfix/queue/pid +# [program:postfix]'s startsecs (build/supervisord.conf): longer than the +# wrapper's wait for the milter sockets, so its exit at the end of the wait is +# one supervisord counts as too quick. A value that is not a number stops the +# start here. +wait_timeout="${MILTER_WAIT_TIMEOUT:-30}" +case "$wait_timeout" in +'' | *[!0-9]*) + echo "entrypoint: MILTER_WAIT_TIMEOUT must be a whole number of seconds, got '$wait_timeout'" >&2 + exit 1 + ;; +esac +export POSTFIX_STARTSECS=$((wait_timeout + 10)) + exec /usr/bin/supervisord -c /etc/supervisor/supervisord.conf diff --git a/build/postfix-wrapper.sh b/build/postfix-wrapper.sh index 7caf178..f204936 100644 --- a/build/postfix-wrapper.sh +++ b/build/postfix-wrapper.sh @@ -4,10 +4,15 @@ # # It blocks until the milter sockets — OpenDKIM, the panel's sender check and # journal-milter and, with the inbound relay on, its inbound journal milter — -# are present, -# then execs `postfix start-fg`. If they are not ready within the -# timeout it exits non-zero WITHOUT starting Postfix, so supervisord/Docker see -# an explicit startup failure instead of a relay running blind. +# are present, then runs `postfix start-fg` and stays its parent. If they are +# not ready within the timeout it exits non-zero WITHOUT starting Postfix. +# supervisord counts that exit as one that came too quickly - the program's +# startsecs is the timeout plus ten seconds (build/entrypoint.sh) - so after +# startretries it is FATAL and crashexit takes the container down, instead of +# a relay running blind (supervisor 4.2.5, supervisor/process.py, +# Subprocess.finish(): an exit before startsecs is "Exited too quickly" and +# goes to BACKOFF; transition(): BACKOFF past startretries is FATAL; +# assumptions C-V6). # # This handles cold start only. Once Postfix runs, a milter that does not # answer costs what its default_action says (build/postfix-config.sh): mail is @@ -42,5 +47,41 @@ echo "postfix-wrapper: milter sockets ready, starting postfix" # Postfix 3.7.11: postfix(1) execs conf/postfix-script (src/postfix/postfix.c), # whose "start-fg" execs master only as PID 1 and otherwise runs "master -s" as # its child; master then makes itself a session leader (src/master/master.c, -# setsid()). The process supervisord watches is that shell, not master. -exec postfix start-fg +# setsid()). A signal supervisord sends this program never reaches master +# (supervisor 4.2.5, supervisor/process.py, Subprocess.kill(): to the pid +# alone without stopasgroup, and master is not in its group anyway): before, +# a stop left master running - a restart of the program then found Postfix +# "already running", and a stop of the container cut Postfix off with +# SIGKILL (assumptions C-P42). So this shell stays, and on TERM or INT runs +# "postfix stop" (conf/postfix-script, "stop": TERM to master, then waits up +# to five seconds and kills its group; src/master/master_sig.c, +# master_sigdeath(): "terminating on signal 15"). +# +# "postfix start-fg" spends its first seconds in its checks before master +# runs; a stop asked then would find nothing to stop, so it is asked again +# until the child is gone. "master -t" exits 0, silently, while no master +# holds the lock (src/master/master.c, test_lock). +daemon_directory=$(postconf -h daemon_directory) +child= +stop_postfix() { + trap '' TERM INT + while [ -n "$child" ] && kill -0 "$child" 2>/dev/null; do + if "$daemon_directory/master" -t 2>/dev/null; then + sleep 1 + else + postfix stop || true + fi + done + exit 0 +} +trap stop_postfix TERM INT +postfix start-fg & +child=$! +# A trapped signal makes wait return at once, the trap is taken right after +# (POSIX, Shell Command Language, 2.11 Signals and Error Handling) and exits. +# Otherwise wait returns when Postfix ended on its own: its status is this +# program's, and supervisord restarts it. +status=0 +wait "$child" || status=$? +echo "postfix-wrapper: postfix exited with status $status" >&2 +exit "$status" diff --git a/build/supervisord.conf b/build/supervisord.conf index 88b68f3..7860ec5 100644 --- a/build/supervisord.conf +++ b/build/supervisord.conf @@ -8,9 +8,15 @@ ; supervisord.py, runforever(), transitions every group in that order in one ; pass, with no wait for a program to be ready.) ; -; If any managed process exhausts its restart retries (FATAL), the crashexit -; event listener brings the whole container down so Docker's restart policy can -; recreate it cleanly, rather than lingering with a dead component. +; 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 +; (build/crashexit.py). [supervisord] nodaemon=true @@ -66,12 +72,22 @@ stdout_logfile_maxbytes=0 stderr_logfile=/dev/stderr stderr_logfile_maxbytes=0 +; startsecs is MILTER_WAIT_TIMEOUT plus ten seconds (build/entrypoint.sh): the +; wrapper's exit when the milter sockets never come counts as too quick, and +; so does a Postfix that will not start. The price: for that long after each +; start the program is STARTING, not RUNNING (supervisor 4.2.5, +; supervisor/options.py, processes_from_section(): startsecs is expanded like +; any value, %(ENV_x)s from supervisord's environment; assumptions C-V6). +; stopwaitsecs covers "postfix stop", which waits five seconds for master +; before it kills (build/postfix-wrapper.sh). [program:postfix] command=/usr/local/bin/postfix-wrapper.sh priority=300 autostart=true autorestart=true +startsecs=%(ENV_POSTFIX_STARTSECS)s startretries=3 +stopwaitsecs=15 stdout_logfile=/dev/stdout stdout_logfile_maxbytes=0 stderr_logfile=/dev/stderr @@ -88,7 +104,9 @@ stderr_logfile_maxbytes=0 ; crashexit listener. (start-fg: see build/postfix-wrapper.sh. supervisor ; 4.2.5, supervisor/process.py, Subprocess.finish(): with startsecs=0 no exit ; counts as "too quickly", so even a failed run ends EXITED - never BACKOFF, -; never FATAL.) +; never FATAL - with its exit status kept, which the panel reads +; (internal/supervisor, RunOnce). Its resting state is STOPPED until the first +; run, EXITED after it; assumptions C-V10.) [program:postfix-reload] command=/usr/sbin/postfix reload autostart=false @@ -117,16 +135,21 @@ stdout_logfile_maxbytes=0 stderr_logfile=/dev/stderr stderr_logfile_maxbytes=0 -; Periodic logrotate for /data/log/mail.log (daily, 7-14 files kept in the -; image). Runs as root so logrotate can read/rotate the log. Exits non-zero when -; the config is group/other-writable (logrotate would ignore it silently); -; autorestart surfaces BACKOFF on the Status page. +; Periodic logrotate for /data/log/mail.log (daily, 14 files kept). Runs as +; root so logrotate can read/rotate the log. Exits non-zero at once when the +; config is group/other-writable (logrotate would ignore it silently): with +; startsecs=1 that exit is too quick; once startretries are spent the program +; is FATAL, and Server > Health shows it. With startsecs=0 it was restarted +; every second for ever, RUNNING and EXITED in turn (supervisor 4.2.5, +; supervisor/process.py, Subprocess.finish(); assumptions C-V5). crashexit +; leaves this FATAL alone: logrotate is not on the mail path. [program:logrotate] command=/usr/local/bin/logrotate-loop.sh priority=400 autostart=true autorestart=true -startsecs=0 +startsecs=1 +startretries=3 stdout_logfile=/dev/stdout stdout_logfile_maxbytes=0 stderr_logfile=/dev/stderr diff --git a/cmd/panel/sendercheck.go b/cmd/panel/sendercheck.go index decd5b8..c42daf5 100644 --- a/cmd/panel/sendercheck.go +++ b/cmd/panel/sendercheck.go @@ -139,7 +139,10 @@ var postfixAskFor, postfixAskEvery = 30 * time.Second, 2 * time.Second // 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). +// (assumptions A-46). For startsecs - that wait plus ten seconds +// (build/supervisord.conf) - after its start the program is STARTING, not +// RUNNING, and is taken here as not running: a panel restart within that +// time after Postfix's own counts no downtime. func postfixStarted() postfixState { deadline := time.Now().Add(postfixAskFor) for { diff --git a/docs/architecture.md b/docs/architecture.md index e5913bf..b2a79a8 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -34,14 +34,26 @@ Managed programs ([build/supervisord.conf](../build/supervisord.conf)): | `logrotate` | root | 400 | Periodic `mail.log` rotation | Start order: OpenDKIM → panel (opens the sender check's and the journal-milter's sockets) → Postfix wrapper -polls unix sockets (timeout `MILTER_WAIT_TIMEOUT`, default 30s) then -`postfix start-fg`. +polls unix sockets (timeout `MILTER_WAIT_TIMEOUT`, default 30s) then runs +`postfix start-fg` and stays its parent: on TERM it runs `postfix stop`, so a +stop of the program or of the container stops Postfix as Postfix means it to +be stopped (master runs in a session of its own, which supervisord's signal +never reaches). Program `postfix` has `startsecs` = `MILTER_WAIT_TIMEOUT` + 10 +(set by the entrypoint), so the wrapper giving up on the sockets, or a Postfix +that will not start, is an exit supervisord counts as too quick: once +`startretries` (3) are spent, the program is FATAL. For those seconds after +each start it is STARTING. -`crashexit` event listener exits the container on any managed process FATAL so -Docker `restart: unless-stopped` recreates a broken instance. +`crashexit` event listener exits the container when a program of the mail path +is FATAL, so Docker `restart: unless-stopped` starts it again. `logrotate`'s +FATAL (a config logrotate would ignore) stays on Server › Health instead. +The panel runs `postfix-reload` through supervisord's XML-RPC interface and +waits for its exit status (`internal/supervisor`, `RunOnce`); the program +rests EXITED after a run. **Liveness:** `GET /healthz` (unauthenticated) returns 200 when opendkim, -panel, and postfix are RUNNING; Docker `HEALTHCHECK` uses the same probe. +panel, and postfix are RUNNING; Docker `HEALTHCHECK` uses the same probe (its +90-second start period covers postfix's STARTING). --- diff --git a/internal/postfix/postfix.go b/internal/postfix/postfix.go index 68470bf..02e709f 100644 --- a/internal/postfix/postfix.go +++ b/internal/postfix/postfix.go @@ -7,6 +7,7 @@ package postfix import ( "fmt" + "log" "path/filepath" "sort" "strings" @@ -186,6 +187,25 @@ func assertMapSafe(address, login string) error { // whenever it is convenient" while new ones get the new configuration; a // texthash table is read into memory once per process // (README_FILES/DATABASE_README). +// +// The call returns when "postfix reload" has ended, with an error unless it +// exited 0 (a postsuper failure, a main.cf postfix(1) cannot read: +// conf/postfix-script, "reload"; src/postfix/postfix.c), which the page that +// saved shows. Before, supervisorctl's start returned as the reload was +// spawned, and a reload already running counted as done though it may have +// read the files before this change (supervisor.RunOnce; assumptions B-U2). +// A reload that fails while program postfix is not RUNNING - stopped, or +// still in its start, the wrapper waiting for the milter sockets - is no +// error: "the Postfix mail system is not running", and the master that starts +// next reads the files as they are now. func reloadViaSupervisor() error { - return supervisor.Start("postfix-reload") + err := supervisor.RunOnce("postfix-reload") + if err == nil { + return nil + } + if state, serr := supervisor.State("postfix"); serr == nil && state != "RUNNING" { + log.Printf("postfix: reload while program postfix is %s, left to its start: %v", state, err) + return nil + } + return err } diff --git a/internal/supervisor/rpc.go b/internal/supervisor/rpc.go new file mode 100644 index 0000000..19b6fb9 --- /dev/null +++ b/internal/supervisor/rpc.go @@ -0,0 +1,280 @@ +package supervisor + +import ( + "bytes" + "context" + "encoding/xml" + "errors" + "fmt" + "io" + "net" + "net/http" + "strconv" + "strings" + "time" +) + +// socketPath is supervisord's control socket: build/supervisord.conf, +// [unix_http_server] file=, group selfpost, which the panel is in. +const socketPath = "/run/supervisor.sock" + +// runOnceFor bounds RunOnce: a reload that is still running after it is +// reported as a failure. "postfix reload" checks that master runs, moves the +// incoming queue to active and sends master SIGHUP (Postfix 3.7.11, +// conf/postfix-script, "reload") - well under a second on the stand. +var runOnceFor = time.Minute + +// pollEvery is how often RunOnce asks how the run is going; supervisord's own +// deferred start answers on the same beat (supervisor 4.2.5, +// supervisor/rpcinterface.py, startProcess(): onwait.delay = 0.05). +var pollEvery = 50 * time.Millisecond + +// supervisord's process states (supervisor 4.2.5, supervisor/states.py, +// ProcessStates) as getProcessInfo returns them in 'state'. +const ( + stateStopped = 0 + stateStarting = 10 + stateRunning = 20 + stateBackoff = 30 + stateStopping = 40 + stateExited = 100 +) + +// faultAlreadyStarted is the fault startProcess raises for a program in +// STARTING, RUNNING or BACKOFF (supervisor 4.2.5, supervisor/xmlrpc.py, +// Faults.ALREADY_STARTED; rpcinterface.py, startProcess(): RUNNING_STATES). +const faultAlreadyStarted = 60 + +// RunOnce runs a one-shot program to its end and reports how it ended: nil +// only when it exited with status 0. +// +// "supervisorctl start" cannot tell that. For a program with startsecs=0 it +// returns as soon as the program is RUNNING - spawned, not finished - and its +// exit status is never reported (supervisor 4.2.5, supervisor/rpcinterface.py, +// startProcess(): process.transition() moves STARTING to RUNNING at once, +// then "return True"; assumptions B-U2). So RunOnce speaks supervisord's +// XML-RPC interface itself: startProcess without waiting, then +// getProcessInfo until the program leaves STARTING and RUNNING, and the +// 'exitstatus' supervisord kept (process.py, Subprocess.finish(): with +// startsecs=0 every end is EXITED, with its status). +// +// A run already in progress started before the caller's change was written, +// and may have read the old files: RunOnce waits for it to end and then starts +// its own. A run someone else starts after this one ended is newer than the +// caller's change, so its end serves just as well. +func RunOnce(program string) error { + return newRPC(socketPath).runOnce(program) +} + +// State is the state supervisord gives a program, by its name: RUNNING, +// STARTING, EXITED ... (supervisor 4.2.5, supervisor/states.py). +func State(program string) (string, error) { + v, err := newRPC(socketPath).call("supervisor.getProcessInfo", program) + if err != nil { + return "", fmt.Errorf("supervisor: state of %s: %w", program, err) + } + return v.members()["statename"].str(), nil +} + +type rpc struct { + client *http.Client +} + +func newRPC(sock string) *rpc { + return &rpc{client: &http.Client{ + Timeout: 10 * time.Second, + Transport: &http.Transport{ + DialContext: func(ctx context.Context, _, _ string) (net.Conn, error) { + var d net.Dialer + return d.DialContext(ctx, "unix", sock) + }, + DisableKeepAlives: true, + }, + }} +} + +func (c *rpc) runOnce(program string) error { + deadline := time.Now().Add(runOnceFor) + for { + _, err := c.call("supervisor.startProcess", program, false) + var f *Fault + if errors.As(err, &f) && f.Code == faultAlreadyStarted { + info, err := c.waitEnd(program, deadline) + if err != nil { + return err + } + if info.state == stateBackoff { + // Never for startsecs=0 (Subprocess.finish()), so no + // start of ours could follow it. + return fmt.Errorf("supervisor: %s is in BACKOFF: %s", program, info.spawnErr) + } + if time.Now().After(deadline) { + return fmt.Errorf("supervisor: %s did not come free within %s", program, runOnceFor) + } + continue + } + if err != nil { + return fmt.Errorf("supervisor: start %s: %w", program, err) + } + break + } + info, err := c.waitEnd(program, deadline) + if err != nil { + return err + } + if info.state == stateExited && info.exitStatus == 0 { + return nil + } + msg := fmt.Sprintf("supervisor: %s ended %s, exit status %d", program, info.stateName, info.exitStatus) + if info.spawnErr != "" { + msg += ": " + info.spawnErr + } + return errors.New(msg) +} + +// processInfo is the part of getProcessInfo's struct RunOnce reads. +type processInfo struct { + state int + stateName string + exitStatus int + spawnErr string +} + +// waitEnd asks for the program's state until it is out of STARTING, RUNNING +// and STOPPING. +func (c *rpc) waitEnd(program string, deadline time.Time) (processInfo, error) { + for { + v, err := c.call("supervisor.getProcessInfo", program) + if err != nil { + return processInfo{}, fmt.Errorf("supervisor: state of %s: %w", program, err) + } + m := v.members() + info := processInfo{ + state: m["state"].int(), + stateName: m["statename"].str(), + exitStatus: m["exitstatus"].int(), + spawnErr: m["spawnerr"].str(), + } + switch info.state { + case stateStarting, stateRunning, stateStopping: + default: + return info, nil + } + if time.Now().After(deadline) { + return info, fmt.Errorf("supervisor: %s still %s after %s", program, info.stateName, runOnceFor) + } + time.Sleep(pollEvery) + } +} + +// Fault is an XML-RPC fault supervisord answered with (supervisor 4.2.5, +// supervisor/xmlrpc.py, Faults; the string is ": "). +type Fault struct { + Code int + String string +} + +func (f *Fault) Error() string { + return fmt.Sprintf("fault %d: %s", f.Code, f.String) +} + +// call makes one XML-RPC call; params are strings and booleans, all the +// methods used here take. +func (c *rpc) call(method string, params ...any) (xvalue, error) { + var b bytes.Buffer + b.WriteString(``) + xml.EscapeText(&b, []byte(method)) + b.WriteString(``) + for _, p := range params { + b.WriteString(``) + switch v := p.(type) { + case string: + b.WriteString(``) + xml.EscapeText(&b, []byte(v)) + b.WriteString(``) + case bool: + if v { + b.WriteString(`1`) + } else { + b.WriteString(`0`) + } + default: + return xvalue{}, fmt.Errorf("xml-rpc: parameter of type %T", p) + } + b.WriteString(``) + } + b.WriteString(``) + + // supervisor 4.2.5, supervisor/xmlrpc.py, supervisor_xmlrpc_handler: + // path '/RPC2'; the host is not looked at. + resp, err := c.client.Post("http://localhost/RPC2", "text/xml", &b) + if err != nil { + return xvalue{}, err + } + defer resp.Body.Close() + body, err := io.ReadAll(io.LimitReader(resp.Body, 1<<20)) + if err != nil { + return xvalue{}, err + } + if resp.StatusCode != http.StatusOK { + return xvalue{}, fmt.Errorf("xml-rpc %s: HTTP %d", method, resp.StatusCode) + } + var r struct { + Params []xvalue `xml:"params>param>value"` + Fault *xvalue `xml:"fault>value"` + } + if err := xml.Unmarshal(body, &r); err != nil { + return xvalue{}, fmt.Errorf("xml-rpc %s: %w", method, err) + } + if r.Fault != nil { + m := r.Fault.members() + return xvalue{}, &Fault{Code: m["faultCode"].int(), String: m["faultString"].str()} + } + if len(r.Params) != 1 { + return xvalue{}, fmt.Errorf("xml-rpc %s: %d values in the answer", method, len(r.Params)) + } + return r.Params[0], nil +} + +// xvalue is an XML-RPC as Python's xmlrpc.client writes it: a typed +// element, or bare text for a string. +type xvalue struct { + Int *string `xml:"int"` + I4 *string `xml:"i4"` + Boolean *string `xml:"boolean"` + String *string `xml:"string"` + Struct *struct { + Members []struct { + Name string `xml:"name"` + Value xvalue `xml:"value"` + } `xml:"member"` + } `xml:"struct"` + Text string `xml:",chardata"` +} + +func (v xvalue) members() map[string]xvalue { + m := map[string]xvalue{} + if v.Struct != nil { + for _, mb := range v.Struct.Members { + m[mb.Name] = mb.Value + } + } + return m +} + +func (v xvalue) int() int { + for _, s := range []*string{v.Int, v.I4, v.Boolean} { + if s != nil { + n, _ := strconv.Atoi(strings.TrimSpace(*s)) + return n + } + } + return 0 +} + +func (v xvalue) str() string { + if v.String != nil { + return *v.String + } + return v.Text +} diff --git a/internal/supervisor/rpc_test.go b/internal/supervisor/rpc_test.go new file mode 100644 index 0000000..860b4b2 --- /dev/null +++ b/internal/supervisor/rpc_test.go @@ -0,0 +1,156 @@ +package supervisor + +import ( + "fmt" + "io" + "net" + "net/http" + "os" + "path/filepath" + "regexp" + "strings" + "sync" + "testing" + "time" +) + +// fakeSupervisord answers startProcess and getProcessInfo the way supervisor +// 4.2.5 does over XML-RPC (Python's xmlrpc.client.dumps with methodresponse: +// one , or a struct), from a script of states. +type fakeSupervisord struct { + mu sync.Mutex + // alreadyStarted is how many startProcess calls get fault 60 first. + alreadyStarted int + // states are the (state, statename, exitstatus) getProcessInfo returns, + // one per call; the last one repeats. + states []fakeState + starts int + asked int +} + +type fakeState struct { + state int + name string + exitStatus int +} + +var methodRe = regexp.MustCompile(`([^<]+)`) + +func (f *fakeSupervisord) ServeHTTP(w http.ResponseWriter, r *http.Request) { + body, _ := io.ReadAll(r.Body) + m := methodRe.FindSubmatch(body) + if r.URL.Path != "/RPC2" || m == nil { + http.Error(w, "no", http.StatusNotFound) + return + } + f.mu.Lock() + defer f.mu.Unlock() + w.Header().Set("Content-Type", "text/xml") + switch string(m[1]) { + case "supervisor.startProcess": + f.starts++ + if !strings.Contains(string(body), "0") { + http.Error(w, "start must not wait", http.StatusBadRequest) + return + } + if f.alreadyStarted > 0 { + f.alreadyStarted-- + io.WriteString(w, "\n\n\n\n"+ + "\nfaultCode\n60\n\n"+ + "\nfaultString\nALREADY_STARTED: postfix-reload\n\n"+ + "\n\n\n") + return + } + io.WriteString(w, "\n\n\n\n1\n\n\n\n") + case "supervisor.getProcessInfo": + s := f.states[min(f.asked, len(f.states)-1)] + f.asked++ + fmt.Fprintf(w, "\n\n\n\n\n"+ + "\nname\npostfix-reload\n\n"+ + "\nstate\n%d\n\n"+ + "\nstatename\n%s\n\n"+ + "\nexitstatus\n%d\n\n"+ + "\nspawnerr\n\n\n"+ + "\n\n\n\n", s.state, s.name, s.exitStatus) + default: + http.Error(w, "unknown method", http.StatusBadRequest) + } +} + +func serveFake(t *testing.T, f *fakeSupervisord) *rpc { + t.Helper() + // A short directory: a unix socket's path is limited to about 100 bytes. + dir, err := os.MkdirTemp("", "sv") + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { os.RemoveAll(dir) }) + sock := filepath.Join(dir, "s") + ln, err := net.Listen("unix", sock) + if err != nil { + t.Skipf("unix sockets: %v", err) + } + srv := &http.Server{Handler: f} + go srv.Serve(ln) + t.Cleanup(func() { srv.Close() }) + old := pollEvery + pollEvery = time.Millisecond + t.Cleanup(func() { pollEvery = old }) + return newRPC(sock) +} + +var ( + running = fakeState{20, "RUNNING", 0} + exited0 = fakeState{100, "EXITED", 0} +) + +func TestRunOnceWaitsForTheEndAndItsStatus(t *testing.T) { + f := &fakeSupervisord{states: []fakeState{running, running, exited0}} + if err := serveFake(t, f).runOnce("postfix-reload"); err != nil { + t.Fatalf("runOnce: %v", err) + } + if f.starts != 1 || f.asked != 3 { + t.Fatalf("starts %d, asked %d; want 1 start and asked until EXITED (3)", f.starts, f.asked) + } +} + +func TestRunOnceReportsAFailedRun(t *testing.T) { + f := &fakeSupervisord{states: []fakeState{running, {100, "EXITED", 1}}} + err := serveFake(t, f).runOnce("postfix-reload") + if err == nil || !strings.Contains(err.Error(), "ended EXITED, exit status 1") { + t.Fatalf("runOnce: %v; want the exit status 1", err) + } +} + +// A run in progress may have read the files before the caller wrote them: +// it is waited out and a run of the caller's own follows. +func TestRunOnceStartsItsOwnAfterARunInProgress(t *testing.T) { + f := &fakeSupervisord{alreadyStarted: 1, states: []fakeState{running, exited0, running, exited0}} + if err := serveFake(t, f).runOnce("postfix-reload"); err != nil { + t.Fatalf("runOnce: %v", err) + } + if f.starts != 2 || f.asked != 4 { + t.Fatalf("starts %d, asked %d; want the running one waited out, then a start of its own (2 starts, 4 asks)", f.starts, f.asked) + } +} + +func TestRunOnceGivesUpOnARunThatDoesNotEnd(t *testing.T) { + f := &fakeSupervisord{states: []fakeState{running}} + c := serveFake(t, f) + old := runOnceFor + runOnceFor = 20 * time.Millisecond + t.Cleanup(func() { runOnceFor = old }) + err := c.runOnce("postfix-reload") + if err == nil || !strings.Contains(err.Error(), "still RUNNING") { + t.Fatalf("runOnce: %v; want still RUNNING", err) + } +} + +func TestFaultIsReadFromTheAnswer(t *testing.T) { + f := &fakeSupervisord{alreadyStarted: 1, states: []fakeState{exited0}} + _, err := serveFake(t, f).call("supervisor.startProcess", "postfix-reload", false) + fault, ok := err.(*Fault) + if !ok || fault.Code != faultAlreadyStarted || fault.String != "ALREADY_STARTED: postfix-reload" { + t.Fatalf("call: %v; want fault 60 ALREADY_STARTED", err) + } +} diff --git a/internal/supervisor/supervisor.go b/internal/supervisor/supervisor.go index 6f8d14f..1b165b9 100644 --- a/internal/supervisor/supervisor.go +++ b/internal/supervisor/supervisor.go @@ -10,21 +10,6 @@ import ( const confPath = "/etc/supervisor/supervisord.conf" -// Start issues a `supervisorctl start` for the named program. A program that -// is already running is not an error (the pending run covers the caller's -// intent). -func Start(program string) error { - cmd := exec.Command("supervisorctl", "-c", confPath, "start", program) - out, err := cmd.CombinedOutput() - if err != nil { - if strings.Contains(string(out), "already started") { - return nil - } - return fmt.Errorf("supervisor start %s: %w: %s", program, err, strings.TrimSpace(string(out))) - } - return nil -} - // Signal sends a signal to a supervised program via `supervisorctl signal`. func Signal(sig, program string) error { cmd := exec.Command("supervisorctl", "-c", confPath, "signal", sig, program) diff --git a/test/e2e/compose.override.yml b/test/e2e/compose.override.yml index 6920a1b..df1df81 100644 --- a/test/e2e/compose.override.yml +++ b/test/e2e/compose.override.yml @@ -55,6 +55,11 @@ services: # often, so renewed_certificate_picked_up does not wait a day. It # reloads Postfix only when the certificate changed. TLS_RELOAD_INTERVAL_SECONDS: "2" + # The wrapper gives up on the milter sockets after this long, and + # program postfix's startsecs is this plus ten (build/entrypoint.sh): + # supervision_stops_postfix_and_gives_up waits for one give-up and + # every start for startsecs, so the stand keeps both short. + MILTER_WAIT_TIMEOUT: "10" ports: !override - "20465:465" - "20587:587" diff --git a/test/e2e/main_test.go b/test/e2e/main_test.go index 956c562..8dbf546 100644 --- a/test/e2e/main_test.go +++ b/test/e2e/main_test.go @@ -334,6 +334,9 @@ func TestE2E(t *testing.T) { run("session_survives_restart", func(t *testing.T) { testSessionSurvivesRestart(t, sc) }) + run("supervision_stops_postfix_and_gives_up", func(t *testing.T) { + testSupervision(t, sc) + }) run("negative_level1_ratelimit", func(t *testing.T) { testLevel1RateLimit(t, sc) }) diff --git a/test/e2e/negative_test.go b/test/e2e/negative_test.go index cb3cb74..fce642c 100644 --- a/test/e2e/negative_test.go +++ b/test/e2e/negative_test.go @@ -153,10 +153,18 @@ func checkContainerAlive(s *stack) error { // testSessionSurvivesRestart is plan C.4 negative/regression check 8 (moved // here from the manual B.1 stand check, plan item C.4's closing note): the // login session (SQLite-backed, plan B.1) must survive `docker restart`. +// +// The stop half of the restart stops Postfix as "postfix stop" does: before, +// supervisord's TERM reached the wrapper's shell alone and master went down +// with the container's SIGKILL (assumptions C-P42; supervision_test.go). func testSessionSurvivesRestart(t *testing.T, sc *scenario) { + stops := postfixStops(t) if err := h.restartSelfpost(); err != nil { t.Fatalf("restart selfpost: %v", err) } + if got := postfixStops(t); got != stops+1 { + t.Fatalf("mail.log has %d lines of postfix stop after the container's restart, want %d\n%s", got, stops+1, mailLogTail(h, "postfix")) + } if err := waitFor("panel HTTP to answer after restart", 30*time.Second, 500*time.Millisecond, func() (bool, error) { _, err := sc.panel.status() return err == nil, err diff --git a/test/e2e/process_check.go b/test/e2e/process_check.go index f2ccba5..40d147b 100644 --- a/test/e2e/process_check.go +++ b/test/e2e/process_check.go @@ -8,17 +8,20 @@ import ( // wantRunning are the supervisord programs that must be RUNNING once the // container is up (build/supervisord.conf). postfix-reload is deliberately -// excluded: autostart=false, its healthy resting state is STOPPED. +// excluded: autostart=false, so it rests STOPPED until its first run and +// EXITED after it (supervisor 4.2.5, supervisor/process.py, +// Subprocess.finish(); assumptions C-V10). var wantRunning = []string{"opendkim", "panel", "postfix", "cert-reload", "logrotate"} // checkSupervisorProcesses shells into the container directly (not through the // panel's /overview page) so it works before an administrator account even // exists — this is the first thing the harness checks after `docker compose // up` (plan C.4). Programs take a moment to leave STARTING right after the -// container starts, so this polls rather than checking once. +// container starts - postfix its startsecs, MILTER_WAIT_TIMEOUT plus ten +// seconds, 20 on this stand - so this polls rather than checking once. func checkSupervisorProcesses(s *stack) error { var lastErr error - err := waitFor("all supervised programs to reach their steady state", 20*time.Second, 500*time.Millisecond, func() (bool, error) { + err := waitFor("all supervised programs to reach their steady state", 60*time.Second, 500*time.Millisecond, func() (bool, error) { out, execErr := s.execIn("selfpost", "supervisorctl", "-c", "/etc/supervisor/supervisord.conf", "status") // supervisorctl exits non-zero when any program is not RUNNING, which // is expected for postfix-reload — parse the output regardless of exit @@ -39,8 +42,8 @@ func checkSupervisorProcesses(s *stack) error { return false, lastErr } } - if state, ok := states["postfix-reload"]; ok && state != "STOPPED" { - lastErr = fmt.Errorf("program postfix-reload is %s, want STOPPED (autostart=false):\n%s", state, out) + if state, ok := states["postfix-reload"]; ok && state != "STOPPED" && state != "EXITED" { + lastErr = fmt.Errorf("program postfix-reload is %s, want STOPPED or EXITED (autostart=false):\n%s", state, out) return false, lastErr } return true, nil diff --git a/test/e2e/supervision_test.go b/test/e2e/supervision_test.go new file mode 100644 index 0000000..de78069 --- /dev/null +++ b/test/e2e/supervision_test.go @@ -0,0 +1,203 @@ +package e2e + +import ( + "fmt" + "net/url" + "strconv" + "strings" + "testing" + "time" +) + +// Supervision as supervisord does it (audit 2026-10-12, stage 2c; assumptions +// C-P42, C-V5, C-V6, C-V10). The stand runs with MILTER_WAIT_TIMEOUT=10 +// (compose.override.yml), so program postfix has startsecs 20. + +const supervisorConfPath = "/etc/supervisor/supervisord.conf" + +// supervisorctl runs supervisorctl in the container; its output comes back +// whatever its exit status, which is non-zero whenever something is not +// RUNNING (supervisor 4.2.5, supervisor/supervisorctl.py, do_status()). +func supervisorctl(args ...string) (string, error) { + return h.execIn("selfpost", append([]string{"supervisorctl", "-c", supervisorConfPath}, args...)...) +} + +// programState is the state supervisorctl status gives one program. +func programState(name string) (string, string) { + out, _ := supervisorctl("status", name) + f := strings.Fields(out) + if len(f) < 2 || f[0] != name { + return "", out + } + return f[1], out +} + +func waitProgramState(t *testing.T, name, want string, within time.Duration) { + t.Helper() + var last string + if err := waitFor(fmt.Sprintf("program %s to be %s", name, want), within, 500*time.Millisecond, func() (bool, error) { + state, out := programState(name) + last = out + return state == want, nil + }); err != nil { + t.Fatalf("%v; last status: %s\n%s", err, last, h.logs("selfpost")) + } +} + +// postfixStops counts the lines "postfix stop" writes to mail.log before it +// sends master TERM (Postfix 3.7.11, conf/postfix-script, "stop": $INFO +// stopping the Postfix mail system; "... with force" when master had not +// gone after five seconds, which this does not count). +func postfixStops(t *testing.T) int { + return countMailLog(t, `postfix-script\[[0-9]*\]: stopping the Postfix mail system$`) +} + +// mastersTerminated counts master's own line for SIGTERM (src/master/ +// master_sig.c, master_sigdeath(): "terminating on signal %d"). master sends +// TERM to its process group, postlogd included, before it writes the line, +// so whether the line reaches mail.log is measured, not asserted. +func mastersTerminated(t *testing.T) int { + return countMailLog(t, `postfix/master\[[0-9]*\]: terminating on signal 15`) +} + +func countMailLog(t *testing.T, re string) int { + t.Helper() + out, _ := h.execIn("selfpost", "sh", "-c", "grep -c '"+re+"' /data/log/mail.log || true") + n, err := strconv.Atoi(strings.TrimSpace(out)) + if err != nil { + t.Fatalf("count %q in mail.log: %q", re, out) + } + return n +} + +// masters counts the processes named master in the container. +func masters(t *testing.T) int { + t.Helper() + out, err := h.execIn("selfpost", "sh", "-c", + `n=0; for c in /proc/[0-9]*/comm; do [ "$(cat "$c" 2>/dev/null)" = master ] && n=$((n+1)); done; echo $n`) + n, cerr := strconv.Atoi(strings.TrimSpace(out)) + if err != nil || cerr != nil { + t.Fatalf("count master processes: %q, %v", out, err) + } + return n +} + +func testSupervision(t *testing.T, sc *scenario) { + // A restart of the program stops Postfix and starts one master. Before, + // the stop reached the wrapper's shell alone; master lived on, and the + // new start ended "the Postfix mail system is already running" until + // the program was FATAL and the container went down. + stops, terminated := postfixStops(t), mastersTerminated(t) + if out, err := supervisorctl("restart", "postfix"); err != nil { + t.Fatalf("supervisorctl restart postfix: %v\n%s", err, out) + } + waitProgramState(t, "postfix", "RUNNING", 60*time.Second) + if got := postfixStops(t); got != stops+1 { + t.Fatalf("mail.log has %d lines of postfix stop after the restart, want %d\n%s", got, stops+1, mailLogTail(h, "postfix")) + } + t.Logf("measured: master's \"terminating on signal 15\" in mail.log after the stop: %d new", mastersTerminated(t)-terminated) + if n := masters(t); n != 1 { + t.Fatalf("%d master processes after restarting the program, want 1", n) + } + if err := waitForSMTPSReady(30 * time.Second); err != nil { + t.Fatal(err) + } + + // The wrapper's give-up on the milter sockets is an exit supervisord + // counts as too quick: BACKOFF, on its way to FATAL, not a restart for + // ever. The panel's sockets are taken away for one attempt, then + // given back, and Postfix comes up on the next one. Postfix is stopped + // before the panel, so the panel's start counts no downtime of the check. + if out, err := supervisorctl("stop", "postfix"); err != nil { + t.Fatalf("stop postfix: %v\n%s", err, out) + } + if out, err := supervisorctl("stop", "panel"); err != nil { + t.Fatalf("stop panel: %v\n%s", err, out) + } + panelUp := false + t.Cleanup(func() { + if !panelUp { + _, _ = supervisorctl("start", "panel") + } + }) + // As build/entrypoint.sh does for a killed container's leftovers. + if _, err := h.execIn("selfpost", "sh", "-c", "rm -f /run/selfpost/*.sock"); err != nil { + t.Fatal(err) + } + // start waits for RUNNING. An exit before startsecs leaves spawnerr + // "Exited too quickly" (process.py, Subprocess.finish()), which onwait() + // looks at before the state: "spawn error" (supervisor 4.2.5, + // rpcinterface.py, startProcess(); supervisorctl.py, _startresult()). + out, err := supervisorctl("start", "postfix") + if err == nil || !strings.Contains(out, "postfix: ERROR (spawn error)") { + t.Fatalf("start postfix without the panel's sockets: %v\n%s; want a spawn error", err, out) + } + if state, status := programState("postfix"); state != "BACKOFF" && state != "STARTING" { + t.Fatalf("postfix after the wrapper gave up: %s", status) + } + if !strings.Contains(h.logs("selfpost"), "postfix-wrapper: timed out after 10s waiting for milter socket") { + t.Fatalf("the wrapper did not say it gave up:\n%s", h.logs("selfpost")) + } + if out, err := supervisorctl("start", "panel"); err != nil { + t.Fatalf("start panel: %v\n%s", err, out) + } + panelUp = true + waitProgramState(t, "postfix", "RUNNING", 90*time.Second) + if err := waitForPanelReady(); err != nil { + t.Fatal(err) + } + if err := waitForSMTPSReady(30 * time.Second); err != nil { + t.Fatal(err) + } + + // logrotate refusing a config it would ignore ends FATAL, and the + // container stays up: it is not on the mail path. With startsecs=0 it + // was restarted every second for ever. + if _, err := h.execIn("selfpost", "chmod", "664", "/etc/logrotate.d/mail"); err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + _, _ = h.execIn("selfpost", "chmod", "644", "/etc/logrotate.d/mail") + _, _ = supervisorctl("start", "logrotate") + }) + _, _ = supervisorctl("restart", "logrotate") + waitProgramState(t, "logrotate", "FATAL", 30*time.Second) + if !strings.Contains(h.logs("selfpost"), "crashexit: logrotate entered FATAL; it is not on the mail path, the container stays up") { + t.Fatalf("crashexit did not spare logrotate:\n%s", h.logs("selfpost")) + } + for _, p := range []string{"opendkim", "panel", "postfix"} { + if state, status := programState(p); state != "RUNNING" { + t.Fatalf("program %s with logrotate FATAL: %s", p, status) + } + } + if _, err := h.execIn("selfpost", "chmod", "644", "/etc/logrotate.d/mail"); err != nil { + t.Fatal(err) + } + if out, err := supervisorctl("start", "logrotate"); err != nil { + t.Fatalf("start logrotate with its config mended: %v\n%s", err, out) + } + waitProgramState(t, "logrotate", "RUNNING", 15*time.Second) + + // The panel's Reload configuration runs postfix-reload to its end and + // reads its exit status (internal/supervisor, RunOnce): Postfix + // refreshed in mail.log by the time the page answers, and the helper + // resting EXITED after it, which the check of the processes takes as + // healthy. + refreshes := countMailLog(t, `postfix-script\[[0-9]*\]: refreshing the Postfix mail system$`) + resp, body, err := sc.panel.postForm("/server/health/reload", url.Values{}) + if err != nil { + t.Fatal(err) + } + if resp.StatusCode != 200 || resp.Request.URL.Path != "/server/health" { + t.Fatalf("Reload configuration: status %d, landed on %s:\n%.800s", resp.StatusCode, resp.Request.URL.Path, body) + } + if got := countMailLog(t, `postfix-script\[[0-9]*\]: refreshing the Postfix mail system$`); got <= refreshes { + t.Fatalf("Reload configuration answered before Postfix was refreshed (%d refresh lines, %d before)", got, refreshes) + } + if state, status := programState("postfix-reload"); state != "EXITED" { + t.Fatalf("postfix-reload after the panel's reload: %s, want EXITED", status) + } + if err := checkSupervisorProcesses(h); err != nil { + t.Fatal(err) + } +}