Add zap logging through the servers.

diff --git a/.gitmodules b/.gitmodules
new file mode 100644 (file)
index 0000000..3886bf1
--- /dev/null
+++ b/.gitmodules
@@ -0,0 +1,6 @@
+[submodule "vendor/uber-go/zap"]
+       path = vendor/github.com/uber-go/zap
+       url = https://github.com/uber-go/zap
+[submodule "vendor/github.com/uber-go/atomic"]
+       path = vendor/github.com/uber-go/atomic
+       url = https://github.com/uber-go/atomic

diff --git a/mailpopbox.go b/mailpopbox.go
index 4b05b6a6198fb0a32fa6d8c38ba54dbebefbc3e7..ece1e6b9702e6d5d6ad825f74f938f5767d4fd89 100644 (file)
--- a/mailpopbox.go
+++ b/mailpopbox.go
@@ -4,6 +4,8 @@ import (
        "encoding/json"
        "fmt"
        "os"
+
+       "github.com/uber-go/zap"
 )
 
 func main() {
@@ -25,8 +27,10 @@ func main() {
        }
        configFile.Close()
 
-       pop3 := runPOP3Server(config)
-       smtp := runSMTPServer(config)
+       log := zap.New(zap.NewTextEncoder())
+
+       pop3 := runPOP3Server(config, log)
+       smtp := runSMTPServer(config, log)
 
        select {
        case err := <-pop3:

diff --git a/pop3.go b/pop3.go
index 0e21ec1fcb938c228fdfebf0083468946ddbea10..c803143b4a8edcac1f802106fa20730008730ec3 100644 (file)
--- a/pop3.go
+++ b/pop3.go
@@ -10,13 +10,16 @@ import (
        "os"
        "path"
 
+       "github.com/uber-go/zap"
+
        "src.bluestatic.org/mailpopbox/pop3"
 )
 
-func runPOP3Server(config Config) <-chan error {
+func runPOP3Server(config Config, log zap.Logger) <-chan error {
        server := pop3Server{
                config: config,
                rc:     make(chan error),
+               log:    log.With(zap.String("server", "pop3")),
        }
        go server.run()
        return server.rc
@@ -25,22 +28,26 @@ func runPOP3Server(config Config) <-chan error {
 type pop3Server struct {
        config Config
        rc     chan error
+       log    zap.Logger
 }
 
 func (server *pop3Server) run() {
        for _, s := range server.config.Servers {
                if err := os.Mkdir(s.MaildropPath, 0700); err != nil && !os.IsExist(err) {
+                       server.log.Error("failed to open maildrop", zap.Error(err))
                        server.rc <- err
                }
        }
 
        tlsConfig, err := server.config.GetTLSConfig()
        if err != nil {
+               server.log.Error("failed to configure TLS", zap.Error(err))
                server.rc <- err
                return
        }
 
        addr := fmt.Sprintf(":%d", server.config.POP3Port)
+       server.log.Info("starting server", zap.String("address", addr))
 
        var l net.Listener
        if tlsConfig == nil {
@@ -49,6 +56,7 @@ func (server *pop3Server) run() {
                l, err = tls.Listen("tcp", addr, tlsConfig)
        }
        if err != nil {
+               server.log.Error("listen", zap.Error(err))
                server.rc <- err
                return
        }
@@ -56,11 +64,12 @@ func (server *pop3Server) run() {
        for {
                conn, err := l.Accept()
                if err != nil {
+                       server.log.Error("accept", zap.Error(err))
                        server.rc <- err
                        break
                }
 
-               go pop3.AcceptConnection(conn, server)
+               go pop3.AcceptConnection(conn, server, server.log)
        }
 }
 

diff --git a/pop3/conn.go b/pop3/conn.go
index 15b7eb473fdfd50adb6f935fab8fdd0347080902..cbf86d32cab8f131d87c3f126a0928517f16a229 100644 (file)
--- a/pop3/conn.go
+++ b/pop3/conn.go
@@ -6,6 +6,8 @@ import (
        "net"
        "net/textproto"
        "strings"
+
+       "github.com/uber-go/zap"
 )
 
 type state int
@@ -30,17 +32,20 @@ type connection struct {
        tp         *textproto.Conn
        remoteAddr net.Addr
 
+       log zap.Logger
+
        state
        line string
 
        user string
 }
 
-func AcceptConnection(netConn net.Conn, po PostOffice) {
+func AcceptConnection(netConn net.Conn, po PostOffice, log zap.Logger) {
        conn := connection{
                po:    po,
                tp:    textproto.NewConn(netConn),
                state: stateAuth,
+               log:   log.With(zap.Stringer("client", netConn.RemoteAddr())),
        }
 
        var err error
@@ -50,6 +55,7 @@ func AcceptConnection(netConn net.Conn, po PostOffice) {
                conn.line, err = conn.tp.ReadLine()
                if err != nil {
                        conn.err("did't catch that")
+                       conn.log.Error("ReadLine()", zap.Error(err))
                        continue
                }
 
@@ -135,10 +141,12 @@ func (conn *connection) doPASS() {
 
        pass := conn.line[len("PASS "):]
        if mbox, err := conn.po.OpenMailbox(conn.user, pass); err == nil {
+               conn.log.Info("authenticated", zap.String("user", conn.user))
                conn.state = stateTxn
                conn.mb = mbox
                conn.ok("")
        } else {
+               conn.log.Error("PASS", zap.Error(err))
                conn.err(err.Error())
        }
 }
@@ -151,6 +159,7 @@ func (conn *connection) doSTAT() {
 
        msgs, err := conn.mb.ListMessages()
        if err != nil {
+               conn.log.Error("STAT", zap.Error(err))
                conn.err(err.Error())
                return
        }
@@ -176,6 +185,7 @@ func (conn *connection) doLIST() {
 
        msgs, err := conn.mb.ListMessages()
        if err != nil {
+               conn.log.Error("LIST", zap.Error(err))
                conn.err(err.Error())
                return
        }
@@ -205,6 +215,7 @@ func (conn *connection) doRETR() {
 
        rc, err := conn.mb.Retrieve(msg)
        if err != nil {
+               conn.log.Error("RETR", zap.Error(err))
                conn.err(err.Error())
                return
        }
@@ -233,6 +244,7 @@ func (conn *connection) doDELE() {
        }
 
        if err := conn.mb.Delete(msg); err != nil {
+               conn.log.Error("DELE", zap.Error(err))
                conn.err(err.Error())
        } else {
                conn.ok("")

diff --git a/smtp.go b/smtp.go
index d229765d23c4f022ab4a8ed92a6a45fef429a2f5..a4d1c199347df3f9b8461a2d8986dc2a960e3659 100644 (file)
--- a/smtp.go
+++ b/smtp.go
@@ -9,13 +9,16 @@ import (
        "path"
        "strings"
 
+       "github.com/uber-go/zap"
+
        "src.bluestatic.org/mailpopbox/smtp"
 )
 
-func runSMTPServer(config Config) <-chan error {
+func runSMTPServer(config Config, log zap.Logger) <-chan error {
        server := smtpServer{
                config: config,
                rc:     make(chan error),
+               log:    log.With(zap.String("server", "smtp")),
        }
        go server.run()
        return server.rc
@@ -25,6 +28,8 @@ type smtpServer struct {
        config    Config
        tlsConfig *tls.Config
 
+       log zap.Logger
+
        rc chan error
 }
 
@@ -32,11 +37,16 @@ func (server *smtpServer) run() {
        var err error
        server.tlsConfig, err = server.config.GetTLSConfig()
        if err != nil {
+               server.log.Error("failed to configure TLS", zap.Error(err))
                server.rc <- err
        }
 
-       l, err := net.Listen("tcp", fmt.Sprintf(":%d", server.config.SMTPPort))
+       addr := fmt.Sprintf(":%d", server.config.SMTPPort)
+       server.log.Info("starting server", zap.String("address", addr))
+
+       l, err := net.Listen("tcp", addr)
        if err != nil {
+               server.log.Error("listen", zap.Error(err))
                server.rc <- err
                return
        }
@@ -44,11 +54,12 @@ func (server *smtpServer) run() {
        for {
                conn, err := l.Accept()
                if err != nil {
+                       server.log.Error("accept", zap.Error(err))
                        server.rc <- err
                        return
                }
 
-               go smtp.AcceptConnection(conn, server)
+               go smtp.AcceptConnection(conn, server, server.log)
        }
 }
 

diff --git a/smtp/conn.go b/smtp/conn.go
index db9a9fff62d92b0825660fd18fb84576dfe79a68..08d14c6887ceaf7f9a5d44355612f485f1bdafce 100644 (file)
--- a/smtp/conn.go
+++ b/smtp/conn.go
@@ -9,6 +9,8 @@ import (
        "net/textproto"
        "strings"
        "time"
+
+       "github.com/uber-go/zap"
 )
 
 type state int
@@ -32,6 +34,8 @@ type connection struct {
 
        esmtp bool
 
+       log zap.Logger
+
        state
        line string
 
@@ -40,12 +44,13 @@ type connection struct {
        rcptTo   []mail.Address
 }
 
-func AcceptConnection(netConn net.Conn, server Server) error {
+func AcceptConnection(netConn net.Conn, server Server, log zap.Logger) error {
        conn := connection{
                server:     server,
                tp:         textproto.NewConn(netConn),
                nc:         netConn,
                remoteAddr: netConn.RemoteAddr(),
+               log:        log.With(zap.Stringer("client", netConn.RemoteAddr())),
                state:      stateNew,
        }
 
@@ -148,6 +153,8 @@ func (conn *connection) doEHLO() {
                conn.tp.PrintfLine("250 SIZE %d", 40960000)
        }
 
+       conn.log.Info("doEHLO()", zap.String("ehlo", conn.ehlo))
+
        conn.state = stateInitial
 }
 
@@ -163,6 +170,7 @@ func (conn *connection) doSTARTTLS() {
                return
        }
 
+       conn.log.Info("doSTARTTLS()")
        conn.writeReply(220, "initiate TLS connection")
 
        newConn := tls.Server(conn.nc, tlsConfig)
@@ -174,6 +182,8 @@ func (conn *connection) doSTARTTLS() {
        conn.tp = textproto.NewConn(conn.tlsNc)
        conn.state = stateInitial
 
+       conn.log.Info("HELO again")
+
        conn.writeReply(220, fmt.Sprintf("%s ESMTPS [%s] (mailpopbox)",
                conn.server.Name(), newConn.LocalAddr()))
 }
@@ -197,6 +207,8 @@ func (conn *connection) doMAIL() {
                return
        }
 
+       conn.log.Info("doMAIL()", zap.String("address", conn.mailFrom.Address))
+
        conn.state = stateMail
        conn.reply(ReplyOK)
 }
@@ -219,10 +231,15 @@ func (conn *connection) doRCPT() {
        }
 
        if reply := conn.server.VerifyAddress(*address); reply != ReplyOK {
+               conn.log.Warn("invalid address",
+                       zap.String("address", address.Address),
+                       zap.Stringer("reply", reply))
                conn.reply(reply)
                return
        }
 
+       conn.log.Info("doRCPT()", zap.String("address", address.Address))
+
        conn.rcptTo = append(conn.rcptTo, *address)
 
        conn.state = stateRecipient
@@ -236,10 +253,11 @@ func (conn *connection) doDATA() {
        }
 
        conn.writeReply(354, "Start mail input; end with <CRLF>.<CRLF>")
+       conn.log.Info("doDATA()")
 
        data, err := conn.tp.ReadDotBytes()
        if err != nil {
-               // TODO: log error
+               conn.log.Error("failed to ReadDotBytes()", zap.Error(err))
                conn.writeReply(552, "transaction failed")
                return
        }
@@ -254,11 +272,17 @@ func (conn *connection) doDATA() {
                ID:         conn.envelopeID(received),
        }
 
+       conn.log.Info("received message",
+               zap.Int("bytes", len(data)),
+               zap.Time("date", received),
+               zap.String("id", env.ID))
+
        trace := conn.getReceivedInfo(env)
 
        env.Data = append(trace, data...)
 
        if reply := conn.server.OnMessageDelivered(env); reply != nil {
+               conn.log.Warn("message was rejected", zap.String("id", env.ID))
                conn.reply(*reply)
                return
        }
@@ -356,6 +380,7 @@ func (conn *connection) getTransportString() string {
 }
 
 func (conn *connection) doRSET() {
+       conn.log.Info("doRSET()")
        conn.state = stateInitial
        conn.resetBuffers()
        conn.reply(ReplyOK)

diff --git a/smtp/server.go b/smtp/server.go
index 395a03dd72558799dcc4f2e7f352ab9aeb24b4d1..d9432aacdabd63722593311c84087b6387627c66 100644 (file)
--- a/smtp/server.go
+++ b/smtp/server.go
@@ -14,6 +14,10 @@ type ReplyLine struct {
        Message string
 }
 
+func (l ReplyLine) String() string {
+       return fmt.Sprintf("%d %s", l.Code, l.Message)
+}
+
 var (
        ReplyOK          = ReplyLine{250, "OK"}
        ReplyBadSyntax   = ReplyLine{501, "syntax error"}

diff --git a/vendor/github.com/uber-go/atomic b/vendor/github.com/uber-go/atomic
new file mode 160000 (submodule)
index 0000000..3b8db5e
--- /dev/null
+++ b/vendor/github.com/uber-go/atomic
@@ -0,0 +1 @@
+Subproject commit 3b8db5e93c4c02efbc313e17b2e796b0914a01fb

diff --git a/vendor/github.com/uber-go/zap b/vendor/github.com/uber-go/zap
new file mode 160000 (submodule)
index 0000000..05dadc4
--- /dev/null
+++ b/vendor/github.com/uber-go/zap
@@ -0,0 +1 @@
+Subproject commit 05dadc4e239529c50d6f730c17f0a3aaf35b64fd