From e38abaea735059c6912d418a5540dc222e77f3d4 Mon Sep 17 00:00:00 2001 From: Robert Sesek Date: Sun, 18 Dec 2016 01:21:28 -0500 Subject: [PATCH] Add zap logging through the servers. --- .gitmodules | 6 ++++++ mailpopbox.go | 8 ++++++-- pop3.go | 13 +++++++++++-- pop3/conn.go | 14 +++++++++++++- smtp.go | 17 ++++++++++++++--- smtp/conn.go | 29 +++++++++++++++++++++++++++-- smtp/server.go | 4 ++++ vendor/github.com/uber-go/atomic | 1 + vendor/github.com/uber-go/zap | 1 + 9 files changed, 83 insertions(+), 10 deletions(-) create mode 100644 .gitmodules create mode 160000 vendor/github.com/uber-go/atomic create mode 160000 vendor/github.com/uber-go/zap diff --git a/.gitmodules b/.gitmodules new file mode 100644 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 4b05b6a..ece1e6b 100644 --- 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 0e21ec1..c803143 100644 --- 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 15b7eb4..cbf86d3 100644 --- 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 d229765..a4d1c19 100644 --- 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 db9a9ff..08d14c6 100644 --- 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 .") + 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 395a03d..d9432aa 100644 --- 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 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 index 0000000..05dadc4 --- /dev/null +++ b/vendor/github.com/uber-go/zap @@ -0,0 +1 @@ +Subproject commit 05dadc4e239529c50d6f730c17f0a3aaf35b64fd -- 2.22.5