Implement structured logs using logrus

This was based loosely on an earlier implementation by
Danny Kopping <[email protected]>

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()
 }

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
 )

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=

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)
+}

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"}
 
-	log.Printf("%s delivery successful\n", env.Recipients)
+			logger.WithError(err).
+				Error("delivery failed")
+		}
+
+		return smtpError
+	}
 
+	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()
 

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"