serv/mox
1
0
Fork 0
mirror of https://github.com/mjl-/mox.git synced 2024-12-26 16:33:47 +03:00
Code Issues Projects Releases Packages Wiki Activity Actions 1

wrap long lines with many logging parameters to multiple lines

Browse source 
for improved readability
This commit is contained in:
Mechiel Lukkien 2023-12-05 16:06:50 +01:00
parent 5b20cba50a
commit fcaa504878
No known key found for this signature in database
31 changed files with 327 additions and 68 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

6
autotls/autotls.go
View file

@ -240,7 +240,11 @@ func (m *Manager) SetAllowedHostnames(log mlog.Log, resolver dns.Resolver, hostn
}
for _, ip := range ips {
if _, ok := publicIPstrs[ip.String()]; !ok {
log.Error("warning: acme tls cert validation for host is likely to fail because not all its ips are being listened on", slog.Any("hostname", h), slog.Any("listenedips", publicIPs), slog.Any("hostips", ips), slog.Any("missingip", ip))
log.Error("warning: acme tls cert validation for host is likely to fail because not all its ips are being listened on",
slog.Any("hostname", h),
slog.Any("listenedips", publicIPs),
slog.Any("hostips", ips),
slog.Any("missingip", ip))
}
}
}

15
backup.go
View file

@ -166,7 +166,10 @@ func backupctl(ctx context.Context, ctl *ctl) {
return nil
})
if err != nil {
xerrx("copying directory (not backed up properly)", err, slog.String("srcdir", srcdir), slog.String("dstdir", dstdir), slog.Duration("duration", time.Since(tmDir)))
xerrx("copying directory (not backed up properly)", err,
slog.String("srcdir", srcdir),
slog.String("dstdir", dstdir),
slog.Duration("duration", time.Since(tmDir)))
return
}
xvlog("backed up directory", slog.String("dir", dir), slog.Duration("duration", time.Since(tmDir)))
@ -341,7 +344,10 @@ func backupctl(ctx context.Context, ctl *ctl) {
if err != nil {
xerrx("processing queue messages (not backed up properly)", err, slog.Duration("duration", time.Since(tmMsgs)))
} else {
xvlog("queue message files linked/copied", slog.Int("linked", nlinked), slog.Int("copied", ncopied), slog.Duration("duration", time.Since(tmMsgs)))
xvlog("queue message files linked/copied",
slog.Int("linked", nlinked),
slog.Int("copied", ncopied),
slog.Duration("duration", time.Since(tmMsgs)))
}
// Read through all files in queue directory and warn about anything we haven't handled yet.
@ -445,7 +451,10 @@ func backupctl(ctx context.Context, ctl *ctl) {
if err != nil {
xerrx("processing account messages (not backed up properly)", err, slog.Duration("duration", time.Since(tmMsgs)))
} else {
xvlog("account message files linked/copied", slog.Int("linked", nlinked), slog.Int("copied", ncopied), slog.Duration("duration", time.Since(tmMsgs)))
xvlog("account message files linked/copied",
slog.Int("linked", nlinked),
slog.Int("copied", ncopied),
slog.Duration("duration", time.Since(tmMsgs)))
}
// Read through all files in account directory and warn about anything we haven't handled yet.

20
dkim/dkim.go
View file

@ -127,7 +127,11 @@ func Sign(ctx context.Context, elog *slog.Logger, localpart smtp.Localpart, doma
log := mlog.New("dkim", elog)
start := timeNow()
defer func() {
log.Debugx("dkim sign result", rerr, slog.Any("localpart", localpart), slog.Any("domain", domain), slog.Bool("smtputf8", smtputf8), slog.Duration("duration", time.Since(start)))
log.Debugx("dkim sign result", rerr,
slog.Any("localpart", localpart),
slog.Any("domain", domain),
slog.Bool("smtputf8", smtputf8),
slog.Duration("duration", time.Since(start)))
}()
hdrs, bodyOffset, err := parseHeaders(bufio.NewReader(&moxio.AtReader{R: msg}))
@ -274,7 +278,12 @@ func Lookup(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, selec
log := mlog.New("dkim", elog)
start := timeNow()
defer func() {
log.Debugx("dkim lookup result", rerr, slog.Any("selector", selector), slog.Any("domain", domain), slog.Any("status", rstatus), slog.Any("record", rrecord), slog.Duration("duration", time.Since(start)))
log.Debugx("dkim lookup result", rerr,
slog.Any("selector", selector),
slog.Any("domain", domain),
slog.Any("status", rstatus),
slog.Any("record", rrecord),
slog.Duration("duration", time.Since(start)))
}()
name := selector.ASCII + "._domainkey." + domain.ASCII + "."
@ -356,7 +365,12 @@ func Verify(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, smtpu
log.Debugx("dkim verify result", rerr, slog.Bool("smtputf8", smtputf8), slog.Duration("duration", time.Since(start)))
}
for _, result := range results {
log.Debugx("dkim verify result", result.Err, slog.Bool("smtputf8", smtputf8), slog.Any("status", result.Status), slog.Any("sig", result.Sig), slog.Any("record", result.Record), slog.Duration("duration", time.Since(start)))
log.Debugx("dkim verify result", result.Err,
slog.Bool("smtputf8", smtputf8),
slog.Any("status", result.Status),
slog.Any("sig", result.Sig),
slog.Any("record", result.Record),
slog.Duration("duration", time.Since(start)))
}
}()

23
dmarc/dmarc.go
View file

@ -103,7 +103,12 @@ func Lookup(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, from
log := mlog.New("dmarc", elog)
start := time.Now()
defer func() {
log.Debugx("dmarc lookup result", rerr, slog.Any("fromdomain", from), slog.Any("status", status), slog.Any("domain", domain), slog.Any("record", record), slog.Duration("duration", time.Since(start)))
log.Debugx("dmarc lookup result", rerr,
slog.Any("fromdomain", from),
slog.Any("status", status),
slog.Any("domain", domain),
slog.Any("record", record),
slog.Duration("duration", time.Since(start)))
}()
// ../rfc/7489:859 ../rfc/7489:1370
@ -206,7 +211,12 @@ func LookupExternalReportsAccepted(ctx context.Context, elog *slog.Logger, resol
log := mlog.New("dmarc", elog)
start := time.Now()
defer func() {
log.Debugx("dmarc externalreports result", rerr, slog.Bool("accepts", accepts), slog.Any("dmarcdomain", dmarcDomain), slog.Any("extdestdomain", extDestDomain), slog.Any("records", records), slog.Duration("duration", time.Since(start)))
log.Debugx("dmarc externalreports result", rerr,
slog.Bool("accepts", accepts),
slog.Any("dmarcdomain", dmarcDomain),
slog.Any("extdestdomain", extDestDomain),
slog.Any("records", records),
slog.Duration("duration", time.Since(start)))
}()
status, records, txts, authentic, rerr = lookupReportsRecord(ctx, resolver, dmarcDomain, extDestDomain)
@ -239,7 +249,14 @@ func Verify(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, from
reject = "yes"
}
metricDMARCVerify.WithLabelValues(string(result.Status), reject, use).Observe(float64(time.Since(start)) / float64(time.Second))
log.Debugx("dmarc verify result", result.Err, slog.Any("fromdomain", from), slog.Any("dkimresults", dkimResults), slog.Any("spfresult", spfResult), slog.Any("status", result.Status), slog.Bool("reject", result.Reject), slog.Bool("use", useResult), slog.Duration("duration", time.Since(start)))
log.Debugx("dmarc verify result", result.Err,
slog.Any("fromdomain", from),
slog.Any("dkimresults", dkimResults),
slog.Any("spfresult", spfResult),
slog.Any("status", result.Status),
slog.Bool("reject", result.Reject),
slog.Bool("use", useResult),
slog.Duration("duration", time.Since(start)))
}()
status, recordDomain, record, _, authentic, err := Lookup(ctx, log.Logger, resolver, from)

7
dnsbl/dnsbl.go
View file

@ -50,7 +50,12 @@ func Lookup(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, zone
start := time.Now()
defer func() {
metricLookup.WithLabelValues(zone.Name(), string(rstatus)).Observe(float64(time.Since(start)) / float64(time.Second))
log.Debugx("dnsbl lookup result", rerr, slog.Any("zone", zone), slog.Any("ip", ip), slog.Any("status", rstatus), slog.String("explanation", rexplanation), slog.Duration("duration", time.Since(start)))
log.Debugx("dnsbl lookup result", rerr,
slog.Any("zone", zone),
slog.Any("ip", ip),
slog.Any("status", rstatus),
slog.String("explanation", rexplanation),
slog.Duration("duration", time.Since(start)))
}()
b := &strings.Builder{}

5
http/gzcache.go
View file

@ -115,7 +115,10 @@ func loadStaticGzipCache(dir string, maxSize int64) {
if err != nil {
pkglog.Infox("removing unusable/unrecognized file in static gzip cache dir", err)
xerr := os.Remove(filepath.Join(dir, name))
pkglog.Check(xerr, "removing unusable file in static gzip cache dir", slog.Any("error", err), slog.String("dir", dir), slog.String("filename", name))
pkglog.Check(xerr, "removing unusable file in static gzip cache dir",
slog.Any("error", err),
slog.String("dir", dir),
slog.String("filename", name))
continue
}
staticgzcache.paths[path] = gzfile{

10
http/web.go
View file

@ -746,7 +746,10 @@ func listen1(ip string, port int, tlsConfig *tls.Config, name string, kinds []st
if tlsConfig == nil {
protocol = "http"
if os.Getuid() == 0 {
pkglog.Print("http listener", slog.String("name", name), slog.String("kinds", strings.Join(kinds, ",")), slog.String("address", addr))
pkglog.Print("http listener",
slog.String("name", name),
slog.String("kinds", strings.Join(kinds, ",")),
slog.String("address", addr))
}
ln, err = mox.Listen(mox.Network(ip), addr)
if err != nil {
@ -755,7 +758,10 @@ func listen1(ip string, port int, tlsConfig *tls.Config, name string, kinds []st
} else {
protocol = "https"
if os.Getuid() == 0 {
pkglog.Print("https listener", slog.String("name", name), slog.String("kinds", strings.Join(kinds, ",")), slog.String("address", addr))
pkglog.Print("https listener",
slog.String("name", name),
slog.String("kinds", strings.Join(kinds, ",")),
slog.String("address", addr))
}
ln, err = mox.Listen(mox.Network(ip), addr)
if err != nil {

11
imapserver/server.go
View file

@ -339,7 +339,10 @@ func listen1(protocol, listenerName, ip string, port int, tlsConfig *tls.Config,
log := mlog.New("imapserver", nil)
addr := net.JoinHostPort(ip, fmt.Sprintf("%d", port))
if os.Getuid() == 0 {
log.Print("listening for imap", slog.String("listener", listenerName), slog.String("addr", addr), slog.String("protocol", protocol))
log.Print("listening for imap",
slog.String("listener", listenerName),
slog.String("addr", addr),
slog.String("protocol", protocol))
}
network := mox.Network(ip)
ln, err := mox.Listen(network, addr)
@ -664,7 +667,11 @@ func serve(listenerName string, cid int64, tlsConfig *tls.Config, nc net.Conn, x
}
}
c.log.Info("new connection", slog.Any("remote", c.conn.RemoteAddr()), slog.Any("local", c.conn.LocalAddr()), slog.Bool("tls", xtls), slog.String("listener", listenerName))
c.log.Info("new connection",
slog.Any("remote", c.conn.RemoteAddr()),
slog.Any("local", c.conn.LocalAddr()),
slog.Bool("tls", xtls),
slog.String("listener", listenerName))
defer func() {
c.conn.Close()

6
import.go
View file

@ -176,7 +176,11 @@ func importctl(ctx context.Context, ctl *ctl, mbox bool) {
if mbox {
kind = "mbox"
}
ctl.log.Info("importing messages", slog.String("kind", kind), slog.String("account", account), slog.String("mailbox", mailbox), slog.String("source", src))
ctl.log.Info("importing messages",
slog.String("kind", kind),
slog.String("account", account),
slog.String("mailbox", mailbox),
slog.String("source", src))
var err error
var mboxf *os.File

5
iprev/iprev.go
View file

@ -63,7 +63,10 @@ func Lookup(ctx context.Context, resolver dns.Resolver, ip net.IP) (rstatus Stat
start := time.Now()
defer func() {
metricIPRev.WithLabelValues(string(rstatus)).Observe(float64(time.Since(start)) / float64(time.Second))
log.Debugx("iprev lookup result", rerr, slog.Any("ip", ip), slog.Any("status", rstatus), slog.Duration("duration", time.Since(start)))
log.Debugx("iprev lookup result", rerr,
slog.Any("ip", ip),
slog.Any("status", rstatus),
slog.Duration("duration", time.Since(start)))
}()
revNames, result, revErr := dns.WithPackage(resolver, "iprev").LookupAddr(ctx, ip.String())

10
junk/filter.go
View file

@ -378,7 +378,10 @@ func (f *Filter) ClassifyWords(ctx context.Context, words map[string]struct{}) (
expect[w] = struct{}{}
}
if len(unknowns) > 0 {
f.log.Debug("unknown words in bloom filter, showing max 50", slog.Any("words", unknowns), slog.Any("totalunknown", totalUnknown), slog.Any("totalwords", len(words)))
f.log.Debug("unknown words in bloom filter, showing max 50",
slog.Any("words", unknowns),
slog.Any("totalunknown", totalUnknown),
slog.Any("totalwords", len(words)))
}
// Fetch words from database.
@ -391,7 +394,10 @@ func (f *Filter) ClassifyWords(ctx context.Context, words map[string]struct{}) (
delete(expect, w)
f.cache[w] = c
}
f.log.Debug("unknown words in db", slog.Any("words", expect), slog.Any("totalunknown", len(expect)), slog.Any("totalwords", len(words)))
f.log.Debug("unknown words in db",
slog.Any("words", expect),
slog.Any("totalunknown", len(expect)),
slog.Any("totalwords", len(words)))
}
for w := range words {

5
message/part.go
View file

@ -330,7 +330,10 @@ func newPart(log mlog.Log, strict bool, r io.ReaderAt, offset int64, parent *Par
p.MediaType = "APPLICATION"
p.MediaSubType = "OCTET-STREAM"
}
log.Debugx("malformed content-type, attempting to recover and continuing", err, slog.String("contenttype", p.header.Get("Content-Type")), slog.String("mediatype", p.MediaType), slog.String("mediasubtype", p.MediaSubType))
log.Debugx("malformed content-type, attempting to recover and continuing", err,
slog.String("contenttype", p.header.Get("Content-Type")),
slog.String("mediatype", p.MediaType),
slog.String("mediasubtype", p.MediaSubType))
} else if mt != "" {
t := strings.SplitN(strings.ToUpper(mt), "/", 2)
if len(t) != 2 {

6
metrics/http.go
View file

@ -57,5 +57,9 @@ func HTTPClientObserve(ctx context.Context, log mlog.Log, pkg, method string, st
result = "error"
}
metricHTTPClient.WithLabelValues(pkg, method, result, fmt.Sprintf("%d", statusCode)).Observe(float64(time.Since(start)) / float64(time.Second))
log.Debugx("httpclient result", err, slog.String("pkg", pkg), slog.String("method", method), slog.Int("code", statusCode), slog.Duration("duration", time.Since(start)))
log.Debugx("httpclient result", err,
slog.String("pkg", pkg),
slog.String("method", method),
slog.Int("code", statusCode),
slog.Duration("duration", time.Since(start)))
}

10
mox-/admin.go
View file

@ -291,7 +291,10 @@ func DomainAdd(ctx context.Context, domain dns.Domain, accountName string, local
log := pkglog.WithContext(ctx)
defer func() {
if rerr != nil {
log.Errorx("adding domain", rerr, slog.Any("domain", domain), slog.String("account", accountName), slog.Any("localpart", localpart))
log.Errorx("adding domain", rerr,
slog.Any("domain", domain),
slog.String("account", accountName),
slog.Any("localpart", localpart))
}
}()
@ -929,7 +932,10 @@ func DestinationSave(ctx context.Context, account, destName string, newDest conf
log := pkglog.WithContext(ctx)
defer func() {
if rerr != nil {
log.Errorx("saving destination", rerr, slog.String("account", account), slog.String("destname", destName), slog.Any("destination", newDest))
log.Errorx("saving destination", rerr,
slog.String("account", account),
slog.String("destname", destName),
slog.Any("destination", newDest))
}
}()

25
mox-/config.go
View file

@ -568,10 +568,16 @@ func PrepareStaticConfig(ctx context.Context, log mlog.Log, configFile string, c
key = findACMEHostPrivateKey(acmeName, host, keyType, 2)
}
if key != nil {
log.Debug("found existing private key for certificate for host", slog.String("acmename", acmeName), slog.String("host", host), slog.Any("keytype", keyType))
log.Debug("found existing private key for certificate for host",
slog.String("acmename", acmeName),
slog.String("host", host),
slog.Any("keytype", keyType))
return key, nil
}
log.Debug("generating new private key for certificate for host", slog.String("acmename", acmeName), slog.String("host", host), slog.Any("keytype", keyType))
log.Debug("generating new private key for certificate for host",
slog.String("acmename", acmeName),
slog.String("host", host),
slog.Any("keytype", keyType))
switch keyType {
case autocert.KeyRSA2048:
return rsa.GenerateKey(cryptorand.Reader, 2048)
@ -657,7 +663,10 @@ func PrepareStaticConfig(ctx context.Context, log mlog.Log, configFile string, c
switch k := privKey.(type) {
case *rsa.PrivateKey:
if k.N.BitLen() != 2048 {
log.Error("need rsa key with 2048 bits, for host private key for DANE/ACME certificates, ignoring", slog.String("listener", name), slog.String("file", keyPath), slog.Int("bits", k.N.BitLen()))
log.Error("need rsa key with 2048 bits, for host private key for DANE/ACME certificates, ignoring",
slog.String("listener", name),
slog.String("file", keyPath),
slog.Int("bits", k.N.BitLen()))
continue
}
l.TLS.HostPrivateRSA2048Keys = append(l.TLS.HostPrivateRSA2048Keys, k)
@ -668,7 +677,10 @@ func PrepareStaticConfig(ctx context.Context, log mlog.Log, configFile string, c
}
l.TLS.HostPrivateECDSAP256Keys = append(l.TLS.HostPrivateECDSAP256Keys, k)
default:
log.Error("unrecognized key type for host private key for DANE/ACME certificates, ignoring", slog.String("listener", name), slog.String("file", keyPath), slog.String("keytype", fmt.Sprintf("%T", privKey)))
log.Error("unrecognized key type for host private key for DANE/ACME certificates, ignoring",
slog.String("listener", name),
slog.String("file", keyPath),
slog.String("keytype", fmt.Sprintf("%T", privKey)))
continue
}
}
@ -1318,7 +1330,10 @@ func prepareDynamicConfig(ctx context.Context, log mlog.Log, dynamicPath string,
if !ok {
addErrorf("could not find localpart %q to replace with address in destinations", lp)
} else {
log.Error(`deprecation warning: support for account destination addresses specified as just localpart ("username") instead of full email address will be removed in the future; update domains.conf, for each Account, for each Destination, ensure each key is an email address by appending "@" and the default domain for the account`, slog.Any("localpart", lp), slog.Any("address", addr), slog.String("account", accName))
log.Error(`deprecation warning: support for account destination addresses specified as just localpart ("username") instead of full email address will be removed in the future; update domains.conf, for each Account, for each Destination, ensure each key is an email address by appending "@" and the default domain for the account`,
slog.Any("localpart", lp),
slog.Any("address", addr),
slog.String("account", accName))
acc.Destinations[addr] = dest
delete(acc.Destinations, lp)
}

17
mtasts/mtasts.go
View file

@ -194,7 +194,10 @@ func LookupRecord(ctx context.Context, elog *slog.Logger, resolver dns.Resolver,
log := mlog.New("mtasts", elog)
start := time.Now()
defer func() {
log.Debugx("mtasts lookup result", rerr, slog.Any("domain", domain), slog.Any("record", rrecord), slog.Duration("duration", time.Since(start)))
log.Debugx("mtasts lookup result", rerr,
slog.Any("domain", domain),
slog.Any("record", rrecord),
slog.Duration("duration", time.Since(start)))
}()
// ../rfc/8461:289
@ -265,7 +268,11 @@ func FetchPolicy(ctx context.Context, elog *slog.Logger, domain dns.Domain) (pol
log := mlog.New("mtasts", elog)
start := time.Now()
defer func() {
log.Debugx("mtasts fetch policy result", rerr, slog.Any("domain", domain), slog.Any("policy", policy), slog.String("policytext", policyText), slog.Duration("duration", time.Since(start)))
log.Debugx("mtasts fetch policy result", rerr,
slog.Any("domain", domain),
slog.Any("policy", policy),
slog.String("policytext", policyText),
slog.Duration("duration", time.Since(start)))
}()
// Timeout of 1 minute. ../rfc/8461:569
@ -335,7 +342,11 @@ func Get(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, domain d
result := "lookuperror"
defer func() {
metricGet.WithLabelValues(result).Observe(float64(time.Since(start)) / float64(time.Second))
log.Debugx("mtasts get result", err, slog.Any("domain", domain), slog.Any("record", record), slog.Any("policy", policy), slog.Duration("duration", time.Since(start)))
log.Debugx("mtasts get result", err,
slog.Any("domain", domain),
slog.Any("record", record),
slog.Any("policy", policy),
slog.Duration("duration", time.Since(start)))
}()
record, _, err = LookupRecord(ctx, log.Logger, resolver, domain)

5
queue/direct.go
View file

@ -293,7 +293,10 @@ func deliverDirect(qlog mlog.Log, resolver dns.Resolver, dialer smtpclient.Diale
}
// todo future: add a configuration option to not fall back?
nqlog.Info("connecting again for delivery attempt without tls", slog.Bool("enforcemtasts", enforceMTASTS), slog.Bool("tlsdane", tlsDANE), slog.Any("requiretls", m.RequireTLS))
nqlog.Info("connecting again for delivery attempt without tls",
slog.Bool("enforcemtasts", enforceMTASTS),
slog.Bool("tlsdane", tlsDANE),
slog.Any("requiretls", m.RequireTLS))
permanent, _, _, secodeOpt, remoteIP, errmsg, _, ok = deliverHost(nqlog, resolver, dialer, ourHostname, transportName, h, enforceMTASTS, haveMX, origNextHopAuthentic, origNextHop, expandedNextHopAuthentic, expandedNextHop, &m, smtpclient.TLSSkip, false, &tlsrpt.Result{})
}

5
queue/queue.go
View file

@ -525,7 +525,10 @@ func queueDelete(ctx context.Context, msgID int64) error {
// The queue is updated, either by removing a delivered or permanently failed
// message, or updating the time for the next attempt. A DSN may be sent.
func deliver(log mlog.Log, resolver dns.Resolver, m Msg) {
qlog := log.WithCid(mox.Cid()).With(slog.Any("from", m.Sender()), slog.Any("recipient", m.Recipient()), slog.Int("attempts", m.Attempts), slog.Int64("msgid", m.ID))
qlog := log.WithCid(mox.Cid()).With(slog.Any("from", m.Sender()),
slog.Any("recipient", m.Recipient()),
slog.Int("attempts", m.Attempts),
slog.Int64("msgid", m.ID))
defer func() {
deliveryResult <- formatIPDomain(m.RecipientDomain)

10
queue/submit.go
View file

@ -54,7 +54,15 @@ func deliverSubmit(qlog mlog.Log, resolver dns.Resolver, dialer smtpclient.Diale
var success bool
defer func() {
metricDelivery.WithLabelValues(fmt.Sprintf("%d", m.Attempts), transportName, string(tlsMode), deliveryResult).Observe(float64(time.Since(start)) / float64(time.Second))
qlog.Debug("queue deliversubmit result", slog.Any("host", transport.DNSHost), slog.Int("port", port), slog.Int("attempt", m.Attempts), slog.Bool("permanent", permanent), slog.String("secodeopt", secodeOpt), slog.String("errmsg", errmsg), slog.Bool("ok", success), slog.Duration("duration", time.Since(start)))
qlog.Debug("queue deliversubmit result",
slog.Any("host", transport.DNSHost),
slog.Int("port", port),
slog.Int("attempt", m.Attempts),
slog.Bool("permanent", permanent),
slog.String("secodeopt", secodeOpt),
slog.String("errmsg", errmsg),
slog.Bool("ok", success),
slog.Duration("duration", time.Since(start)))
}()
// todo: SMTP-DANE should be used when relaying on port 25.

52
serve_unix.go
View file

@ -90,7 +90,11 @@ func monitorDNSBL(log mlog.Log) {
for _, zone := range zones {
status, expl, err := dnsbl.Lookup(mox.Context, log.Logger, resolver, zone, ip)
if err != nil {
log.Errorx("dnsbl monitor lookup", err, slog.Any("ip", ip), slog.Any("zone", zone), slog.String("expl", expl), slog.Any("status", status))
log.Errorx("dnsbl monitor lookup", err,
slog.Any("ip", ip),
slog.Any("zone", zone),
slog.String("expl", expl),
slog.Any("status", status))
}
k := key{zone, ip.String()}
@ -161,7 +165,11 @@ Only implemented on unix systems, not Windows.
domainsconf, err := filepath.Abs(mox.ConfigDynamicPath)
log.Check(err, "finding absolute domains.conf path")
log.Print("starting as root, initializing network listeners", slog.String("version", moxvar.Version), slog.Any("pid", os.Getpid()), slog.String("moxconf", moxconf), slog.String("domainsconf", domainsconf))
log.Print("starting as root, initializing network listeners",
slog.String("version", moxvar.Version),
slog.Any("pid", os.Getpid()),
slog.String("moxconf", moxconf),
slog.String("domainsconf", domainsconf))
if os.Getenv("MOX_SOCKETS") != "" {
log.Fatal("refusing to start as root with $MOX_SOCKETS set")
}
@ -187,7 +195,11 @@ Only implemented on unix systems, not Windows.
} else {
mox.RestorePassedFiles()
mox.MustLoadConfig(true, checkACMEHosts)
log.Print("starting as unprivileged user", slog.String("user", mox.Conf.Static.User), slog.Any("uid", mox.Conf.Static.UID), slog.Any("gid", mox.Conf.Static.GID), slog.Any("pid", os.Getpid()))
log.Print("starting as unprivileged user",
slog.String("user", mox.Conf.Static.User),
slog.Any("uid", mox.Conf.Static.UID),
slog.Any("gid", mox.Conf.Static.GID),
slog.Any("pid", os.Getpid()))
}
syscall.Umask(syscall.Umask(007) | 007)
@ -205,7 +217,10 @@ Only implemented on unix systems, not Windows.
log.Fatalx("writing recvidpath", err, slog.String("path", recvidpath))
}
err := os.Chown(recvidpath, int(mox.Conf.Static.UID), 0)
log.Check(err, "chown receveidid.key", slog.String("path", recvidpath), slog.Any("uid", mox.Conf.Static.UID), slog.Any("gid", 0))
log.Check(err, "chown receveidid.key",
slog.String("path", recvidpath),
slog.Any("uid", mox.Conf.Static.UID),
slog.Any("gid", 0))
err = os.Chmod(recvidpath, 0640)
log.Check(err, "chmod receveidid.key to 0640", slog.String("path", recvidpath))
}
@ -308,7 +323,10 @@ Only implemented on unix systems, not Windows.
log.Errorx("changelog delivery", err)
return next
}
log.Info("delivered changelog", slog.Any("current", current), slog.Any("lastknown", lastknown), slog.Any("latest", latest))
log.Info("delivered changelog",
slog.Any("current", current),
slog.Any("lastknown", lastknown),
slog.Any("latest", latest))
if err := mox.StoreLastKnown(latest); err != nil {
// This will be awkward, we'll keep notifying the postmaster once every 24h...
log.Infox("updating last known version", err)
@ -485,11 +503,19 @@ func fixperms(log mlog.Log, workdir, configdir, datadir string, moxuid, moxgid u
for _, ch := range changes {
if ch.uid != nil {
err := os.Chown(ch.path, int(*ch.uid), int(*ch.gid))
log.Printx("chown, fixing uid/gid", err, slog.String("path", ch.path), slog.Any("olduid", ch.olduid), slog.Any("oldgid", ch.oldgid), slog.Any("newuid", *ch.uid), slog.Any("newgid", *ch.gid))
log.Printx("chown, fixing uid/gid", err,
slog.String("path", ch.path),
slog.Any("olduid", ch.olduid),
slog.Any("oldgid", ch.oldgid),
slog.Any("newuid", *ch.uid),
slog.Any("newgid", *ch.gid))
}
if ch.mode != nil {
err := os.Chmod(ch.path, *ch.mode)
log.Printx("chmod, fixing permissions", err, slog.String("path", ch.path), slog.Any("oldmode", fmt.Sprintf("%03o", ch.oldmode)), slog.Any("newmode", fmt.Sprintf("%03o", *ch.mode)))
log.Printx("chmod, fixing permissions", err,
slog.String("path", ch.path),
slog.Any("oldmode", fmt.Sprintf("%03o", ch.oldmode)),
slog.Any("newmode", fmt.Sprintf("%03o", *ch.mode)))
}
}
@ -511,7 +537,12 @@ func fixperms(log mlog.Log, workdir, configdir, datadir string, moxuid, moxgid u
}
if st.Uid != moxuid || st.Gid != root {
err := os.Chown(path, int(moxuid), root)
log.Printx("walk chown, fixing uid/gid", err, slog.String("path", path), slog.Any("olduid", st.Uid), slog.Any("oldgid", st.Gid), slog.Any("newuid", moxuid), slog.Any("newgid", root))
log.Printx("walk chown, fixing uid/gid", err,
slog.String("path", path),
slog.Any("olduid", st.Uid),
slog.Any("oldgid", st.Gid),
slog.Any("newuid", moxuid),
slog.Any("newgid", root))
}
omode := fi.Mode() & (fs.ModeSetgid | 0777)
var nmode fs.FileMode
@ -522,7 +553,10 @@ func fixperms(log mlog.Log, workdir, configdir, datadir string, moxuid, moxgid u
}
if omode != nmode {
err := os.Chmod(path, nmode)
log.Printx("walk chmod, fixing permissions", err, slog.String("path", path), slog.Any("oldmode", fmt.Sprintf("%03o", omode)), slog.Any("newmode", fmt.Sprintf("%03o", nmode)))
log.Printx("walk chmod, fixing permissions", err,
slog.String("path", path),
slog.Any("oldmode", fmt.Sprintf("%03o", omode)),
slog.Any("newmode", fmt.Sprintf("%03o", nmode)))
}
return nil
})

11
smtpclient/client.go
View file

@ -282,7 +282,10 @@ func New(ctx context.Context, elog *slog.Logger, conn net.Conn, tlsMode TLSMode,
c.tlsResultAdd(1, 0, nil)
c.conn = tlsconn
tlsversion, ciphersuite := mox.TLSInfo(tlsconn)
c.log.Debug("tls client handshake done", slog.String("tls", tlsversion), slog.String("ciphersuite", ciphersuite), slog.Any("servername", remoteHostname))
c.log.Debug("tls client handshake done",
slog.String("tls", tlsversion),
slog.String("ciphersuite", ciphersuite),
slog.Any("servername", remoteHostname))
c.tls = true
} else {
c.conn = conn
@ -545,7 +548,11 @@ func (c *Client) readecode(ecodes bool) (code int, secode, lastLine string, text
}
}
metricCommands.WithLabelValues(cmd, fmt.Sprintf("%d", co), sec).Observe(float64(time.Since(c.cmdStart)) / float64(time.Second))
c.log.Debug("smtpclient command result", slog.String("cmd", cmd), slog.Int("code", co), slog.String("secode", sec), slog.Duration("duration", time.Since(c.cmdStart)))
c.log.Debug("smtpclient command result",
slog.String("cmd", cmd),
slog.Int("code", co),
slog.String("secode", sec),
slog.Duration("duration", time.Since(c.cmdStart)))
}
return co, sec, line, texts, nil
}

10
smtpclient/dial.go
View file

@ -76,12 +76,18 @@ func Dial(ctx context.Context, elog *slog.Logger, dialer Dialer, host dns.IPDoma
}
conn, err := dial(ctx, dialer, timeout, addr, laddr)
if err == nil {
log.Debug("connected to host", slog.Any("host", host), slog.String("addr", addr), slog.Any("laddr", laddr))
log.Debug("connected to host",
slog.Any("host", host),
slog.String("addr", addr),
slog.Any("laddr", laddr))
name := host.String()
dialedIPs[name] = append(dialedIPs[name], ip)
return conn, ip, nil
}
log.Debugx("connection attempt", err, slog.Any("host", host), slog.String("addr", addr), slog.Any("laddr", laddr))
log.Debugx("connection attempt", err,
slog.Any("host", host),
slog.String("addr", addr),
slog.Any("laddr", laddr))
lastErr = err
lastIP = ip
}

10
smtpclient/gather.go
View file

@ -301,7 +301,10 @@ func GatherTLSA(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, h
}
daneRequired = len(l) > 0
l = filterUsableTLSARecords(log, l)
log.Debug("tlsa records exist", slog.Bool("danerequired", daneRequired), slog.Any("records", l), slog.Any("basedomain", tlsaBaseDomain))
log.Debug("tlsa records exist",
slog.Bool("danerequired", daneRequired),
slog.Any("records", l),
slog.Any("basedomain", tlsaBaseDomain))
return daneRequired, l, tlsaBaseDomain, err
}
@ -333,7 +336,10 @@ func lookupTLSACNAME(ctx context.Context, log mlog.Log, resolver dns.Resolver, p
var err error
l, result, err = resolver.LookupTLSA(ctx, 0, "", name)
if dns.IsNotFound(err) || err == nil && len(l) == 0 {
log.Debugx("no tlsa records for host, not doing dane", err, slog.Any("host", host), slog.String("name", name), slog.Bool("authentic", result.Authentic))
log.Debugx("no tlsa records for host, not doing dane", err,
slog.Any("host", host),
slog.String("name", name),
slog.Bool("authentic", result.Authentic))
return nil, nil
} else if err != nil {
return nil, fmt.Errorf("looking up tlsa records for tlsa candidate base domain: %w", err)

10
smtpserver/analyze.go
View file

@ -302,7 +302,10 @@ func analyze(ctx context.Context, log mlog.Log, resolver dns.Resolver, d deliver
log.Infox("determining reputation", err, slog.Any("message", d.m))
return reject(smtp.C451LocalErr, smtp.SeSys3Other0, "error processing", err, reasonReputationError)
}
log.Info("reputation analyzed", slog.Bool("conclusive", conclusive), slog.Any("isjunk", isjunk), slog.String("method", string(method)))
log.Info("reputation analyzed",
slog.Bool("conclusive", conclusive),
slog.Any("isjunk", isjunk),
slog.String("method", string(method)))
if conclusive {
if !*isjunk {
return analysis{accept: true, mailbox: mailbox, dmarcReport: dmarcReport, tlsReport: tlsReport, reason: reason, dmarcOverrideReason: dmarcOverrideReason, headers: headers}
@ -414,7 +417,10 @@ func analyze(ctx context.Context, log mlog.Log, resolver dns.Resolver, d deliver
}
accept = contentProb <= threshold
junkSubjectpass = contentProb < threshold-0.2
log.Info("content analyzed", slog.Bool("accept", accept), slog.Float64("contentprob", contentProb), slog.Bool("subjectpass", junkSubjectpass))
log.Info("content analyzed",
slog.Bool("accept", accept),
slog.Float64("contentprob", contentProb),
slog.Bool("subjectpass", junkSubjectpass))
} else if err != store.ErrNoJunkFilter {
log.Errorx("open junkfilter", err)
return reject(smtp.C451LocalErr, smtp.SeSys3Other0, "error processing", err, reasonJunkFilterError)

5
smtpserver/reputation.go
View file

@ -143,7 +143,10 @@ func reputation(tx *bstore.Tx, log mlog.Log, m *store.Message) (rjunk *bool, rco
xmessageList := func(q *bstore.Query[store.Message], descr string) []store.Message {
t0 := time.Now()
l, err := q.List()
log.Debugx("querying messages for reputation", err, slog.Int("msgs", len(l)), slog.String("descr", descr), slog.Duration("queryduration", time.Since(t0)))
log.Debugx("querying messages for reputation", err,
slog.Int("msgs", len(l)),
slog.String("descr", descr),
slog.Duration("queryduration", time.Since(t0)))
if err != nil {
panic(queryError(fmt.Sprintf("listing messages: %v", err)))
}

40
smtpserver/server.go
View file

@ -233,7 +233,10 @@ func listen1(protocol, name, ip string, port int, hostname dns.Domain, tlsConfig
log := mlog.New("smtpserver", nil)
addr := net.JoinHostPort(ip, fmt.Sprintf("%d", port))
if os.Getuid() == 0 {
log.Print("listening for smtp", slog.String("listener", name), slog.String("address", addr), slog.String("protocol", protocol))
log.Print("listening for smtp",
slog.String("listener", name),
slog.String("address", addr),
slog.String("protocol", protocol))
}
network := mox.Network(ip)
ln, err := mox.Listen(network, addr)
@ -476,7 +479,12 @@ func (c *conn) bwritecodeline(code int, secode string, msg string, err error) {
ecode = fmt.Sprintf("%d.%s", code/100, secode)
}
metricCommands.WithLabelValues(c.kind(), c.cmd, fmt.Sprintf("%d", code), ecode).Observe(float64(time.Since(c.cmdStart)) / float64(time.Second))
c.log.Debugx("smtp command result", err, slog.String("kind", c.kind()), slog.String("cmd", c.cmd), slog.Int("code", code), slog.String("ecode", ecode), slog.Duration("duration", time.Since(c.cmdStart)))
c.log.Debugx("smtp command result", err,
slog.String("kind", c.kind()),
slog.String("cmd", c.cmd),
slog.Int("code", code),
slog.String("ecode", ecode),
slog.Duration("duration", time.Since(c.cmdStart)))
var sep string
if ecode != "" {
@ -584,7 +592,12 @@ func serve(listenerName string, cid int64, hostname dns.Domain, tlsConfig *tls.C
c.w = bufio.NewWriter(c.tw)
metricConnection.WithLabelValues(c.kind()).Inc()
c.log.Info("new connection", slog.Any("remote", c.conn.RemoteAddr()), slog.Any("local", c.conn.LocalAddr()), slog.Bool("submission", submission), slog.Bool("tls", tls), slog.String("listener", listenerName))
c.log.Info("new connection",
slog.Any("remote", c.conn.RemoteAddr()),
slog.Any("local", c.conn.LocalAddr()),
slog.Bool("submission", submission),
slog.Bool("tls", tls),
slog.String("listener", listenerName))
defer func() {
c.origConn.Close() // Close actual TCP socket, regardless of TLS on top.
@ -1897,7 +1910,11 @@ func (c *conn) submit(ctx context.Context, recvHdrFor func(string) string, msgWr
xsmtpServerErrorf(errCodes(smtp.C451LocalErr, smtp.SeSys3Other0, err), "error delivering message: %v", err)
}
metricSubmission.WithLabelValues("ok").Inc()
c.log.Info("message queued for delivery", slog.Any("mailfrom", *c.mailFrom), slog.Any("rcptto", rcptAcc.rcptTo), slog.Bool("smtputf8", c.smtputf8), slog.Int64("msgsize", msgSize))
c.log.Info("message queued for delivery",
slog.Any("mailfrom", *c.mailFrom),
slog.Any("rcptto", rcptAcc.rcptTo),
slog.Bool("smtputf8", c.smtputf8),
slog.Int64("msgsize", msgSize))
err := c.account.DB.Insert(ctx, &store.Outgoing{Recipient: rcptAcc.rcptTo.XString(true)})
xcheckf(err, "adding outgoing message")
@ -2150,7 +2167,13 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
errmsg = r.Err.Error()
}
authResAddDKIM(string(r.Status), comment, errmsg, props)
c.log.Debugx("dkim verification result", r.Err, slog.Int("index", i), slog.Any("mailfrom", c.mailFrom), slog.Any("status", r.Status), slog.Any("domain", domain), slog.Any("selector", selector), slog.Any("identity", identity))
c.log.Debugx("dkim verification result", r.Err,
slog.Int("index", i),
slog.Any("mailfrom", c.mailFrom),
slog.Any("status", r.Status),
slog.Any("domain", domain),
slog.Any("selector", selector),
slog.Any("identity", identity))
}
// Add SPF results to Authentication-Results header. ../rfc/7208:2141
@ -2307,7 +2330,12 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
var deliverErrors []deliverError
addError := func(rcptAcc rcptAccount, code int, secode string, userError bool, errmsg string) {
e := deliverError{rcptAcc.rcptTo, code, secode, userError, errmsg}
c.log.Info("deliver error", slog.Any("rcptto", e.rcptTo), slog.Int("code", code), slog.String("secode", "secode"), slog.Bool("usererror", userError), slog.String("errmsg", errmsg))
c.log.Info("deliver error",
slog.Any("rcptto", e.rcptTo),
slog.Int("code", code),
slog.String("secode", "secode"),
slog.Bool("usererror", userError),
slog.String("errmsg", errmsg))
deliverErrors = append(deliverErrors, e)
}

22
spf/spf.go
View file

@ -133,7 +133,11 @@ func Lookup(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, domai
log := mlog.New("spf", elog)
start := time.Now()
defer func() {
log.Debugx("spf lookup result", rerr, slog.Any("domain", domain), slog.Any("status", rstatus), slog.Any("record", rrecord), slog.Duration("duration", time.Since(start)))
log.Debugx("spf lookup result", rerr,
slog.Any("domain", domain),
slog.Any("status", rstatus),
slog.Any("record", rrecord),
slog.Duration("duration", time.Since(start)))
}()
// ../rfc/7208:586
@ -199,7 +203,12 @@ func Verify(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, args
start := time.Now()
defer func() {
metricSPFVerify.WithLabelValues(string(received.Result)).Observe(float64(time.Since(start)) / float64(time.Second))
log.Debugx("spf verify result", rerr, slog.Any("domain", args.domain), slog.Any("ip", args.RemoteIP), slog.Any("status", received.Result), slog.String("explanation", explanation), slog.Duration("duration", time.Since(start)))
log.Debugx("spf verify result", rerr,
slog.Any("domain", args.domain),
slog.Any("ip", args.RemoteIP),
slog.Any("status", received.Result),
slog.String("explanation", explanation),
slog.Duration("duration", time.Since(start)))
}()
isHello, ok := prepare(&args)
@ -298,7 +307,14 @@ func Evaluate(ctx context.Context, elog *slog.Logger, record *Record, resolver d
func evaluate(ctx context.Context, log mlog.Log, record *Record, resolver dns.Resolver, args Args) (rstatus Status, mechanism, rexplanation string, rauthentic bool, rerr error) {
start := time.Now()
defer func() {
log.Debugx("spf evaluate result", rerr, slog.Int("dnsrequests", *args.dnsRequests), slog.Int("voidlookups", *args.voidLookups), slog.Any("domain", args.domain), slog.Any("status", rstatus), slog.String("mechanism", mechanism), slog.String("explanation", rexplanation), slog.Duration("duration", time.Since(start)))
log.Debugx("spf evaluate result", rerr,
slog.Int("dnsrequests", *args.dnsRequests),
slog.Int("voidlookups", *args.voidLookups),
slog.Any("domain", args.domain),
slog.Any("status", rstatus),
slog.String("mechanism", mechanism),
slog.String("explanation", rexplanation),
slog.Duration("duration", time.Since(start)))
}()
if args.dnsRequests == nil {

6
store/train.go
View file

@ -98,7 +98,11 @@ func (a *Account) RetrainMessage(ctx context.Context, log mlog.Log, tx *bstore.T
return nil
}
log.Debug("updating junk filter", slog.Bool("untrain", untrain), slog.Bool("untrainjunk", untrainJunk), slog.Bool("train", train), slog.Bool("trainjunk", trainJunk))
log.Debug("updating junk filter",
slog.Bool("untrain", untrain),
slog.Bool("untrainjunk", untrainJunk),
slog.Bool("train", train),
slog.Bool("trainjunk", trainJunk))
mr := a.MessageReader(*m)
defer func() {

5
tlsrpt/lookup.go
View file

@ -54,7 +54,10 @@ func Lookup(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, domai
}
}
metricLookup.WithLabelValues(result).Observe(float64(time.Since(start)) / float64(time.Second))
log.Debugx("tlsrpt lookup result", rerr, slog.Any("domain", domain), slog.Any("record", rrecord), slog.Duration("duration", time.Since(start)))
log.Debugx("tlsrpt lookup result", rerr,
slog.Any("domain", domain),
slog.Any("record", rrecord),
slog.Duration("duration", time.Since(start)))
}()
name := "_smtp._tls." + domain.ASCII + "."

4
tlsrptsend/send.go
View file

@ -236,7 +236,9 @@ func sendReports(ctx context.Context, log mlog.Log, resolver dns.Resolver, db *b
}()
defer wg.Done()
rlog := log.WithCid(mox.Cid()).With(slog.String("policydomain", k.policyDomain), slog.String("daytutc", k.dayUTC), slog.Bool("isrcptdom", isRcptDom))
rlog := log.WithCid(mox.Cid()).With(slog.String("policydomain", k.policyDomain),
slog.String("daytutc", k.dayUTC),
slog.Bool("isrcptdom", isRcptDom))
rlog.Info("looking to send tls report for domain")
cleanup, err := sendReportDomain(ctx, rlog, resolver, db, endTimeUTC, isRcptDom, k.policyDomain, k.dayUTC)
if err != nil {

19
updates/updates.go
View file

@ -90,7 +90,11 @@ func Lookup(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, domai
result = "error"
}
metricLookup.WithLabelValues(result).Observe(float64(time.Since(start)) / float64(time.Second))
log.Debugx("updates lookup result", rerr, slog.Any("domain", domain), slog.Any("version", rversion), slog.Any("record", rrecord), slog.Duration("duration", time.Since(start)))
log.Debugx("updates lookup result", rerr,
slog.Any("domain", domain),
slog.Any("version", rversion),
slog.Any("record", rrecord),
slog.Duration("duration", time.Since(start)))
}()
nctx, cancel := context.WithTimeout(ctx, 30*time.Second)
@ -141,7 +145,10 @@ func FetchChangelog(ctx context.Context, elog *slog.Logger, baseURL string, base
result = "error"
}
metricFetchChangelog.WithLabelValues(result).Observe(float64(time.Since(start)) / float64(time.Second))
log.Debugx("updates fetch changelog result", rerr, slog.String("baseurl", baseURL), slog.Any("base", base), slog.Duration("duration", time.Since(start)))
log.Debugx("updates fetch changelog result", rerr,
slog.String("baseurl", baseURL),
slog.Any("base", base),
slog.Duration("duration", time.Since(start)))
}()
url := baseURL + "?from=" + base.String()
@ -186,7 +193,13 @@ func Check(ctx context.Context, elog *slog.Logger, resolver dns.Resolver, domain
log := mlog.New("updates", elog)
start := time.Now()
defer func() {
log.Debugx("updates check result", rerr, slog.Any("domain", domain), slog.Any("lastknown", lastKnown), slog.String("changelogbaseurl", changelogBaseURL), slog.Any("version", rversion), slog.Any("record", rrecord), slog.Duration("duration", time.Since(start)))
log.Debugx("updates check result", rerr,
slog.Any("domain", domain),
slog.Any("lastknown", lastKnown),
slog.String("changelogbaseurl", changelogBaseURL),
slog.Any("version", rversion),
slog.Any("record", rrecord),
slog.Duration("duration", time.Since(start)))
}()
latest, record, err := Lookup(ctx, log.Logger, resolver, domain)