Rework logging

Implement debug log (can be enabled using `debug` config directive)
Remove errors directive for IMAP endpoint module.

CONFIG_REFERENCE.md

@@ -39,21 +39,14 @@ Valid configuration directives and their forms:
 * `io_debug`
   Write all protocol commands from clients and responses to stderr.
 
-* `errors stderr`
+* `debug`
-  Write protocol errors log to stderr (default).
+  Verbose log only for this module.
-
-* `errors stdout`
-  Write protocol errors log to stdout.
-
-* `errors <file>` 
-   Write the protocol error log to the specified file (deprecated).
 
 ```
 imap imap://0.0.0.0 imaps://0.0.0.0:993 {
     tls /etc/ssl/private/cert.pem /etc/ssl/private/pkey.key
     auth pam
     insecure_auth
-    errors /var/lob/imap-errs.log
     storage spool
 }
 ```
@@ -99,6 +92,9 @@ Valid configuration directives and their forms:
 * `io_debug`
   Write all protocol commands from clients and responses to stderr.
 
+* `debug`
+  Verbose log only for this module.
+
 * `hostname <domain>`
   Set server domain name to advertise in EHLO/HELO response and for matching
   during delivery. Required.
@@ -239,6 +235,9 @@ Valid configuration directives:
 * `appendlimit <value>`
   Refuse to accept messages larger than `value` bytes. Default is 32 MiB.
 
+* `debug`
+  Verbose log only for this module.
+
 ### 'dummy' module
 
 No-op module. It doesn't need to be configured explicitly and can be referenced

cmd/maddy/main.go

@@ -2,12 +2,12 @@ package main
 
 import (
 	"flag"
-	"log"
 	"os"
 	"path/filepath"
 
 	"github.com/emersion/maddy"
 	"github.com/emersion/maddy/config"
+	"github.com/emersion/maddy/log"
 )
 
 func main() {
@@ -17,21 +17,25 @@ func main() {
 
 	absCfg, err := filepath.Abs(configpath)
 	if err != nil {
-		log.Fatalf("Failed to resolve path to config: %v", err)
+		log.Println("Failed to resolve path to config: %v", err)
+		os.Exit(1)
 	}
 
 	f, err := os.Open(absCfg)
 	if err != nil {
-		log.Fatalf("Cannot open %q: %v", configpath, err)
+		log.Println("Cannot open %q: %v", configpath, err)
+		os.Exit(1)
 	}
 	defer f.Close()
 
 	config, err := config.Read(f, absCfg)
 	if err != nil {
-		log.Fatalf("Cannot parse %q: %v", configpath, err)
+		log.Println("Cannot parse %q: %v", configpath, err)
+		os.Exit(1)
 	}
 
 	if err := maddy.Start(config); err != nil {
-		log.Fatal(err)
+		log.Println(err)
+		os.Exit(1)
 	}
 }

config.go

@@ -3,10 +3,6 @@ package maddy
 import (
 	"errors"
 	"fmt"
-	"io"
-	"io/ioutil"
-	"log"
-	"os"
 
 	"github.com/emersion/maddy/config"
 	"github.com/emersion/maddy/module"
@@ -123,31 +119,3 @@ func defaultStorage() (interface{}, error) {
 	}
 	return res, nil
 }
-
-func errorsDirective(m *config.Map, node *config.Node) (interface{}, error) {
-	if len(node.Args) != 1 {
-		return nil, m.MatchErr("expected 1 argument")
-	}
-	if len(node.Children) != 0 {
-		return nil, m.MatchErr("can't declare block here")
-	}
-
-	output := node.Args[0]
-	var w io.Writer
-	switch output {
-	case "off":
-		w = ioutil.Discard
-	case "stdout":
-		w = os.Stdout
-	case "stderr":
-		w = os.Stderr
-	default:
-		f, err := os.OpenFile(output, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0666)
-		if err != nil {
-			return nil, err
-		}
-		w = f
-	}
-
-	return log.New(w, "imap ", log.LstdFlags), nil
-}

default.go

@@ -1,9 +1,8 @@
 package maddy
 
 import (
-	"log"
-
 	"github.com/emersion/maddy/config"
+	"github.com/emersion/maddy/log"
 	"github.com/emersion/maddy/module"
 )
 

imap.go

@@ -4,18 +4,19 @@ import (
 	"crypto/tls"
 	"errors"
 	"fmt"
-	"log"
 	"net"
 	"os"
 	"strings"
 	"sync"
 
-	appendlimit "github.com/emersion/go-imap-appendlimit"
-	move "github.com/emersion/go-imap-move"
 	imapbackend "github.com/emersion/go-imap/backend"
 	imapserver "github.com/emersion/go-imap/server"
 	"github.com/emersion/maddy/config"
+	"github.com/emersion/maddy/log"
 	"github.com/emersion/maddy/module"
+
+	appendlimit "github.com/emersion/go-imap-appendlimit"
+	move "github.com/emersion/go-imap-move"
 	"github.com/foxcpp/go-sqlmail/imap/children"
 )
 
@@ -28,13 +29,17 @@ type IMAPEndpoint struct {
 
 	tlsConfig   *tls.Config
 	listenersWg sync.WaitGroup
+
+	Log log.Logger
 }
 
 func NewIMAPEndpoint(instName string, globalCfg map[string]config.Node, rawCfg config.Node) (module.Module, error) {
-	endp := new(IMAPEndpoint)
+	endp := &IMAPEndpoint{
+		name: instName,
+		Log:  log.Logger{Out: log.StderrLog, Name: "imap"},
+	}
 	endp.name = instName
 	var (
-		errorLog     *log.Logger
 		insecureAuth bool
 		ioDebug      bool
 	)
@@ -45,10 +50,7 @@ func NewIMAPEndpoint(instName string, globalCfg map[string]config.Node, rawCfg c
 	cfg.Custom("tls", true, true, nil, tlsDirective, &endp.tlsConfig)
 	cfg.Bool("insecure_auth", false, &insecureAuth)
 	cfg.Bool("io_debug", false, &insecureAuth)
-	cfg.Custom("errors", false, false, func() (interface{}, error) {
+	cfg.Bool("debug", true, &endp.Log.Debug)
-		return log.New(os.Stderr, "imap ", log.LstdFlags), nil
-	}, errorsDirective, &errorLog)
-
 	if _, err := cfg.Process(globalCfg, &rawCfg); err != nil {
 		return nil, err
 	}
@@ -57,10 +59,10 @@ func NewIMAPEndpoint(instName string, globalCfg map[string]config.Node, rawCfg c
 	for _, addr := range rawCfg.Args {
 		saddr, err := standardizeAddress(addr)
 		if err != nil {
-			return nil, fmt.Errorf("invalid address: %s", instName)
+			return nil, fmt.Errorf("imap: invalid address: %s", instName)
 		}
 		if saddr.Scheme != "imap" && saddr.Scheme != "imaps" {
-			return nil, fmt.Errorf("imap %s: imap or imaps scheme must be used, got %s", instName, saddr.Scheme)
+			return nil, fmt.Errorf("imap: imap or imaps scheme must be used, got %s", saddr.Scheme)
 		}
 		addresses = append(addresses, saddr)
 	}
@@ -68,6 +70,7 @@ func NewIMAPEndpoint(instName string, globalCfg map[string]config.Node, rawCfg c
 	endp.serv = imapserver.New(endp)
 	endp.serv.AllowInsecureAuth = insecureAuth
 	endp.serv.TLSConfig = endp.tlsConfig
+	endp.serv.ErrorLog = endp.Log.DebugWriter()
 	if ioDebug {
 		endp.serv.Debug = os.Stderr
 	}
@@ -83,7 +86,7 @@ func NewIMAPEndpoint(instName string, globalCfg map[string]config.Node, rawCfg c
 		if err != nil {
 			return nil, fmt.Errorf("failed to bind on %v: %v", addr, err)
 		}
-		log.Printf("imap: listening on %v\n", addr)
+		endp.Log.Printf("imap: listening on %v", addr)
 
 		if addr.IsTLS() {
 			if endp.tlsConfig == nil {
@@ -98,17 +101,17 @@ func NewIMAPEndpoint(instName string, globalCfg map[string]config.Node, rawCfg c
 		addr := addr
 		go func() {
 			if err := endp.serv.Serve(l); err != nil && !strings.HasSuffix(err.Error(), "use of closed network connection") {
-				log.Printf("imap: failed to serve %s: %s\n", addr, err)
+				endp.Log.Printf("imap: failed to serve %s: %s", addr, err)
 			}
 			endp.listenersWg.Done()
 		}()
 	}
 
 	if endp.serv.AllowInsecureAuth {
-		log.Printf("imap %s: authentication over unencrypted connections is allowed, this is insecure configuration and should be used only for testing!", endp.name)
+		endp.Log.Println("authentication over unencrypted connections is allowed, this is insecure configuration and should be used only for testing!")
 	}
 	if endp.serv.TLSConfig == nil {
-		log.Printf("imap %s: TLS is disabled, this is insecure configuration and should be used only for testing!", endp.name)
+		endp.Log.Println("TLS is disabled, this is insecure configuration and should be used only for testing!")
 		endp.serv.AllowInsecureAuth = true
 	}
 

log/log.go

@@ -0,0 +1,74 @@
+package log
+
+import (
+	"fmt"
+	"io"
+	"os"
+	"time"
+)
+
+/*
+Brutal logging library.
+*/
+
+type FuncLog func(t time.Time, debug bool, str string)
+
+type Logger struct {
+	Out   FuncLog
+	Name  string
+	Debug bool
+}
+
+func (l *Logger) Debugf(format string, val ...interface{}) {
+	if !l.Debug {
+		return
+	}
+	l.log(true, fmt.Sprintf(format+"\n", val...))
+}
+
+func (l *Logger) Debugln(val ...interface{}) {
+	if !l.Debug {
+		return
+	}
+	l.log(true, fmt.Sprintln(val...))
+}
+
+func (l *Logger) Printf(format string, val ...interface{}) {
+	l.log(false, fmt.Sprintf(format+"\n", val...))
+}
+
+func (l *Logger) Println(val ...interface{}) {
+	l.log(false, fmt.Sprintln(val...))
+}
+
+func (l *Logger) Write(s []byte) (int, error) {
+	l.log(false, string(s))
+	return len(s), nil
+}
+
+func (l Logger) DebugWriter() *Logger {
+	l.Debug = true
+	return &l
+}
+
+func (l *Logger) log(debug bool, s string) {
+	if l.Name != "" {
+		s = l.Name + ": " + s
+	}
+	l.Out(time.Now(), debug, s)
+}
+
+var DefaultLogger = Logger{Out: StderrLog}
+
+func Debugf(format string, val ...interface{}) { DefaultLogger.Debugf(format, val...) }
+func Debugln(val ...interface{})               { DefaultLogger.Debugln(val...) }
+func Printf(format string, val ...interface{}) { DefaultLogger.Printf(format, val...) }
+func Println(val ...interface{})               { DefaultLogger.Println(val...) }
+
+func StderrLog(t time.Time, debug bool, str string) {
+	if debug {
+		str = "[debug] " + str
+	}
+	str = t.Format("02.01.06 15:04:05") + " " + str
+	io.WriteString(os.Stderr, str)
+}

maddy.go

@@ -3,12 +3,12 @@ package maddy
 import (
 	"fmt"
 	"io"
-	"log"
 	"os"
 	"os/signal"
 	"syscall"
 
 	"github.com/emersion/maddy/config"
+	"github.com/emersion/maddy/log"
 	"github.com/emersion/maddy/module"
 )
 
@@ -19,7 +19,7 @@ func Start(cfg []config.Node) error {
 	defaultPresent := false
 	for _, block := range cfg {
 		switch block.Name {
-		case "tls", "hostname":
+		case "tls", "hostname", "debug":
 			globalCfg[block.Name] = block
 			continue
 		default:
@@ -33,9 +33,13 @@ func Start(cfg []config.Node) error {
 		initDefaultStorage(globalCfg)
 	}
 
+	if _, ok := globalCfg["debug"]; ok {
+		log.DefaultLogger.Debug = true
+	}
+
 	for _, block := range cfg {
 		switch block.Name {
-		case "hostname", "tls":
+		case "hostname", "tls", "debug":
 			continue
 		}
 
@@ -57,9 +61,10 @@ func Start(cfg []config.Node) error {
 			return fmt.Errorf("%s:%d: module instance named %s already exists", block.File, block.Line, instName)
 		}
 
+		log.Debugln("init for module", modName, instName)
 		inst, err := factory(instName, globalCfg, block)
 		if err != nil {
-			return fmt.Errorf("module instance %s initialization failed: %v", instName, err)
+			return err
 		}
 
 		module.RegisterInstance(inst)
@@ -70,15 +75,16 @@ func Start(cfg []config.Node) error {
 	signal.Notify(sig, os.Interrupt, syscall.SIGTERM, syscall.SIGHUP, syscall.SIGINT)
 
 	s := <-sig
-	log.Printf("signal received (%v), next signal will force immediate shutdown.\n", s)
+	log.Printf("signal received (%v), next signal will force immediate shutdown.", s)
 	go func() {
 		s := <-sig
-		log.Printf("forced shutdown due to signal (%v)!\n", s)
+		log.Printf("forced shutdown due to signal (%v)!", s)
 		os.Exit(1)
 	}()
 
 	for _, inst := range instances {
 		if closer, ok := inst.(io.Closer); ok {
+			log.Debugln("clean-up for module", inst.Name(), inst.InstanceName())
 			closer.Close()
 		}
 	}

smtp.go

@@ -6,7 +6,6 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"log"
 	"net"
 	"net/mail"
 	"os"
@@ -15,6 +14,7 @@ import (
 
 	"github.com/emersion/go-smtp"
 	"github.com/emersion/maddy/config"
+	"github.com/emersion/maddy/log"
 	"github.com/emersion/maddy/module"
 )
 
@@ -62,7 +62,7 @@ func (u SMTPUser) Send(from string, to []string, r io.Reader) error {
 				return nil
 			}
 			if err != nil {
-				log.Printf("smtp %s: %T failed: %v", u.endp.name, step, err)
+				u.endp.Log.Printf("%T failed: %v", step, err)
 				return err
 			}
 		}
@@ -70,13 +70,16 @@ func (u SMTPUser) Send(from string, to []string, r io.Reader) error {
 		if r != nil && r != io.Reader(currentMsg) {
 			buf.Reset()
 			if _, err := io.Copy(&buf, r); err != nil {
-				log.Printf("smtp %s: failed to buffer message: %v", u.endp.name, err)
+				u.endp.Log.Printf("failed to buffer message: %v", err)
 				return err
 			}
 			currentMsg.Reset(buf.Bytes())
 		}
 		currentMsg.Seek(0, io.SeekStart)
 	}
+
+	u.endp.Log.Printf("accepted incoming message from %s (%s)", ctx.SrcHostname, ctx.SrcAddr)
+
 	return nil
 }
 
@@ -94,6 +97,9 @@ type SMTPEndpoint struct {
 	submission bool
 
 	listenersWg sync.WaitGroup
+
+	debug bool
+	Log   log.Logger
 }
 
 func (endp *SMTPEndpoint) Name() string {
@@ -109,18 +115,25 @@ func (endp *SMTPEndpoint) Version() string {
 }
 
 func NewSMTPEndpoint(instName string, globalCfg map[string]config.Node, cfg config.Node) (module.Module, error) {
-	endp := new(SMTPEndpoint)
+	endp := &SMTPEndpoint{
+		name: instName,
+		Log:  log.Logger{Out: log.StderrLog, Name: "smtp"},
+	}
+	endp.serv = smtp.NewServer(endp)
 	endp.name = instName
 	endp.serv = smtp.NewServer(endp)
 	if err := endp.setConfig(globalCfg, cfg); err != nil {
 		return nil, err
 	}
 
+	endp.Log.Debugf("authentication provider: %s %s", endp.Auth.(module.Module).Name(), endp.Auth.(module.Module).InstanceName())
+	endp.Log.Debugf("pipeline: %#v", endp.pipeline)
+
 	addresses := make([]Address, 0, len(cfg.Args))
 	for _, addr := range cfg.Args {
 		saddr, err := standardizeAddress(addr)
 		if err != nil {
-			return nil, fmt.Errorf("invalid address: %s", instName)
+			return nil, fmt.Errorf("smtp: invalid address: %s", addr)
 		}
 
 		addresses = append(addresses, saddr)
@@ -134,10 +147,10 @@ func NewSMTPEndpoint(instName string, globalCfg map[string]config.Node, cfg conf
 	}
 
 	if endp.serv.AllowInsecureAuth {
-		log.Printf("smtp %s: authentication over unencrypted connections is allowed, this is insecure configuration and should be used only for testing!", endp.name)
+		endp.Log.Println("authentication over unencrypted connections is allowed, this is insecure configuration and should be used only for testing!")
 	}
 	if endp.serv.TLSConfig == nil && !endp.serv.LMTP {
-		log.Printf("smtp %s: TLS is disabled, this is insecure configuration and should be used only for testing!", endp.name)
+		endp.Log.Println("TLS is disabled, this is insecure configuration and should be used only for testing!")
 		endp.serv.AllowInsecureAuth = true
 	}
 
@@ -164,6 +177,7 @@ func (endp *SMTPEndpoint) setConfig(globalCfg map[string]config.Node, rawCfg con
 	cfg.Custom("tls", true, true, nil, tlsDirective, &endp.serv.TLSConfig)
 	cfg.Bool("insecure_auth", false, &endp.serv.AllowInsecureAuth)
 	cfg.Bool("io_debug", false, &ioDebug)
+	cfg.Bool("debug", true, &endp.Log.Debug)
 	cfg.Bool("submission", false, &endp.submission)
 	cfg.AllowUnknown()
 
@@ -176,27 +190,27 @@ func (endp *SMTPEndpoint) setConfig(globalCfg map[string]config.Node, rawCfg con
 		switch entry.Name {
 		case "local_delivery":
 			if len(entry.Args) == 0 {
-				return errors.New("local_delivery: expected at least 1 argument")
+				return errors.New("smtp: local_delivery: expected at least 1 argument")
 			}
 			if len(endp.pipeline) != 0 {
-				return errors.New("can't use custom pipeline with local_delivery or remote_delivery")
+				return errors.New("smtp: can't use custom pipeline with local_delivery or remote_delivery")
 			}
 
 			localDeliveryDefault = entry.Args[0]
 			localDeliveryOpts = readOpts(entry.Args[1:])
 		case "remote_delivery":
 			if len(entry.Args) == 0 {
-				return errors.New("remote_delivery: expected at least 1 argument")
+				return errors.New("smtp: remote_delivery: expected at least 1 argument")
 			}
 			if len(endp.pipeline) != 0 {
-				return errors.New("can't use custom pipeline with local_delivery or remote_delivery")
+				return errors.New("smtp: can't use custom pipeline with local_delivery or remote_delivery")
 			}
 
 			remoteDeliveryDefault = entry.Args[0]
 			remoteDeliveryOpts = readOpts(entry.Args[1:])
 		case "filter", "delivery", "match", "stop", "require_auth":
 			if localDeliveryDefault != "" || remoteDeliveryDefault != "" {
-				return errors.New("can't use custom pipeline with local_delivery or remote_delivery")
+				return errors.New("smtp: can't use custom pipeline with local_delivery or remote_delivery")
 			}
 
 			step, err := StepFromCfg(entry)
@@ -205,7 +219,7 @@ func (endp *SMTPEndpoint) setConfig(globalCfg map[string]config.Node, rawCfg con
 			}
 			endp.pipeline = append(endp.pipeline, step)
 		default:
-			return fmt.Errorf("unknown config directive: %v", entry.Name)
+			return fmt.Errorf("smtp: unknown config directive: %v", entry.Name)
 		}
 	}
 
@@ -231,13 +245,13 @@ func (endp *SMTPEndpoint) setupListeners(addresses []Address) error {
 	for _, addr := range addresses {
 		if addr.Scheme == "smtp" || addr.Scheme == "smtps" {
 			if lmtpUsed {
-				return errors.New("can't mix LMTP with SMTP in one endpoint block")
+				return errors.New("smtp: can't mix LMTP with SMTP in one endpoint block")
 			}
 			smtpUsed = true
 		}
 		if addr.Scheme == "lmtp+unix" || addr.Scheme == "lmtp" {
 			if smtpUsed {
-				return errors.New("can't mix LMTP with SMTP in one endpoint block")
+				return errors.New("smtp: can't mix LMTP with SMTP in one endpoint block")
 			}
 			lmtpUsed = true
 		}
@@ -248,11 +262,11 @@ func (endp *SMTPEndpoint) setupListeners(addresses []Address) error {
 		if err != nil {
 			return fmt.Errorf("failed to bind on %v: %v", addr, err)
 		}
-		log.Printf("smtp: listening on %v\n", addr)
+		endp.Log.Printf("listening on %v", addr)
 
 		if addr.IsTLS() {
 			if endp.serv.TLSConfig == nil {
-				return errors.New("can't bind on SMTPS endpoint without TLS configuration")
+				return errors.New("smtp: can't bind on SMTPS endpoint without TLS configuration")
 			}
 			l = tls.NewListener(l, endp.serv.TLSConfig)
 		}
@@ -263,7 +277,7 @@ func (endp *SMTPEndpoint) setupListeners(addresses []Address) error {
 		addr := addr
 		go func() {
 			if err := endp.serv.Serve(l); err != nil && !strings.HasSuffix(err.Error(), "use of closed network connection") {
-				log.Printf("smtp: failed to serve %s: %s\n", addr, err)
+				endp.Log.Printf("failed to serve %s: %s", addr, err)
 			}
 			endp.listenersWg.Done()
 		}()

sqlmail.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/emersion/go-imap/backend"
 	"github.com/emersion/maddy/config"
+	"github.com/emersion/maddy/log"
 	"github.com/emersion/maddy/module"
 	"github.com/foxcpp/go-sqlmail"
 	imapsqlmail "github.com/foxcpp/go-sqlmail/imap"
@@ -17,6 +18,7 @@ import (
 type SQLMail struct {
 	*imapsqlmail.Backend
 	instName string
+	Log      log.Logger
 }
 
 func (sqlm *SQLMail) Name() string {
@@ -37,11 +39,16 @@ func NewSQLMail(instName string, globalCfg map[string]config.Node, rawCfg config
 	appendlimitVal := int64(-1)
 
 	opts := imapsqlmail.Opts{}
+	mod := SQLMail{
+		instName: instName,
+		Log:      log.Logger{Out: log.StderrLog, Name: "sqlmail"},
+	}
 
 	cfg := config.Map{}
 	cfg.String("driver", false, true, "", &driver)
 	cfg.String("dsn", false, true, "", &dsn)
 	cfg.Int64("appendlimit", false, false, 32*1024*1024, &appendlimitVal)
+	cfg.Bool("debug", true, &mod.Log.Debug)
 
 	if _, err := cfg.Process(globalCfg, &rawCfg); err != nil {
 		return nil, err
@@ -54,11 +61,7 @@ func NewSQLMail(instName string, globalCfg map[string]config.Node, rawCfg config
 		*opts.MaxMsgBytes = uint32(appendlimitVal)
 	}
 	sqlm, err := imapsqlmail.NewBackend(driver, dsn, opts)
-
+	mod.Backend = sqlm
-	mod := SQLMail{
-		Backend:  sqlm,
-		instName: instName,
-	}
 
 	if err != nil {
 		return nil, err
@@ -79,6 +82,7 @@ func (sqlm *SQLMail) Deliver(ctx module.DeliveryContext, msg io.Reader) error {
 	for _, rcpt := range ctx.To {
 		parts := strings.Split(rcpt, "@")
 		if len(parts) != 2 {
+			sqlm.Log.Println("malformed address:", rcpt)
 			return errors.New("Deliver: missing domain part")
 		}
 
@@ -89,6 +93,7 @@ func (sqlm *SQLMail) Deliver(ctx module.DeliveryContext, msg io.Reader) error {
 			}
 
 			if parts[1] != hostname {
+				sqlm.Log.Debugf("local_only, skipping %s", rcpt)
 				continue
 			}
 		}
@@ -99,12 +104,14 @@ func (sqlm *SQLMail) Deliver(ctx module.DeliveryContext, msg io.Reader) error {
 			}
 
 			if parts[1] == hostname {
+				sqlm.Log.Debugf("remote_only, skipping %s", rcpt)
 				continue
 			}
 		}
 
 		u, err := sqlm.GetExistingUser(parts[0])
 		if err != nil {
+			sqlm.Log.Debugf("failed to get user for %s: %v", rcpt, err)
 			return err
 		}
 
@@ -115,7 +122,9 @@ func (sqlm *SQLMail) Deliver(ctx module.DeliveryContext, msg io.Reader) error {
 		if err != nil {
 			if err == backend.ErrNoSuchMailbox {
 				// Create INBOX if it doesn't exists.
+				sqlm.Log.Debugln("creating inbox for", rcpt)
 				if err := u.CreateMailbox(tgtMbox); err != nil {
+					sqlm.Log.Debugln("inbox creation failed for", rcpt)
 					return err
 				}
 				mbox, err = u.GetMailbox(tgtMbox)
@@ -123,11 +132,13 @@ func (sqlm *SQLMail) Deliver(ctx module.DeliveryContext, msg io.Reader) error {
 					return err
 				}
 			} else {
+				sqlm.Log.Debugf("failed to get inbox for %s: %v", rcpt, err)
 				return err
 			}
 		}
 
 		if err := mbox.CreateMessage([]string{}, time.Now(), &buf); err != nil {
+			sqlm.Log.Debugf("failed to save msg for %s: %v", rcpt, err)
 			return err
 		}
 	}

submission.go

@@ -11,6 +11,7 @@ import (
 	"github.com/emersion/go-message"
 	"github.com/emersion/go-smtp"
 	"github.com/emersion/maddy/config"
+	"github.com/emersion/maddy/log"
 	"github.com/emersion/maddy/module"
 	"github.com/google/uuid"
 )
@@ -33,6 +34,7 @@ func (step submissionPrepareStep) Pass(ctx *module.DeliveryContext, msg io.Reade
 		if err != nil {
 			return nil, false, errors.New("Message-ID generation failed")
 		}
+		log.Debugf("adding missing Message-ID header to message from %s (%s)", ctx.SrcHostname, ctx.SrcAddr)
 		parsed.Header.Set("Message-ID", "<"+msgId.String()+"@"+ctx.OurHostname+">")
 	}
 
@@ -90,6 +92,7 @@ func (step submissionPrepareStep) Pass(ctx *module.DeliveryContext, msg io.Reade
 			}
 		}
 	} else {
+		log.Debugf("adding missing Date header to message from %s (%s)", ctx.SrcHostname, ctx.SrcAddr)
 		parsed.Header.Set("Date", time.Now().Format("Mon, 2 Jan 2006 15:04:05 -0700"))
 	}