diff --git a/CHANGELOG.md b/CHANGELOG.md index 940ecb8..e0d379e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -59,6 +59,15 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version `MAIL FROM`. A refusal written from `mail.log` after a restart says that Postfix's line names the last recipient only (assumptions A-15, A-21, A-23). +- **A delivery reaches the row of every recipient Postfix delivers to.** A + quoted local part with a blank in it (`"a b"@x`) was cut at the blank, a + needlessly quoted one (`"ab"@x`) kept quotes Postfix does not log, a + recipient Postfix had rewritten was looked for under its new address, and + a recipient given twice made two rows of which Postfix reports one - each + row then waited for a line that never named it, and the sweep closed it + as `bounced`. The row now holds the recipient as Postfix logs it, once, + and is found under `orig_to=` when Postfix rewrote it (assumptions B-G5, + A-9, A-31, D-S20). - **A bounce is judged by the filter lists as the panel counts it.** rspamd's sender rules took a bounce's `From:` header when the envelope sender was empty, so a bounce could be refused or allowed by an entry the diff --git a/docs/architecture.md b/docs/architecture.md index a94e13d..e5913bf 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -481,9 +481,19 @@ the meantime stands. A deferred row is the sweep's too because Postfix can drop a deferred message without a final line for its recipients: at expiry before `2.5.2` read that line, and with `postsuper -d`, which logs only `removed`. The listing's `#` - a message forced to expire - is read as part -of the id's flags (`src/postqueue/showq_compat.c`, `showq_message()`). A delivery line updates only the newest row of its queue id -and recipient: Postfix reuses a short queue id once the message has left the -queue, and an old row must not be rewritten. `UpdateStatus`'s transaction +of the id's flags (`src/postqueue/showq_compat.c`, `showq_message()`). + +**Which row a delivery line is.** The journal milter writes a row's +recipient as Postfix will log it: the address the client gave, its quoted +local part unquoted and quoted again only where it needs to be (`"ab"@x` +becomes `ab@x`, `"a b"@x` stays; Postfix 3.7.11, `tok822_parse.c`, +`quote_822_local.c`), case kept, and a recipient given twice - in any case - +once, since cleanup keeps one (`cleanup_out_recipient.c`, `been_here()` +folding case). A delivery line names it in `orig_to=` when Postfix rewrote +the address, in `to=` otherwise (`log_adhoc.c` writes `orig_to=` only then), +and is matched without regard to case. It updates only the newest row of its +queue id and recipient: Postfix reuses a short queue id once the message has +left the queue, and an old row must not be rewritten. `UpdateStatus`'s transaction starts with a write, so a commit by the `dmarc-ingest` process in between cannot fail it with `database is locked`. Now that the log survives the container, reaching this path should mean the diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index a0e4253..60eccc6 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -116,17 +116,24 @@ type RetentionDays func() int // controls. A bounce whose reply quoted "status=sent" would then be filed as a // success. The real field is always the first one after to=<…>: in // log_adhoc() the reply is the "(%s)" after status=. -var deliveryRe = regexp.MustCompile(`^\S+ [^\s\[]+\[\d+\]: ([0-9A-Za-z]+): to=<(.*?)>, (?:orig_to=<.*?>, )?relay=.*?\bstatus=(\w+)`) +var deliveryRe = regexp.MustCompile(`^\S+ [^\s\[]+\[\d+\]: ([0-9A-Za-z]+): to=<(.*?)>, (?:orig_to=<(.*?)>, )?relay=.*?\bstatus=(\w+)`) // parseDelivery extracts (queue-id, recipient, status) from a mail.log line. -// ok is false for lines that are not recognised delivery results. +// ok is false for lines that are not recognised delivery results. The +// recipient is the one the application gave: orig_to= when Postfix rewrote +// the address (log_adhoc() writes it only then), to= otherwise - the row +// holds the RCPT TO address (assumptions A-9). func parseDelivery(line string) (queueID, recipient, status string, ok bool) { _, rest := SplitTimestamp(line) m := deliveryRe.FindStringSubmatch(rest) if m == nil { return "", "", "", false } - switch m[3] { + recipient = m[2] + if m[3] != "" { + recipient = m[3] + } + switch m[4] { case "sent": status = store.StatusSent case "deferred": @@ -136,7 +143,7 @@ func parseDelivery(line string) (queueID, recipient, status string, ok bool) { default: return "", "", "", false } - return m[1], m[2], status, true + return m[1], recipient, status, true } // expiryRe matches qmgr's line for a message it gave up on: diff --git a/internal/logtail/logtail_test.go b/internal/logtail/logtail_test.go index 7ef37a2..d4f722c 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -153,13 +153,14 @@ func TestParseDelivery(t *testing.T) { status: store.StatusSent, }, { - // An alias/virtual expansion carries orig_to= as well; the address - // the message was actually delivered to is the one in to=. - name: "orig_to is ignored in favour of to", + // A rewritten recipient carries orig_to= as well, the address the + // application gave - the one its row holds (log_adhoc() writes + // orig_to= only when it differs; assumptions A-9). + name: "orig_to is the row's recipient", line: "host postfix/lmtp[26]: 4Xk9tS1abcz: to=, orig_to=, relay=x, dsn=2.0.0, status=sent (ok)", wantOK: true, queueID: "4Xk9tS1abcz", - recipient: "real@example.net", + recipient: "alias@example.net", status: store.StatusSent, }, { diff --git a/internal/milter/address_test.go b/internal/milter/address_test.go index 666db7b..ada918e 100644 --- a/internal/milter/address_test.go +++ b/internal/milter/address_test.go @@ -1,23 +1,132 @@ package milter -import "testing" +import ( + "context" + "net" + "strings" + "testing" + "time" -// The journal row's recipient has to be the address Postfix later logs in -// to=<…>, or the delivery line matches no row and the sweep closes it as -// bounced. A quoted local part may hold a space or a ">". + "github.com/emersion/go-milter" +) + +// The milter gets the address as go-milter v0.4.1 hands it: the command's +// first argument, the ESMTP parameters left out, "<>" trimmed (session.go, +// case CodeMail/CodeRcpt). Nothing more is cut: a quoted local part may hold +// a blank or a ">" (assumptions B-G5). func TestCleanAddress(t *testing.T) { for _, c := range []struct{ in, want string }{ - {"", "a@example.net"}, - {" SIZE=100 BODY=8BITMIME", "a@example.net"}, {"a@example.net", "a@example.net"}, - {"a@example.net SIZE=100", "a@example.net"}, - {"<>", ""}, - {`<"a b"@example.net>`, `"a b"@example.net`}, - {`<"a>b"@example.net> NOTIFY=SUCCESS`, `"a>b"@example.net`}, - {`<"a\"> b"@example.net>`, `"a\"> b"@example.net`}, + {"", ""}, + {`"a b"@example.net`, `"a b"@example.net`}, + {`"a>b"@example.net`, `"a>b"@example.net`}, + {` a@example.net `, "a@example.net"}, } { if got := cleanAddress(c.in); got != c.want { t.Errorf("cleanAddress(%q) = %q, want %q", c.in, got, c.want) } } } + +// The journal row's recipient has to be the address Postfix later logs in +// to=<…>, or the delivery line matches no row and the sweep closes it as +// bounced: the local part unquoted, then quoted again only when it is not a +// dot-string (Postfix 3.7.11, src/global/tok822_parse.c and +// quote_822_local.c). Composed by hand after those functions. +func TestRecipientAsLogged(t *testing.T) { + for _, c := range []struct{ in, want string }{ + {"a@example.net", "a@example.net"}, + {"User@Example.NET", "User@Example.NET"}, // case kept + {`"ab"@example.net`, "ab@example.net"}, // quotes not needed + {`"a.b"@example.net`, "a.b@example.net"}, + {`"a b"@example.net`, `"a b"@example.net`}, + {`"a\b"@example.net`, "ab@example.net"}, // the backslash only escapes + {`"a\"b"@example.net`, `"a\"b"@example.net`}, + {`"a..b"@example.net`, `"a..b"@example.net`}, + {`".a"@example.net`, `".a"@example.net`}, + {`"a(b)"@example.net`, `"a(b)"@example.net`}, + {`"почта"@example.net`, "почта@example.net"}, // 8-bit clean + {"postmaster", "postmaster"}, + } { + if got := recipientAsLogged(c.in); got != c.want { + t.Errorf("recipientAsLogged(%q) = %q, want %q", c.in, got, c.want) + } + } +} + +// Through go-milter's own client, as Postfix sends it: the address and its +// ESMTP parameters as separate strings. A recipient given twice, in another +// case, is one row - cleanup keeps one (assumptions A-31). +func TestRecipientsThroughGoMilter(t *testing.T) { + ln, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatal(err) + } + rec := &fakeRecorder{} + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + go Serve(ctx, ln, rec) + + // The library's server speaks milter version 2, so the client asks for no + // action only version 6 has (go-milter v0.4.1, client.go, negotiate(); + // its client_test.go does the same). + cl := milter.NewClientWithOptions("tcp", ln.Addr().String(), milter.ClientOptions{ + ActionMask: milter.OptAddHeader | milter.OptChangeHeader, + }) + defer cl.Close() + s, err := cl.Session() + if err != nil { + t.Fatal(err) + } + defer s.Close() + step := func(what string, act *milter.Action, err error) { + t.Helper() + if err != nil || act.Code != milter.ActContinue { + t.Fatalf("%s: %+v, %v", what, act, err) + } + } + act, err := s.Conn("client.example.org", milter.FamilyInet, 40000, "203.0.113.7") + step("connect", act, err) + if err := s.Macros(milter.CodeMail, "{auth_authen}", "app1"); err != nil { + t.Fatal(err) + } + act, err = s.Mail("", []string{"SIZE=100", "BODY=8BITMIME"}) + step("mail", act, err) + for _, r := range []struct { + rcpt string + args []string + }{ + {`<"a b"@example.net>`, []string{"NOTIFY=SUCCESS"}}, + {`<"ab"@example.net>`, nil}, + {``, nil}, // ab@example.net again, in capitals + } { + act, err = s.Rcpt(r.rcpt, r.args) + step("rcpt "+r.rcpt, act, err) + } + act, err = s.HeaderField("Subject", "hello") + step("header", act, err) + act, err = s.HeaderEnd() + step("end of headers", act, err) + if err := s.Macros(milter.CodeEOB, "i", "Q1"); err != nil { + t.Fatal(err) + } + _, act, err = s.End() + step("end", act, err) + + deadline := time.Now().Add(2 * time.Second) + for { + rec.mu.Lock() + var got []string + for _, e := range rec.entries { + got = append(got, e.To) + } + rec.mu.Unlock() + if strings.Join(got, "; ") == `"a b"@example.net; ab@example.net` { + return + } + if time.Now().After(deadline) { + t.Fatalf("rows for %v, want \"a b\"@example.net and ab@example.net", got) + } + time.Sleep(10 * time.Millisecond) + } +} diff --git a/internal/milter/inbound_test.go b/internal/milter/inbound_test.go index 37fada5..96424bb 100644 --- a/internal/milter/inbound_test.go +++ b/internal/milter/inbound_test.go @@ -85,8 +85,10 @@ func inboundSessionFor(t *testing.T, rec InboundStore, filter bool) *inboundSess func TestInboundRecordsAcceptedMessage(t *testing.T) { rec := &fakeInbound{domains: map[string]bool{"in.example.com": true}} s := inboundSessionFor(t, rec, false) - resp := message(t, s, " SIZE=1200", - []string{"", "b@IN.example.com"}, + // As go-milter hands them: brackets trimmed, ESMTP parameters left out + // (go-milter v0.4.1, session.go, case CodeMail/CodeRcpt). + resp := message(t, s, "sender@example.net", + []string{"a@in.example.com", "b@IN.example.com"}, [][2]string{{"Subject", "=?utf-8?Q?Sch=C3=B6n?="}}) if resp != milter.RespContinue { t.Errorf("end-of-message response = %v, want continue", resp) diff --git a/internal/milter/milter.go b/internal/milter/milter.go index c5cfcb5..f5ffbd4 100644 --- a/internal/milter/milter.go +++ b/internal/milter/milter.go @@ -146,8 +146,21 @@ func (s *session) MailFrom(from string, m *milter.Modifier) (milter.Response, er // Postfix 3.7.11, src/smtpd/smtpd.c, rcpt_cmd(): milter_rcpt_event() once per // RCPT TO; a recipient Postfix refused goes only to a milter that asked for // SMFIP_RCPT_REJ, which Serve's Protocol does not. +// A recipient given twice - in any case - is one row: cleanup keeps the first +// and drops the rest (Postfix 3.7.11, src/cleanup/cleanup_out_recipient.c, +// cleanup_out_recipient(), been_here() on a table made with BH_FLAG_FOLD in +// cleanup_state.c), so only one delivery line will come (assumptions A-31). +// Its key also holds the DSN NOTIFY= and ORCPT= of the RCPT TO command, which +// go-milter does not hand over (session.go, case CodeRcpt): a recipient given +// twice with different ones is two recipients to Postfix and one row here. func (s *session) RcptTo(rcpt string, m *milter.Modifier) (milter.Response, error) { - s.rcpts = append(s.rcpts, cleanAddress(rcpt)) + to := recipientAsLogged(rcpt) + for _, have := range s.rcpts { + if strings.EqualFold(have, to) { + return milter.RespContinue, nil + } + } + s.rcpts = append(s.rcpts, to) return milter.RespContinue, nil } @@ -253,37 +266,86 @@ func (s *session) record(queueID string) { } } -// cleanAddress strips the angle brackets and any ESMTP parameters Postfix may -// pass with an address, leaving the bare mailbox. A bracketed address ends at -// the first ">" outside a quoted local part: a quoted local part may hold a -// space or a ">", and an address cut there matched no delivery line, so its -// row was left for the reconcile sweep to close as bounced (review of audit -// stage 1). +// cleanAddress is an address as the milter gets it, without the angle +// brackets: Postfix 3.7.11 hands the milter the command's argument as the +// client wrote it, ESMTP parameters as separate strings (src/smtpd/smtpd.c, +// mail_cmd()/rcpt_cmd(), milter_argv()), and go-milter v0.4.1 passes the first +// with "<>" trimmed (session.go, case CodeMail/CodeRcpt). A quoted local part +// may hold a blank, so nothing is cut at one (assumptions B-G5). func cleanAddress(a string) string { - a = strings.TrimSpace(a) - if strings.HasPrefix(a, "<") { - quoted := false - for i := 1; i < len(a); i++ { - switch a[i] { - case '\\': - if quoted { - i++ // the escaped character is part of the local part - } - case '"': - quoted = !quoted - case '>': - if !quoted { - return a[1:i] - } + return strings.Trim(strings.TrimSpace(a), "<>") +} + +// recipientAsLogged is a recipient in the form Postfix writes it in "to=<..>" +// and "orig_to=<..>", so a delivery line finds its row. Postfix 3.7.11 keeps +// the address in internal form - a quoted local part unquoted, a backslash +// dropped before the character it escapes, a blank in quotes made a space +// (src/smtpd/smtpd.c, extract_addr(), over src/global/tok822_parse.c, +// COLLECT and tok822_internalize()) - and logs it in external form +// (src/global/info_log_addr_form.c with info_log_address_format=external, +// quote_822_local(): the local part quoted again only when it is not a plain +// dot-string). So "ab"@x is logged ab@x, and "a b"@x stays "a b"@x. Case is +// kept. An address with a comment or a blank outside quotes is taken as +// written: tok822 would drop or join them, and no application writes one. +func recipientAsLogged(a string) string { + a = cleanAddress(a) + at := strings.LastIndexByte(a, '@') + local, domain := a, "" + if at >= 0 { + local, domain = a[:at], a[at:] + } + if len(local) >= 2 && local[0] == '"' && local[len(local)-1] == '"' { + var b strings.Builder + for i := 1; i < len(local)-1; i++ { + c := local[i] + if c == '\\' && i+1 < len(local)-1 { + i++ + c = local[i] } + if c == ' ' || c == '\t' || c == '\r' || c == '\n' { + c = ' ' + } + b.WriteByte(c) + } + local = b.String() + } + return quoteLocalPart(local) + domain +} + +// quoteLocalPart is quote_822_local() of Postfix 3.7.11 +// (src/global/quote_822_local.c, with QUOTE_FLAG_8BITCLEAN, the default): a +// local part that is a dot-string - atoms of no blank, control character or +// one of ()<>@,;:\"[], joined by single dots, none first or last - is left as +// it is; any other is put in quotes, with a backslash before ", \ and CR. +func quoteLocalPart(local string) string { + if isDotString(local) { + return local + } + var b strings.Builder + b.WriteByte('"') + for i := 0; i < len(local); i++ { + c := local[i] + if c == '"' || c == '\\' || c == '\r' { + b.WriteByte('\\') + } + b.WriteByte(c) + } + b.WriteByte('"') + return b.String() +} + +// isDotString is is_822_dot_string() of quote_822_local.c, 8-bit clean. +func isDotString(s string) bool { + if s == "" || s[0] == '.' || s[len(s)-1] == '.' || strings.Contains(s, "..") { + return false + } + for i := 0; i < len(s); i++ { + c := s[i] + if c == ' ' || c < 32 || c == 127 || strings.IndexByte(`()<>@,;:\"[]`, c) >= 0 { + return false } } - if i := strings.IndexByte(a, ' '); i >= 0 { // drop "addr SIZE=… BODY=…" params - a = a[:i] - } - a = strings.TrimPrefix(a, "<") - a = strings.TrimSuffix(a, ">") - return a + return true } // domainOf returns the lower-cased domain of an email address, or "" if there diff --git a/internal/store/sendlog.go b/internal/store/sendlog.go index 76c8d3d..408f96b 100644 --- a/internal/store/sendlog.go +++ b/internal/store/sendlog.go @@ -93,8 +93,15 @@ func (s *Store) InsertRejected(e SendLogEntry) error { // UpdateStatus advances the delivery status of the send-log rows matching a // (queue-id, recipient) pair, which the log-tailer parses out of mail.log. -// Recipient matching is case-insensitive because Postfix may normalise address -// case between the milter (envelope) and the delivery log. It returns the +// Recipient matching is case-insensitive. Postfix keeps the case the client +// wrote, and the milter's row holds it as Postfix logs it +// (milter.recipientAsLogged); but a recipient repeated in another case is +// one recipient to Postfix - cleanup drops the second, comparing folded +// (Postfix 3.7.11, src/cleanup/cleanup_out_recipient.c, been_here() with +// BH_FLAG_FOLD) - and one row to the milter, spelt as first given, and +// log_adhoc() writes orig_to= only when it differs from to= other than in +// case (src/global/log_adhoc.c, strcasecmp_utf8()). Assumptions D-S20. It +// returns the // number of rows updated so the caller can tell whether the line matched a // journal entry. // diff --git a/test/e2e/delivery_log_test.go b/test/e2e/delivery_log_test.go index 1e4916a..3da1a02 100644 --- a/test/e2e/delivery_log_test.go +++ b/test/e2e/delivery_log_test.go @@ -150,3 +150,34 @@ print("" if r is None else r[0]+" "+r[1])`, token) t.Fatalf("no expiry line in mail.log: %v\n%s", err, out) } } + +// testRecipientsAsPostfixLogsThem: each recipient's row reaches "sent". The +// row holds the recipient as Postfix logs it - "a b" stays quoted, "ab" loses +// its quotes - and a recipient given again in other capitals is one row, as +// cleanup keeps one (Postfix 3.7.11, src/global/quote_822_local.c, +// src/cleanup/cleanup_out_recipient.c; assumptions B-G5, A-31). Before, the +// first was cut at its blank and its row closed as bounced by the sweep. +func testRecipientsAsPostfixLogsThem(t *testing.T, sc *scenario) { + token := uniqueToken("rcpt") + if res := attemptSend(sendAttempt{ + authLogin: sc.appLogin, authPassword: sc.appPassword, + from: "alerts@" + senderDomain, headerFrom: "alerts@" + senderDomain, + to: `"x y"@sink.e2e.test`, + moreTo: []string{`"ab"@sink.e2e.test`, `"X Y"@sink.e2e.test`}, + subject: "e2e " + token, body: "three RCPT TO, two recipients", + }); !res.ok() { + t.Fatalf("send: %v", res.firstErr()) + } + want := `"x y"@sink.e2e.test sent; ab@sink.e2e.test sent` + if err := waitFor("both rows to be sent", 30*time.Second, 500*time.Millisecond, func() (bool, error) { + out, err := asPanel(`import sqlite3,sys +rows=sqlite3.connect("/data/selfpost.db").execute("select to_addr, status from send_log where subject like ? order by id",("%"+sys.argv[1]+"%",)).fetchall() +print("; ".join(r[0]+" "+r[1] for r in rows))`, token) + if err != nil { + return false, err + } + return out == want, fmt.Errorf("rows %q, want %q", out, want) + }); err != nil { + t.Fatal(err) + } +} diff --git a/test/e2e/main_test.go b/test/e2e/main_test.go index c2d0a34..85d4826 100644 --- a/test/e2e/main_test.go +++ b/test/e2e/main_test.go @@ -345,6 +345,9 @@ func TestE2E(t *testing.T) { // From here on the installation is no longer the one the run started: it // is restored from its own backup, then switched to accept mail on port 25. + run("recipients_as_postfix_logs_them", func(t *testing.T) { + testRecipientsAsPostfixLogsThem(t, sc) + }) run("expired_message_is_closed", func(t *testing.T) { testExpiredMessageIsClosed(t, sc) }) diff --git a/test/e2e/smtp_client.go b/test/e2e/smtp_client.go index 46dff01..b5ca4c6 100644 --- a/test/e2e/smtp_client.go +++ b/test/e2e/smtp_client.go @@ -23,6 +23,7 @@ const smtpsAddr = "127.0.0.1:20465" type sendAttempt struct { authLogin, authPassword string from, to string + moreTo []string // further RCPT TO, after to headerFrom string subject, body string } @@ -133,10 +134,12 @@ func attemptSend(a sendAttempt) sendResult { _ = c.Quit() return res } - if err := c.Rcpt(a.to); err != nil { - res.rcptErr = err - _ = c.Quit() - return res + for _, to := range append([]string{a.to}, a.moreTo...) { + if err := c.Rcpt(to); err != nil { + res.rcptErr = err + _ = c.Quit() + return res + } } w, err := c.Data() if err != nil {