Rework how error inspection and logging is done

Previous error reporting code was inconsistent in terms of what is
logged, when and by whom. This caused several problems such as: logs
missing important error context, duplicated error messages, too verbose
messages, etc.

Instead of logging all generated errors, module should log
only errors it 'handles' somehow and does not simply pass it to the
caller. This removes duplication, however, also it removes context
information. To fix this, exterrors package was extended to provide
utilities for error wrapping. These utilities provide ability to
'attach' arbitrary key-value ('fields') pairs to any error object while
preserving the original value (using to Go 1.13 error handling
primitives).

In additional to solving problems described above this commit makes logs
machine-readable, creating the possibility for automated analysis.
Three new functions were added to the Logger object, providing
loosely-typed structured logging. However, they do not completely
replace plain logging and are used only where they are useful (to allow
automated analysis of message processing logs).

So, basically, instead of being logged god knows where and when,
all context information is attached to the error object and then it is
passed up until it is handled somewhere, at this point it is logged
together with all context information and then discarded.

HACKING.md

@@ -76,22 +76,4 @@ definition represent "inline arguments". They are passed to the module instance
 directly and not used anyhow by other code (i.e. they are not guaranteed to be
 unique).
 
-### A word on error logging
-
-Shortly put, it is a module's responsibility to log errors it generated since it
-is assumed it can provide all useful details about possible causes.
-
-Modules should not log errors received from other modules. However, it is 
-fine to log decisions made based on these errors.
-
-This does not apply to "debug log", anything can be logged using it if it is
-considered useful for troubleshooting.
-
-Here is the example: remote module logs all errors received from the remote
-server and passes them to the caller. Queue module only logs whether delivery to
-the certain recipient is permanently failed or it will be retried. When used
-together, remote module will provide logs about concrete errors happened and
-queue module will provide information about tries made and scheduled to be made
-in the future.
-
 [1]: https://github.com/foxcpp/maddy/wiki/Dev:-Comments-on-design

auth/shadow/module.go

@@ -74,18 +74,18 @@ func (a *Auth) CheckPlain(username, password string) bool {
 	ent, err := Lookup(username)
 	if err != nil {
 		if err != ErrNoSuchUser {
-			a.Log.Printf("%v, username = %s", err, username)
+			a.Log.Error("lookup error", err, "username", username)
 		}
 		return false
 	}
 
 	if !ent.IsAccountValid() {
-		a.Log.Printf("account is expired, username = %s", username)
+		a.Log.Msg("account is expired", "username", username)
 		return false
 	}
 
 	if !ent.IsPasswordValid() {
-		a.Log.Printf("password is expired, username = %s", username)
+		a.Log.Msg("password is expired", "username", username)
 		return false
 	}
 
@@ -93,7 +93,7 @@ func (a *Auth) CheckPlain(username, password string) bool {
 		if err != ErrWrongPassword {
 			a.Log.Printf("%v", err)
 		}
-		a.Log.Debugf("password verification failed, username = %s", username)
+		a.Log.Msg("password verification failed", "username", username)
 		return false
 	}
 

check/action.go

@@ -35,13 +35,11 @@ func FailActionDirective(m *config.Map, node *config.Node) (interface{}, error)
 // Apply merges the result of check execution with action configuration specified
 // in the check configuration.
 func (cfa FailAction) Apply(originalRes module.CheckResult) module.CheckResult {
-	if originalRes.RejectErr == nil {
+	if originalRes.Reason == nil {
 		return originalRes
 	}
 
 	originalRes.Quarantine = cfa.Quarantine || originalRes.Quarantine
-	if !cfa.Reject {
+	originalRes.Reject = cfa.Reject || originalRes.Reject
-		originalRes.RejectErr = nil
-	}
 	return originalRes
 }

check/dkim/dkim.go

@@ -10,10 +10,10 @@ import (
 	"github.com/emersion/go-message/textproto"
 	"github.com/emersion/go-msgauth/authres"
 	"github.com/emersion/go-msgauth/dkim"
-	"github.com/emersion/go-smtp"
 	"github.com/foxcpp/maddy/buffer"
 	"github.com/foxcpp/maddy/check"
 	"github.com/foxcpp/maddy/config"
+	"github.com/foxcpp/maddy/exterrors"
 	"github.com/foxcpp/maddy/log"
 	"github.com/foxcpp/maddy/module"
 	"github.com/foxcpp/maddy/target"
@@ -100,10 +100,11 @@ func (d dkimCheckState) CheckBody(header textproto.Header, body buffer.Buffer) m
 			d.log.Debugf("no signatures present")
 		}
 		return d.c.noSigAction.Apply(module.CheckResult{
-			RejectErr: &smtp.SMTPError{
+			Reason: &exterrors.SMTPError{
 				Code:         550,
-				EnhancedCode: smtp.EnhancedCode{5, 7, 20},
+				EnhancedCode: exterrors.EnhancedCode{5, 7, 20},
-				Message:      "No DKIM signatures present",
+				Message:      "No DKIM signatures",
+				CheckName:    "verify_dkim",
 			},
 			AuthResult: []authres.Result{
 				&authres.DKIMResult{
@@ -119,9 +120,8 @@ func (d dkimCheckState) CheckBody(header textproto.Header, body buffer.Buffer) m
 	textproto.WriteHeader(&b, header)
 	bodyRdr, err := body.Open()
 	if err != nil {
-		d.log.Println("can't open body:", err)
 		return module.CheckResult{
-			RejectErr: err,
+			Reason: exterrors.WithFields(err, map[string]interface{}{"check": "verify_dkim"}),
 			AuthResult: []authres.Result{
 				&authres.DKIMResult{
 					Value:  authres.ResultPermError,
@@ -133,9 +133,8 @@ func (d dkimCheckState) CheckBody(header textproto.Header, body buffer.Buffer) m
 
 	verifications, err := dkim.Verify(io.MultiReader(&b, bodyRdr))
 	if err != nil {
-		d.log.Println("unexpected verification fail:", err)
 		return module.CheckResult{
-			RejectErr: err,
+			Reason: exterrors.WithFields(err, map[string]interface{}{"check": "verify_dkim"}),
 			AuthResult: []authres.Result{
 				&authres.DKIMResult{
 					Value:  authres.ResultPermError,
@@ -154,7 +153,7 @@ func (d dkimCheckState) CheckBody(header textproto.Header, body buffer.Buffer) m
 		if verif.Err != nil {
 			val = authres.ResultFail
 			reason = strings.TrimPrefix(verif.Err.Error(), "dkim: ")
-			d.log.Printf("%v (domain = %s, identifier = %s)", reason, verif.Domain, verif.Identifier)
+			d.log.DebugMsg("bad signature", "domain", verif.Domain, "identifier", verif.Identifier)
 			if dkim.IsPermFail(err) {
 				val = authres.ResultPermError
 			}
@@ -172,7 +171,7 @@ func (d dkimCheckState) CheckBody(header textproto.Header, body buffer.Buffer) m
 		}
 
 		goodSigs = true
-		d.log.Debugf("good signature from %s (%s)", verif.Domain, verif.Identifier)
+		d.log.DebugMsg("good signature", "domain", verif.Domain, "identifier", verif.Identifier)
 
 		signedFields := make(map[string]struct{}, len(verif.HeaderKeys))
 		for _, field := range verif.HeaderKeys {
@@ -199,11 +198,21 @@ func (d dkimCheckState) CheckBody(header textproto.Header, body buffer.Buffer) m
 	}
 
 	if !goodSigs {
+		res.Reason = &exterrors.SMTPError{
+			Code:         550,
+			EnhancedCode: exterrors.EnhancedCode{5, 7, 20},
+			Message:      "No passing DKIM signatures",
+			CheckName:    "verify_dkim",
+		}
 		return d.c.brokenSigAction.Apply(res)
 	}
 	return res
 }
 
+func (d dkimCheckState) Name() string {
+	return "verify_dkim"
+}
+
 func (d dkimCheckState) Close() error {
 	return nil
 }

check/dns/dns.go

@@ -5,9 +5,9 @@ import (
 	"net"
 	"strings"
 
-	"github.com/emersion/go-smtp"
 	"github.com/foxcpp/maddy/address"
 	"github.com/foxcpp/maddy/check"
+	"github.com/foxcpp/maddy/exterrors"
 	"github.com/foxcpp/maddy/log"
 	"github.com/foxcpp/maddy/module"
 )
@@ -15,18 +15,19 @@ import (
 func requireMatchingRDNS(ctx check.StatelessCheckContext) module.CheckResult {
 	tcpAddr, ok := ctx.MsgMeta.SrcAddr.(*net.TCPAddr)
 	if !ok {
-		log.Debugf("non TCP/IP source (%v), skipped", ctx.MsgMeta.SrcAddr)
+		log.Debugf("non TCP/IP source, skipped")
 		return module.CheckResult{}
 	}
 
 	names, err := ctx.Resolver.LookupAddr(context.Background(), tcpAddr.IP.String())
 	if err != nil || len(names) == 0 {
-		ctx.Logger.Println(err)
 		return module.CheckResult{
-			RejectErr: &smtp.SMTPError{
+			Reason: &exterrors.SMTPError{
 				Code:         550,
-				EnhancedCode: smtp.EnhancedCode{5, 7, 25},
+				EnhancedCode: exterrors.EnhancedCode{5, 7, 25},
-				Message:      "could look up rDNS address for source",
+				Message:      "rDNS lookup failure during policy check",
+				CheckName:    "require_matching_rdns",
+				Err:          err,
 			},
 		}
 	}
@@ -39,12 +40,12 @@ func requireMatchingRDNS(ctx check.StatelessCheckContext) module.CheckResult {
 			return module.CheckResult{}
 		}
 	}
-	ctx.Logger.Printf("no PTR records for %v IP pointing to %s", tcpAddr.IP, srcDomain)
 	return module.CheckResult{
-		RejectErr: &smtp.SMTPError{
+		Reason: &exterrors.SMTPError{
 			Code:         550,
-			EnhancedCode: smtp.EnhancedCode{5, 7, 25},
+			EnhancedCode: exterrors.EnhancedCode{5, 7, 25},
 			Message:      "rDNS name does not match source hostname",
+			CheckName:    "require_matching_rdns",
 		},
 	}
 }
@@ -52,44 +53,49 @@ func requireMatchingRDNS(ctx check.StatelessCheckContext) module.CheckResult {
 func requireMXRecord(ctx check.StatelessCheckContext, mailFrom string) module.CheckResult {
 	_, domain, err := address.Split(mailFrom)
 	if err != nil {
-		return module.CheckResult{RejectErr: err}
+		return module.CheckResult{
+			Reason: exterrors.WithFields(err, map[string]interface{}{
+				"check": "require_matching_rdns",
+			}),
+		}
 	}
 	if domain == "" {
-		// TODO: Make it configurable whether <postmaster> is allowed.
 		return module.CheckResult{
-			RejectErr: &smtp.SMTPError{
+			Reason: &exterrors.SMTPError{
 				Code:         501,
-				EnhancedCode: smtp.EnhancedCode{5, 1, 8},
+				EnhancedCode: exterrors.EnhancedCode{5, 1, 8},
-				Message:      "<postmaster> is not allowed",
+				Message:      "No domain part",
+				CheckName:    "require_matching_rdns",
 			},
 		}
 	}
 
 	_, ok := ctx.MsgMeta.SrcAddr.(*net.TCPAddr)
 	if !ok {
-		ctx.Logger.Debugf("not TCP/IP source (%v), skipped", ctx.MsgMeta.SrcAddr)
+		ctx.Logger.Println("non-TCP/IP source")
 		return module.CheckResult{}
 	}
 
 	srcMx, err := ctx.Resolver.LookupMX(context.Background(), domain)
 	if err != nil {
-		ctx.Logger.Println(err)
 		return module.CheckResult{
-			RejectErr: &smtp.SMTPError{
+			Reason: &exterrors.SMTPError{
 				Code:         501,
-				EnhancedCode: smtp.EnhancedCode{5, 7, 27},
+				EnhancedCode: exterrors.EnhancedCode{5, 7, 27},
-				Message:      "could not find MX records for MAIL FROM domain",
+				Message:      "Could not find MX records for MAIL FROM domain",
+				CheckName:    "require_matching_rdns",
+				Err:          err,
 			},
 		}
 	}
 
 	if len(srcMx) == 0 {
-		ctx.Logger.Printf("%s got no MX records", domain)
 		return module.CheckResult{
-			RejectErr: &smtp.SMTPError{
+			Reason: &exterrors.SMTPError{
 				Code:         501,
-				EnhancedCode: smtp.EnhancedCode{5, 7, 27},
+				EnhancedCode: exterrors.EnhancedCode{5, 7, 27},
-				Message:      "domain in MAIL FROM has no MX records",
+				Message:      "Domain in MAIL FROM has no MX records",
+				CheckName:    "require_matching_rdns",
 			},
 		}
 	}
@@ -100,19 +106,19 @@ func requireMXRecord(ctx check.StatelessCheckContext, mailFrom string) module.Ch
 func requireMatchingEHLO(ctx check.StatelessCheckContext) module.CheckResult {
 	tcpAddr, ok := ctx.MsgMeta.SrcAddr.(*net.TCPAddr)
 	if !ok {
-		ctx.Logger.Debugf("not TCP/IP source (%v), skipped", ctx.MsgMeta.SrcAddr)
+		ctx.Logger.Printf("non-TCP/IP source, skipped")
 		return module.CheckResult{}
 	}
 
 	srcIPs, err := ctx.Resolver.LookupIPAddr(context.Background(), ctx.MsgMeta.SrcHostname)
 	if err != nil {
-		ctx.Logger.Println(err)
-		// TODO: Check whether lookup is failed due to temporary error and reject with 4xx code.
 		return module.CheckResult{
-			RejectErr: &smtp.SMTPError{
+			Reason: &exterrors.SMTPError{
 				Code:         550,
-				EnhancedCode: smtp.EnhancedCode{5, 7, 0},
+				EnhancedCode: exterrors.EnhancedCode{5, 7, 0},
 				Message:      "DNS lookup failure during policy check",
+				CheckName:    "require_matching_ehlo",
+				Err:          err,
 			},
 		}
 	}
@@ -123,12 +129,12 @@ func requireMatchingEHLO(ctx check.StatelessCheckContext) module.CheckResult {
 			return module.CheckResult{}
 		}
 	}
-	ctx.Logger.Printf("no A/AAA records found for %s for %s domain", tcpAddr.IP, ctx.MsgMeta.SrcHostname)
 	return module.CheckResult{
-		RejectErr: &smtp.SMTPError{
+		Reason: &exterrors.SMTPError{
 			Code:         550,
-			EnhancedCode: smtp.EnhancedCode{5, 7, 0},
+			EnhancedCode: exterrors.EnhancedCode{5, 7, 0},
-			Message:      "no matching A/AAA records found for EHLO hostname",
+			Message:      "No matching A/AAA records found for EHLO hostname",
+			CheckName:    "require_matching_ehlo",
 		},
 	}
 }

check/spf/spf.go

@@ -10,17 +10,19 @@ import (
 	"github.com/emersion/go-message/textproto"
 	"github.com/emersion/go-msgauth/authres"
 	"github.com/emersion/go-msgauth/dmarc"
-	"github.com/emersion/go-smtp"
 	"github.com/foxcpp/maddy/address"
 	"github.com/foxcpp/maddy/buffer"
 	"github.com/foxcpp/maddy/check"
 	maddydmarc "github.com/foxcpp/maddy/check/dmarc"
 	"github.com/foxcpp/maddy/config"
+	"github.com/foxcpp/maddy/exterrors"
 	"github.com/foxcpp/maddy/log"
 	"github.com/foxcpp/maddy/module"
 	"github.com/foxcpp/maddy/target"
 )
 
+const modName = "apply_spf"
+
 type Check struct {
 	instName     string
 	enforceEarly bool
@@ -36,12 +38,12 @@ type Check struct {
 func New(_, instName string, _, _ []string) (module.Module, error) {
 	return &Check{
 		instName: instName,
-		log:      log.Logger{Name: "apply_spf"},
+		log:      log.Logger{Name: modName},
 	}, nil
 }
 
 func (c *Check) Name() string {
-	return "apply_spf"
+	return modName
 }
 
 func (c *Check) InstanceName() string {
@@ -119,47 +121,56 @@ func (s *state) spfResult(res spf.Result, err error) module.CheckResult {
 	case spf.Fail:
 		spfAuth.Value = authres.ResultFail
 		return s.c.failAction.Apply(module.CheckResult{
-			RejectErr: &smtp.SMTPError{
+			Reason: &exterrors.SMTPError{
 				Code:         550,
-				EnhancedCode: smtp.EnhancedCode{5, 7, 23},
+				EnhancedCode: exterrors.EnhancedCode{5, 7, 23},
 				Message:      "SPF authentication failed",
+				CheckName:    modName,
 			},
 			AuthResult: []authres.Result{spfAuth},
 		})
 	case spf.SoftFail:
 		spfAuth.Value = authres.ResultSoftFail
 		return s.c.softfailAction.Apply(module.CheckResult{
-			RejectErr: &smtp.SMTPError{
+			Reason: &exterrors.SMTPError{
 				Code:         550,
-				EnhancedCode: smtp.EnhancedCode{5, 7, 23},
+				EnhancedCode: exterrors.EnhancedCode{5, 7, 23},
 				Message:      "SPF authentication soft-failed",
+				CheckName:    modName,
 			},
 			AuthResult: []authres.Result{spfAuth},
 		})
 	case spf.TempError:
 		spfAuth.Value = authres.ResultTempError
 		return s.c.softfailAction.Apply(module.CheckResult{
-			RejectErr: &smtp.SMTPError{
+			Reason: &exterrors.SMTPError{
 				Code:         451,
-				EnhancedCode: smtp.EnhancedCode{4, 7, 23},
+				EnhancedCode: exterrors.EnhancedCode{4, 7, 23},
 				Message:      "SPF authentication failed with temporary error",
+				CheckName:    modName,
 			},
 			AuthResult: []authres.Result{spfAuth},
 		})
 	case spf.PermError:
 		spfAuth.Value = authres.ResultPermError
 		return s.c.softfailAction.Apply(module.CheckResult{
-			RejectErr: &smtp.SMTPError{
+			Reason: &exterrors.SMTPError{
 				Code:         550,
-				EnhancedCode: smtp.EnhancedCode{4, 7, 23},
+				EnhancedCode: exterrors.EnhancedCode{4, 7, 23},
 				Message:      "SPF authentication failed with permanent error",
+				CheckName:    modName,
 			},
 			AuthResult: []authres.Result{spfAuth},
 		})
 	}
 
 	return module.CheckResult{
-		RejectErr:  fmt.Errorf("unknown SPF status: %s", res),
+		Reason: &exterrors.SMTPError{
+			Code:         550,
+			EnhancedCode: exterrors.EnhancedCode{4, 7, 23},
+			Message:      fmt.Sprintf("Unknown SPF status: %s", res),
+			CheckName:    modName,
+		},
 		AuthResult: []authres.Result{spfAuth},
 	}
 }
@@ -167,7 +178,7 @@ func (s *state) spfResult(res spf.Result, err error) module.CheckResult {
 func (s *state) relyOnDMARC(hdr textproto.Header) bool {
 	orgDomain, fromDomain, record, err := maddydmarc.FetchRecord(context.Background(), hdr)
 	if err != nil {
-		s.log.Printf("can't fetch DMARC policy (%s, %s): %v", orgDomain, fromDomain, err)
+		s.log.Error("DMARC fetch", err, "orgDomain", orgDomain, "fromDomain", fromDomain)
 		return false
 	}
 	if record == nil {
@@ -186,17 +197,13 @@ func (s *state) relyOnDMARC(hdr textproto.Header) bool {
 func (s *state) CheckConnection() module.CheckResult {
 	ip, ok := s.msgMeta.SrcAddr.(*net.TCPAddr)
 	if !ok {
-		s.log.Printf("skipping message with non-IP SrcAddr (%T)", s.msgMeta.SrcAddr)
+		s.log.Println("non-IP SrcAddr")
 		return module.CheckResult{}
 	}
 
 	if s.c.enforceEarly {
 		res, err := spf.CheckHostWithSender(ip.IP, s.msgMeta.SrcHostname, s.msgMeta.OriginalFrom)
-		if res != spf.Pass {
-			s.log.Printf("result: %s (%v)", res, err)
-		} else {
 		s.log.Debugf("result: %s (%v)", res, err)
-		}
 		return s.spfResult(res, err)
 	}
 
@@ -207,11 +214,7 @@ func (s *state) CheckConnection() module.CheckResult {
 
 	go func() {
 		res, err := spf.CheckHostWithSender(ip.IP, s.msgMeta.SrcHostname, s.msgMeta.OriginalFrom)
-		if res != spf.Pass {
-			s.log.Printf("result: %s (%v)", res, err)
-		} else {
 		s.log.Debugf("result: %s (%v)", res, err)
-		}
 		s.spfFetch <- spfRes{res, err}
 	}()
 
@@ -242,7 +245,7 @@ func (s *state) CheckBody(header textproto.Header, body buffer.Buffer) module.Ch
 
 		checkRes := s.spfResult(res.res, res.err)
 		checkRes.Quarantine = false
-		checkRes.RejectErr = nil
+		checkRes.Reject = false
 		return checkRes
 	}
 
@@ -254,9 +257,9 @@ func (s *state) Close() error {
 }
 
 func init() {
-	module.Register("apply_spf", New)
+	module.Register(modName, New)
 	module.RegisterInstance(&Check{
-		instName: "apply_spf",
+		instName: modName,
-		log:      log.Logger{Name: "apply_spf"},
+		log:      log.Logger{Name: modName},
 	}, &config.Map{Block: &config.Node{}})
 }

dist/fail2ban/filter.d/maddy

@@ -1,2 +1,2 @@
 [Definition]
-failregex = authentication failed for (.+) \(from <HOST>:[0-9]+\)
+failregex = authentication failed \(username="(.+)"; src_ip="<HOST>:[0-9]+"\)

endpoint/imap/imap.go

@@ -163,7 +163,7 @@ func (endp *Endpoint) Close() error {
 
 func (endp *Endpoint) Login(connInfo *imap.ConnInfo, username, password string) (imapbackend.User, error) {
 	if !endp.Auth.CheckPlain(username, password) {
-		endp.Log.Printf("authentication failed for %s (from %v)", username, connInfo.RemoteAddr)
+		endp.Log.Msg("authentication failed", "username", username, "src_ip", connInfo.RemoteAddr)
 		return nil, imapbackend.ErrInvalidCredentials
 	}
 

endpoint/smtp/smtp.go

@@ -20,6 +20,7 @@ import (
 	"github.com/foxcpp/maddy/config"
 	modconfig "github.com/foxcpp/maddy/config/module"
 	"github.com/foxcpp/maddy/dns"
+	"github.com/foxcpp/maddy/exterrors"
 	"github.com/foxcpp/maddy/future"
 	"github.com/foxcpp/maddy/log"
 	"github.com/foxcpp/maddy/module"
@@ -27,22 +28,6 @@ import (
 	"github.com/foxcpp/maddy/target"
 )
 
-func MsgMetaLog(l log.Logger, msgMeta *module.MsgMetadata) log.Logger {
-	out := l.Out
-	if out == nil {
-		out = log.DefaultLogger.Out
-	}
-
-	return log.Logger{
-		Out: log.FuncOutput(func(t time.Time, debug bool, str string) {
-			ctxInfo := fmt.Sprintf(", HELO = %s, IP = %s, MAIL FROM = %s, msg ID = %s", msgMeta.SrcHostname, msgMeta.SrcAddr, msgMeta.OriginalFrom, msgMeta.ID)
-			out.Write(t, debug, str+ctxInfo)
-		}, out.Close),
-		Debug: l.Debug,
-		Name:  l.Name,
-	}
-}
-
 type Session struct {
 	endp        *Endpoint
 	delivery    module.Delivery
@@ -61,9 +46,11 @@ var errInternal = &smtp.SMTPError{
 func (s *Session) Reset() {
 	if s.delivery != nil {
 		if err := s.delivery.Abort(); err != nil {
-			s.endp.Log.Printf("failed to abort delivery: %v", err)
+			s.endp.Log.Error("delivery abort failed", err)
 		}
+		s.log.Msg("aborted")
 		s.delivery = nil
+		s.log = s.endp.Log
 	}
 }
 
@@ -71,27 +58,29 @@ func (s *Session) Mail(from string) error {
 	var err error
 	s.msgMeta.ID, err = msgpipeline.GenerateMsgID()
 	if err != nil {
-		s.endp.Log.Printf("rand.Rand error: %v", err)
+		s.log.Msg("rand.Rand fail", "err", err)
 		return s.wrapErr(errInternal)
 	}
 	s.msgMeta.OriginalFrom = from
 
-	s.log.Printf("incoming message")
-
-	// Left here for future use.
-	mailCtx := context.TODO()
-
 	if s.endp.resolver != nil && s.msgMeta.SrcAddr != nil {
-		rdnsCtx, cancelRDNS := context.WithCancel(mailCtx)
+		rdnsCtx, cancelRDNS := context.WithCancel(context.TODO())
 		s.msgMeta.SrcRDNSName = future.New()
 		s.cancelRDNS = cancelRDNS
 		go s.fetchRDNSName(rdnsCtx)
 	}
 
 	if !s.endp.deferServerReject {
+		s.log = target.DeliveryLogger(s.log, s.msgMeta)
+		s.log.Msg("incoming message",
+			"src_host", s.msgMeta.SrcHostname,
+			"src_ip", s.msgMeta.SrcAddr.String(),
+			"sender", s.msgMeta.OriginalFrom,
+		)
+
 		s.delivery, err = s.endp.pipeline.Start(s.msgMeta, s.msgMeta.OriginalFrom)
 		if err != nil {
-			s.log.Printf("sender rejected: %v", err)
+			s.log.Error("MAIL FROM error", err)
 			return s.wrapErr(err)
 		}
 	}
@@ -108,7 +97,7 @@ func (s *Session) fetchRDNSName(ctx context.Context) {
 
 	name, err := dns.LookupAddr(ctx, s.endp.resolver, tcpAddr.IP)
 	if err != nil {
-		s.log.Printf("failed to do RDNS lookup for %v: %v", tcpAddr.IP, err)
+		s.log.Error("rDNS error", err)
 		s.msgMeta.SrcRDNSName.Set(nil)
 		return
 	}
@@ -118,15 +107,21 @@ func (s *Session) fetchRDNSName(ctx context.Context) {
 
 func (s *Session) Rcpt(to string) error {
 	if s.delivery == nil {
+		s.log = target.DeliveryLogger(s.log, s.msgMeta)
+		s.log.Msg("incoming message",
+			"src_host", s.msgMeta.SrcHostname,
+			"src_ip", s.msgMeta.SrcAddr.String(),
+			"sender", s.msgMeta.OriginalFrom,
+		)
+
 		if s.deliveryErr != nil {
-			s.log.Printf("sender rejected (repeated): %v, RCPT TO = %s", s.deliveryErr, to)
+			s.log.Error("MAIL FROM error (repeated)", s.deliveryErr, "rcpt", to)
 			return s.wrapErr(s.deliveryErr)
 		}
-
 		var err error
 		s.delivery, err = s.endp.pipeline.Start(s.msgMeta, s.msgMeta.OriginalFrom)
 		if err != nil {
-			s.log.Printf("sender rejected (deferred): %v, RCPT TO = %s", err, to)
+			s.log.Error("MAIL FROM error (deferred)", err, "rcpt", to)
 			s.deliveryErr = err
 			return s.wrapErr(err)
 		}
@@ -134,16 +129,19 @@ func (s *Session) Rcpt(to string) error {
 
 	err := s.delivery.AddRcpt(to)
 	if err != nil {
-		s.log.Printf("recipient rejected: %v, RCPT TO = %s", err, to)
+		s.log.Error("RCPT error", err, "rcpt", to)
-	}
 		return s.wrapErr(err)
 	}
+	s.log.Msg("RCPT ok", "rcpt", to)
+	return nil
+}
 
 func (s *Session) Logout() error {
 	if s.delivery != nil {
 		if err := s.delivery.Abort(); err != nil {
 			s.endp.Log.Printf("failed to abort delivery: %v", err)
 		}
+		s.log.Msg("aborted")
 		s.delivery = nil
 	}
 	if s.cancelRDNS != nil {
@@ -156,13 +154,13 @@ func (s *Session) Data(r io.Reader) error {
 	bufr := bufio.NewReader(r)
 	header, err := textproto.ReadHeader(bufr)
 	if err != nil {
-		s.log.Printf("malformed header or I/O error: %v", err)
+		s.log.Error("DATA error", err)
 		return s.wrapErr(err)
 	}
 
 	if s.endp.submission {
 		if err := SubmissionPrepare(s.msgMeta, header, s.endp.serv.Domain); err != nil {
-			s.log.Printf("malformed header or I/O error: %v", err)
+			s.log.Error("DATA error", err)
 			return s.wrapErr(err)
 		}
 	}
@@ -170,28 +168,29 @@ func (s *Session) Data(r io.Reader) error {
 	// TODO: Disk buffering.
 	buf, err := buffer.BufferInMemory(bufr)
 	if err != nil {
-		s.log.Printf("I/O error: %v", err)
+		s.log.Error("DATA error", err)
 		return s.wrapErr(errInternal)
 	}
 	s.msgMeta.BodyLength = len(buf.(buffer.MemoryBuffer).Slice)
 
 	received, err := target.GenerateReceived(context.TODO(), s.msgMeta, s.endp.serv.Domain, s.msgMeta.OriginalFrom)
 	if err != nil {
+		s.log.Error("DATA error", err)
 		return err
 	}
 	header.Add("Received", received)
 
 	if err := s.delivery.Body(header, buf); err != nil {
-		s.log.Printf("%v", err)
+		s.log.Error("DATA error", err)
 		return s.wrapErr(err)
 	}
 
 	if err := s.delivery.Commit(); err != nil {
-		s.log.Printf("%v", err)
+		s.log.Error("DATA error", err)
 		return s.wrapErr(err)
 	}
 
-	s.log.Printf("message accepted")
+	s.log.Msg("accepted")
 	s.delivery = nil
 
 	return nil
@@ -202,14 +201,39 @@ func (s *Session) wrapErr(err error) error {
 		return nil
 	}
 
+	res := &smtp.SMTPError{
+		Code:         554,
+		EnhancedCode: smtp.EnhancedCodeNotSet,
+		Message:      err.Error(),
+	}
+
+	if exterrors.IsTemporary(err) {
+		res.Code = 451
+	}
+
+	ctxInfo := exterrors.Fields(err)
+	ctxCode, ok := ctxInfo["smtp_code"].(int)
+	if ok {
+		res.Code = ctxCode
+	}
+	ctxEnchCode, ok := ctxInfo["smtp_enchcode"].(exterrors.EnhancedCode)
+	if ok {
+		res.EnhancedCode = smtp.EnhancedCode(ctxEnchCode)
+	}
+	ctxMsg, ok := ctxInfo["smtp_msg"].(string)
+	if ok {
+		res.Message = ctxMsg
+	}
+
 	if smtpErr, ok := err.(*smtp.SMTPError); ok {
-		return &smtp.SMTPError{
+		s.endp.Log.Printf("plain SMTP error returned, this is deprecated")
-			Code:         smtpErr.Code,
+		res.Code = smtpErr.Code
-			EnhancedCode: smtpErr.EnhancedCode,
+		res.EnhancedCode = smtpErr.EnhancedCode
-			Message:      smtpErr.Message + " (msg ID = " + s.msgMeta.ID + ")",
+		res.Message = smtpErr.Message
 	}
-	}
+
-	return fmt.Errorf("%v (msg ID = %s)", err, s.msgMeta.ID)
+	res.Message += " (msg ID = " + s.msgMeta.ID + ")"
+	return res
 }
 
 type Endpoint struct {
@@ -383,7 +407,7 @@ func (endp *Endpoint) Login(state *smtp.ConnectionState, username, password stri
 	}
 
 	if !endp.Auth.CheckPlain(username, password) {
-		endp.Log.Printf("authentication failed for %s (from %v)", username, state.RemoteAddr)
+		endp.Log.Msg("authentication failed", "username", username, "src_ip", state.RemoteAddr)
 		return nil, errors.New("Invalid credentials")
 	}
 
@@ -423,7 +447,7 @@ func (endp *Endpoint) newSession(anonymous bool, username, password string, stat
 	return &Session{
 		endp:    endp,
 		msgMeta: ctx,
-		log:     MsgMetaLog(endp.Log, ctx),
+		log:     endp.Log,
 	}
 }
 

exterrors/fields.go

@@ -0,0 +1,51 @@
+package exterrors
+
+type fieldsErr interface {
+	Fields() map[string]interface{}
+}
+
+type unwrapper interface {
+	Unwrap() error
+}
+
+type fieldsWrap struct {
+	err    error
+	fields map[string]interface{}
+}
+
+func (fw fieldsWrap) Error() string {
+	return fw.err.Error()
+}
+
+func (fw fieldsWrap) Unwrap() error {
+	return fw.err
+}
+
+func (fw fieldsWrap) Fields() map[string]interface{} {
+	return fw.fields
+}
+
+func Fields(err error) map[string]interface{} {
+	fields := make(map[string]interface{}, 5)
+
+	for err != nil {
+		errFields, ok := err.(fieldsErr)
+		if ok {
+			for k, v := range errFields.Fields() {
+				fields[k] = v
+			}
+		}
+
+		unwrap, ok := err.(unwrapper)
+		if !ok {
+			break
+		}
+		err = unwrap.Unwrap()
+	}
+
+	return fields
+}
+
+func WithFields(err error, fields map[string]interface{}) error {
+	return fieldsWrap{err: err, fields: fields}
+}

exterrors/smtp.go

@@ -0,0 +1,66 @@
+package exterrors
+
+import (
+	"fmt"
+
+	"github.com/emersion/go-smtp"
+)
+
+type EnhancedCode smtp.EnhancedCode
+
+func (ec EnhancedCode) FormatLog() string {
+	return fmt.Sprintf("%d.%d.%d", ec[0], ec[1], ec[2])
+}
+
+// SMTPError type is a copy of emersion/go-smtp.SMTPError type
+// that extends it with Fields method for logging and reporting
+// in maddy. It should be used instead of library type for all
+// errors.
+type SMTPError struct {
+	Code         int
+	EnhancedCode EnhancedCode
+	Message      string
+
+	// If the error was generated by a message check
+	// this field includes module name.
+	CheckName string
+
+	// If the error was generated by a delivery target
+	// this field includes module name.
+	TargetName string
+
+	// If the error was generated as a result of another
+	// error - this field contains the original error object.
+	Err error
+
+	Misc map[string]interface{}
+}
+
+func (se *SMTPError) Unwrap() error {
+	return se.Err
+}
+
+func (se *SMTPError) Fields() map[string]interface{} {
+	ctx := make(map[string]interface{}, len(se.Misc)+3)
+	for k, v := range se.Misc {
+		ctx[k] = v
+	}
+	ctx["smtp_code"] = se.Code
+	ctx["smtp_enchcode"] = se.EnhancedCode
+	ctx["smtp_msg"] = se.Message
+	if se.CheckName != "" {
+		ctx["check"] = se.CheckName
+	}
+	if se.TargetName != "" {
+		ctx["target"] = se.TargetName
+	}
+	return ctx
+}
+
+func (se *SMTPError) Temporary() bool {
+	return se.Code/100 == 4
+}
+
+func (se *SMTPError) Error() string {
+	return se.Message
+}

log/log.go

@@ -6,48 +6,181 @@ import (
 	"io"
 	"io/ioutil"
 	"os"
+	"sort"
+	"strconv"
 	"strings"
 	"time"
+
+	"github.com/foxcpp/maddy/exterrors"
 )
 
-// Logger is the structure that writes formatted output
+// Logger is the structure that writes formatted output to the underlying
-// to the underlying log.Output object.
+// log.Output object.
 //
-// Logger is stateless and can be copied freely.
+// Logger is stateless and can be copied freely.  However, consider that
-// However, consider that underlying log.Output will not
+// underlying log.Output will not be copied.
-// be copied.
 //
-// Each log message is prefixed with logger name.
+// Each log message is prefixed with logger name.  Timestamp and debug flag
-// Timestamp and debug flag formatting is done by log.Output.
+// formatting is done by log.Output.
 //
-// No serialization is provided by Logger, its log.Output
+// No serialization is provided by Logger, its log.Output responsibility to
-// responsibility to ensure goroutine-safety if necessary.
+// ensure goroutine-safety if necessary.
 type Logger struct {
 	Out   Output
 	Name  string
 	Debug bool
+
+	// Additional fields that will be added
+	// to the Msg output.
+	Fields []interface{}
 }
 
 func (l Logger) Debugf(format string, val ...interface{}) {
 	if !l.Debug {
 		return
 	}
-	l.log(true, fmt.Sprintf(format, val...))
+	l.log(true, l.formatMsg(fmt.Sprintf(format, val...), nil))
 }
 
 func (l Logger) Debugln(val ...interface{}) {
 	if !l.Debug {
 		return
 	}
-	l.log(true, fmt.Sprintln(val...))
+	l.log(true, l.formatMsg(strings.TrimRight(fmt.Sprintln(val...), "\n"), nil))
 }
 
 func (l Logger) Printf(format string, val ...interface{}) {
-	l.log(false, fmt.Sprintf(format, val...))
+	l.log(false, l.formatMsg(fmt.Sprintf(format, val...), nil))
 }
 
 func (l Logger) Println(val ...interface{}) {
-	l.log(false, fmt.Sprintln(val...))
+	l.log(false, l.formatMsg(strings.TrimRight(fmt.Sprintln(val...), "\n"), nil))
+}
+
+// Msg writes an event log message in a loosely defined machine-readable format.
+//   name: msg | key=value; key2=value2;
+//
+// Key-value pairs are built from ctx slice which should
+// contain key strings followed by corresponding values.
+// That is, for example, []interface{"key", "value", "key2", "value2"}.
+//
+// Field values are formatted depending on the underlying type as follows:
+// - Numbers are added as is.
+//    key=5; key2=5.66;
+// - Strings are quoted using strconv.Quote
+//    key="aaa\nbbb\"ccc"
+// - For time.Duration String() is used *without* quoting.
+// - time.Time is formatted as 2006-01-02T15:04:05 without quoting.
+// - If fmt.Stringer is implemented, strconv.Quote(val.String()) is used
+// - If LogFormatter is implemented, FormatLog() is used as is
+func (l Logger) Msg(msg string, fields ...interface{}) {
+	l.log(false, l.formatMsg(msg, fields))
+}
+
+// Error writes an event log message in a loosely defined machine-readable format
+// containing information about the error. If err does have a Fields method
+// that returns []interface{}, its result will be added to the message.
+//   name: kind | key=value; key2=value2;
+//
+// In the context of Error method, "msg" typically indicates the top-level
+// context in which the error is *handled*. For example, if error leads to
+// rejection of SMTP DATA command, msg will probably be "DATA error".
+//
+// See Logger.Msg for how fields are formatted.
+func (l Logger) Error(msg string, err error, fields ...interface{}) {
+	errFields := exterrors.Fields(err)
+	allFields := make([]interface{}, 0, len(fields)+len(errFields)+2)
+
+	errKeys := make([]string, 0, len(errFields))
+	for k := range errFields {
+		errKeys = append(errKeys, k)
+	}
+	sort.Strings(errKeys)
+
+	allFields = append(allFields, "reason", err.Error())
+	for _, key := range errKeys {
+		allFields = append(allFields, key, errFields[key])
+	}
+	allFields = append(allFields, fields...)
+
+	l.log(false, l.formatMsg(msg, allFields))
+}
+
+func (l Logger) DebugMsg(kind string, ctx ...interface{}) {
+	l.log(true, l.formatMsg(kind, ctx))
+}
+
+func (l Logger) formatMsg(msg string, ctx []interface{}) string {
+	formatted := strings.Builder{}
+
+	formatted.WriteString(msg)
+
+	if len(ctx)+len(l.Fields) != 0 {
+		formatted.WriteString(" (")
+		formatFields(&formatted, ctx, len(l.Fields) != 0)
+		formatFields(&formatted, l.Fields, false)
+		formatted.WriteString(")")
+	}
+
+	return formatted.String()
+}
+
+type LogFormatter interface {
+	FormatLog() string
+}
+
+func formatFields(msg *strings.Builder, ctx []interface{}, lastSemicolon bool) {
+	for i, val := range ctx {
+		if i%2 == 0 {
+			// Key
+			msg.WriteString(val.(string))
+			msg.WriteString("=")
+		} else {
+			// Value
+			switch val := val.(type) {
+			case int:
+				msg.WriteString(strconv.FormatInt(int64(val), 10))
+			case int8:
+				msg.WriteString(strconv.FormatInt(int64(val), 10))
+			case int16:
+				msg.WriteString(strconv.FormatInt(int64(val), 10))
+			case int32:
+				msg.WriteString(strconv.FormatInt(int64(val), 10))
+			case int64:
+				msg.WriteString(strconv.FormatInt(val, 10))
+			case uint:
+				msg.WriteString(strconv.FormatUint(uint64(val), 10))
+			case uint8:
+				msg.WriteString(strconv.FormatUint(uint64(val), 10))
+			case uint16:
+				msg.WriteString(strconv.FormatUint(uint64(val), 10))
+			case uint32:
+				msg.WriteString(strconv.FormatUint(uint64(val), 10))
+			case uint64:
+				msg.WriteString(strconv.FormatUint(val, 10))
+			case float32:
+				msg.WriteString(strconv.FormatFloat(float64(val), 'f', 2, 32))
+			case float64:
+				msg.WriteString(strconv.FormatFloat(val, 'f', 2, 64))
+			case string:
+				msg.WriteString(strconv.Quote(val))
+			case LogFormatter:
+				msg.WriteString(val.FormatLog())
+			case time.Time:
+				msg.WriteString(val.Format("2006-01-02T15:04:05"))
+			case time.Duration:
+				msg.WriteString(val.String())
+			case fmt.Stringer:
+				msg.WriteString(strconv.Quote(val.String()))
+			default:
+				fmt.Fprintf(msg, `"%#v"`, val)
+			}
+
+			if lastSemicolon || i+1 != len(ctx) {
+				msg.WriteString("; ")
+			}
+		}
+	}
 }
 
 // Write implements io.Writer, all bytes sent
@@ -70,8 +203,6 @@ func (l Logger) DebugWriter() io.Writer {
 }
 
 func (l Logger) log(debug bool, s string) {
-	s = strings.TrimRight(s, "\n\t ")
-
 	if l.Name != "" {
 		s = l.Name + ": " + s
 	}

modify/dkim/dkim.go

@@ -13,6 +13,7 @@ import (
 	"github.com/foxcpp/maddy/address"
 	"github.com/foxcpp/maddy/buffer"
 	"github.com/foxcpp/maddy/config"
+	"github.com/foxcpp/maddy/exterrors"
 	"github.com/foxcpp/maddy/log"
 	"github.com/foxcpp/maddy/module"
 	"github.com/foxcpp/maddy/target"
@@ -235,33 +236,36 @@ func (m *Modifier) shouldSign(msgId string, h textproto.Header, mailFrom string,
 
 	fromVal := h.Get("From")
 	if fromVal == "" {
-		m.log.Printf("not signing, empty From (msg ID = %s)", msgId)
+		m.log.Msg("not signing, empty From", "msg_id", msgId)
 		return "", false
 	}
 	fromAddrs, err := mail.ParseAddressList(fromVal)
 	if err != nil {
-		m.log.Printf("not signing, malformed From: %v (msg ID = %s)", err, msgId)
+		m.log.Msg("not signing, malformed From field", "err", err, "msg_id", msgId)
 		return "", false
 	}
 	if len(fromAddrs) != 1 && !m.multipleFromOk {
-		m.log.Printf("not signing, multiple From (msg ID = %s)", msgId)
+		m.log.Msg("not signing, multiple addresses in From", "msg_id", msgId)
 		return "", false
 	}
 
 	fromAddr := fromAddrs[0].Address
 	fromUser, fromDomain, err := address.Split(fromAddr)
 	if err != nil {
-		m.log.Printf("not signing, malformed From address: %s (msg ID = %s)", authName, msgId)
+		m.log.Msg("not signing, malformed address in From",
+			"err", err, "from_addr", fromAddr, "msg_id", msgId)
 		return "", false
 	}
 
 	if !strings.EqualFold(fromDomain, m.domain) {
-		m.log.Printf("not signing, %s (From domain) != %s (key domain) (msg ID = %s)", fromDomain, m.domain, msgId)
+		m.log.Msg("not signing, From domain is not key domain",
+			"from_domain", fromDomain, "key_domain", m.domain, "msg_id", msgId)
 		return "", false
 	}
 
 	if _, do := m.senderMatch["envelope"]; do && !strings.EqualFold(fromAddr, mailFrom) {
-		m.log.Printf("not signing, %s (From) != %s (MAIL FROM) (msg ID = %s)", fromAddr, mailFrom, msgId)
+		m.log.Msg("not signing, From address is not envelope address",
+			"from_addr", fromAddr, "envelope", mailFrom, "msg_id", msgId)
 		return "", false
 	}
 
@@ -271,7 +275,8 @@ func (m *Modifier) shouldSign(msgId string, h textproto.Header, mailFrom string,
 			compareWith = fromAddr
 		}
 		if !strings.EqualFold(compareWith, authName) {
-			m.log.Printf("not signing, %s (From) != %s (auth) (msg ID = %s)", fromAddr, authName, msgId)
+			m.log.Msg("not signing, From address is not authenticated identity",
+				"from_addr", fromAddr, "auth_id", authName, "msg_id", msgId)
 			return "", false
 		}
 	}
@@ -308,34 +313,29 @@ func (s state) RewriteBody(h textproto.Header, body buffer.Buffer) error {
 	}
 	signer, err := dkim.NewSigner(&opts)
 	if err != nil {
-		s.m.log.Printf("%v", strings.TrimPrefix(err.Error(), "dkim: "))
+		return exterrors.WithFields(err, map[string]interface{}{"modifier": "sign_dkim"})
-		return err
 	}
 	if err := textproto.WriteHeader(signer, h); err != nil {
-		s.m.log.Printf("I/O error: %v", err)
 		signer.Close()
-		return err
+		return exterrors.WithFields(err, map[string]interface{}{"modifier": "sign_dkim"})
 	}
 	r, err := body.Open()
 	if err != nil {
-		s.m.log.Printf("I/O error: %v", err)
 		signer.Close()
-		return err
+		return exterrors.WithFields(err, map[string]interface{}{"modifier": "sign_dkim"})
 	}
 	if _, err := io.Copy(signer, r); err != nil {
-		s.m.log.Printf("I/O error: %v", err)
 		signer.Close()
-		return err
+		return exterrors.WithFields(err, map[string]interface{}{"modifier": "sign_dkim"})
 	}
 
 	if err := signer.Close(); err != nil {
-		s.m.log.Printf("%v", strings.TrimPrefix(err.Error(), "dkim: "))
+		return exterrors.WithFields(err, map[string]interface{}{"modifier": "sign_dkim"})
-		return err
 	}
 
 	h.Add("DKIM-Signature", signer.SignatureValue())
 
-	s.m.log.Debugf("signed, identifier = %s", id)
+	s.m.log.DebugMsg("signed", "identifier", id)
 
 	return nil
 }

module/check.go

@@ -42,9 +42,13 @@ type CheckState interface {
 }
 
 type CheckResult struct {
-	// RejectErr is the error that is reported to the message source
+	// Reason is the error that is reported to the message source
 	// if check decided that the message should be rejected.
-	RejectErr error
+	Reason error
+
+	// Reject is the flag that specifies that the message
+	// should be rejected.
+	Reject bool
 
 	// Quarantine is the flag that specifies that the message
 	// is considered "possibly malicious" and should be

msgpipeline/check_runner.go

@@ -9,10 +9,9 @@ import (
 	"github.com/emersion/go-message/textproto"
 	"github.com/emersion/go-msgauth/authres"
 	"github.com/emersion/go-msgauth/dmarc"
-	"github.com/emersion/go-smtp"
-	"github.com/foxcpp/maddy/atomicbool"
 	"github.com/foxcpp/maddy/buffer"
 	maddydmarc "github.com/foxcpp/maddy/check/dmarc"
+	"github.com/foxcpp/maddy/exterrors"
 	"github.com/foxcpp/maddy/log"
 	"github.com/foxcpp/maddy/module"
 )
@@ -134,12 +133,17 @@ func (cr *checkRunner) checkStates(checks []module.Check) ([]module.CheckState,
 
 func (cr *checkRunner) runAndMergeResults(states []module.CheckState, runner func(module.CheckState) module.CheckResult) error {
 	data := struct {
-		quarantineFlag atomicbool.AtomicBool
 		authResLock sync.Mutex
 		headerLock  sync.Mutex
-		firstErr       error
 
-		setErr sync.Once
+		quarantineErr    error
+		quarantineCheck  string
+		setQuarantineErr sync.Once
+
+		rejectErr    error
+		rejectCheck  string
+		setRejectErr sync.Once
+
 		wg sync.WaitGroup
 	}{}
 
@@ -165,10 +169,14 @@ func (cr *checkRunner) runAndMergeResults(states []module.CheckState, runner fun
 			}
 
 			if subCheckRes.Quarantine {
-				data.quarantineFlag.Set(true)
+				data.setQuarantineErr.Do(func() {
+					data.quarantineErr = subCheckRes.Reason
+				})
 			}
-			if subCheckRes.RejectErr != nil {
+			if subCheckRes.Reject {
-				data.setErr.Do(func() { data.firstErr = subCheckRes.RejectErr })
+				data.setRejectErr.Do(func() {
+					data.rejectErr = subCheckRes.Reason
+				})
 			}
 
 			data.wg.Done()
@@ -176,11 +184,12 @@ func (cr *checkRunner) runAndMergeResults(states []module.CheckState, runner fun
 	}
 
 	data.wg.Wait()
-	if data.firstErr != nil {
+	if data.rejectErr != nil {
-		return data.firstErr
+		return data.rejectErr
 	}
 
-	if data.quarantineFlag.IsSet() {
+	if data.quarantineErr != nil {
+		cr.log.Error("quarantined", data.quarantineErr, "reason", data.quarantineErr.Error())
 		cr.mergedRes.Quarantine = true
 	}
 
@@ -266,7 +275,7 @@ func (cr *checkRunner) applyDMARC() error {
 		return dmarcData.err
 	}
 	if dmarcData.record == nil {
-		cr.log.Debugf("no DMARC record (orgDomain = %s)", dmarcData.orgDomain)
+		cr.log.DebugMsg("no record", "orgdomain", dmarcData.orgDomain)
 		return nil
 	}
 
@@ -291,17 +300,15 @@ func (cr *checkRunner) applyDMARC() error {
 	}
 
 	if !dmarcFail {
-		cr.log.Debugf("DMARC check passed (p = %s, orgDomain = %s)", dmarcData.record.Policy, dmarcData.orgDomain)
+		cr.log.DebugMsg("pass", "p", dmarcData.record.Policy, "orgdomain", dmarcData.orgDomain)
 		return nil
 	}
 	// TODO: Report generation.
 
-	if dmarcData.record.Percent == nil || rand.Int31n(100) < int32(*dmarcData.record.Percent) {
+	if dmarcData.record.Percent != nil && rand.Int31n(100) > int32(*dmarcData.record.Percent) {
-		cr.log.Printf("DMARC check failed: %s (p = %s, orgDomain = %s)",
+		cr.log.Msg("DMARC not enforced due to pct",
-			result.Reason, dmarcData.record.Policy, dmarcData.orgDomain)
+			"pct", *dmarcData.record.Percent, "p", dmarcData.record.Policy,
-	} else {
+			"orgdomain", dmarcData.orgDomain, "fromdomain", dmarcData.fromDomain)
-		cr.log.Printf("DMARC check ignored: %s (pct = %v, p = %s, orgDomain = %s)",
-			result.Reason, dmarcData.record.Percent, dmarcData.record.Policy, dmarcData.orgDomain)
 		return nil
 	}
 
@@ -312,20 +319,29 @@ func (cr *checkRunner) applyDMARC() error {
 
 	switch policy {
 	case dmarc.PolicyReject:
-		return &smtp.SMTPError{
+		return &exterrors.SMTPError{
 			Code:         550,
-			EnhancedCode: smtp.EnhancedCode{5, 7, 1},
+			EnhancedCode: exterrors.EnhancedCode{5, 7, 1},
 			Message:      "DMARC check failed",
+			CheckName:    "dmarc",
+			Misc: map[string]interface{}{
+				"reason":     result.Reason,
+				"fromdomain": dmarcData.fromDomain,
+				"orgdomain":  dmarcData.orgDomain,
+			},
 		}
 	case dmarc.PolicyQuarantine:
 		cr.msgMeta.Quarantine = true
+
+		// Mimick the message structure for regular checks.
+		cr.log.Msg("quarantined", "reason", result.Reason, "check", "dmarc",
+			"fromdomain", dmarcData.fromDomain, "orgdomain", dmarcData.orgDomain)
 	}
 	return nil
 }
 
 func (cr *checkRunner) applyResults(hostname string, header *textproto.Header) error {
 	if cr.mergedRes.Quarantine {
-		cr.log.Printf("quarantined message due to check result")
 		cr.msgMeta.Quarantine = true
 	}
 

msgpipeline/check_test.go

@@ -177,10 +177,10 @@ func TestMsgPipeline_Globalcheck_Errors(t *testing.T) {
 	target := testutils.Target{}
 	check_ := testutils.Check{
 		InitErr:   errors.New("1"),
-		ConnRes:   module.CheckResult{RejectErr: errors.New("2")},
+		ConnRes:   module.CheckResult{Reject: true, Reason: errors.New("2")},
-		SenderRes: module.CheckResult{RejectErr: errors.New("3")},
+		SenderRes: module.CheckResult{Reject: true, Reason: errors.New("3")},
-		RcptRes:   module.CheckResult{RejectErr: errors.New("4")},
+		RcptRes:   module.CheckResult{Reject: true, Reason: errors.New("4")},
-		BodyRes:   module.CheckResult{RejectErr: errors.New("5")},
+		BodyRes:   module.CheckResult{Reject: true, Reason: errors.New("5")},
 	}
 	d := MsgPipeline{
 		msgpipelineCfg: msgpipelineCfg{
@@ -213,7 +213,7 @@ func TestMsgPipeline_Globalcheck_Errors(t *testing.T) {
 		}
 	})
 
-	check_.ConnRes.RejectErr = nil
+	check_.ConnRes.Reject = false
 
 	t.Run("mail from err", func(t *testing.T) {
 		_, err := testutils.DoTestDeliveryErr(t, &d, "sender@example.com", []string{"rcpt1@example.com", "rcpt2@example.com"})
@@ -222,7 +222,7 @@ func TestMsgPipeline_Globalcheck_Errors(t *testing.T) {
 		}
 	})
 
-	check_.SenderRes.RejectErr = nil
+	check_.SenderRes.Reject = false
 
 	t.Run("rcpt to err", func(t *testing.T) {
 		_, err := testutils.DoTestDeliveryErr(t, &d, "sender@example.com", []string{"rcpt1@example.com", "rcpt2@example.com"})
@@ -231,7 +231,7 @@ func TestMsgPipeline_Globalcheck_Errors(t *testing.T) {
 		}
 	})
 
-	check_.RcptRes.RejectErr = nil
+	check_.RcptRes.Reject = false
 
 	t.Run("body err", func(t *testing.T) {
 		_, err := testutils.DoTestDeliveryErr(t, &d, "sender@example.com", []string{"rcpt1@example.com", "rcpt2@example.com"})
@@ -240,7 +240,7 @@ func TestMsgPipeline_Globalcheck_Errors(t *testing.T) {
 		}
 	})
 
-	check_.BodyRes.RejectErr = nil
+	check_.BodyRes.Reject = false
 
 	t.Run("no err", func(t *testing.T) {
 		testutils.DoTestDelivery(t, &d, "sender@example.com", []string{"rcpt1@example.com", "rcpt2@example.com"})
@@ -255,10 +255,10 @@ func TestMsgPipeline_SourceCheck_Errors(t *testing.T) {
 	target := testutils.Target{}
 	check_ := testutils.Check{
 		InitErr:   errors.New("1"),
-		ConnRes:   module.CheckResult{RejectErr: errors.New("2")},
+		ConnRes:   module.CheckResult{Reject: true, Reason: errors.New("2")},
-		SenderRes: module.CheckResult{RejectErr: errors.New("3")},
+		SenderRes: module.CheckResult{Reject: true, Reason: errors.New("3")},
-		RcptRes:   module.CheckResult{RejectErr: errors.New("4")},
+		RcptRes:   module.CheckResult{Reject: true, Reason: errors.New("4")},
-		BodyRes:   module.CheckResult{RejectErr: errors.New("5")},
+		BodyRes:   module.CheckResult{Reject: true, Reason: errors.New("5")},
 	}
 	globalCheck := testutils.Check{}
 	d := MsgPipeline{
@@ -293,7 +293,7 @@ func TestMsgPipeline_SourceCheck_Errors(t *testing.T) {
 		}
 	})
 
-	check_.ConnRes.RejectErr = nil
+	check_.ConnRes.Reject = false
 
 	t.Run("mail from err", func(t *testing.T) {
 		_, err := testutils.DoTestDeliveryErr(t, &d, "sender@example.com", []string{"rcpt1@example.com", "rcpt2@example.com"})
@@ -302,7 +302,7 @@ func TestMsgPipeline_SourceCheck_Errors(t *testing.T) {
 		}
 	})
 
-	check_.SenderRes.RejectErr = nil
+	check_.SenderRes.Reject = false
 
 	t.Run("rcpt to err", func(t *testing.T) {
 		_, err := testutils.DoTestDeliveryErr(t, &d, "sender@example.com", []string{"rcpt1@example.com", "rcpt2@example.com"})
@@ -311,7 +311,7 @@ func TestMsgPipeline_SourceCheck_Errors(t *testing.T) {
 		}
 	})
 
-	check_.RcptRes.RejectErr = nil
+	check_.RcptRes.Reject = false
 
 	t.Run("body err", func(t *testing.T) {
 		_, err := testutils.DoTestDeliveryErr(t, &d, "sender@example.com", []string{"rcpt1@example.com", "rcpt2@example.com"})
@@ -320,7 +320,7 @@ func TestMsgPipeline_SourceCheck_Errors(t *testing.T) {
 		}
 	})
 
-	check_.BodyRes.RejectErr = nil
+	check_.BodyRes.Reject = false
 
 	t.Run("no err", func(t *testing.T) {
 		testutils.DoTestDelivery(t, &d, "sender@example.com", []string{"rcpt1@example.com", "rcpt2@example.com"})
@@ -336,10 +336,10 @@ func TestMsgPipeline_RcptCheck_Errors(t *testing.T) {
 	target := testutils.Target{}
 	check_ := testutils.Check{
 		InitErr:   errors.New("1"),
-		ConnRes:   module.CheckResult{RejectErr: errors.New("2")},
+		ConnRes:   module.CheckResult{Reject: true, Reason: errors.New("2")},
-		SenderRes: module.CheckResult{RejectErr: errors.New("3")},
+		SenderRes: module.CheckResult{Reject: true, Reason: errors.New("3")},
-		RcptRes:   module.CheckResult{RejectErr: errors.New("4")},
+		RcptRes:   module.CheckResult{Reject: true, Reason: errors.New("4")},
-		BodyRes:   module.CheckResult{RejectErr: errors.New("5")},
+		BodyRes:   module.CheckResult{Reject: true, Reason: errors.New("5")},
 
 		InstName: "err_check",
 	}
@@ -384,7 +384,7 @@ func TestMsgPipeline_RcptCheck_Errors(t *testing.T) {
 		t.Log("!!!", check_.UnclosedStates)
 	})
 
-	check_.ConnRes.RejectErr = nil
+	check_.ConnRes.Reject = false
 
 	t.Run("mail from err", func(t *testing.T) {
 		d.Log = testutils.Logger(t, "msgpipeline")
@@ -396,7 +396,7 @@ func TestMsgPipeline_RcptCheck_Errors(t *testing.T) {
 		t.Log("!!!", check_.UnclosedStates)
 	})
 
-	check_.SenderRes.RejectErr = nil
+	check_.SenderRes.Reject = false
 
 	t.Run("rcpt to err", func(t *testing.T) {
 		d.Log = testutils.Logger(t, "msgpipeline")
@@ -406,7 +406,7 @@ func TestMsgPipeline_RcptCheck_Errors(t *testing.T) {
 		}
 	})
 
-	check_.RcptRes.RejectErr = nil
+	check_.RcptRes.Reject = false
 
 	t.Run("body err", func(t *testing.T) {
 		d.Log = testutils.Logger(t, "msgpipeline")
@@ -416,7 +416,7 @@ func TestMsgPipeline_RcptCheck_Errors(t *testing.T) {
 		}
 	})
 
-	check_.BodyRes.RejectErr = nil
+	check_.BodyRes.Reject = false
 
 	t.Run("no err", func(t *testing.T) {
 		d.Log = testutils.Logger(t, "msgpipeline")

msgpipeline/msgpipeline.go

@@ -216,7 +216,6 @@ func (dd *msgpipelineDelivery) AddRcpt(to string) error {
 	}
 
 	if rcptBlock.rejectErr != nil {
-		dd.log.Debugf("recipient %s rejected: %v", to, rcptBlock.rejectErr)
 		return rcptBlock.rejectErr
 	}
 
@@ -248,10 +247,8 @@ func (dd *msgpipelineDelivery) AddRcpt(to string) error {
 		}
 
 		if err := delivery.AddRcpt(to); err != nil {
-			dd.log.Debugf("delivery.AddRcpt(%s) failure, Delivery object = %T: %v", to, delivery, err)
 			return err
 		}
-		dd.log.Debugf("delivery.AddRcpt(%s) ok, Delivery object = %T", to, delivery)
 		delivery.recipients = append(delivery.recipients, originalTo)
 	}
 
@@ -282,7 +279,6 @@ func (dd *msgpipelineDelivery) Body(header textproto.Header, body buffer.Buffer)
 
 	for _, delivery := range dd.deliveries {
 		if err := delivery.Body(header, body); err != nil {
-			dd.log.Debugf("delivery.Body failure, Delivery object = %T: %v", delivery, err)
 			return err
 		}
 		dd.log.Debugf("delivery.Body ok, Delivery object = %T", delivery)
@@ -351,12 +347,10 @@ func (dd *msgpipelineDelivery) BodyNonAtomic(c module.StatusCollector, header te
 		}
 
 		if err := delivery.Body(header, body); err != nil {
-			dd.log.Debugf("delivery.Body failure, Delivery object = %T: %v", delivery, err)
 			for _, rcpt := range delivery.recipients {
 				c.SetStatus(rcpt, err)
 			}
 		}
-		dd.log.Debugf("delivery.Body ok, Delivery object = %T", delivery)
 	}
 }
 
@@ -365,11 +359,9 @@ func (dd msgpipelineDelivery) Commit() error {
 
 	for _, delivery := range dd.deliveries {
 		if err := delivery.Commit(); err != nil {
-			dd.log.Debugf("delivery.Commit failure, Delivery object = %T: %v", delivery, err)
 			// No point in Committing remaining deliveries, everything is broken already.
 			return err
 		}
-		dd.log.Debugf("delivery.Commit ok, Delivery object = %T", delivery)
 	}
 	return nil
 }
@@ -398,7 +390,6 @@ func (dd msgpipelineDelivery) Abort() error {
 			lastErr = err
 			// Continue anyway and try to Abort all remaining delivery objects.
 		}
-		dd.log.Debugf("delivery.Abort ok, Delivery object = %T", delivery)
 	}
 	dd.log.Debugf("delivery aborted")
 	return lastErr

mtasts/cache.go

@@ -118,7 +118,7 @@ func (c *Cache) RefreshCache() error {
 		// See https://tools.ietf.org/html/rfc8461#section-10.2.
 		cacheHit, _, err := c.fetch(true, time.Now().Add(6*time.Hour), ent.Name())
 		if err != nil {
-			c.Logger.Printf("failed to update MTA-STS policy for %v: %v", ent.Name(), err)
+			c.Logger.Error("policy update error", err, "domain", ent.Name())
 		}
 		if !cacheHit && err == nil {
 			c.Logger.Debugln("updated MTA-STS policy for", ent.Name())
@@ -128,9 +128,9 @@ func (c *Cache) RefreshCache() error {
 		// Remove cached version to save space.
 		if !cacheHit && err == ErrNoPolicy {
 			if err := os.Remove(filepath.Join(c.Location, ent.Name())); err != nil {
-				c.Logger.Println("failed to remove MTA-STS policy for", ent.Name())
+				c.Logger.Error("failed to remove policy", err, "domain", ent.Name())
 			}
-			c.Logger.Debugln("removed MTA-STS policy for", ent.Name())
+			c.Logger.Debugln("removed policy for", ent.Name())
 		}
 	}
 
@@ -190,7 +190,7 @@ func (c *Cache) fetch(ignoreDns bool, now time.Time, domain string) (cacheHit bo
 		}
 
 		if err := c.store(domain, dnsId, time.Now(), policy); err != nil {
-			c.Logger.Printf("failed to store new policy for %s: %v", domain, err)
+			c.Logger.Error("failed to store new policy", err, "domain", domain)
 			// We still got up-to-date policy, cache is not critcial.
 			return false, cachedPolicy, nil
 		}

target/delivery.go

@@ -1,23 +1,15 @@
 package target
 
 import (
-	"time"
-
 	"github.com/foxcpp/maddy/log"
 	"github.com/foxcpp/maddy/module"
 )
 
 func DeliveryLogger(l log.Logger, msgMeta *module.MsgMetadata) log.Logger {
-	out := l.Out
+	eventCtx := make([]interface{}, 0, len(l.Fields)+2)
-	if out == nil {
+	copy(eventCtx, l.Fields)
-		out = log.DefaultLogger.Out
+	eventCtx = append(eventCtx, "msg_id", msgMeta.ID)
-	}
 
-	return log.Logger{
+	l.Fields = eventCtx
-		Out: log.FuncOutput(func(t time.Time, debug bool, str string) {
+	return l
-			out.Write(t, debug, str+" (msg ID = "+msgMeta.ID+")")
-		}, out.Close),
-		Name:  l.Name,
-		Debug: l.Debug,
-	}
 }

target/queue/queue.go

@@ -261,7 +261,7 @@ func (q *Queue) dispatch() {
 			q.Log.Debugln("delivery semaphore acquired for", id)
 			meta, header, body, err := q.openMessage(id)
 			if err != nil {
-				q.Log.Printf("failed to read message: %v", err)
+				q.Log.Error("read message", err)
 				return
 			}
 
@@ -270,6 +270,44 @@ func (q *Queue) dispatch() {
 	}
 }
 
+func toSMTPErr(err error) *smtp.SMTPError {
+	if err == nil {
+		return nil
+	}
+
+	res := &smtp.SMTPError{
+		Code:         554,
+		EnhancedCode: smtp.EnhancedCodeNotSet,
+	}
+
+	if exterrors.IsTemporaryOrUnspec(err) {
+		res.Code = 451
+	}
+
+	ctxInfo := exterrors.Fields(err)
+	ctxCode, ok := ctxInfo["smtp_code"].(int)
+	if ok {
+		res.Code = ctxCode
+	}
+	ctxEnchCode, ok := ctxInfo["smtp_enchcode"].(smtp.EnhancedCode)
+	if ok {
+		res.EnhancedCode = ctxEnchCode
+	}
+	ctxMsg, ok := ctxInfo["smtp_msg"].(string)
+	if ok {
+		res.Message = ctxMsg
+	}
+
+	if smtpErr, ok := err.(*smtp.SMTPError); ok {
+		log.Printf("plain SMTP error returned, this is deprecated")
+		res.Code = smtpErr.Code
+		res.EnhancedCode = smtpErr.EnhancedCode
+		res.Message = smtpErr.Message
+	}
+
+	return res
+}
+
 func (q *Queue) tryDelivery(meta *QueueMetadata, header textproto.Header, body buffer.Buffer) {
 	dl := target.DeliveryLogger(q.Log, meta.MsgMeta)
 	dl.Debugf("delivery attempt #%d", meta.TriesCount+1)
@@ -283,27 +321,14 @@ func (q *Queue) tryDelivery(meta *QueueMetadata, header textproto.Header, body b
 			continue
 		}
 
-		dl.Printf("delivered to %s after %d attempt(s)", rcpt, meta.TriesCount+1)
+		dl.Msg("delivered", "rcpt", rcpt, "attempt", meta.TriesCount+1)
 	}
 
 	// Save errors information for reporting in bounce message.
 	meta.FailedRcpts = append(meta.FailedRcpts, partialErr.Failed...)
 	for rcpt, rcptErr := range partialErr.Errs {
-		var smtpErr *smtp.SMTPError
+		dl.Error("delivery attempt failed", rcptErr, "rcpt", rcpt)
-		var ok bool
+		meta.RcptErrs[rcpt] = toSMTPErr(rcptErr)
-		if smtpErr, ok = rcptErr.(*smtp.SMTPError); !ok {
-			smtpErr = &smtp.SMTPError{
-				Code:         554,
-				EnhancedCode: smtp.EnhancedCode{5, 0, 0},
-				Message:      rcptErr.Error(),
-			}
-			if exterrors.IsTemporaryOrUnspec(rcptErr) {
-				smtpErr.Code = 451
-				smtpErr.EnhancedCode = smtp.EnhancedCode{4, 0, 0}
-			}
-		}
-
-		meta.RcptErrs[rcpt] = smtpErr
 	}
 	meta.To = partialErr.TemporaryFailed
 
@@ -312,11 +337,11 @@ func (q *Queue) tryDelivery(meta *QueueMetadata, header textproto.Header, body b
 		// Attempt either fully succeeded or completely failed.
 		if meta.TriesCount == q.maxTries {
 			for _, rcpt := range meta.TemporaryFailedRcpts {
-				dl.Printf("gave up trying to deliver to %s", rcpt)
+				dl.Msg("not delivered, temporary error", "rcpt", rcpt)
 			}
 		}
 		for _, rcpt := range meta.FailedRcpts {
-			dl.Printf("failed to deliver to %s", rcpt)
+			dl.Msg("not delivered, permanent error", "rcpt", rcpt)
 		}
 		if (len(meta.FailedRcpts) != 0 || meta.TriesCount == q.maxTries) && !meta.DSN {
 			q.emitDSN(meta, header)
@@ -328,13 +353,15 @@ func (q *Queue) tryDelivery(meta *QueueMetadata, header textproto.Header, body b
 	meta.TriesCount++
 
 	if err := q.updateMetadataOnDisk(meta); err != nil {
-		dl.Printf("failed to update meta-data: %v", err)
+		dl.Error("meta-data update", err)
 	}
 
 	nextTryTime := time.Now()
 	nextTryTime = nextTryTime.Add(q.initialRetryTime * time.Duration(math.Pow(q.retryTimeScale, float64(meta.TriesCount-1))))
-	dl.Printf("%d attempt failed, will retry in %v (at %v) for %v",
+	dl.Msg("will retry",
-		meta.TriesCount, time.Until(nextTryTime), nextTryTime.Truncate(time.Second), meta.To)
+		"attempts_count", meta.TriesCount,
+		"next_try_delay", time.Until(nextTryTime),
+		"rcpts", meta.To)
 
 	q.wheel.Add(nextTryTime, meta.MsgMeta.ID)
 }
@@ -385,7 +412,7 @@ func (q *Queue) deliver(meta *QueueMetadata, header textproto.Header, body buffe
 	if len(acceptedRcpts) == 0 {
 		dl.Debugf("delivery.Abort (no accepted receipients)")
 		if err := delivery.Abort(); err != nil {
-			dl.Printf("delivery.Abort failed: %v", err)
+			dl.Error("delivery.Abort failed", err)
 		}
 		return perr
 	}
@@ -423,7 +450,7 @@ func (q *Queue) deliver(meta *QueueMetadata, header textproto.Header, body buffe
 		// No recipients succeeded.
 		dl.Debugf("delivery.Abort (all recipients failed)")
 		if err := delivery.Abort(); err != nil {
-			dl.Printf("delivery.Abort failed: %v", err)
+			dl.Msg("delivery.Abort failed", err)
 		}
 		return perr
 	}
@@ -516,15 +543,15 @@ func (q *Queue) removeFromDisk(msgMeta *module.MsgMetadata) {
 	// will detect and report it.
 	headerPath := filepath.Join(q.location, id+".header")
 	if err := os.Remove(headerPath); err != nil {
-		dl.Printf("failed to remove header from disk: %v", err)
+		dl.Error("failed to remove header from disk", err)
 	}
 	bodyPath := filepath.Join(q.location, id+".body")
 	if err := os.Remove(bodyPath); err != nil {
-		dl.Printf("failed to remove body from disk: %v", err)
+		dl.Error("failed to remove body from disk", err)
 	}
 	metaPath := filepath.Join(q.location, id+".meta")
 	if err := os.Remove(metaPath); err != nil {
-		dl.Printf("failed to remove meta-data from disk: %v", err)
+		dl.Error("failed to remove meta-data from disk", err)
 	}
 	dl.Debugf("removed message from disk")
 }
@@ -691,7 +718,7 @@ type BufferedReadCloser struct {
 
 func (q *Queue) tryRemoveDanglingFile(name string) {
 	if err := os.Remove(filepath.Join(q.location, name)); err != nil {
-		q.Log.Println(err)
+		q.Log.Error("dangling file remove failed", err)
 		return
 	}
 	q.Log.Printf("removed dangling file %s", name)
@@ -748,7 +775,7 @@ func (q *Queue) emitDSN(meta *QueueMetadata, header textproto.Header) {
 
 	dsnID, err := msgpipeline.GenerateMsgID()
 	if err != nil {
-		q.Log.Printf("rand.Rand error: %v", err)
+		q.Log.Error("rand.Rand error", err)
 		return
 	}
 
@@ -789,7 +816,7 @@ func (q *Queue) emitDSN(meta *QueueMetadata, header textproto.Header) {
 	dl := target.DeliveryLogger(q.Log, meta.MsgMeta)
 	dsnHeader, err := dsn.GenerateDSN(dsnEnvelope, mtaInfo, rcptInfo, header, &dsnBodyBlob)
 	if err != nil {
-		dl.Printf("failed to generate fail DSN: %v", err)
+		dl.Msg("failed to generate fail DSN", err)
 		return
 	}
 	dsnBody := buffer.MemoryBuffer{Slice: dsnBodyBlob.Bytes()}
@@ -799,18 +826,18 @@ func (q *Queue) emitDSN(meta *QueueMetadata, header textproto.Header) {
 		SrcProto:    "",
 		SrcHostname: q.hostname,
 	}
-	dl.Printf("generated failed DSN, DSN ID = %s", dsnID)
+	dl.Msg("generated failed DSN", "dsn_id", dsnID)
 
 	dsnDelivery, err := q.StartDSN(dsnMeta, "MAILER-DAEMON@"+q.autogenMsgDomain)
 	if err != nil {
-		dl.Printf("failed to enqueue DSN: %v", err)
+		dl.Error("failed to enqueue DSN", err, "dsn_id", dsnID)
 		return
 	}
 	defer func() {
 		if err != nil {
-			dl.Printf("failed to enqueue DSN: %v", err)
+			dl.Msg("failed to enqueue DSN", err, "dsn_id", dsnID)
 			if err := dsnDelivery.Abort(); err != nil {
-				dl.Printf("failed to abort DSN delivery: %v", err)
+				dl.Error("failed to abort DSN delivery", err, "dsn_id", dsnID)
 			}
 		}
 	}()

target/queue/queue_test.go

@@ -10,7 +10,6 @@ import (
 	"time"
 
 	"github.com/emersion/go-message/textproto"
-	"github.com/emersion/go-smtp"
 	"github.com/foxcpp/maddy/buffer"
 	"github.com/foxcpp/maddy/exterrors"
 	"github.com/foxcpp/maddy/module"
@@ -414,10 +413,7 @@ func TestQueueDelivery_TemporaryRcptReject(t *testing.T) {
 	dt := unreliableTarget{
 		rcptFailures: []map[string]error{
 			{
-				"tester1@example.org": &smtp.SMTPError{
+				"tester1@example.org": exterrors.WithTemporary(errors.New("go away"), true),
-					Code:    400,
-					Message: "go away",
-				},
 			},
 		},
 		committed: make(chan testutils.Msg, 10),
@@ -451,10 +447,7 @@ func TestQueueDelivery_SerializationRoundtrip(t *testing.T) {
 	dt := unreliableTarget{
 		rcptFailures: []map[string]error{
 			{
-				"tester1@example.org": &smtp.SMTPError{
+				"tester1@example.org": exterrors.WithTemporary(errors.New("go away"), true),
-					Code:    400,
-					Message: "go away",
-				},
 			},
 		},
 		committed: make(chan testutils.Msg, 10),
@@ -502,10 +495,7 @@ func TestQueueDelivery_DeserlizationCleanUp(t *testing.T) {
 		dt := unreliableTarget{
 			rcptFailures: []map[string]error{
 				{
-					"tester1@example.org": &smtp.SMTPError{
+					"tester1@example.org": exterrors.WithTemporary(errors.New("go away"), true),
-						Code:    400,
-						Message: "go away",
-					},
 				},
 			},
 			committed: make(chan testutils.Msg, 10),

target/remote/remote.go

@@ -176,9 +176,52 @@ func (rt *Target) Start(msgMeta *module.MsgMetadata, mailFrom string) (module.De
 	}, nil
 }
 
+func (rd *remoteDelivery) wrapClientErr(err error, serverName string) error {
+	if err == nil {
+		return nil
+	}
+	switch err := err.(type) {
+	case *smtp.SMTPError:
+		return &exterrors.SMTPError{
+			Code:         err.Code,
+			EnhancedCode: exterrors.EnhancedCode(err.EnhancedCode),
+			Message:      err.Message,
+			TargetName:   "remote",
+			Misc: map[string]interface{}{
+				"remote_server": serverName,
+			},
+		}
+	case *net.OpError:
+		return exterrors.WithTemporary(
+			exterrors.WithFields(
+				err.Err,
+				map[string]interface{}{
+					"remote_addr": err.Addr,
+					"io_op":       err.Op,
+					"target":      "remote",
+				},
+			),
+			err.Temporary(),
+		)
+	default:
+		return exterrors.WithFields(err, map[string]interface{}{
+			"remote_server": serverName,
+			"target":        "remote",
+		})
+	}
+}
+
 func (rd *remoteDelivery) AddRcpt(to string) error {
 	if rd.msgMeta.Quarantine {
-		return errors.New("remote: refusing to deliver quarantined message")
+		return exterrors.WithFields(
+			exterrors.WithTemporary(
+				errors.New("remote: refusing to deliver quarantined message"),
+				false,
+			),
+			map[string]interface{}{
+				"target": "remote",
+			},
+		)
 	}
 
 	_, domain, err := address.Split(to)
@@ -189,18 +232,25 @@ func (rd *remoteDelivery) AddRcpt(to string) error {
 	// Special-case for <postmaster> address. If it is not handled by a rewrite rule before
 	// - we should not attempt to do anything with it and reject it as invalid.
 	if domain == "" {
-		return fmt.Errorf("<postmaster> address is not supported")
+		return exterrors.WithFields(
+			exterrors.WithTemporary(
+				errors.New("remote: <postmaster> address is not supported"),
+				false,
+			),
+			map[string]interface{}{
+				"target": "remote",
+			},
+		)
 	}
 
 	// serverName (MX serv. address) is very useful for tracing purposes and should be logged on all related errors.
 	conn, err := rd.connectionForDomain(domain)
 	if err != nil {
-		return err
+		return rd.wrapClientErr(err, domain)
 	}
 
 	if err := conn.Rcpt(to); err != nil {
-		rd.Log.Printf("RCPT TO %s failed: %v (server = %s)", to, err, conn.serverName)
+		return rd.wrapClientErr(err, conn.serverName)
-		return err
 	}
 
 	rd.recipients = append(rd.recipients, to)
@@ -259,30 +309,25 @@ func (rd *remoteDelivery) BodyNonAtomic(c module.StatusCollector, header textpro
 
 			bodyW, err := conn.Data()
 			if err != nil {
-				rd.Log.Printf("DATA failed: %v (server = %s)", err, conn.serverName)
 				setErr(err)
 				return
 			}
 			bodyR, err := b.Open()
 			if err != nil {
-				rd.Log.Printf("failed to open body buffer: %v", err)
 				setErr(err)
 				return
 			}
 			defer bodyR.Close()
 			if err = textproto.WriteHeader(bodyW, header); err != nil {
-				rd.Log.Printf("header write failed: %v (server = %s)", err, conn.serverName)
 				setErr(err)
 				return
 			}
 			if _, err = io.Copy(bodyW, bodyR); err != nil {
-				rd.Log.Printf("body write failed: %v (server = %s)", err, conn.serverName)
 				setErr(err)
 				return
 			}
 
 			if err := bodyW.Close(); err != nil {
-				rd.Log.Printf("body write final failed: %v (server = %s)", err, conn.serverName)
 				setErr(err)
 				return
 			}
@@ -323,7 +368,7 @@ func (rd *remoteDelivery) connectionForDomain(domain string) (*remoteConnection,
 	}
 	requireTLS = requireTLS || rd.rt.requireTLS
 	if !requireTLS {
-		rd.Log.Printf("TLS is not enforced when delivering to %s", domain)
+		rd.Log.Msg("TLS not enforced", "domain", domain)
 	}
 
 	var lastErr error
@@ -333,22 +378,22 @@ func (rd *remoteDelivery) connectionForDomain(domain string) (*remoteConnection,
 
 		conn.Client, err = rd.rt.connectToServer(addr, requireTLS)
 		if err != nil {
-			rd.Log.Printf("failed to connect to %s: %v", addr, err)
+			if len(addrs) != 1 {
+				rd.Log.Error("connect error", err, "remote_server", addr)
+			}
 			lastErr = err
 			continue
 		}
 	}
 	if conn.Client == nil {
-		rd.Log.Printf("no usable MX servers found for %s", domain)
 		return nil, lastErr
 	}
 
 	if err := conn.Mail(rd.mailFrom); err != nil {
-		rd.Log.Printf("MAIL FROM %s failed: %v (server = %s)", rd.mailFrom, err, conn.serverName)
+		return nil, rd.wrapClientErr(err, conn.serverName)
-		return nil, err
 	}
 
-	rd.Log.Debugf("connected to %s", conn.serverName)
+	rd.Log.DebugMsg("connected", "remote_server", conn.serverName)
 	rd.connections[domain] = conn
 
 	return conn, nil
@@ -368,7 +413,7 @@ func (rt *Target) stsCacheUpdater() {
 	// time.
 	rt.Log.Debugln("updating MTA-STS cache...")
 	if err := rt.mtastsCache.RefreshCache(); err != nil {
-		rt.Log.Printf("MTA-STS cache opdate failed: %v", err)
+		rt.Log.Msg("MTA-STS cache update error", err)
 	}
 	rt.Log.Debugln("updating MTA-STS cache... done!")
 
@@ -377,7 +422,7 @@ func (rt *Target) stsCacheUpdater() {
 		case <-rt.stsCacheUpdateTick.C:
 			rt.Log.Debugln("updating MTA-STS cache...")
 			if err := rt.mtastsCache.RefreshCache(); err != nil {
-				rt.Log.Printf("MTA-STS cache opdate failed: %v", err)
+				rt.Log.Msg("MTA-STS cache opdate error", err)
 			}
 			rt.Log.Debugln("updating MTA-STS cache... done!")
 		case <-rt.stsCacheUpdateDone:
@@ -417,6 +462,7 @@ func (rd *remoteDelivery) lookupAndFilter(domain string) (candidates []string, r
 		if err != nil {
 			return nil, false, err
 		}
+		if policy != nil {
 			switch policy.Mode {
 			case mtasts.ModeEnforce:
 				requireTLS = true
@@ -424,6 +470,7 @@ func (rd *remoteDelivery) lookupAndFilter(domain string) (candidates []string, r
 				policy = nil
 			}
 		}
+	}
 
 	dnssecOk, mxs, err := rd.lookupMX(domain)
 	if err != nil {
@@ -452,34 +499,34 @@ func (rd *remoteDelivery) lookupAndFilter(domain string) (candidates []string, r
 		if policy != nil {
 			if policy.Match(mx.Host) {
 				// Policy in 'testing' mode is enough to authenticate MX too.
-				rd.Log.Debugf("authenticated MX (%s) using MTA-STS", mx.Host)
+				rd.Log.Msg("authenticated MX using MTA-STS", "mx", mx.Host, "domain", domain)
 				authenticated = true
 			} else if policy.Mode == mtasts.ModeEnforce {
 				// Honor *enforced* policy and skip non-matching MXs even if we
 				// don't require authentication.
-				rd.Log.Printf("ignoring MX (%s) due to MTA-STS", mx.Host)
+				rd.Log.Msg("ignoring MX due to MTA-STS", "mx", mx.Host, "domain", domain)
 				skippedMXs = true
 				continue
 			}
 		}
 		// If we have DNSSEC - DNSSEC-signed MX record also qualifies as "safe".
 		if dnssecOk {
-			rd.Log.Debugf("authenticated MX (%s) using DNSSEC", mx.Host)
+			rd.Log.Msg("authenticated MX using DNSSEC", "mx", mx.Host, "domain", domain)
 			authenticated = true
 		}
 		if _, use := rd.rt.mxAuth[AuthCommonDomain]; use && commonDomainCheck(domain, mx.Host) {
-			rd.Log.Printf("authenticated MX (%s) using 'common domain' rule", mx.Host)
+			rd.Log.Msg("authenticated MX using common domain rule", "mx", mx.Host, "domain", domain)
 			authenticated = true
 		}
 
 		if !authenticated {
 			if rd.rt.requireMXAuth {
-				rd.Log.Printf("ignoring non-authenticated MX (%s)", mx.Host)
+				rd.Log.Msg("ignoring non-authenticated MX", "mx", mx.Host, "domain", domain)
 				skippedMXs = true
 				continue
 			}
 			if _, disabled := rd.rt.mxAuth[AuthDisabled]; !disabled {
-				rd.Log.Printf("adding non-authenticated MX (%s) to candidates", mx.Host)
+				rd.Log.Msg("using non-authenticated MX", "mx", mx.Host, "domain", domain)
 			}
 		}
 

target/smtp_downstream/smtp_upstream.go

@@ -17,6 +17,7 @@ import (
 	"github.com/emersion/go-smtp"
 	"github.com/foxcpp/maddy/buffer"
 	"github.com/foxcpp/maddy/config"
+	"github.com/foxcpp/maddy/exterrors"
 	"github.com/foxcpp/maddy/log"
 	"github.com/foxcpp/maddy/module"
 	"github.com/foxcpp/maddy/target"
@@ -97,6 +98,7 @@ type delivery struct {
 	body     io.ReadCloser
 	hdr      textproto.Header
 
+	downstreamAddr string
 	client         *smtp.Client
 }
 
@@ -115,21 +117,32 @@ func (u *Upstream) Start(msgMeta *module.MsgMetadata, mailFrom string) (module.D
 
 func (d *delivery) connect() error {
 	// TODO: Review possibility of connection pooling here.
-	var lastErr error
+	var (
+		lastErr        error
+		lastDownstream string
+	)
 	for _, endp := range d.u.endpoints {
+		addr := net.JoinHostPort(endp.Host, endp.Port)
 		cl, err := d.attemptConnect(endp, d.u.attemptStartTLS)
 		if err == nil {
-			d.log.Debugf("connected to %s:%s", endp.Host, endp.Port)
+			d.log.DebugMsg("connected", "downstream_server", addr)
 			lastErr = nil
+			d.downstreamAddr = addr
 			d.client = cl
 			break
 		}
 
-		d.log.Debugf("connect to %s:%s failed: %v", endp.Host, endp.Port, err)
+		if len(d.u.endpoints) != 1 {
+			d.log.Msg("connect error", err, "downstream_server", addr)
+		}
 		lastErr = err
+		lastDownstream = addr
 	}
 	if lastErr != nil {
-		return lastErr
+		return exterrors.WithFields(lastErr, map[string]interface{}{
+			"target":            "smtp_downstream",
+			"downstream_server": lastDownstream,
+		})
 	}
 
 	if d.u.saslFactory != nil {
@@ -189,14 +202,37 @@ func (d *delivery) attemptConnect(endp config.Endpoint, attemptStartTLS bool) (*
 	return cl, nil
 }
 
+func (d *delivery) wrapClientErr(err error) error {
+	if err == nil {
+		return nil
+	}
+	switch err := err.(type) {
+	case *smtp.SMTPError:
+		return &exterrors.SMTPError{
+			Code:         err.Code,
+			EnhancedCode: exterrors.EnhancedCode(err.EnhancedCode),
+			Message:      err.Message,
+			TargetName:   "smtp_downstream",
+			Misc: map[string]interface{}{
+				"downstream_server": d.downstreamAddr,
+			},
+		}
+	default:
+		return exterrors.WithFields(err, map[string]interface{}{
+			"downstream_server": d.downstreamAddr,
+			"target":            "smtp_downstream",
+		})
+	}
+}
+
 func (d *delivery) AddRcpt(rcptTo string) error {
-	return d.client.Rcpt(rcptTo)
+	return d.wrapClientErr(d.client.Rcpt(rcptTo))
 }
 
 func (d *delivery) Body(header textproto.Header, body buffer.Buffer) error {
 	r, err := body.Open()
 	if err != nil {
-		return err
+		return exterrors.WithFields(err, map[string]interface{}{"target": "smtp_downstream"})
 	}
 
 	d.body = r
@@ -215,18 +251,18 @@ func (d *delivery) Commit() error {
 
 	wc, err := d.client.Data()
 	if err != nil {
-		return err
+		return d.wrapClientErr(err)
 	}
 
 	if err := textproto.WriteHeader(wc, d.hdr); err != nil {
-		return err
+		return d.wrapClientErr(err)
 	}
 
 	if _, err := io.Copy(wc, d.body); err != nil {
-		return err
+		return d.wrapClientErr(err)
 	}
 
-	return wc.Close()
+	return d.wrapClientErr(wc.Close())
 }
 
 func init() {