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.
This commit is contained in:
Mechiel Lukkien 2023-03-09 20:18:34 +01:00
parent eb26e9b921
commit 5742ed1537
No known key found for this signature in database
12 changed files with 93 additions and 18 deletions

2
ctl.go
View file

@ -397,7 +397,7 @@ func servectlcmd(ctx context.Context, log *mlog.Log, ctl *ctl, xcmd *string, shu
if qm.LastAttempt != nil { if qm.LastAttempt != nil {
lastAttempt = time.Since(*qm.LastAttempt).Round(time.Second).String() 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 { if len(qmsgs) == 0 {
fmt.Fprint(xw, "(empty)\n") fmt.Fprint(xw, "(empty)\n")

View file

@ -56,6 +56,12 @@ func (d Domain) ASCIIExtra(smtputf8 bool) string {
// Strings returns a human-readable string. // Strings returns a human-readable string.
// For IDNA names, the string contains both the unicode and ASCII name. // For IDNA names, the string contains both the unicode and ASCII name.
func (d Domain) String() string { 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 == "" { if d.Unicode == "" {
return d.ASCII return d.ASCII
} }

View file

@ -24,6 +24,15 @@ func (d IPDomain) String() string {
return d.Domain.Name() 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. // XString is like String, but only returns UTF-8 domains if utf8 is true.
func (d IPDomain) XString(utf8 bool) string { func (d IPDomain) XString(utf8 bool) string {
if d.IsIP() { if d.IsIP() {

View file

@ -511,7 +511,7 @@ func checkDomain(ctx context.Context, resolver dns.Resolver, dialer *net.Dialer,
mxs, err := resolver.LookupMX(ctx, domain.ASCII+".") mxs, err := resolver.LookupMX(ctx, domain.ASCII+".")
if err != nil { 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)) r.MX.Records = make([]MX, len(mxs))
for i, mx := range mxs { for i, mx := range mxs {
@ -1397,7 +1397,7 @@ func dnsblsStatus(ctx context.Context, resolver dns.Resolver) map[string]map[str
if expl != "" { if expl != "" {
result += ": " + expl result += ": " + expl
} }
r[ipstr][zone.String()] = result r[ipstr][zone.LogString()] = result
} }
} }
return r return r

View file

@ -1442,7 +1442,7 @@ can be found in message headers.
} else { } else {
spfIdentity = heloDomain spfIdentity = heloDomain
} }
fmt.Printf("spf result: %q: %q\n", spfDomain, spfStatus) fmt.Printf("spf result: %s: %s\n", spfDomain, spfStatus)
} }
} }

View file

@ -75,6 +75,12 @@ const (
LevelTracedata Level = 7 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. // 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. // The empty string is the default/fallback log level.
var config atomic.Value var config atomic.Value
@ -262,6 +268,9 @@ func stringValue(iscid, nested bool, v any) string {
return "" return ""
} }
if r, ok := v.(LogStringer); ok {
return r.LogString()
}
if r, ok := v.(fmt.Stringer); ok { if r, ok := v.(fmt.Stringer); ok {
return r.String() return r.String()
} }

View file

@ -695,14 +695,14 @@ func prepareDynamicConfig(ctx context.Context, dynamicPath string, static config
if err != nil { if err != nil {
addErrorf("bad domain %q: %s", d, err) addErrorf("bad domain %q: %s", d, err)
} else if dnsdomain.Name() != d { } 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 domain.Domain = dnsdomain
for _, sign := range domain.DKIM.Sign { for _, sign := range domain.DKIM.Sign {
if _, ok := domain.DKIM.Selectors[sign]; !ok { 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 { 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") log.Error("using sha1 with DKIM is deprecated as not secure enough, switch to sha256")
case "sha256": case "sha256":
default: 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)) pemBuf, err := os.ReadFile(configDirPath(dynamicPath, sel.PrivateKeyFile))
if err != nil { 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 continue
} }
p, _ := pem.Decode(pemBuf) p, _ := pem.Decode(pemBuf)
if p == nil { 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 continue
} }
key, err := x509.ParsePKCS8PrivateKey(p.Bytes) key, err := x509.ParsePKCS8PrivateKey(p.Bytes)
if err != nil { 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 continue
} }
switch k := key.(type) { switch k := key.(type) {
@ -763,7 +763,7 @@ func prepareDynamicConfig(ctx context.Context, dynamicPath string, static config
} }
sel.Key = k sel.Key = k
default: 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 { if len(sel.Headers) == 0 {
@ -816,7 +816,7 @@ func prepareDynamicConfig(ctx context.Context, dynamicPath string, static config
var err error var err error
acc.DNSDomain, err = dns.ParseDomain(acc.Domain) acc.DNSDomain, err = dns.ParseDomain(acc.Domain)
if err != nil { 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") { 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) address = smtp.NewAddress(localpart, acc.DNSDomain)
if _, ok := c.Domains[acc.DNSDomain.Name()]; !ok { 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 continue
} }
} }

View file

@ -551,7 +551,7 @@ func deliver(resolver dns.Resolver, m Msg) {
// ../rfc/8461:913 // ../rfc/8461:913
if policy != nil && policy.Mode == mtasts.ModeEnforce && !policy.Matches(h.Domain) { 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)) qlog.Error("mx host does not match enforce mta-sts policy, skipping", mlog.Field("host", h.Domain))
continue continue
} }
@ -665,9 +665,9 @@ func gatherHosts(resolver dns.Resolver, m Msg, cid int64, qlog *mlog.Log) (hosts
_, err = resolver.LookupHost(ctx, effectiveDomain.ASCII+".") _, err = resolver.LookupHost(ctx, effectiveDomain.ASCII+".")
cancel() cancel()
if dns.IsNotFound(err) { 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 { } 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}} hosts = []dns.IPDomain{{Domain: effectiveDomain}}
} else if err != nil { } else if err != nil {

View file

@ -107,7 +107,7 @@ func monitorDNSBL(log *mlog.Log) {
Name: "mox_dnsbl_ips_success", Name: "mox_dnsbl_ips_success",
Help: "DNSBL lookups to configured DNSBLs of our IPs.", Help: "DNSBL lookups to configured DNSBLs of our IPs.",
ConstLabels: prometheus.Labels{ ConstLabels: prometheus.Labels{
"zone": zone.String(), "zone": zone.LogString(),
"ip": k.ip, "ip": k.ip,
}, },
}, },

View file

@ -3,6 +3,7 @@ package smtp
import ( import (
"errors" "errors"
"fmt" "fmt"
"strconv"
"strings" "strings"
"github.com/mjl-/mox/dns" "github.com/mjl-/mox/dns"
@ -53,6 +54,17 @@ func (lp Localpart) String() string {
return r 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. // 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 // 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. // 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() 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. // ParseAddress parses an email address. UTF-8 is allowed.
// Returns ErrBadAddress for invalid addresses. // Returns ErrBadAddress for invalid addresses.
func ParseAddress(s string) (address Address, err error) { func ParseAddress(s string) (address Address, err error) {

View file

@ -1,6 +1,7 @@
package smtp package smtp
import ( import (
"strconv"
"strings" "strings"
"github.com/mjl-/mox/dns" "github.com/mjl-/mox/dns"
@ -22,6 +23,24 @@ func (p Path) String() string {
return p.XString(false) 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 // XString is like String, but returns unicode UTF-8 domain names if utf8 is
// true. // true.
func (p Path) XString(utf8 bool) string { func (p Path) XString(utf8 bool) string {

View file

@ -133,7 +133,7 @@ func AddReport(ctx context.Context, verifiedFromDomain dns.Domain, mailFrom stri
return fmt.Errorf("unknown domain") return fmt.Errorf("unknown domain")
} }
if reportdom != zerodom && d != reportdom { 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 reportdom = d