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>
239 lines
9.9 KiB
Go
239 lines
9.9 KiB
Go
package e2e
|
|
|
|
import (
|
|
"fmt"
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
// testLevel2RateLimit is plan C.4 negative check 5: a limit set through the
|
|
// panel (not the environment) rejects the message that exceeds it, and the
|
|
// rejection is visible in the send log — the panel -> DB -> milter path.
|
|
func testLevel2RateLimit(t *testing.T, sc *scenario) {
|
|
ip, err := lastSMTPClientIP(h)
|
|
if err != nil {
|
|
t.Fatalf("determine observed SMTP client IP: %v", err)
|
|
}
|
|
sc.clientIP = ip
|
|
|
|
login, password, err := sc.panel.addApplication(sc.domainID, "l2app", "wildcard", "")
|
|
if err != nil {
|
|
t.Fatalf("add application: %v", err)
|
|
}
|
|
if err := waitForSenderMap(login, password, "billing@"+senderDomain); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
sc.l2AppLogin, sc.l2AppPassword = login, password
|
|
|
|
appID, err := sc.panel.applicationID(sc.domainID, login)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if err := sc.panel.setApplicationLimit(sc.domainID, appID, 1, 3600); err != nil {
|
|
t.Fatalf("save application rate limit: %v", err)
|
|
}
|
|
|
|
from := "billing@" + senderDomain
|
|
|
|
first := attemptSend(sendAttempt{
|
|
authLogin: login, authPassword: password,
|
|
from: from, to: recipient, subject: "e2e " + uniqueToken("l2-first"), body: "ok",
|
|
})
|
|
if !first.ok() {
|
|
t.Fatalf("first message under the level-2 limit was rejected: %v", first.firstErr())
|
|
}
|
|
|
|
second := attemptSend(sendAttempt{
|
|
authLogin: login, authPassword: password,
|
|
from: from, to: recipient, subject: "e2e " + uniqueToken("l2-second"), body: "should be rejected",
|
|
})
|
|
// The milter answers tempfail at MAIL FROM, which Postfix words as below
|
|
// (Postfix 3.7.11, src/milter/milter8.c, milter8_event(), SMFIR_TEMPFAIL:
|
|
// "451 4.7.1 Service unavailable - try again later").
|
|
if err := second.refusedAt("MAIL", 451, "4.7.1 Service unavailable"); err != nil {
|
|
t.Fatalf("the second message over the level-2 limit: %v", err)
|
|
}
|
|
|
|
// The limit holds for every message of a connection, not for its first
|
|
// only. The milter library hands the milter a fresh session after any reply
|
|
// that is not "continue" - the refusal above is one - and Postfix does not
|
|
// introduce the client again, so a second MAIL FROM on the same connection
|
|
// used to arrive with no client address and was let through (found by the
|
|
// technical review of 2026-10-12; the same hole let an application past its
|
|
// client-address list). Postfix's half: 3.7.11, src/smtpd/smtpd.c,
|
|
// smtpd_proto(), calls milter_conn_event() once per connection.
|
|
errs := mailTwiceOnOneConnection(login, password, from)
|
|
for i, err := range errs {
|
|
if err := replyIs(err, 451, "4.7.1 Service unavailable"); err != nil {
|
|
t.Fatalf("over the level-2 limit, MAIL FROM %d of one connection: %v", i+1, err)
|
|
}
|
|
}
|
|
|
|
if err := waitFor("a rate-limited row for l2app in the send log", 15*time.Second, 500*time.Millisecond, func() (bool, error) {
|
|
rows, err := sc.panel.sendLogRows(senderDomain, login)
|
|
if err != nil {
|
|
return false, err
|
|
}
|
|
if containsCell(rows, "rate-limited") {
|
|
return true, nil
|
|
}
|
|
return false, fmt.Errorf("no rate-limited row for l2app yet")
|
|
}); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
}
|
|
|
|
// testSenderLoginMismatch is plan C.4 negative check 2: an authenticated
|
|
// application cannot send as a sender it does not own (architecture.md § Mail
|
|
// path, reject_sender_login_mismatch) — the core anti-spoofing control.
|
|
func testSenderLoginMismatch(t *testing.T, sc *scenario) {
|
|
res := attemptSend(sendAttempt{
|
|
authLogin: sc.appLogin, authPassword: sc.appPassword,
|
|
from: "someone@not-" + senderDomain, to: recipient,
|
|
subject: "e2e " + uniqueToken("mismatch"), body: "should be rejected",
|
|
})
|
|
// Postfix evaluates smtpd_sender_restrictions with smtpd_delay_reject=yes
|
|
// (the default): the mismatch is detected at MAIL FROM but the reject is
|
|
// only sent back at RCPT TO. (Postfix 3.7.11, src/global/mail_params.h,
|
|
// DEF_SMTPD_DELAY_REJECT 1; src/smtpd/smtpd_check.c,
|
|
// reject_auth_sender_login_mismatch(): 553 5.7.1 "Sender address rejected:
|
|
// not owned by user".)
|
|
if err := res.refusedAt("RCPT", 553, "5.7.1"); err != nil {
|
|
t.Fatalf("a sender the application does not own: %v", err)
|
|
}
|
|
if err := replyIs(res.rcptErr, 553, "Sender address rejected: not owned by user"); err != nil {
|
|
t.Fatalf("a sender the application does not own: %v", err)
|
|
}
|
|
}
|
|
|
|
// testNoAuthRejected is plan C.4 negative check 1: no SASL session, no mail.
|
|
// The sender address used here belongs to no registered domain, so the
|
|
// rejection is unambiguously about the missing AUTH and not sender ownership.
|
|
// The reply: smtps's client restrictions end in "reject" (build/
|
|
// postfix-config.sh), Postfix 3.7.11, src/smtpd/smtpd_check.c,
|
|
// generic_checks(): var_reject_code (554) "<%s>: %s rejected: Access denied",
|
|
// delayed to RCPT by smtpd_delay_reject.
|
|
func testNoAuthRejected(t *testing.T, sc *scenario) {
|
|
res := attemptSend(sendAttempt{
|
|
from: "anyone@unregistered.e2e.test", to: recipient,
|
|
subject: "e2e " + uniqueToken("noauth"), body: "should be rejected",
|
|
})
|
|
if err := res.refusedAt("RCPT", 554, "Client host rejected: Access denied"); err != nil {
|
|
t.Fatalf("an unauthenticated send: %v", err)
|
|
}
|
|
}
|
|
|
|
// testForeignRelayRejected is plan C.4 negative check 3: a direct proof that
|
|
// the submission port is not an open relay — even the exact recipient the
|
|
// positive path just delivered to is refused without AUTH. The refusal is
|
|
// smtpd_client_restrictions (permit_sasl_authenticated, reject), which on 465
|
|
// and 587 comes before reject_unauth_destination, so the reply is the same as
|
|
// check 1's; reject_unauth_destination's own "Relay access denied" is held on
|
|
// port 25 (testInboundRelay), where clients do not authenticate.
|
|
func testForeignRelayRejected(t *testing.T, sc *scenario) {
|
|
res := attemptSend(sendAttempt{
|
|
from: "anyone@unregistered.e2e.test", to: recipient,
|
|
subject: "e2e " + uniqueToken("relay"), body: "should be rejected",
|
|
})
|
|
if err := res.refusedAt("RCPT", 554, "Client host rejected: Access denied"); err != nil {
|
|
t.Fatalf("an unauthenticated relay to an external destination: %v", err)
|
|
}
|
|
}
|
|
|
|
// checkContainerAlive confirms the container is still up after a component
|
|
// stop — the crashexit listener must not have brought it down.
|
|
func checkContainerAlive(s *stack) error {
|
|
out, err := s.execIn("selfpost", "true")
|
|
if err != nil {
|
|
return fmt.Errorf("container not responding to exec: %v (%s)", err, out)
|
|
}
|
|
return nil
|
|
}
|
|
|
|
// 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
|
|
}); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
// The panel and Postfix come up independently after a restart (see
|
|
// waitForSMTPSReady) — the next subtest sends mail, so make sure smtpd is
|
|
// actually listening before this one returns.
|
|
if err := waitForSMTPSReady(30 * time.Second); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
resp, err := sc.panel.status()
|
|
if err != nil {
|
|
t.Fatalf("GET /overview after restart: %v", err)
|
|
}
|
|
if resp.Request.URL.Path != "/overview" {
|
|
t.Fatalf("session did not survive restart: landed on %s instead of /overview", resp.Request.URL.Path)
|
|
}
|
|
}
|
|
|
|
// testLevel1RateLimit is plan C.4 negative check 4: the native Postfix anvil
|
|
// backstop (smtpd_client_message_rate_limit, guide § Rate limiting), set by
|
|
// the override to RATE_LIMIT_MESSAGES_PER_IP=50, rejects once exceeded. It
|
|
// uses a dedicated application with no level-2 limit of its own, and retries
|
|
// well past that count, so the result is unambiguous regardless of how much of
|
|
// the shared per-IP budget earlier subtests already spent (they stay well
|
|
// under 50 between them).
|
|
//
|
|
// Only anvil's own reply counts, and only after at least one message of the
|
|
// loop went through: the case once passed on "limit tripped on attempt 1/60"
|
|
// when the connection was reset because Postfix was still starting - and,
|
|
// held to anvil's reply, it turned out the first message had always been
|
|
// refused for another reason: the new login was not yet in the sender map an
|
|
// smtpd from before the panel's reload held (waitForSenderMap). (An incident
|
|
// on the stand, date not recorded.) Anvil's reply: Postfix 3.7.11,
|
|
// src/smtpd/smtpd.c, mail_cmd(): "450 4.7.1 Error: too much mail from %s".
|
|
func testLevel1RateLimit(t *testing.T, sc *scenario) {
|
|
login, password, err := sc.panel.addApplication(sc.domainID, "l1app", "wildcard", "")
|
|
if err != nil {
|
|
t.Fatalf("add application: %v", err)
|
|
}
|
|
send := func() sendResult {
|
|
return attemptSend(sendAttempt{
|
|
authLogin: login, authPassword: password,
|
|
from: "l1@" + senderDomain, to: recipient,
|
|
subject: "e2e " + uniqueToken("l1"), body: "rate limit probe",
|
|
})
|
|
}
|
|
|
|
if err := waitForSenderMap(login, password, "l1@"+senderDomain); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if res := send(); !res.ok() {
|
|
t.Fatalf("the first message of %s, before any limit could trip: %v", login, res.firstErr())
|
|
}
|
|
|
|
const maxAttempts = 60
|
|
for i := 1; i < maxAttempts; i++ {
|
|
res := send()
|
|
if res.ok() {
|
|
continue
|
|
}
|
|
if err := res.refusedAt("MAIL", 450, "4.7.1 Error: too much mail from"); err != nil {
|
|
t.Fatalf("attempt %d/%d: %v", i+1, maxAttempts, err)
|
|
}
|
|
t.Logf("level-1 limit tripped on attempt %d/%d: %v", i+1, maxAttempts, res.firstErr())
|
|
return
|
|
}
|
|
t.Fatalf("level-1 rate limit (RATE_LIMIT_MESSAGES_PER_IP=50) never tripped after %d sends", maxAttempts)
|
|
}
|