diff --git a/config.go b/config.go index 2ff92a7..f6e3bbc 100644 --- a/config.go +++ b/config.go @@ -13,6 +13,8 @@ var ( var ( logFile = flag.String("logfile", "/var/log/smtprelay.log", "Path to logfile") + logFormat = flag.String("log_format", "default", "Log output format") + logLevel = flag.String("log_level", "info", "Minimum log level to output") hostName = flag.String("hostname", "localhost.localdomain", "Server hostname") welcomeMsg = flag.String("welcome_msg", "", "Welcome message for SMTP session") listen = flag.String("listen", "127.0.0.1:25 [::1]:25", "Address and port to listen for incoming SMTP") @@ -33,4 +35,7 @@ var ( func ConfigLoad() { iniflags.Parse() + + // Set up logging as soon as possible + setupLogger() } diff --git a/go.mod b/go.mod index 4d01687..a1199e2 100644 --- a/go.mod +++ b/go.mod @@ -2,6 +2,8 @@ module github.com/decke/smtprelay require ( github.com/chrj/smtpd v0.2.0 + github.com/google/uuid v1.2.0 + github.com/sirupsen/logrus v1.7.0 github.com/vharitonsky/iniflags v0.0.0-20180513140207-a33cd0b5f3de golang.org/x/crypto v0.0.0-20201221181555-eec23a3978ad ) diff --git a/go.sum b/go.sum index 5a8a810..8f02620 100644 --- a/go.sum +++ b/go.sum @@ -1,6 +1,16 @@ github.com/chrj/smtpd v0.2.0 h1:QGbE4UQz7sKjvXpRgNLuiBOjcWTzBKu/dj0hyDLpD14= github.com/chrj/smtpd v0.2.0/go.mod h1:1hmG9KbrE10JG1SmvG79Krh4F6713oUrw2+gRp1oSYk= +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/eaigner/dkim v0.0.0-20150301120808-6fe4a7ee9cfb/go.mod h1:FSCIHbrqk7D01Mj8y/jW+NS1uoCerr+ad+IckTHTFf4= +github.com/google/uuid v1.2.0 h1:qJYtXnJRWmpe7m/3XlyhrsLrEURqHRM2kxzoxXqyUDs= +github.com/google/uuid v1.2.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= +github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/sirupsen/logrus v1.7.0 h1:ShrD1U9pZB12TX0cVy0DtePoCH97K8EtX+mg7ZARUtM= +github.com/sirupsen/logrus v1.7.0/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0= +github.com/stretchr/testify v1.2.2 h1:bSDNvY7ZPG5RlJ8otE/7V6gMiyenm9RtJ7IUVIAoJ1w= +github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs= github.com/vharitonsky/iniflags v0.0.0-20180513140207-a33cd0b5f3de h1:fkw+7JkxF3U1GzQoX9h69Wvtvxajo5Rbzy6+YMMzPIg= github.com/vharitonsky/iniflags v0.0.0-20180513140207-a33cd0b5f3de/go.mod h1:irMhzlTz8+fVFj6CH2AN2i+WI5S6wWFtK3MBCIxIpyI= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= @@ -8,6 +18,7 @@ golang.org/x/crypto v0.0.0-20201221181555-eec23a3978ad h1:DN0cp81fZ3njFcrLCytUHR golang.org/x/crypto v0.0.0-20201221181555-eec23a3978ad/go.mod h1:jdWPYTVW3xRLrWPugEBEK3UY2ZEsg3UU495nc5E+M+I= golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= +golang.org/x/sys v0.0.0-20191026070338-33540a1f6037 h1:YyJpGZS1sBuBCzLAR1VEpK193GlqGZbnPFnPV/5Rsb4= golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/term v0.0.0-20201117132131-f5c789dd3221/go.mod h1:Nr5EML6q2oocZ2LXRh80K7BxOlk5/8JxuGnuhpl+muw= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= diff --git a/logger.go b/logger.go new file mode 100644 index 0000000..4ed33ef --- /dev/null +++ b/logger.go @@ -0,0 +1,58 @@ +package main + +import ( + "fmt" + "os" + "time" + + "github.com/sirupsen/logrus" +) + +var ( + log *logrus.Logger +) + +func setupLogger() { + log = logrus.New() + + // Handle logfile + if (*logFile != "") { + writer, err := os.OpenFile(*logFile, os.O_CREATE|os.O_RDWR|os.O_APPEND, 0600) + if err != nil { + fmt.Printf("cannot open log file: %s\n", err) + os.Exit(1) + } + + log.SetOutput(writer) + } + + // Handle log_format + switch *logFormat { + case "json": + log.SetFormatter(&logrus.JSONFormatter{ + TimestampFormat: time.RFC3339Nano, + DisableHTMLEscape: true, + }) + case "plain": + log.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + case "", "default": + log.SetFormatter(&logrus.TextFormatter{ + FullTimestamp: true, + }) + default: + fmt.Fprintf(os.Stderr, "Invalid log_format: %s\n", *logFormat) + os.Exit(1) + } + + // Handle log_level + level, err := logrus.ParseLevel(*logLevel) + if err != nil { + level = logrus.InfoLevel + + log.WithField("given_level", *logLevel). + Warn("could not parse log level, defaulting to 'info'") + } + log.SetLevel(level) +} diff --git a/main.go b/main.go index 2e7d518..0024c1f 100644 --- a/main.go +++ b/main.go @@ -3,16 +3,17 @@ package main import ( "crypto/tls" "fmt" - "io" - "log" "net" "net/smtp" + "net/textproto" "os" "regexp" "strings" "time" "github.com/chrj/smtpd" + "github.com/google/uuid" + "github.com/sirupsen/logrus" ) func connectionChecker(peer smtpd.Peer) error { @@ -20,6 +21,8 @@ func connectionChecker(peer smtpd.Peer) error { if addr, ok := peer.Addr.(*net.TCPAddr); ok { peerIP = net.ParseIP(addr.IP.String()) } else { + log.WithField("ip", addr.IP). + Warn("failed to parse IP") return smtpd.Error{Code: 421, Message: "Denied"} } @@ -33,7 +36,9 @@ func connectionChecker(peer smtpd.Peer) error { } } - log.Printf("Connection from peer=[%s] denied: Not in allowed_nets\n", peerIP) + log.WithFields(logrus.Fields{ + "ip": peerIP, + }).Warn("Connection refused from address outside of allowed_nets") return smtpd.Error{Code: 421, Message: "Denied"} } @@ -86,12 +91,19 @@ func senderChecker(peer smtpd.Peer, addr string) error { user, err := AuthFetch(peer.Username) if err != nil { // Shouldn't happen: authChecker already validated username+password + log.WithFields(logrus.Fields{ + "peer": peer.Addr, + "username": peer.Username, + }).WithError(err).Warn("could not fetch auth user") return smtpd.Error{Code: 451, Message: "Bad sender address"} } if !addrAllowed(addr, user.allowedAddresses) { - log.Printf("Mail from=<%s> not allowed for authenticated user %s (%v)\n", - addr, peer.Username, peer.Addr) + log.WithFields(logrus.Fields{ + "peer": peer.Addr, + "username": peer.Username, + "sender_address": addr, + }).Warn("sender address not allowed for authenticated user") return smtpd.Error{Code: 451, Message: "Bad sender address"} } } @@ -102,7 +114,9 @@ func senderChecker(peer smtpd.Peer, addr string) error { re, err := regexp.Compile(*allowedSender) if err != nil { - log.Printf("allowed_sender invalid: %v\n", err) + log.WithFields(logrus.Fields{ + "allowed_sender": *allowedSender, + }).WithError(err).Warn("allowed_sender pattern invalid") return smtpd.Error{Code: 451, Message: "Bad sender address"} } @@ -110,8 +124,10 @@ func senderChecker(peer smtpd.Peer, addr string) error { return nil } - log.Printf("Mail from=<%s> not allowed by allowed_sender pattern for peer %v\n", - addr, peer.Addr) + log.WithFields(logrus.Fields{ + "sender_address": addr, + "peer": peer.Addr, + }).Warn("Sender address not allowed by allowed_sender pattern") return smtpd.Error{Code: 451, Message: "Bad sender address"} } @@ -122,7 +138,9 @@ func recipientChecker(peer smtpd.Peer, addr string) error { re, err := regexp.Compile(*allowedRecipients) if err != nil { - log.Printf("allowed_recipients invalid: %v\n", err) + log.WithFields(logrus.Fields{ + "allowed_recipients": *allowedRecipients, + }).WithError(err).Warn("allowed_recipients pattern invalid") return smtpd.Error{Code: 451, Message: "Bad recipient address"} } @@ -130,15 +148,20 @@ func recipientChecker(peer smtpd.Peer, addr string) error { return nil } - log.Printf("Mail to=<%s> not allowed by allowed_recipients pattern for peer %v\n", - addr, peer.Addr) + log.WithFields(logrus.Fields{ + "peer": peer.Addr, + "recipient_address": addr, + }).Warn("recipient address not allowed by allowed_recipients pattern") return smtpd.Error{Code: 451, Message: "Bad recipient address"} } func authChecker(peer smtpd.Peer, username string, password string) error { err := AuthCheckPassword(username, password) if err != nil { - log.Printf("Auth error for peer %v: %v\n", peer.Addr, err) + log.WithFields(logrus.Fields{ + "peer": peer.Addr, + "username": username, + }).WithError(err).Warn("auth error") return smtpd.Error{Code: 535, Message: "Authentication credentials invalid"} } return nil @@ -150,8 +173,14 @@ func mailHandler(peer smtpd.Peer, env smtpd.Envelope) error { peerIP = addr.IP.String() } - log.Printf("new mail from=<%s> to=%s peer=[%s]\n", env.Sender, - env.Recipients, peerIP) + logger := log.WithFields(logrus.Fields{ + "from": env.Sender, + "to": env.Recipients, + "peer": peerIP, + "host": *remoteHost, + "uuid": generateUUID(), + }) + logger.Info("delivering mail from peer using smarthost") var auth smtp.Auth host, _, _ := net.SplitHostPort(*remoteHost) @@ -169,8 +198,6 @@ func mailHandler(peer smtpd.Peer, env smtpd.Envelope) error { env.AddReceivedLine(peer) - log.Printf("delivering using smarthost %s\n", *remoteHost) - var sender string if *remoteSender == "" { @@ -187,15 +214,44 @@ func mailHandler(peer smtpd.Peer, env smtpd.Envelope) error { env.Data, ) if err != nil { - log.Printf("delivery failed: %v\n", err) - return smtpd.Error{Code: 554, Message: "Forwarding failed"} + var smtpError smtpd.Error + + switch err.(type) { + case *textproto.Error: + err := err.(*textproto.Error) + smtpError = smtpd.Error{Code: err.Code, Message: err.Msg} + + logger.WithFields(logrus.Fields{ + "err_code": err.Code, + "err_msg": err.Msg, + }).Error("delivery failed") + default: + smtpError = smtpd.Error{Code: 554, Message: "Forwarding failed"} + + logger.WithError(err). + Error("delivery failed") + } + + return smtpError } - log.Printf("%s delivery successful\n", env.Recipients) - + logger.Debug("delivery successful") return nil } +func generateUUID() string { + uniqueID, err := uuid.NewRandom() + + if err != nil { + log.WithError(err). + Error("could not generate UUIDv4") + + return "" + } + + return uniqueID.String() +} + func getTLSConfig() *tls.Config { // Ciphersuites as defined in stock Go but without 3DES and RC4 // https://golang.org/src/crypto/tls/cipher_suites.go @@ -214,12 +270,16 @@ func getTLSConfig() *tls.Config { } if *localCert == "" || *localKey == "" { - log.Fatal("TLS certificate/key not defined in config") + log.WithFields(logrus.Fields{ + "cert_file": *localCert, + "key_file": *localKey, + }).Fatal("TLS certificate/key file not defined in config") } cert, err := tls.LoadX509KeyPair(*localCert, *localKey) if err != nil { - log.Fatal(err) + log.WithField("error", err). + Fatal("cannot load X509 keypair") } return &tls.Config{ @@ -238,21 +298,16 @@ func main() { os.Exit(0) } - if *logFile != "" { - f, err := os.OpenFile(*logFile, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0600) - if err != nil { - log.Fatalf("Error opening logfile: %v", err) - } - defer f.Close() - - log.SetOutput(io.MultiWriter(os.Stdout, f)) - } + log.WithField("version", appVersion). + Debug("starting smtprelay") // Load allowed users file if *allowedUsers != "" { err := AuthLoadFile(*allowedUsers) if err != nil { - log.Fatalf("Authentication file: %s\n", err) + log.WithField("file", *allowedUsers). + WithError(err). + Fatal("cannot load allowed users file") } } @@ -275,7 +330,8 @@ func main() { var err error if strings.Index(listenAddr, "://") == -1 { - log.Printf("Listen on %s ...\n", listenAddr) + log.WithField("address", listenAddr). + Info("listening on address") lsnr, err = net.Listen("tcp", listenAddr) } else if strings.HasPrefix(listenAddr, "starttls://") { @@ -284,21 +340,26 @@ func main() { server.TLSConfig = getTLSConfig() server.ForceTLS = *localForceTLS - log.Printf("Listen on %s (STARTTLS) ...\n", listenAddr) + log.WithField("address", listenAddr). + Info("listening on address (STARTTLS)") lsnr, err = net.Listen("tcp", listenAddr) } else if strings.HasPrefix(listenAddr, "tls://") { listenAddr = strings.TrimPrefix(listenAddr, "tls://") server.TLSConfig = getTLSConfig() - log.Printf("Listen on %s (TLS) ...\n", listenAddr) + log.WithField("address", listenAddr). + Info("listening on address (TLS)") lsnr, err = tls.Listen("tcp", listenAddr, server.TLSConfig) } else { - log.Fatal("Unknown protocol in listen address ", listenAddr) + log.WithField("address", listenAddr). + Fatal("unknown protocol in listen address") } if err != nil { - log.Fatal(err) + log.WithFields(logrus.Fields{ + "address": listenAddr, + }).WithError(err).Fatal("error starting listener") } defer lsnr.Close() diff --git a/smtprelay.ini b/smtprelay.ini index 5417451..99b5c33 100644 --- a/smtprelay.ini +++ b/smtprelay.ini @@ -3,6 +3,12 @@ ; Logfile ;logfile = /var/log/smtprelay.log +; Log format: default, plain (no timestamp), json +;log_format = "default" + +; Log level: panic, fatal, error, warn, info, debug, trace +;log_level = "info" + ; Hostname for this SMTP server ;hostname = "localhost.localdomain"