From 5742ed15377048b61f3fc44e44faf50d91c971c9 Mon Sep 17 00:00:00 2001 From: Mechiel Lukkien Date: Thu, 9 Mar 2023 20:18:34 +0100 Subject: [PATCH] when logging email addresses with IDNA domain and/or special characters or utf8 in localpart, log both native utf8 form and form with escape localpart and ascii-only domain the idea is to make it clear from the logging if non-ascii characters are used. this is implemented by making mlog recognize if a field value that will be logged has a LogString method. if so, that value is logged. dns.Domain, smtp.Address, smtp.Localpart, smtp.Path now have a LogString method. some explicit calls to String have been replaced to LogString, and some %q formatting have been replaced with %s, because the escaped localpart would already have double quotes, and double doublequotes aren't easy to read. --- ctl.go | 2 +- dns/dns.go | 6 ++++++ dns/ipdomain.go | 9 +++++++++ http/admin.go | 4 ++-- main.go | 2 +- mlog/log.go | 9 +++++++++ mox-/config.go | 18 +++++++++--------- queue/queue.go | 6 +++--- serve.go | 2 +- smtp/address.go | 32 ++++++++++++++++++++++++++++++++ smtp/path.go | 19 +++++++++++++++++++ tlsrptdb/db.go | 2 +- 12 files changed, 93 insertions(+), 18 deletions(-) diff --git a/ctl.go b/ctl.go index c17fefd..3bc0eb3 100644 --- a/ctl.go +++ b/ctl.go @@ -397,7 +397,7 @@ func servectlcmd(ctx context.Context, log *mlog.Log, ctl *ctl, xcmd *string, shu if qm.LastAttempt != nil { lastAttempt = time.Since(*qm.LastAttempt).Round(time.Second).String() } - fmt.Fprintf(xw, "%5d %s from:%s@%s to:%s@%s next %s last %s error %q\n", qm.ID, qm.Queued.Format(time.RFC3339), qm.SenderLocalpart, qm.SenderDomain, qm.RecipientLocalpart, qm.RecipientDomain, -time.Since(qm.NextAttempt).Round(time.Second), lastAttempt, qm.LastError) + fmt.Fprintf(xw, "%5d %s from:%s to:%s next %s last %s error %q\n", qm.ID, qm.Queued.Format(time.RFC3339), qm.Sender().LogString(), qm.Recipient().LogString(), -time.Since(qm.NextAttempt).Round(time.Second), lastAttempt, qm.LastError) } if len(qmsgs) == 0 { fmt.Fprint(xw, "(empty)\n") diff --git a/dns/dns.go b/dns/dns.go index f5d77af..1d41bf1 100644 --- a/dns/dns.go +++ b/dns/dns.go @@ -56,6 +56,12 @@ func (d Domain) ASCIIExtra(smtputf8 bool) string { // Strings returns a human-readable string. // For IDNA names, the string contains both the unicode and ASCII name. func (d Domain) String() string { + return d.LogString() +} + +// LogString returns a domain for logging. +// For IDNA names, the string contains both the unicode and ASCII name. +func (d Domain) LogString() string { if d.Unicode == "" { return d.ASCII } diff --git a/dns/ipdomain.go b/dns/ipdomain.go index 9d1d50a..31184a3 100644 --- a/dns/ipdomain.go +++ b/dns/ipdomain.go @@ -24,6 +24,15 @@ func (d IPDomain) String() string { return d.Domain.Name() } +// LogString returns a string with both ASCII-only and optional UTF-8 +// representation. +func (d IPDomain) LogString() string { + if len(d.IP) > 0 { + return d.IP.String() + } + return d.Domain.LogString() +} + // XString is like String, but only returns UTF-8 domains if utf8 is true. func (d IPDomain) XString(utf8 bool) string { if d.IsIP() { diff --git a/http/admin.go b/http/admin.go index 8ec91c2..d1bde8a 100644 --- a/http/admin.go +++ b/http/admin.go @@ -511,7 +511,7 @@ func checkDomain(ctx context.Context, resolver dns.Resolver, dialer *net.Dialer, mxs, err := resolver.LookupMX(ctx, domain.ASCII+".") if err != nil { - addf(&r.MX.Errors, "Looking up MX records for %q: %s", domain, err) + addf(&r.MX.Errors, "Looking up MX records for %s: %s", domain, err) } r.MX.Records = make([]MX, len(mxs)) for i, mx := range mxs { @@ -1397,7 +1397,7 @@ func dnsblsStatus(ctx context.Context, resolver dns.Resolver) map[string]map[str if expl != "" { result += ": " + expl } - r[ipstr][zone.String()] = result + r[ipstr][zone.LogString()] = result } } return r diff --git a/main.go b/main.go index b7a658c..3fcf0f4 100644 --- a/main.go +++ b/main.go @@ -1442,7 +1442,7 @@ can be found in message headers. } else { spfIdentity = heloDomain } - fmt.Printf("spf result: %q: %q\n", spfDomain, spfStatus) + fmt.Printf("spf result: %s: %s\n", spfDomain, spfStatus) } } diff --git a/mlog/log.go b/mlog/log.go index 01092d7..0e1da8c 100644 --- a/mlog/log.go +++ b/mlog/log.go @@ -75,6 +75,12 @@ const ( LevelTracedata Level = 7 ) +// LogStringer is used when formatting field values during logging. If a value +// implements it, LogString is called for the value to log. +type LogStringer interface { + LogString() string +} + // Holds a map[string]Level, mapping a package (field pkg in logs) to a log level. // The empty string is the default/fallback log level. var config atomic.Value @@ -262,6 +268,9 @@ func stringValue(iscid, nested bool, v any) string { return "" } + if r, ok := v.(LogStringer); ok { + return r.LogString() + } if r, ok := v.(fmt.Stringer); ok { return r.String() } diff --git a/mox-/config.go b/mox-/config.go index 359d2f4..cc1d36a 100644 --- a/mox-/config.go +++ b/mox-/config.go @@ -695,14 +695,14 @@ func prepareDynamicConfig(ctx context.Context, dynamicPath string, static config if err != nil { addErrorf("bad domain %q: %s", d, err) } else if dnsdomain.Name() != d { - addErrorf("domain %q must be specified in IDNA form, %q", d, dnsdomain.Name()) + addErrorf("domain %s must be specified in IDNA form, %s", d, dnsdomain.Name()) } domain.Domain = dnsdomain for _, sign := range domain.DKIM.Sign { if _, ok := domain.DKIM.Selectors[sign]; !ok { - addErrorf("selector %q for signing is missing in domain %q", sign, d) + addErrorf("selector %s for signing is missing in domain %s", sign, d) } } for name, sel := range domain.DKIM.Selectors { @@ -731,22 +731,22 @@ func prepareDynamicConfig(ctx context.Context, dynamicPath string, static config log.Error("using sha1 with DKIM is deprecated as not secure enough, switch to sha256") case "sha256": default: - addErrorf("unsupported hash %q for selector %q in domain %q", sel.HashEffective, name, d) + addErrorf("unsupported hash %q for selector %q in domain %s", sel.HashEffective, name, d) } pemBuf, err := os.ReadFile(configDirPath(dynamicPath, sel.PrivateKeyFile)) if err != nil { - addErrorf("reading private key for selector %q in domain %q: %s", name, d, err) + addErrorf("reading private key for selector %s in domain %s: %s", name, d, err) continue } p, _ := pem.Decode(pemBuf) if p == nil { - addErrorf("private key for selector %q in domain %q has no PEM block", name, d) + addErrorf("private key for selector %s in domain %s has no PEM block", name, d) continue } key, err := x509.ParsePKCS8PrivateKey(p.Bytes) if err != nil { - addErrorf("parsing private key for selector %q in domain %q: %s", name, d, err) + addErrorf("parsing private key for selector %s in domain %s: %s", name, d, err) continue } switch k := key.(type) { @@ -763,7 +763,7 @@ func prepareDynamicConfig(ctx context.Context, dynamicPath string, static config } sel.Key = k default: - addErrorf("private key type %T not yet supported, at selector %q in domain %q", key, name, d) + addErrorf("private key type %T not yet supported, at selector %s in domain %s", key, name, d) } if len(sel.Headers) == 0 { @@ -816,7 +816,7 @@ func prepareDynamicConfig(ctx context.Context, dynamicPath string, static config var err error acc.DNSDomain, err = dns.ParseDomain(acc.Domain) if err != nil { - addErrorf("parsing domain %q for account %q: %s", acc.Domain, accName, err) + addErrorf("parsing domain %s for account %q: %s", acc.Domain, accName, err) } if strings.EqualFold(acc.RejectsMailbox, "Inbox") { @@ -924,7 +924,7 @@ func prepareDynamicConfig(ctx context.Context, dynamicPath string, static config } address = smtp.NewAddress(localpart, acc.DNSDomain) if _, ok := c.Domains[acc.DNSDomain.Name()]; !ok { - addErrorf("unknown domain %q for account %q", acc.DNSDomain.Name(), accName) + addErrorf("unknown domain %s for account %q", acc.DNSDomain.Name(), accName) continue } } diff --git a/queue/queue.go b/queue/queue.go index 604cd0f..23a2d85 100644 --- a/queue/queue.go +++ b/queue/queue.go @@ -551,7 +551,7 @@ func deliver(resolver dns.Resolver, m Msg) { // ../rfc/8461:913 if policy != nil && policy.Mode == mtasts.ModeEnforce && !policy.Matches(h.Domain) { - errmsg = fmt.Sprintf("mx host %v does not match enforced mta-sts policy", h.Domain) + errmsg = fmt.Sprintf("mx host %s does not match enforced mta-sts policy", h.Domain) qlog.Error("mx host does not match enforce mta-sts policy, skipping", mlog.Field("host", h.Domain)) continue } @@ -665,9 +665,9 @@ func gatherHosts(resolver dns.Resolver, m Msg, cid int64, qlog *mlog.Log) (hosts _, err = resolver.LookupHost(ctx, effectiveDomain.ASCII+".") cancel() if dns.IsNotFound(err) { - return nil, effectiveDomain, true, fmt.Errorf("%w: recipient domain/host %v", errNoRecord, effectiveDomain) + return nil, effectiveDomain, true, fmt.Errorf("%w: recipient domain/host %s", errNoRecord, effectiveDomain) } else if err != nil { - return nil, effectiveDomain, false, fmt.Errorf("%w: looking up host %v because of no mx record: %v", errDNS, effectiveDomain, err) + return nil, effectiveDomain, false, fmt.Errorf("%w: looking up host %s because of no mx record: %v", errDNS, effectiveDomain, err) } hosts = []dns.IPDomain{{Domain: effectiveDomain}} } else if err != nil { diff --git a/serve.go b/serve.go index 523ba34..7d03698 100644 --- a/serve.go +++ b/serve.go @@ -107,7 +107,7 @@ func monitorDNSBL(log *mlog.Log) { Name: "mox_dnsbl_ips_success", Help: "DNSBL lookups to configured DNSBLs of our IPs.", ConstLabels: prometheus.Labels{ - "zone": zone.String(), + "zone": zone.LogString(), "ip": k.ip, }, }, diff --git a/smtp/address.go b/smtp/address.go index ad23d92..c33dd74 100644 --- a/smtp/address.go +++ b/smtp/address.go @@ -3,6 +3,7 @@ package smtp import ( "errors" "fmt" + "strconv" "strings" "github.com/mjl-/mox/dns" @@ -53,6 +54,17 @@ func (lp Localpart) String() string { return r } +// LogString returns the localpart as string for use in smtp, and an escaped +// representation if it has non-ascii characters. +func (lp Localpart) LogString() string { + s := lp.String() + qs := strconv.QuoteToASCII(s) + if qs != `"`+s+`"` { + s = "/" + qs + } + return s +} + // DSNString returns the localpart as string for use in a DSN. // utf8 indicates if the remote MTA supports utf8 messaging. If not, the 7bit DSN // encoding for "utf-8-addr-xtext" from RFC 6533 is used. @@ -116,6 +128,26 @@ func (a Address) String() string { return a.Localpart.String() + "@" + a.Domain.Name() } +// LogString returns the address with with utf-8 in localpart and/or domain. In +// case of an IDNA domain and/or quotable characters in the localpart, an address +// with quoted/escaped localpart and ASCII domain is also returned. +func (a Address) LogString() string { + if a.IsZero() { + return "" + } + s := a.Pack(true) + lp := a.Localpart.String() + qlp := strconv.QuoteToASCII(lp) + escaped := qlp != `"`+lp+`"` + if a.Domain.Unicode != "" || escaped { + if escaped { + lp = qlp + } + s += "/" + lp + "@" + a.Domain.ASCII + } + return s +} + // ParseAddress parses an email address. UTF-8 is allowed. // Returns ErrBadAddress for invalid addresses. func ParseAddress(s string) (address Address, err error) { diff --git a/smtp/path.go b/smtp/path.go index ae98cd6..aa53b09 100644 --- a/smtp/path.go +++ b/smtp/path.go @@ -1,6 +1,7 @@ package smtp import ( + "strconv" "strings" "github.com/mjl-/mox/dns" @@ -22,6 +23,24 @@ func (p Path) String() string { return p.XString(false) } +// LogString returns both the ASCII-only and optional UTF-8 representation. +func (p Path) LogString() string { + if p.Localpart == "" && p.IPDomain.IsZero() { + return "" + } + s := p.XString(true) + lp := p.Localpart.String() + qlp := strconv.QuoteToASCII(lp) + escaped := qlp != `"`+lp+`"` + if p.IPDomain.Domain.Unicode != "" || escaped { + if escaped { + lp = qlp + } + s += "/" + lp + "@" + p.IPDomain.XString(false) + } + return s +} + // XString is like String, but returns unicode UTF-8 domain names if utf8 is // true. func (p Path) XString(utf8 bool) string { diff --git a/tlsrptdb/db.go b/tlsrptdb/db.go index b281d9a..f3e25c2 100644 --- a/tlsrptdb/db.go +++ b/tlsrptdb/db.go @@ -133,7 +133,7 @@ func AddReport(ctx context.Context, verifiedFromDomain dns.Domain, mailFrom stri return fmt.Errorf("unknown domain") } if reportdom != zerodom && d != reportdom { - return fmt.Errorf("multiple domains in report %v and %v", reportdom, d) + return fmt.Errorf("multiple domains in report %s and %s", reportdom, d) } reportdom = d