Slightly improve debug logging for complex authentication pipelines

Author: foxcpp

framework/log/orderedjson.go

@@ -31,6 +31,11 @@ import (
 // human-readable when values from multiple messages are lined up to each
 // other.
 
+type module interface {
+	Name() string
+	InstanceName() string
+}
+
 func marshalOrderedJSON(output *strings.Builder, m map[string]interface{}) error {
 	order := make([]string, 0, len(m))
 	for k := range m {
@@ -62,6 +67,8 @@ func marshalOrderedJSON(output *strings.Builder, m map[string]interface{}) error
 			val = casted.FormatLog()
 		case fmt.Stringer:
 			val = casted.String()
+		case module:
+			val = casted.Name() + "/" + casted.InstanceName()
 		case error:
 			val = casted.Error()
 		}

internal/auth/sasl.go

@@ -105,12 +105,16 @@ func (s *SASLAuth) AuthPlain(username, password string) error {
 
 	var lastErr error
 	for _, p := range s.Plain {
-		username, err := s.usernameForAuth(context.TODO(), username)
+		mappedUsername, err := s.usernameForAuth(context.TODO(), username)
 		if err != nil {
 			return err
 		}
 
-		lastErr = p.AuthPlain(username, password)
+		s.Log.DebugMsg("attempting authentication",
+			"mapped_username", mappedUsername, "original_username", username,
+			"module", p)
+
+		lastErr = p.AuthPlain(mappedUsername, password)
 		if lastErr == nil {
 			return nil
 		}
@@ -139,12 +143,7 @@ func (s *SASLAuth) CreateSASL(mech string, remoteAddr net.Addr, successCb func(i
 				return ErrInvalidAuthCred
 			}
 
-			username, err := s.usernameForAuth(context.Background(), username)
-			if err != nil {
-				return err
-			}
-
-			err = s.AuthPlain(username, password)
+			err := s.AuthPlain(username, password)
 			if err != nil {
 				s.Log.Error("authentication failed", err, "username", username, "src_ip", remoteAddr)
 				return ErrInvalidAuthCred

internal/endpoint/dovecot_sasld/dovecot_sasl.go

@@ -79,6 +79,7 @@ func (endp *Endpoint) Init(cfg *config.Map) error {
 
 	endp.srv = dovecotsasl.NewServer()
 	endp.srv.Log = stdlog.New(endp.log, "", 0)
+	endp.saslAuth.Log.Debug = endp.log.Debug
 
 	for _, mech := range endp.saslAuth.SASLMechanisms() {
 		endp.srv.AddMechanism(mech, mechInfo[mech], func(req *dovecotsasl.AuthReq) sasl.Server {

internal/endpoint/imap/imap.go

@@ -112,6 +112,8 @@ func (endp *Endpoint) Init(cfg *config.Map) error {
 		}
 	}
 
+	endp.saslAuth.Log.Debug = endp.Log.Debug
+
 	addresses := make([]config.Endpoint, 0, len(endp.addrs))
 	for _, addr := range endp.addrs {
 		saddr, err := config.ParseEndpoint(addr)

maddy.go

@@ -110,15 +110,15 @@ func init() {
 			Value:   filepath.Join(ConfigDirectory, "maddy.conf"),
 		},
 	)
+	maddycli.AddGlobalFlag(&cli.BoolFlag{
+		Name:        "debug",
+		Usage:       "enable debug logging early",
+		Destination: &log.DefaultLogger.Debug,
+	})
 	maddycli.AddSubcommand(&cli.Command{
 		Name:  "run",
 		Usage: "Start the server",
 		Flags: []cli.Flag{
-			&cli.BoolFlag{
-				Name:        "debug",
-				Usage:       "enable debug logging early",
-				Destination: &log.DefaultLogger.Debug,
-			},
 			&cli.StringFlag{
 				Name:        "libexec",
 				Value:       DefaultLibexecDirectory,