Skip to content

Commit

Permalink
Merge pull request #15 from decke/structured-logging
Browse files Browse the repository at this point in the history 
Add structured logging via logrus
  • Loading branch information
@decke
decke committed Mar 13, 2021
2 parents b36ed8e + 9921b38 commit d1933a2
Show file tree
Hide file tree
Showing 6 changed files with 185 additions and 40 deletions.
7 changes: 6 additions & 1 deletion config.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,9 @@ var (
)

var (
logFile = flag.String("logfile", "/var/log/smtprelay.log", "Path to logfile")
logFile = flag.String("logfile", "", "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")
Expand All @@ -33,4 +35,7 @@ var (

func ConfigLoad() {
iniflags.Parse()

// Set up logging as soon as possible
setupLogger()
}
2 changes: 2 additions & 0 deletions go.mod
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
)
Expand Down
11 changes: 11 additions & 0 deletions go.sum
View file
Original file line number Diff line number Diff line change
@@ -1,13 +1,24 @@
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=
golang.org/x/crypto v0.0.0-20201221181555-eec23a3978ad h1:DN0cp81fZ3njFcrLCytUHRSUkqBjfTo4Tx9RJTWs0EY=
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=
60 changes: 60 additions & 0 deletions logger.go
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,60 @@
package main

import (
"fmt"
"os"
"time"

"github.com/sirupsen/logrus"
)

var (
log *logrus.Logger
)

func setupLogger() {
log = logrus.New()

// Handle logfile
if (*logFile == "") {
log.SetOutput(os.Stderr)
} else {
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)
}
135 changes: 98 additions & 37 deletions main.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,23 +3,26 @@ 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 {
var peerIP net.IP
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"}
}

Expand All @@ -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"}
}

Expand Down Expand Up @@ -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"}
}
}
Expand All @@ -102,16 +114,20 @@ 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"}
}

if re.MatchString(addr) {
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"}
}

Expand All @@ -122,23 +138,30 @@ 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"}
}

if re.MatchString(addr) {
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
Expand All @@ -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)
Expand All @@ -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 == "" {
Expand All @@ -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
Expand All @@ -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{
Expand All @@ -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")
}
}

Expand All @@ -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://") {
Expand All @@ -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()

Expand Down

0 comments on commit d1933a2

Please sign in to comment.