Skip to content

Add structured logging via logrus #15

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
Mar 13, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 6 additions & 1 deletion config.go
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
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
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
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
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:
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch! In which kind of error situation does SendMail return this?

Copy link
Collaborator Author

@JonathonReinhart JonathonReinhart Mar 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I can't take credit for this; it was taken straight from #13. But in my testing I have seen:

ERRO[2021-03-13T02:47:27-05:00] delivery failed                               err_code=530 err_msg="5.7.0 Authentication Required. Learn more at\n5.7.0  https://support.google.com/mail/?p=WantAuthError h75sm6304163qke.80 - gsmtp" from=jreinhart@jrr-vaio host="smtp.gmail.com:587" peer=127.0.0.1 to="[[email protected]]" uuid=ada212ce-ca9d-4a2b-923a-830ce6f19e37

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@dannykopping do you know in which situation SendMail returns this error? I can check myself later but need a bigger screen.

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
Loading