diff --git a/CONFIG_REFERENCE.md b/CONFIG_REFERENCE.md index 8a3e3e6..a456409 100644 --- a/CONFIG_REFERENCE.md +++ b/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` - Write protocol errors log to stderr (default). - -* `errors stdout` - Write protocol errors log to stdout. - -* `errors ` - Write the protocol error log to the specified file (deprecated). +* `debug` + Verbose log only for this module. ``` 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 ` Set server domain name to advertise in EHLO/HELO response and for matching during delivery. Required. @@ -239,6 +235,9 @@ Valid configuration directives: * `appendlimit ` 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 diff --git a/cmd/maddy/main.go b/cmd/maddy/main.go index db91f45..e7a18f6 100644 --- a/cmd/maddy/main.go +++ b/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) } } diff --git a/config.go b/config.go index 593e0e9..3cf2e5d 100644 --- a/config.go +++ b/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 -} diff --git a/default.go b/default.go index 238e5d2..1a76a79 100644 --- a/default.go +++ b/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" ) diff --git a/imap.go b/imap.go index e79ac17..f2cf636 100644 --- a/imap.go +++ b/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) { - return log.New(os.Stderr, "imap ", log.LstdFlags), nil - }, errorsDirective, &errorLog) - + cfg.Bool("debug", true, &endp.Log.Debug) 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 } diff --git a/log/log.go b/log/log.go new file mode 100644 index 0000000..7b66bb8 --- /dev/null +++ b/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) +} diff --git a/maddy.go b/maddy.go index 18a49a9..d1a0639 100644 --- a/maddy.go +++ b/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() } } diff --git a/smtp.go b/smtp.go index 700cba8..3bf8ebf 100644 --- a/smtp.go +++ b/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() }() diff --git a/sqlmail.go b/sqlmail.go index fcff6bf..6450c23 100644 --- a/sqlmail.go +++ b/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 := SQLMail{ - Backend: sqlm, - instName: instName, - } + mod.Backend = sqlm 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 } } diff --git a/submission.go b/submission.go index c58e6b5..dab7062 100644 --- a/submission.go +++ b/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")) }