change some log levels from info to debug, and use lower case log messages

This commit is contained in:
Mechiel Lukkien 2023-02-11 23:54:22 +01:00
parent bf04fb8a1a
commit 87854cfde3
No known key found for this signature in database
6 changed files with 16 additions and 16 deletions

View file

@ -1519,7 +1519,7 @@ func (c *conn) cmdAuthenticate(tag, cmd string, p *parser) {
xsyntaxErrorf("malformed cram-md5 response") xsyntaxErrorf("malformed cram-md5 response")
} }
addr := t[0] addr := t[0]
c.log.Info("cram-md5 auth", mlog.Field("address", addr)) c.log.Debug("cram-md5 auth", mlog.Field("address", addr))
acc, _, err := store.OpenEmail(addr) acc, _, err := store.OpenEmail(addr)
if err != nil { if err != nil {
if errors.Is(err, store.ErrUnknownCredentials) { if errors.Is(err, store.ErrUnknownCredentials) {
@ -1586,7 +1586,7 @@ func (c *conn) cmdAuthenticate(tag, cmd string, p *parser) {
if err != nil { if err != nil {
xsyntaxErrorf("starting scram: %w", err) xsyntaxErrorf("starting scram: %w", err)
} }
c.log.Info("scram auth", mlog.Field("authentication", ss.Authentication)) c.log.Debug("scram auth", mlog.Field("authentication", ss.Authentication))
acc, _, err := store.OpenEmail(ss.Authentication) acc, _, err := store.OpenEmail(ss.Authentication)
if err != nil { if err != nil {
// todo: we could continue scram with a generated salt, deterministically generated // todo: we could continue scram with a generated salt, deterministically generated

View file

@ -255,7 +255,7 @@ func (f *Filter) Save() error {
return words[i] < words[j] return words[i] < words[j]
}) })
f.log.Info("inserting words in junkfilter db", mlog.Field("words", len(f.changed))) f.log.Debug("inserting words in junkfilter db", mlog.Field("words", len(f.changed)))
// start := time.Now() // start := time.Now()
if f.isNew { if f.isNew {
if err := f.db.HintAppend(true, wordscore{}); err != nil { if err := f.db.HintAppend(true, wordscore{}); err != nil {

View file

@ -568,7 +568,7 @@ func deliver(resolver dns.Resolver, m Msg) {
if !ok && badTLS && tlsMode == smtpclient.TLSOpportunistic { if !ok && badTLS && tlsMode == smtpclient.TLSOpportunistic {
// In case of failure with opportunistic TLS, try again without TLS. ../rfc/7435:459 // In case of failure with opportunistic TLS, try again without TLS. ../rfc/7435:459
// todo future: revisit this decision. perhaps it should be a configuration option that defaults to not doing this? // todo future: revisit this decision. perhaps it should be a configuration option that defaults to not doing this?
nqlog.Info("connecting again for delivery attempt without TLS") nqlog.Info("connecting again for delivery attempt without tls")
permanent, badTLS, secodeOpt, remoteIP, errmsg, ok = deliverHost(nqlog, resolver, cid, h, &m, smtpclient.TLSSkip) permanent, badTLS, secodeOpt, remoteIP, errmsg, ok = deliverHost(nqlog, resolver, cid, h, &m, smtpclient.TLSSkip)
} }
if ok { if ok {

View file

@ -98,7 +98,7 @@ func analyze(ctx context.Context, log *mlog.Log, resolver dns.Resolver, d delive
if d.rcptAcc.destination.DMARCReports { if d.rcptAcc.destination.DMARCReports {
// Messages with DMARC aggregate reports must have a dmarc pass. ../rfc/7489:1866 // Messages with DMARC aggregate reports must have a dmarc pass. ../rfc/7489:1866
if d.dmarcResult.Status != dmarc.StatusPass { if d.dmarcResult.Status != dmarc.StatusPass {
log.Info("received DMARC report without DMARC pass, not processing as DMARC report") log.Info("received dmarc report without dmarc pass, not processing as dmarc report")
} else if report, err := dmarcrpt.ParseMessageReport(store.FileMsgReader(d.m.MsgPrefix, d.dataFile)); err != nil { } else if report, err := dmarcrpt.ParseMessageReport(store.FileMsgReader(d.m.MsgPrefix, d.dataFile)); err != nil {
log.Infox("parsing dmarc report", err) log.Infox("parsing dmarc report", err)
} else if d, err := dns.ParseDomain(report.PolicyPublished.Domain); err != nil { } else if d, err := dns.ParseDomain(report.PolicyPublished.Domain); err != nil {
@ -130,22 +130,22 @@ func analyze(ctx context.Context, log *mlog.Log, resolver dns.Resolver, d delive
} }
if !ok { if !ok {
log.Info("received mail to TLSRPT without acceptable DKIM signature, not processing as TLSRPT") log.Info("received mail to tlsrpt without acceptable DKIM signature, not processing as tls report")
} else if report, err := tlsrpt.ParseMessage(store.FileMsgReader(d.m.MsgPrefix, d.dataFile)); err != nil { } else if report, err := tlsrpt.ParseMessage(store.FileMsgReader(d.m.MsgPrefix, d.dataFile)); err != nil {
log.Infox("parsing TLSRPT report", err) log.Infox("parsing tls report", err)
} else { } else {
var known bool var known bool
for _, p := range report.Policies { for _, p := range report.Policies {
log.Info("tlsrpt policy domain", mlog.Field("domain", p.Policy.Domain)) log.Info("tlsrpt policy domain", mlog.Field("domain", p.Policy.Domain))
if d, err := dns.ParseDomain(p.Policy.Domain); err != nil { if d, err := dns.ParseDomain(p.Policy.Domain); err != nil {
log.Infox("parsing domain in TLSRPT report", err) log.Infox("parsing domain in tls report", err)
} else if _, ok := mox.Conf.Domain(d); ok { } else if _, ok := mox.Conf.Domain(d); ok {
known = true known = true
break break
} }
} }
if !known { if !known {
log.Info("TLSRPT report without one of configured domains, ignoring") log.Info("tls report without one of configured domains, ignoring")
} else { } else {
tlsReport = report tlsReport = report
} }

View file

@ -985,7 +985,7 @@ func (c *conn) cmdAuth(p *parser) {
xsmtpUserErrorf(smtp.C501BadParamSyntax, smtp.SeProto5BadParams4, "malformed cram-md5 response") xsmtpUserErrorf(smtp.C501BadParamSyntax, smtp.SeProto5BadParams4, "malformed cram-md5 response")
} }
addr := t[0] addr := t[0]
c.log.Info("cram-md5 auth", mlog.Field("address", addr)) c.log.Debug("cram-md5 auth", mlog.Field("address", addr))
acc, _, err := store.OpenEmail(addr) acc, _, err := store.OpenEmail(addr)
if err != nil { if err != nil {
if errors.Is(err, store.ErrUnknownCredentials) { if errors.Is(err, store.ErrUnknownCredentials) {
@ -1057,7 +1057,7 @@ func (c *conn) cmdAuth(p *parser) {
c0 := xreadInitial() c0 := xreadInitial()
ss, err := scram.NewServer(h, c0) ss, err := scram.NewServer(h, c0)
xcheckf(err, "starting scram") xcheckf(err, "starting scram")
c.log.Info("scram auth", mlog.Field("authentication", ss.Authentication)) c.log.Debug("scram auth", mlog.Field("authentication", ss.Authentication))
acc, _, err := store.OpenEmail(ss.Authentication) acc, _, err := store.OpenEmail(ss.Authentication)
if err != nil { if err != nil {
// todo: we could continue scram with a generated salt, deterministically generated // todo: we could continue scram with a generated salt, deterministically generated
@ -1500,7 +1500,7 @@ func (c *conn) cmdData(p *parser) {
if err != nil { if err != nil {
c.log.Infox("reverse-forward lookup", err, mlog.Field("remoteip", c.remoteIP)) c.log.Infox("reverse-forward lookup", err, mlog.Field("remoteip", c.remoteIP))
} }
c.log.Info("dns iprev check", mlog.Field("addr", c.remoteIP), mlog.Field("status", iprevStatus)) c.log.Debug("dns iprev check", mlog.Field("addr", c.remoteIP), mlog.Field("status", iprevStatus))
var name string var name string
if revName != "" { if revName != "" {
name = revName name = revName
@ -1804,7 +1804,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
c.log.Errorx("dkim verify", dkimErr) c.log.Errorx("dkim verify", dkimErr)
authResAddDKIM("none", "", dkimErr.Error(), nil) authResAddDKIM("none", "", dkimErr.Error(), nil)
} else if len(dkimResults) == 0 { } else if len(dkimResults) == 0 {
c.log.Info("dkim verify: no dkim-signature header", mlog.Field("mailfrom", c.mailFrom)) c.log.Info("no dkim-signature header", mlog.Field("mailfrom", c.mailFrom))
authResAddDKIM("none", "", "no dkim signatures", nil) authResAddDKIM("none", "", "no dkim signatures", nil)
} }
for i, r := range dkimResults { for i, r := range dkimResults {
@ -1868,7 +1868,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
}) })
switch receivedSPF.Result { switch receivedSPF.Result {
case spf.StatusPass: case spf.StatusPass:
c.log.Info("spf pass", mlog.Field("ip", spfArgs.RemoteIP), mlog.Field("mailfromDomain", spfArgs.MailFromDomain.ASCII)) // todo: log the domain that was actually verified. c.log.Debug("spf pass", mlog.Field("ip", spfArgs.RemoteIP), mlog.Field("mailfromDomain", spfArgs.MailFromDomain.ASCII)) // todo: log the domain that was actually verified.
case spf.StatusFail: case spf.StatusFail:
if spfExpl != "" { if spfExpl != "" {
// Filter out potentially hostile text. ../rfc/7208:2529 // Filter out potentially hostile text. ../rfc/7208:2529
@ -1934,7 +1934,7 @@ func (c *conn) deliver(ctx context.Context, recvHdrFor func(string) string, msgW
// todo future: consider enforcing an spf fail if there is no dmarc policy or the dmarc policy is none. ../rfc/7489:1507 // todo future: consider enforcing an spf fail if there is no dmarc policy or the dmarc policy is none. ../rfc/7489:1507
} }
authResults.Methods = append(authResults.Methods, dmarcMethod) authResults.Methods = append(authResults.Methods, dmarcMethod)
c.log.Info("dmarc verification", mlog.Field("result", dmarcResult.Status), mlog.Field("domain", msgFrom.Domain)) c.log.Debug("dmarc verification", mlog.Field("result", dmarcResult.Status), mlog.Field("domain", msgFrom.Domain))
// Prepare for analyzing content, calculating reputation. // Prepare for analyzing content, calculating reputation.
var ipmasked1, ipmasked2, ipmasked3 string var ipmasked1, ipmasked2, ipmasked3 string

View file

@ -92,7 +92,7 @@ func (a *Account) RetrainMessage(log *mlog.Log, tx *bstore.Tx, jf *junk.Filter,
return nil return nil
} }
log.Info("updating junk filter", mlog.Field("untrain", untrain), mlog.Field("untrainJunk", untrainJunk), mlog.Field("train", train), mlog.Field("trainJunk", trainJunk)) log.Debug("updating junk filter", mlog.Field("untrain", untrain), mlog.Field("untrainJunk", untrainJunk), mlog.Field("train", train), mlog.Field("trainJunk", trainJunk))
mr := a.MessageReader(*m) mr := a.MessageReader(*m)
defer mr.Close() defer mr.Close()