From 96425dd5158a22a66cc5e53bde1da84fb39bf546 Mon Sep 17 00:00:00 2001 From: Mix Date: Wed, 14 Oct 2026 14:10:47 +0300 Subject: [PATCH] e2e: a negative case passes only on its own refusal (audit stage 0) sendResult.refusedAt(stage, code, text) and replyIs(err, code, text): nil only for the server's reply with that code and text at that stage; a reset, a timeout or another reply is described for the failure. - level 1: only anvil's "450 4.7.1 Error: too much mail from", only after a message of the loop was accepted. Held to that, it failed twice on the stand, each time for a real reason: 1. waitForSMTPSReady took a TCP connect for readiness; Docker's port proxy accepts before Postfix listens and then resets - the reset once taken for the limit. It now waits for the TLS 220 greeting. 2. the first message then got "553 ... not owned by user l1app": an smtpd idle from before the panel's postfix reload took the connection with the old sender_login_maps. The level-1 limit had never been what the case saw. The first message now waits (15 s at most) for the map, failing at once on any other refusal. Now: "level-1 limit tripped on attempt 51/60: 450 4.7.1 Error: too much mail from 10.77.0.1". - level 2: 451 4.7.1 at MAIL, and both MAIL FROM of one connection. - sender mismatch: 553 at RCPT, "not owned by user". - no AUTH and the relay case: 554 "Client host rejected: Access denied" at RCPT; the relay case's comment claimed reject_unauth_destination, which on 465 comes after the client restriction - port 25 holds "554 Relay access denied". - port 25: 550 5.1.1 for unknown recipients and report addresses. - panel down: a 4xx reply (textproto), not just text starting with 4. The product side (a second after an application is saved when its first message can get 553) is written in the audit plan, not changed. Audit plan line ticked with what was found, roadmap 7/61. No CHANGELOG line: tests only. Evidence: make e2e on the test server for this tree, exit 0. Co-Authored-By: Claude Opus 5.5 --- docs/audit-2026-10-12.md | 19 ++++++- docs/roadmap.md | 2 +- test/e2e/negative_test.go | 92 +++++++++++++++++++++----------- test/e2e/port25_features_test.go | 19 ++++--- test/e2e/sender_check_test.go | 7 ++- test/e2e/smtp_client.go | 66 ++++++++++++++++++++--- 6 files changed, 156 insertions(+), 49 deletions(-) diff --git a/docs/audit-2026-10-12.md b/docs/audit-2026-10-12.md index 1235325..5125728 100644 --- a/docs/audit-2026-10-12.md +++ b/docs/audit-2026-10-12.md @@ -563,7 +563,7 @@ has already run is never edited — the next file is added; the published development.md that the image is rebuilt after each Go patch release (`golang:1.26-bookworm` floats, so a rebuild suffices). — **Haiku** - [x] The four `staticcheck` items. — **Haiku** -- [ ] **A negative e2e case passes only on the refusal it is about** (owner, +- [x] **A negative e2e case passes only on the refusal it is about** (owner, 2026-10-14; seen, not found by the audit). `negative_level1_ratelimit` sends up to sixty messages and waits for one to be refused; it once passed on "limit tripped on attempt 1/60" when the connection was reset @@ -573,6 +573,23 @@ has already run is never edited — the next file is added; the published came. Then every other negative case of the suite is read for the same mistake - any failure taken for the expected refusal - and held to its own reply code. - **Opus** + *Done 2026-10-14; what the stand showed:* `waitForSMTPSReady` took a TCP + connect for readiness, and Docker's port proxy accepts before Postfix + listens - that was the reset; it now waits for the TLS greeting. Held to + anvil's `450`, the case then failed on its first message: `553 … not owned + by user l1app`, an smtpd process from before the panel's `postfix reload` + still holding the old `sender_login_maps` - so the level-1 limit had never + been the refusal the case saw. The first message now waits (at most 15 s) + for the map; the limit trips at 51/60 with `450 4.7.1 Error: too much mail + from`. In the product this is a second or so after an application is + saved in which its first message can get a permanent 553; not worth a + change (an application is configured after it is created, not within the + second). The other cases are held to `451 4.7.1` (level 2, both MAIL FROM + of one connection), `553` at RCPT (sender mismatch), `554 … Client host + rejected` at RCPT (no AUTH, and the relay case, whose comment claimed + `reject_unauth_destination` - on 465 the client restriction comes first; + port 25 holds `554 … Relay access denied`), `550 5.1.1` (port 25 unknown + recipients), any `4xx` reply (panel down). ### Stage 1 — mail that is shown wrong (H3, H2, M12, M13) → `2.5.0` diff --git a/docs/roadmap.md b/docs/roadmap.md index b46473b..a0d9102 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -42,7 +42,7 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md). | from-header-binding | Hold a message's `From:` header against the application that sends it | shipped `2.4.0` | 9/9 | [plans/from-header-binding.md](plans/from-header-binding.md) | | panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) | | schema-squash | Squash SQLite migrations into a 2.x baseline | built in panel-redesign (stage 1) | — | [plans/panel-redesign.md](plans/panel-redesign.md) | -| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | agreed (2026-10-12: stage 0 first, then 1+2; the rest after) | 6/61 | [audit-2026-10-12.md](audit-2026-10-12.md) | +| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | agreed (2026-10-12: stage 0 first, then 1+2; the rest after) | 7/61 | [audit-2026-10-12.md](audit-2026-10-12.md) | **Recommended order** (not binding; owner, 2026-10-09: feature order follows development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and diff --git a/test/e2e/negative_test.go b/test/e2e/negative_test.go index f96505b..a527121 100644 --- a/test/e2e/negative_test.go +++ b/test/e2e/negative_test.go @@ -44,12 +44,9 @@ func testLevel2RateLimit(t *testing.T, sc *scenario) { authLogin: login, authPassword: password, from: from, to: recipient, subject: "e2e " + uniqueToken("l2-second"), body: "should be rejected", }) - if second.ok() { - t.Fatal("second message exceeding the level-2 limit was accepted, want rejected") - } - if second.mailErr == nil { - t.Fatalf("expected the level-2 rejection at MAIL FROM, got: dial=%v auth=%v rcpt=%v data=%v", - second.dialErr, second.authErr, second.rcptErr, second.dataErr) + // The milter answers tempfail at MAIL FROM, which Postfix words as below. + 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 @@ -59,8 +56,11 @@ func testLevel2RateLimit(t *testing.T, sc *scenario) { // 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). - if errs := mailTwiceOnOneConnection(login, password, from); errs[0] == nil || errs[1] == nil { - t.Fatalf("over the level-2 limit, two MAIL FROM on one connection were answered %v and %v, want both refused", errs[0], errs[1]) + 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) { @@ -86,15 +86,14 @@ func testSenderLoginMismatch(t *testing.T, sc *scenario) { from: "someone@not-" + senderDomain, to: recipient, subject: "e2e " + uniqueToken("mismatch"), body: "should be rejected", }) - if res.ok() { - t.Fatal("send with a sender the application does not own was accepted, want 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, so the error can land on either call here. - if res.mailErr == nil && res.rcptErr == nil { - t.Fatalf("expected the mismatch rejected at MAIL or RCPT, got: dial=%v auth=%v data=%v", - res.dialErr, res.authErr, res.dataErr) + // only sent back at RCPT TO. + 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) } } @@ -106,24 +105,25 @@ func testNoAuthRejected(t *testing.T, sc *scenario) { from: "anyone@unregistered.e2e.test", to: recipient, subject: "e2e " + uniqueToken("noauth"), body: "should be rejected", }) - if res.ok() { - t.Fatal("unauthenticated send was accepted, want 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 -// this is not an open relay — even the exact recipient the positive path just -// delivered to is refused without AUTH (reject_unauth_destination). +// 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 res.ok() { - t.Fatal("unauthenticated relay to an external destination was accepted, want reject_unauth_destination") - } - if res.rcptErr == nil && res.mailErr == nil { - t.Fatalf("expected rejection at MAIL or RCPT, got: dial=%v auth=%v data=%v", res.dialErr, res.authErr, res.dataErr) + if err := res.refusedAt("RCPT", 554, "Client host rejected: Access denied"); err != nil { + t.Fatalf("an unauthenticated relay to an external destination: %v", err) } } @@ -172,23 +172,53 @@ func testSessionSurvivesRestart(t *testing.T, sc *scenario) { // 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 (below). 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) } - - const maxAttempts = 60 - for i := 0; i < maxAttempts; i++ { - res := attemptSend(sendAttempt{ + send := func() sendResult { + return attemptSend(sendAttempt{ authLogin: login, authPassword: password, from: "l1@" + senderDomain, to: recipient, subject: "e2e " + uniqueToken("l1"), body: "rate limit probe", }) - if !res.ok() { - t.Logf("level-1 limit tripped on attempt %d/%d: %v", i+1, maxAttempts, res.firstErr()) - return + } + + // The panel writes sender_login_maps and reloads Postfix, but an smtpd + // process that was idle before the reload can still take the next + // connection with the old map and answer 553 for the new login (seen on + // the stand: the process that greeted waitForSMTPSReady). Wait for the map + // to take effect; any other refusal fails at once. + deadline := time.Now().Add(15 * time.Second) + for { + res := send() + if res.ok() { + break } + if res.refusedAt("RCPT", 553, "not owned by user "+login) != nil || time.Now().After(deadline) { + t.Fatalf("the first message of %s, before any limit could trip: %v", login, res.firstErr()) + } + time.Sleep(300 * time.Millisecond) + } + + 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) } diff --git a/test/e2e/port25_features_test.go b/test/e2e/port25_features_test.go index 62e3e48..a71d793 100644 --- a/test/e2e/port25_features_test.go +++ b/test/e2e/port25_features_test.go @@ -127,8 +127,8 @@ func testDMARCReportReachesThePanel(t *testing.T, sc *scenario) { // An address nobody chose is refused before DATA, hosted form or not. res := deliverPort25("noreply@"+reportReporter, "dmarc-reports+nobody.e2e.test@"+selfpostHostname, "Subject: x\r\n\r\nx\r\n") - if res.rcptErr == nil { - t.Fatalf("port 25 accepted a report address no domain uses (first error: %v)", res.firstErr()) + if err := res.refusedAt("RCPT", 550, "5.1.1"); err != nil { + t.Fatalf("port 25, a report address no domain uses: %v", err) } res = deliverPort25("noreply@"+reportReporter, address, reportMessage(t, address, aggregateXML(senderDomain, "e2e-report-1"))) @@ -344,10 +344,17 @@ func testInboundRelay(t *testing.T, sc *scenario) { t.Fatalf("the Inbound log holds %d rows, want the relayed message alone:\n%s", len(rows), strings.Join(rows, "\n")) } - for _, to := range []string{"nobody@" + inboundDomain, "someone@elsewhere.e2e.test"} { - res := deliverPort25("someone@stranger.e2e.test", to, message(to, uniqueToken("refused"))) - if res.rcptErr == nil { - t.Fatalf("port 25 accepted the recipient %s (first error: %v)", to, res.firstErr()) + for _, c := range []struct { + to string + code int + text string + }{ + {"nobody@" + inboundDomain, 550, "User unknown in relay recipient table"}, + {"someone@elsewhere.e2e.test", 554, "Relay access denied"}, + } { + res := deliverPort25("someone@stranger.e2e.test", c.to, message(c.to, uniqueToken("refused"))) + if err := res.refusedAt("RCPT", c.code, c.text); err != nil { + t.Fatalf("port 25, the recipient %s: %v", c.to, err) } } diff --git a/test/e2e/sender_check_test.go b/test/e2e/sender_check_test.go index 2054e28..f1085ef 100644 --- a/test/e2e/sender_check_test.go +++ b/test/e2e/sender_check_test.go @@ -1,7 +1,9 @@ package e2e import ( + "errors" "fmt" + "net/textproto" "regexp" "strconv" "strings" @@ -127,8 +129,9 @@ func testPanelDownDefersMail(t *testing.T, sc *scenario) { // Temporary, and before any message is offered: Postfix answers 451 from // the connection on, and "454 4.3.0 Try again later" at AUTH, which is // where a client that authenticates gives up. - if err := res.firstErr(); err == nil || !strings.HasPrefix(fmt.Sprint(err), "4") { - t.Fatalf("want a temporary 4xx with the panel down, got %v", res.firstErr()) + var reply *textproto.Error + if err := res.firstErr(); !errors.As(err, &reply) || reply.Code/100 != 4 { + t.Fatalf("want a temporary 4xx reply with the panel down, got %v", err) } if err := checkContainerAlive(h); err != nil { t.Fatalf("container did not survive the panel stopping: %v", err) diff --git a/test/e2e/smtp_client.go b/test/e2e/smtp_client.go index c6bdd76..a86dedf 100644 --- a/test/e2e/smtp_client.go +++ b/test/e2e/smtp_client.go @@ -2,9 +2,12 @@ package e2e import ( "crypto/tls" + "errors" "fmt" "net" "net/smtp" + "net/textproto" + "strings" "time" ) @@ -51,6 +54,40 @@ func (r sendResult) firstErr() error { return nil } +// refusedAt says nil only when the transaction was refused at stage +// ("connect", "AUTH", "MAIL", "RCPT" or "DATA") with the server's reply code +// and a reply text containing text. A negative case passes on its own refusal +// and nothing else: a reset or a timeout while Postfix was still starting once +// passed for the level-1 rate limit. Anything else is described for the +// failure message - where it stopped and what came. +func (r sendResult) refusedAt(stage string, code int, text string) error { + for _, s := range []struct { + name string + err error + }{{"connect", r.dialErr}, {"AUTH", r.authErr}, {"MAIL", r.mailErr}, {"RCPT", r.rcptErr}, {"DATA", r.dataErr}} { + if s.err == nil { + continue + } + if s.name != stage { + return fmt.Errorf("stopped at %s, not at %s: %v", s.name, stage, s.err) + } + return replyIs(s.err, code, text) + } + return fmt.Errorf("accepted, want refused at %s with %d", stage, code) +} + +// replyIs says nil when err is the server's reply code with text in it. +func replyIs(err error, code int, text string) error { + var reply *textproto.Error + if !errors.As(err, &reply) { + return fmt.Errorf("no SMTP reply but %v, want %d ...%s", err, code, text) + } + if reply.Code != code || !strings.Contains(reply.Msg, text) { + return fmt.Errorf("reply %d %s, want %d ...%s", reply.Code, reply.Msg, code, text) + } + return nil +} + // attemptSend drives one SMTP transaction over the implicit-TLS port, exactly // as an application client library would: TLS connect, EHLO, optional AUTH // PLAIN, MAIL/RCPT/DATA. The certificate is the stand's throwaway self-signed @@ -117,18 +154,31 @@ func attemptSend(a sendAttempt) sendResult { return res } -// waitForSMTPSReady polls the implicit-TLS port until a bare TCP connect -// succeeds. Used after a container (re)start: the panel's HTTP port and -// Postfix's smtpd come up independently (postfix-wrapper.sh additionally -// waits on both milter sockets before starting Postfix at all), so a caller -// that only waited for the panel could still race a not-yet-listening smtpd. +// waitForSMTPSReady polls the implicit-TLS port until Postfix greets over +// TLS. Used after a container (re)start: the panel's HTTP port and Postfix's +// smtpd come up independently (postfix-wrapper.sh additionally waits on both +// milter sockets before starting Postfix at all), so a caller that only +// waited for the panel could still race a not-yet-listening smtpd. A bare TCP +// connect is not enough: Docker's port proxy accepts on the host side before +// anything listens in the container and then resets the connection, which is +// how the level-1 rate-limit case once took a reset for its limit. func waitForSMTPSReady(timeout time.Duration) error { - return waitFor("smtps port to accept connections", timeout, 300*time.Millisecond, func() (bool, error) { - conn, err := net.DialTimeout("tcp", smtpsAddr, 2*time.Second) + return waitFor("smtps port to greet", timeout, 300*time.Millisecond, func() (bool, error) { + conn, err := tls.DialWithDialer(&net.Dialer{Timeout: 2 * time.Second}, "tcp", smtpsAddr, &tls.Config{ + InsecureSkipVerify: true, + ServerName: selfpostHostname, + }) if err != nil { return false, err } - _ = conn.Close() + _ = conn.SetDeadline(time.Now().Add(5 * time.Second)) + c, err := smtp.NewClient(conn, selfpostHostname) // reads the 220 greeting + if err != nil { + _ = conn.Close() + return false, err + } + _ = c.Quit() + _ = c.Close() return true, nil }) }