supervision as supervisord does it: Postfix stopped, give-ups FATAL, reload's exit read
test / test (push) Canceled after 0s

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 <noreply@anthropic.com>
This commit is contained in:
mix
2026-10-14 23:49:25 +03:00
co-authored by Claude Opus 5.5
parent ee37d16dc7
commit f2ad699473
15 changed files with 834 additions and 59 deletions
+27 -8
View File
@@ -1,10 +1,12 @@
#!/usr/bin/env python3 #!/usr/bin/env python3
"""Supervisor event listener: bring the container down on unrecoverable failure. """Supervisor event listener: bring the container down on unrecoverable failure.
If any managed program exhausts its restart retries and enters FATAL, this If a managed program of the mail path exhausts its restart retries and
listener signals supervisord (its parent) to terminate, so the whole container enters FATAL, this listener signals supervisord (its parent) to terminate, so
exits and Docker's `restart` policy can recreate it cleanly — rather than the whole container exits and Docker's `restart` policy starts it again —
lingering "alive" with a dead Postfix/OpenDKIM/panel. 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 Communication with supervisord uses the event listener protocol over stdin and
stdout, so stdout must carry only protocol tokens. 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 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 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". 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 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). (docs/running.rst, "Signals"); it is PID 1 here (build/entrypoint.sh, exec).
""" """
@@ -19,6 +24,9 @@ import os
import signal import signal
import sys import sys
# Programs whose FATAL does not take the container down (build/supervisord.conf).
SPARED = {"logrotate"}
def write_stdout(s): def write_stdout(s):
sys.stdout.write(s) sys.stdout.write(s)
@@ -35,13 +43,24 @@ def main():
return return
headers = dict(pair.split(":", 1) for pair in line.split()) headers = dict(pair.split(":", 1) for pair in line.split())
payload_len = int(headers.get("len", 0)) payload_len = int(headers.get("len", 0))
if payload_len: payload = sys.stdin.read(payload_len) if payload_len else ""
sys.stdin.read(payload_len) 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 # We only subscribe to PROCESS_STATE_FATAL, so any event means a managed
# program can no longer be restarted. Take the container down. # program can no longer be restarted.
if name in SPARED:
sys.stderr.write( sys.stderr.write(
"crashexit: a managed process entered FATAL; shutting down container\n" "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() sys.stderr.flush()
os.kill(os.getppid(), signal.SIGTERM) os.kill(os.getppid(), signal.SIGTERM)
+19 -5
View File
@@ -177,11 +177,12 @@ rm -f /run/opendkim/*.sock /run/selfpost/*.sock /run/selfpost/*.alive
# start the same way the /data normalisation above is. # start the same way the /data normalisation above is.
/usr/local/bin/postfix-config.sh /usr/local/bin/postfix-config.sh
# Initialise the persistent queue tree on first start or after restore. postfix # The queue tree, on a first start or after a restore, is already built here:
# set-permissions reads queue_directory from main.cf (set by postfix-config.sh). # postfix-config.sh ends with "postfix check", whose check-fatal runs
if [ ! -d /data/postfix/queue/active ]; then # "post-install create-missing" (Postfix 3.7.11, conf/postfix-script;
postfix set-permissions # conf/postfix-files, "$queue_directory/active:d:$mail_owner:-:700:ucr").
fi # A "postfix set-permissions" for a missing active/ stood here and never ran
# (assumptions C-P34).
chown -R postfix:postfix /data/postfix/queue chown -R postfix:postfix /data/postfix/queue
# The recursive chown above would leave public/ and maildrop/ in group postfix. # 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 # 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".) # root".)
chown root /data/postfix/queue /data/postfix/queue/pid 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 exec /usr/bin/supervisord -c /etc/supervisor/supervisord.conf
+47 -6
View File
@@ -4,10 +4,15 @@
# #
# It blocks until the milter sockets — OpenDKIM, the panel's sender check and # 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 — # journal-milter and, with the inbound relay on, its inbound journal milter —
# are present, # are present, then runs `postfix start-fg` and stays its parent. If they are
# then execs `postfix start-fg`. If they are not ready within the # not ready within the timeout it exits non-zero WITHOUT starting Postfix.
# timeout it exits non-zero WITHOUT starting Postfix, so supervisord/Docker see # supervisord counts that exit as one that came too quickly - the program's
# an explicit startup failure instead of a relay running blind. # 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 # 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 # 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), # 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 # 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, # its child; master then makes itself a session leader (src/master/master.c,
# setsid()). The process supervisord watches is that shell, not master. # setsid()). A signal supervisord sends this program never reaches master
exec postfix start-fg # (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"
+32 -9
View File
@@ -8,9 +8,15 @@
; supervisord.py, runforever(), transitions every group in that order in one ; supervisord.py, runforever(), transitions every group in that order in one
; pass, with no wait for a program to be ready.) ; pass, with no wait for a program to be ready.)
; ;
; If any managed process exhausts its restart retries (FATAL), the crashexit ; If a managed process of the mail path exhausts its restart retries (FATAL),
; event listener brings the whole container down so Docker's restart policy can ; the crashexit event listener brings the whole container down so Docker's
; recreate it cleanly, rather than lingering with a dead component. ; 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] [supervisord]
nodaemon=true nodaemon=true
@@ -66,12 +72,22 @@ stdout_logfile_maxbytes=0
stderr_logfile=/dev/stderr stderr_logfile=/dev/stderr
stderr_logfile_maxbytes=0 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] [program:postfix]
command=/usr/local/bin/postfix-wrapper.sh command=/usr/local/bin/postfix-wrapper.sh
priority=300 priority=300
autostart=true autostart=true
autorestart=true autorestart=true
startsecs=%(ENV_POSTFIX_STARTSECS)s
startretries=3 startretries=3
stopwaitsecs=15
stdout_logfile=/dev/stdout stdout_logfile=/dev/stdout
stdout_logfile_maxbytes=0 stdout_logfile_maxbytes=0
stderr_logfile=/dev/stderr stderr_logfile=/dev/stderr
@@ -88,7 +104,9 @@ stderr_logfile_maxbytes=0
; crashexit listener. (start-fg: see build/postfix-wrapper.sh. supervisor ; crashexit listener. (start-fg: see build/postfix-wrapper.sh. supervisor
; 4.2.5, supervisor/process.py, Subprocess.finish(): with startsecs=0 no exit ; 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, ; 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] [program:postfix-reload]
command=/usr/sbin/postfix reload command=/usr/sbin/postfix reload
autostart=false autostart=false
@@ -117,16 +135,21 @@ stdout_logfile_maxbytes=0
stderr_logfile=/dev/stderr stderr_logfile=/dev/stderr
stderr_logfile_maxbytes=0 stderr_logfile_maxbytes=0
; Periodic logrotate for /data/log/mail.log (daily, 7-14 files kept in the ; Periodic logrotate for /data/log/mail.log (daily, 14 files kept). Runs as
; image). Runs as root so logrotate can read/rotate the log. Exits non-zero when ; root so logrotate can read/rotate the log. Exits non-zero at once when the
; the config is group/other-writable (logrotate would ignore it silently); ; config is group/other-writable (logrotate would ignore it silently): with
; autorestart surfaces BACKOFF on the Status page. ; 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] [program:logrotate]
command=/usr/local/bin/logrotate-loop.sh command=/usr/local/bin/logrotate-loop.sh
priority=400 priority=400
autostart=true autostart=true
autorestart=true autorestart=true
startsecs=0 startsecs=1
startretries=3
stdout_logfile=/dev/stdout stdout_logfile=/dev/stdout
stdout_logfile_maxbytes=0 stdout_logfile_maxbytes=0
stderr_logfile=/dev/stderr stderr_logfile=/dev/stderr
+4 -1
View File
@@ -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 // 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 // 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 // "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 { func postfixStarted() postfixState {
deadline := time.Now().Add(postfixAskFor) deadline := time.Now().Add(postfixAskFor)
for { for {
+17 -5
View File
@@ -34,14 +34,26 @@ Managed programs ([build/supervisord.conf](../build/supervisord.conf)):
| `logrotate` | root | 400 | Periodic `mail.log` rotation | | `logrotate` | root | 400 | Periodic `mail.log` rotation |
Start order: OpenDKIM → panel (opens the sender check's and the journal-milter's sockets) → Postfix wrapper 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 polls unix sockets (timeout `MILTER_WAIT_TIMEOUT`, default 30s) then runs
`postfix start-fg`. `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 `crashexit` event listener exits the container when a program of the mail path
Docker `restart: unless-stopped` recreates a broken instance. 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, **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).
--- ---
+21 -1
View File
@@ -7,6 +7,7 @@ package postfix
import ( import (
"fmt" "fmt"
"log"
"path/filepath" "path/filepath"
"sort" "sort"
"strings" "strings"
@@ -186,6 +187,25 @@ func assertMapSafe(address, login string) error {
// whenever it is convenient" while new ones get the new configuration; a // whenever it is convenient" while new ones get the new configuration; a
// texthash table is read into memory once per process // texthash table is read into memory once per process
// (README_FILES/DATABASE_README). // (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 { 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
} }
+280
View File
@@ -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 "<NAME>: <detail>").
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 version="1.0"?><methodCall><methodName>`)
xml.EscapeText(&b, []byte(method))
b.WriteString(`</methodName><params>`)
for _, p := range params {
b.WriteString(`<param><value>`)
switch v := p.(type) {
case string:
b.WriteString(`<string>`)
xml.EscapeText(&b, []byte(v))
b.WriteString(`</string>`)
case bool:
if v {
b.WriteString(`<boolean>1</boolean>`)
} else {
b.WriteString(`<boolean>0</boolean>`)
}
default:
return xvalue{}, fmt.Errorf("xml-rpc: parameter of type %T", p)
}
b.WriteString(`</value></param>`)
}
b.WriteString(`</params></methodCall>`)
// 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 <value> 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
}
+156
View File
@@ -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 <param>, or a <fault> 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(`<methodName>([^<]+)</methodName>`)
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), "<boolean>0</boolean>") {
http.Error(w, "start must not wait", http.StatusBadRequest)
return
}
if f.alreadyStarted > 0 {
f.alreadyStarted--
io.WriteString(w, "<?xml version='1.0'?>\n<methodResponse>\n<fault>\n<value><struct>\n"+
"<member>\n<name>faultCode</name>\n<value><int>60</int></value>\n</member>\n"+
"<member>\n<name>faultString</name>\n<value><string>ALREADY_STARTED: postfix-reload</string></value>\n</member>\n"+
"</struct></value>\n</fault>\n</methodResponse>\n")
return
}
io.WriteString(w, "<?xml version='1.0'?>\n<methodResponse>\n<params>\n<param>\n<value><boolean>1</boolean></value>\n</param>\n</params>\n</methodResponse>\n")
case "supervisor.getProcessInfo":
s := f.states[min(f.asked, len(f.states)-1)]
f.asked++
fmt.Fprintf(w, "<?xml version='1.0'?>\n<methodResponse>\n<params>\n<param>\n<value><struct>\n"+
"<member>\n<name>name</name>\n<value><string>postfix-reload</string></value>\n</member>\n"+
"<member>\n<name>state</name>\n<value><int>%d</int></value>\n</member>\n"+
"<member>\n<name>statename</name>\n<value><string>%s</string></value>\n</member>\n"+
"<member>\n<name>exitstatus</name>\n<value><int>%d</int></value>\n</member>\n"+
"<member>\n<name>spawnerr</name>\n<value><string></string></value>\n</member>\n"+
"</struct></value>\n</param>\n</params>\n</methodResponse>\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)
}
}
-15
View File
@@ -10,21 +10,6 @@ import (
const confPath = "/etc/supervisor/supervisord.conf" 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`. // Signal sends a signal to a supervised program via `supervisorctl signal`.
func Signal(sig, program string) error { func Signal(sig, program string) error {
cmd := exec.Command("supervisorctl", "-c", confPath, "signal", sig, program) cmd := exec.Command("supervisorctl", "-c", confPath, "signal", sig, program)
+5
View File
@@ -55,6 +55,11 @@ services:
# often, so renewed_certificate_picked_up does not wait a day. It # often, so renewed_certificate_picked_up does not wait a day. It
# reloads Postfix only when the certificate changed. # reloads Postfix only when the certificate changed.
TLS_RELOAD_INTERVAL_SECONDS: "2" 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 ports: !override
- "20465:465" - "20465:465"
- "20587:587" - "20587:587"
+3
View File
@@ -334,6 +334,9 @@ func TestE2E(t *testing.T) {
run("session_survives_restart", func(t *testing.T) { run("session_survives_restart", func(t *testing.T) {
testSessionSurvivesRestart(t, sc) 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) { run("negative_level1_ratelimit", func(t *testing.T) {
testLevel1RateLimit(t, sc) testLevel1RateLimit(t, sc)
}) })
+8
View File
@@ -153,10 +153,18 @@ func checkContainerAlive(s *stack) error {
// testSessionSurvivesRestart is plan C.4 negative/regression check 8 (moved // 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 // 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`. // 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) { func testSessionSurvivesRestart(t *testing.T, sc *scenario) {
stops := postfixStops(t)
if err := h.restartSelfpost(); err != nil { if err := h.restartSelfpost(); err != nil {
t.Fatalf("restart selfpost: %v", err) 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) { if err := waitFor("panel HTTP to answer after restart", 30*time.Second, 500*time.Millisecond, func() (bool, error) {
_, err := sc.panel.status() _, err := sc.panel.status()
return err == nil, err return err == nil, err
+8 -5
View File
@@ -8,17 +8,20 @@ import (
// wantRunning are the supervisord programs that must be RUNNING once the // wantRunning are the supervisord programs that must be RUNNING once the
// container is up (build/supervisord.conf). postfix-reload is deliberately // 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"} var wantRunning = []string{"opendkim", "panel", "postfix", "cert-reload", "logrotate"}
// checkSupervisorProcesses shells into the container directly (not through the // checkSupervisorProcesses shells into the container directly (not through the
// panel's /overview page) so it works before an administrator account even // panel's /overview page) so it works before an administrator account even
// exists — this is the first thing the harness checks after `docker compose // 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 // 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 { func checkSupervisorProcesses(s *stack) error {
var lastErr 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") out, execErr := s.execIn("selfpost", "supervisorctl", "-c", "/etc/supervisor/supervisord.conf", "status")
// supervisorctl exits non-zero when any program is not RUNNING, which // supervisorctl exits non-zero when any program is not RUNNING, which
// is expected for postfix-reload — parse the output regardless of exit // is expected for postfix-reload — parse the output regardless of exit
@@ -39,8 +42,8 @@ func checkSupervisorProcesses(s *stack) error {
return false, lastErr return false, lastErr
} }
} }
if state, ok := states["postfix-reload"]; ok && state != "STOPPED" { if state, ok := states["postfix-reload"]; ok && state != "STOPPED" && state != "EXITED" {
lastErr = fmt.Errorf("program postfix-reload is %s, want STOPPED (autostart=false):\n%s", state, out) lastErr = fmt.Errorf("program postfix-reload is %s, want STOPPED or EXITED (autostart=false):\n%s", state, out)
return false, lastErr return false, lastErr
} }
return true, nil return true, nil
+203
View File
@@ -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)
}
}