From 2e78e4e6f7d5ecc58ade4ad8745c0724e37a50dd Mon Sep 17 00:00:00 2001 From: James Hillyerd Date: Fri, 13 Sep 2013 14:06:57 -0700 Subject: [PATCH] Logging and unit test changes Logging methods were renamed so they don't trigger go-vet warnings for error() and Error() formatting. Unit tests were updated to use new github.com/stretchr repo (was renamed from stretchrcom) Missing methods were added to Message mock object. --- inbucket.go | 16 +++--- log/logging.go | 10 ++-- pop3d/handler.go | 117 +++++++++++++++++++------------------- pop3d/listener.go | 14 ++--- smtpd/filestore.go | 18 +++--- smtpd/filestore_test.go | 2 +- smtpd/handler.go | 87 ++++++++++++++-------------- smtpd/listener.go | 18 +++--- smtpd/retention.go | 14 ++--- smtpd/retention_test.go | 13 ++++- smtpd/utils_test.go | 2 +- web/helpers.go | 2 +- web/helpers_test.go | 2 +- web/mailbox_controller.go | 2 +- web/server.go | 24 ++++---- web/template.go | 10 ++-- 16 files changed, 180 insertions(+), 171 deletions(-) diff --git a/inbucket.go b/inbucket.go index 674b265..0235011 100644 --- a/inbucket.go +++ b/inbucket.go @@ -87,7 +87,7 @@ func main() { if *pidfile != "none" { pidf, err := os.Create(*pidfile) if err != nil { - log.Error("Failed to create %v: %v", *pidfile, err) + log.LogError("Failed to create %v: %v", *pidfile, err) os.Exit(1) } defer pidf.Close() @@ -119,13 +119,13 @@ func openLogFile() error { return fmt.Errorf("Failed to create %v: %v\n", *logfile, err) } golog.SetOutput(logf) - log.Trace("Opened new logfile") + log.LogTrace("Opened new logfile") return nil } // closeLogFile closes the current logfile func closeLogFile() error { - log.Trace("Closing logfile") + log.LogTrace("Closing logfile") return logf.Close() } @@ -137,21 +137,21 @@ func signalProcessor(c <-chan os.Signal) { case syscall.SIGHUP: // Rotate logs if configured if logf != nil { - log.Info("Recieved SIGHUP, cycling logfile") + log.LogInfo("Recieved SIGHUP, cycling logfile") closeLogFile() openLogFile() } else { - log.Info("Ignoring SIGHUP, logfile not configured") + log.LogInfo("Ignoring SIGHUP, logfile not configured") } case syscall.SIGTERM: // Initiate shutdown - log.Info("Received SIGTERM, shutting down") + log.LogInfo("Received SIGTERM, shutting down") go timedExit() web.Stop() if smtpServer != nil { smtpServer.Stop() } else { - log.Error("smtpServer was nil during shutdown") + log.LogError("smtpServer was nil during shutdown") } } } @@ -160,7 +160,7 @@ func signalProcessor(c <-chan os.Signal) { // timedExit is called as a goroutine during shutdown, it will force an exit after 15 seconds func timedExit() { time.Sleep(15 * time.Second) - log.Error("Inbucket clean shutdown timed out, forcing exit") + log.LogError("Inbucket clean shutdown timed out, forcing exit") os.Exit(0) } diff --git a/log/logging.go b/log/logging.go index 1fec113..9508e85 100644 --- a/log/logging.go +++ b/log/logging.go @@ -28,20 +28,20 @@ func SetLogLevel(level string) (ok bool) { case "TRACE": MaxLogLevel = TRACE default: - Error("Unknown log level requested: %v", level) + LogError("Unknown log level requested: %v", level) return false } return true } // Error logs a message to the 'standard' Logger (always) -func Error(msg string, args ...interface{}) { +func LogError(msg string, args ...interface{}) { msg = "[ERROR] " + msg log.Printf(msg, args...) } // Warn logs a message to the 'standard' Logger if MaxLogLevel is >= WARN -func Warn(msg string, args ...interface{}) { +func LogWarn(msg string, args ...interface{}) { if MaxLogLevel >= WARN { msg = "[WARN ] " + msg log.Printf(msg, args...) @@ -49,7 +49,7 @@ func Warn(msg string, args ...interface{}) { } // Info logs a message to the 'standard' Logger if MaxLogLevel is >= INFO -func Info(msg string, args ...interface{}) { +func LogInfo(msg string, args ...interface{}) { if MaxLogLevel >= INFO { msg = "[INFO ] " + msg log.Printf(msg, args...) @@ -57,7 +57,7 @@ func Info(msg string, args ...interface{}) { } // Trace logs a message to the 'standard' Logger if MaxLogLevel is >= TRACE -func Trace(msg string, args ...interface{}) { +func LogTrace(msg string, args ...interface{}) { if MaxLogLevel >= TRACE { msg = "[TRACE] " + msg log.Printf(msg, args...) diff --git a/pop3d/handler.go b/pop3d/handler.go index 3bacd51..3889f7b 100644 --- a/pop3d/handler.go +++ b/pop3d/handler.go @@ -84,7 +84,7 @@ func (ses *Session) String() string { * 5. Goto 2 */ func (s *Server) startSession(id int, conn net.Conn) { - log.Info("POP3 connection from %v, starting session <%v>", conn.RemoteAddr(), id) + log.LogInfo("POP3 connection from %v, starting session <%v>", conn.RemoteAddr(), id) //expConnectsCurrent.Add(1) defer func() { conn.Close() @@ -108,7 +108,7 @@ func (s *Server) startSession(id int, conn net.Conn) { } if !commands[cmd] { ses.send(fmt.Sprintf("-ERR Syntax error, %v command unrecognized", cmd)) - ses.warn("Unrecognized command: %v", cmd) + ses.logWarn("Unrecognized command: %v", cmd) continue } @@ -134,7 +134,7 @@ func (s *Server) startSession(id int, conn net.Conn) { ses.transactionHandler(cmd, arg) continue } - ses.error("Session entered unexpected state %v", ses.state) + ses.logError("Session entered unexpected state %v", ses.state) break } else { ses.send("-ERR Syntax error, command garbled") @@ -145,14 +145,14 @@ func (s *Server) startSession(id int, conn net.Conn) { switch ses.state { case AUTHORIZATION: // EOF is common here - ses.info("Client closed connection (state %v)", ses.state) + ses.logInfo("Client closed connection (state %v)", ses.state) default: - ses.warn("Got EOF while in state %v", ses.state) + ses.logWarn("Got EOF while in state %v", ses.state) } break } // not an EOF - ses.warn("Connection error: %v", err) + ses.logWarn("Connection error: %v", err) if netErr, ok := err.(net.Error); ok { if netErr.Timeout() { ses.send("-ERR Idle timeout, bye bye") @@ -164,9 +164,9 @@ func (s *Server) startSession(id int, conn net.Conn) { } } if ses.sendError != nil { - ses.warn("Network send error: %v", ses.sendError) + ses.logWarn("Network send error: %v", ses.sendError) } - ses.info("Closing connection") + ses.logInfo("Closing connection") } // AUTHORIZATION state @@ -189,7 +189,7 @@ func (ses *Session) authorizationHandler(cmd string, args []string) { var err error ses.mailbox, err = ses.server.dataStore.MailboxFor(ses.user) if err != nil { - ses.error("Failed to open mailbox for %v", ses.user) + ses.logError("Failed to open mailbox for %v", ses.user) ses.send(fmt.Sprintf("-ERR Failed to open mailbox for %v", ses.user)) ses.enterState(QUIT) return @@ -200,7 +200,7 @@ func (ses *Session) authorizationHandler(cmd string, args []string) { } case "APOP": if len(args) != 2 { - ses.warn("Expected two arguments for APOP") + ses.logWarn("Expected two arguments for APOP") ses.send("-ERR APOP requires two arguments") return } @@ -208,7 +208,7 @@ func (ses *Session) authorizationHandler(cmd string, args []string) { var err error ses.mailbox, err = ses.server.dataStore.MailboxFor(ses.user) if err != nil { - ses.error("Failed to open mailbox for %v", ses.user) + ses.logError("Failed to open mailbox for %v", ses.user) ses.send(fmt.Sprintf("-ERR Failed to open mailbox for %v", ses.user)) ses.enterState(QUIT) return @@ -226,7 +226,7 @@ func (ses *Session) transactionHandler(cmd string, args []string) { switch cmd { case "STAT": if len(args) != 0 { - ses.warn("STAT got an unexpected argument") + ses.logWarn("STAT got an unexpected argument") ses.send("-ERR STAT command must have no arguments") return } @@ -241,29 +241,29 @@ func (ses *Session) transactionHandler(cmd string, args []string) { ses.send(fmt.Sprintf("+OK %v %v", count, size)) case "LIST": if len(args) > 1 { - ses.warn("LIST command had more than 1 argument") + ses.logWarn("LIST command had more than 1 argument") ses.send("-ERR LIST command must have zero or one argument") return } if len(args) == 1 { msgNum, err := strconv.ParseInt(args[0], 10, 32) if err != nil { - ses.warn("LIST command argument was not an integer") + ses.logWarn("LIST command argument was not an integer") ses.send("-ERR LIST command requires an integer argument") return } if msgNum < 1 { - ses.warn("LIST command argument was less than 1") + ses.logWarn("LIST command argument was less than 1") ses.send("-ERR LIST argument must be greater than 0") return } if int(msgNum) > len(ses.messages) { - ses.warn("LIST command argument was greater than number of messages") + ses.logWarn("LIST command argument was greater than number of messages") ses.send("-ERR LIST argument must not exceed the number of messages") return } if !ses.retain[msgNum-1] { - ses.warn("Client tried to LIST a message it had deleted") + ses.logWarn("Client tried to LIST a message it had deleted") ses.send(fmt.Sprintf("-ERR You deleted message %v", msgNum)) return } @@ -279,29 +279,29 @@ func (ses *Session) transactionHandler(cmd string, args []string) { } case "UIDL": if len(args) > 1 { - ses.warn("UIDL command had more than 1 argument") + ses.logWarn("UIDL command had more than 1 argument") ses.send("-ERR UIDL command must have zero or one argument") return } if len(args) == 1 { msgNum, err := strconv.ParseInt(args[0], 10, 32) if err != nil { - ses.warn("UIDL command argument was not an integer") + ses.logWarn("UIDL command argument was not an integer") ses.send("-ERR UIDL command requires an integer argument") return } if msgNum < 1 { - ses.warn("UIDL command argument was less than 1") + ses.logWarn("UIDL command argument was less than 1") ses.send("-ERR UIDL argument must be greater than 0") return } if int(msgNum) > len(ses.messages) { - ses.warn("UIDL command argument was greater than number of messages") + ses.logWarn("UIDL command argument was greater than number of messages") ses.send("-ERR UIDL argument must not exceed the number of messages") return } if !ses.retain[msgNum-1] { - ses.warn("Client tried to UIDL a message it had deleted") + ses.logWarn("Client tried to UIDL a message it had deleted") ses.send(fmt.Sprintf("-ERR You deleted message %v", msgNum)) return } @@ -317,23 +317,23 @@ func (ses *Session) transactionHandler(cmd string, args []string) { } case "DELE": if len(args) != 1 { - ses.warn("DELE command had invalid number of arguments") + ses.logWarn("DELE command had invalid number of arguments") ses.send("-ERR DELE command requires a single argument") return } msgNum, err := strconv.ParseInt(args[0], 10, 32) if err != nil { - ses.warn("DELE command argument was not an integer") + ses.logWarn("DELE command argument was not an integer") ses.send("-ERR DELE command requires an integer argument") return } if msgNum < 1 { - ses.warn("DELE command argument was less than 1") + ses.logWarn("DELE command argument was less than 1") ses.send("-ERR DELE argument must be greater than 0") return } if int(msgNum) > len(ses.messages) { - ses.warn("DELE command argument was greater than number of messages") + ses.logWarn("DELE command argument was greater than number of messages") ses.send("-ERR DELE argument must not exceed the number of messages") return } @@ -342,28 +342,28 @@ func (ses *Session) transactionHandler(cmd string, args []string) { ses.msgCount -= 1 ses.send(fmt.Sprintf("+OK Deleted message %v", msgNum)) } else { - ses.warn("Client tried to DELE an already deleted message") + ses.logWarn("Client tried to DELE an already deleted message") ses.send(fmt.Sprintf("-ERR Message %v has already been deleted", msgNum)) } case "RETR": if len(args) != 1 { - ses.warn("RETR command had invalid number of arguments") + ses.logWarn("RETR command had invalid number of arguments") ses.send("-ERR RETR command requires a single argument") return } msgNum, err := strconv.ParseInt(args[0], 10, 32) if err != nil { - ses.warn("RETR command argument was not an integer") + ses.logWarn("RETR command argument was not an integer") ses.send("-ERR RETR command requires an integer argument") return } if msgNum < 1 { - ses.warn("RETR command argument was less than 1") + ses.logWarn("RETR command argument was less than 1") ses.send("-ERR RETR argument must be greater than 0") return } if int(msgNum) > len(ses.messages) { - ses.warn("RETR command argument was greater than number of messages") + ses.logWarn("RETR command argument was greater than number of messages") ses.send("-ERR RETR argument must not exceed the number of messages") return } @@ -371,23 +371,23 @@ func (ses *Session) transactionHandler(cmd string, args []string) { ses.sendMessage(ses.messages[msgNum-1]) case "TOP": if len(args) != 2 { - ses.warn("TOP command had invalid number of arguments") + ses.logWarn("TOP command had invalid number of arguments") ses.send("-ERR TOP command requires two arguments") return } msgNum, err := strconv.ParseInt(args[0], 10, 32) if err != nil { - ses.warn("TOP command first argument was not an integer") + ses.logWarn("TOP command first argument was not an integer") ses.send("-ERR TOP command requires an integer argument") return } if msgNum < 1 { - ses.warn("TOP command first argument was less than 1") + ses.logWarn("TOP command first argument was less than 1") ses.send("-ERR TOP first argument must be greater than 0") return } if int(msgNum) > len(ses.messages) { - ses.warn("TOP command first argument was greater than number of messages") + ses.logWarn("TOP command first argument was greater than number of messages") ses.send("-ERR TOP first argument must not exceed the number of messages") return } @@ -395,12 +395,12 @@ func (ses *Session) transactionHandler(cmd string, args []string) { var lines int64 lines, err = strconv.ParseInt(args[1], 10, 32) if err != nil { - ses.warn("TOP command second argument was not an integer") + ses.logWarn("TOP command second argument was not an integer") ses.send("-ERR TOP command requires an integer argument") return } if lines < 0 { - ses.warn("TOP command second argument was negative") + ses.logWarn("TOP command second argument was negative") ses.send("-ERR TOP second argument must be non-negative") return } @@ -414,7 +414,7 @@ func (ses *Session) transactionHandler(cmd string, args []string) { ses.send("+OK I have sucessfully done nothing") case "RSET": // Reset session, don't actually delete anything I told you to - ses.trace("Resetting session state on RSET request") + ses.logTrace("Resetting session state on RSET request") ses.reset() ses.send("+OK Session reset") default: @@ -427,7 +427,7 @@ func (ses *Session) sendMessage(msg smtpd.Message) { reader, err := msg.RawReader() defer reader.Close() if err != nil { - ses.error("Failed to read message for RETR command") + ses.logError("Failed to read message for RETR command") ses.send("-ERR Failed to RETR that message, internal error") return } @@ -442,7 +442,7 @@ func (ses *Session) sendMessage(msg smtpd.Message) { } if err = scanner.Err(); err != nil { - ses.error("Failed to read message for RETR command") + ses.logError("Failed to read message for RETR command") ses.send(".") ses.send("-ERR Failed to RETR that message, internal error") return @@ -455,7 +455,7 @@ func (ses *Session) sendMessageTop(msg smtpd.Message, lineCount int) { reader, err := msg.RawReader() defer reader.Close() if err != nil { - ses.error("Failed to read message for RETR command") + ses.logError("Failed to read message for RETR command") ses.send("-ERR Failed to RETR that message, internal error") return } @@ -484,7 +484,7 @@ func (ses *Session) sendMessageTop(msg smtpd.Message, lineCount int) { } if err = scanner.Err(); err != nil { - ses.error("Failed to read message for RETR command") + ses.logError("Failed to read message for RETR command") ses.send(".") ses.send("-ERR Failed to RETR that message, internal error") return @@ -497,7 +497,7 @@ func (ses *Session) loadMailbox() { var err error ses.messages, err = ses.mailbox.GetMessages() if err != nil { - ses.error("Failed to load messages for %v", ses.user) + ses.logError("Failed to load messages for %v", ses.user) } ses.retainAll() @@ -517,10 +517,10 @@ func (ses *Session) retainAll() { // indicates that the session was closed cleanly and that deletes should be // processed. func (ses *Session) processDeletes() { - ses.info("Processing deletes") + ses.logInfo("Processing deletes") for i, msg := range ses.messages { if !ses.retain[i] { - ses.trace("Deleting %v", msg) + ses.logTrace("Deleting %v", msg) msg.Delete() } } @@ -528,7 +528,7 @@ func (ses *Session) processDeletes() { func (ses *Session) enterState(state State) { ses.state = state - ses.trace("Entering state %v", state) + ses.logTrace("Entering state %v", state) } // Calculate the next read or write deadline based on maxIdleSeconds @@ -544,10 +544,10 @@ func (ses *Session) send(msg string) { } if _, err := fmt.Fprint(ses.conn, msg+"\r\n"); err != nil { ses.sendError = err - ses.warn("Failed to send: '%v'", msg) + ses.logWarn("Failed to send: '%v'", msg) return } - ses.trace(">> %v >>", msg) + ses.logTrace(">> %v >>", msg) } // readByteLine reads a line of input into the provided buffer. Does @@ -575,7 +575,6 @@ func (ses *Session) readByteLine(buf *bytes.Buffer) error { // Else, keep looking } // Should be unreachable - return nil } // Reads a line of input @@ -587,7 +586,7 @@ func (ses *Session) readLine() (line string, err error) { if err != nil { return "", err } - ses.trace("<< %v <<", strings.TrimRight(line, "\r\n")) + ses.logTrace("<< %v <<", strings.TrimRight(line, "\r\n")) return line, nil } @@ -607,26 +606,26 @@ func (ses *Session) reset() { func (ses *Session) ooSeq(cmd string) { ses.send(fmt.Sprintf("-ERR Command %v is out of sequence", cmd)) - ses.warn("Wasn't expecting %v here", cmd) + ses.logWarn("Wasn't expecting %v here", cmd) } // Session specific logging methods -func (ses *Session) trace(msg string, args ...interface{}) { - log.Trace("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...)) +func (ses *Session) logTrace(msg string, args ...interface{}) { + log.LogTrace("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...)) } -func (ses *Session) info(msg string, args ...interface{}) { - log.Info("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...)) +func (ses *Session) logInfo(msg string, args ...interface{}) { + log.LogInfo("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...)) } -func (ses *Session) warn(msg string, args ...interface{}) { +func (ses *Session) logWarn(msg string, args ...interface{}) { // Update metrics //expWarnsTotal.Add(1) - log.Warn("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...)) + log.LogWarn("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...)) } -func (ses *Session) error(msg string, args ...interface{}) { +func (ses *Session) logError(msg string, args ...interface{}) { // Update metrics //expErrorsTotal.Add(1) - log.Error("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...)) + log.LogError("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...)) } diff --git a/pop3d/listener.go b/pop3d/listener.go index 3bbfb73..f2eb03d 100644 --- a/pop3d/listener.go +++ b/pop3d/listener.go @@ -35,15 +35,15 @@ func (s *Server) Start() { addr, err := net.ResolveTCPAddr("tcp4", fmt.Sprintf("%v:%v", cfg.Ip4address, cfg.Ip4port)) if err != nil { - log.Error("POP3 Failed to build tcp4 address: %v", err) + log.LogError("POP3 Failed to build tcp4 address: %v", err) // TODO More graceful early-shutdown procedure panic(err) } - log.Info("POP3 listening on TCP4 %v", addr) + log.LogInfo("POP3 listening on TCP4 %v", addr) s.listener, err = net.ListenTCP("tcp4", addr) if err != nil { - log.Error("POP3 failed to start tcp4 listener: %v", err) + log.LogError("POP3 failed to start tcp4 listener: %v", err) // TODO More graceful early-shutdown procedure panic(err) } @@ -62,12 +62,12 @@ func (s *Server) Start() { if max := 1 * time.Second; tempDelay > max { tempDelay = max } - log.Error("POP3 accept error: %v; retrying in %v", err, tempDelay) + log.LogError("POP3 accept error: %v; retrying in %v", err, tempDelay) time.Sleep(tempDelay) continue } else { if s.shutdown { - log.Trace("POP3 listener shutting down on request") + log.LogTrace("POP3 listener shutting down on request") return } // TODO Implement a max error counter before shutdown? @@ -84,7 +84,7 @@ func (s *Server) Start() { // Stop requests the POP3 server closes it's listener func (s *Server) Stop() { - log.Trace("POP3 shutdown requested, connections will be drained") + log.LogTrace("POP3 shutdown requested, connections will be drained") s.shutdown = true s.listener.Close() } @@ -92,5 +92,5 @@ func (s *Server) Stop() { // Drain causes the caller to block until all active POP3 sessions have finished func (s *Server) Drain() { s.waitgroup.Wait() - log.Trace("POP3 connections drained") + log.LogTrace("POP3 connections drained") } diff --git a/smtpd/filestore.go b/smtpd/filestore.go index b38d4f8..40c45f8 100644 --- a/smtpd/filestore.go +++ b/smtpd/filestore.go @@ -46,11 +46,11 @@ type FileDataStore struct { func NewFileDataStore() DataStore { path, err := config.Config.String("datastore", "path") if err != nil { - log.Error("Error getting datastore path: %v", err) + log.LogError("Error getting datastore path: %v", err) return nil } if path == "" { - log.Error("No value configured for datastore path") + log.LogError("No value configured for datastore path") return nil } mailPath := filepath.Join(path, "mail") @@ -66,7 +66,7 @@ func (ds *FileDataStore) MailboxFor(emailAddress string) (Mailbox, error) { s2 := dir[0:6] path := filepath.Join(ds.mailPath, s1, s2, dir) if err := os.MkdirAll(path, 0770); err != nil { - log.Error("Failed to create directory %v, %v", path, err) + log.LogError("Failed to create directory %v, %v", path, err) return nil, err } return &FileMailbox{store: ds, name: name, dirName: dir, path: path}, nil @@ -132,7 +132,7 @@ func (mb *FileMailbox) GetMessages() ([]Message, error) { if err != nil { return nil, err } - log.Trace("Scanning %v files for %v", len(files), mb) + log.LogTrace("Scanning %v files for %v", len(files), mb) messages := make([]Message, 0, len(files)) for _, f := range files { @@ -149,7 +149,7 @@ func (mb *FileMailbox) GetMessages() ([]Message, error) { } file.Close() msg.mailbox = mb - log.Trace("Found: %v", msg) + log.LogTrace("Found: %v", msg) messages = append(messages, msg) } } @@ -170,7 +170,7 @@ func (mb *FileMailbox) GetMessage(id string) (Message, error) { } file.Close() msg.mailbox = mb - log.Trace("Found: %v", msg) + log.LogTrace("Found: %v", msg) return msg, nil } @@ -335,7 +335,7 @@ func (m *FileMessage) Close() error { err := m.createGob() if err != nil { - log.Error("Failed to create gob: %v", err) + log.LogError("Failed to create gob: %v", err) return err } @@ -344,12 +344,12 @@ func (m *FileMessage) Close() error { // Delete this Message from disk by removing both the gob and raw files func (m *FileMessage) Delete() error { - log.Trace("Deleting %v", m.gobPath()) + log.LogTrace("Deleting %v", m.gobPath()) err := os.Remove(m.gobPath()) if err != nil { return err } - log.Trace("Deleting %v", m.rawPath()) + log.LogTrace("Deleting %v", m.rawPath()) return os.Remove(m.rawPath()) } diff --git a/smtpd/filestore_test.go b/smtpd/filestore_test.go index 49ff409..4c933b3 100644 --- a/smtpd/filestore_test.go +++ b/smtpd/filestore_test.go @@ -1,7 +1,7 @@ package smtpd import ( - "github.com/stretchrcom/testify/assert" + "github.com/stretchr/testify/assert" "io/ioutil" "os" "path/filepath" diff --git a/smtpd/handler.go b/smtpd/handler.go index d591cb4..595d82d 100644 --- a/smtpd/handler.go +++ b/smtpd/handler.go @@ -88,7 +88,7 @@ func (ss *Session) String() string { * 5. Goto 2 */ func (s *Server) startSession(id int, conn net.Conn) { - log.Info("SMTP Connection from %v, starting session <%v>", conn.RemoteAddr(), id) + log.LogInfo("SMTP Connection from %v, starting session <%v>", conn.RemoteAddr(), id) expConnectsCurrent.Add(1) defer func() { conn.Close() @@ -116,7 +116,7 @@ func (s *Server) startSession(id int, conn net.Conn) { } if !commands[cmd] { ss.send(fmt.Sprintf("500 Syntax error, %v command unrecognized", cmd)) - ss.warn("Unrecognized command: %v", cmd) + ss.logWarn("Unrecognized command: %v", cmd) continue } @@ -125,7 +125,7 @@ func (s *Server) startSession(id int, conn net.Conn) { case "SEND", "SOML", "SAML", "EXPN", "HELP", "TURN": // These commands are not implemented in any state ss.send(fmt.Sprintf("502 %v command not implemented", cmd)) - ss.warn("Command %v not implemented by Inbucket", cmd) + ss.logWarn("Command %v not implemented by Inbucket", cmd) continue case "VRFY": ss.send("252 Cannot VRFY user, but will accept message") @@ -135,7 +135,7 @@ func (s *Server) startSession(id int, conn net.Conn) { continue case "RSET": // Reset session - ss.trace("Resetting session state on RSET request") + ss.logTrace("Resetting session state on RSET request") ss.reset() ss.send("250 Session reset") continue @@ -157,7 +157,7 @@ func (s *Server) startSession(id int, conn net.Conn) { ss.mailHandler(cmd, arg) continue } - ss.error("Session entered unexpected state %v", ss.state) + ss.logError("Session entered unexpected state %v", ss.state) break } else { ss.send("500 Syntax error, command garbled") @@ -168,14 +168,14 @@ func (s *Server) startSession(id int, conn net.Conn) { switch ss.state { case GREET, READY: // EOF is common here - ss.info("Client closed connection (state %v)", ss.state) + ss.logInfo("Client closed connection (state %v)", ss.state) default: - ss.warn("Got EOF while in state %v", ss.state) + ss.logWarn("Got EOF while in state %v", ss.state) } break } // not an EOF - ss.warn("Connection error: %v", err) + ss.logWarn("Connection error: %v", err) if netErr, ok := err.(net.Error); ok { if netErr.Timeout() { ss.send("221 Idle timeout, bye bye") @@ -187,9 +187,9 @@ func (s *Server) startSession(id int, conn net.Conn) { } } if ss.sendError != nil { - ss.warn("Network send error: %v", ss.sendError) + ss.logWarn("Network send error: %v", ss.sendError) } - ss.info("Closing connection") + ss.logInfo("Closing connection") } // GREET state -> waiting for HELO @@ -216,7 +216,7 @@ func (ss *Session) readyHandler(cmd string, arg string) { m := re.FindStringSubmatch(arg) if m == nil { ss.send("501 Was expecting MAIL arg syntax of FROM:
") - ss.warn("Bad MAIL argument: '%v'", arg) + ss.logWarn("Bad MAIL argument: '%v'", arg) return } from := m[1] @@ -226,26 +226,26 @@ func (ss *Session) readyHandler(cmd string, arg string) { args, ok := ss.parseArgs(m[2]) if !ok { ss.send("501 Unable to parse MAIL ESMTP parameters") - ss.warn("Bad MAIL argument: '%v'", arg) + ss.logWarn("Bad MAIL argument: '%v'", arg) return } if args["SIZE"] != "" { size, err := strconv.ParseInt(args["SIZE"], 10, 32) if err != nil { ss.send("501 Unable to parse SIZE as an integer") - ss.warn("Unable to parse SIZE '%v' as an integer", args["SIZE"]) + ss.logWarn("Unable to parse SIZE '%v' as an integer", args["SIZE"]) return } if int(size) > ss.server.maxMessageBytes { ss.send("552 Max message size exceeded") - ss.warn("Client wanted to send oversized message: %v", args["SIZE"]) + ss.logWarn("Client wanted to send oversized message: %v", args["SIZE"]) return } } } ss.from = from ss.recipients = list.New() - ss.info("Mail from: %v", from) + ss.logInfo("Mail from: %v", from) ss.send(fmt.Sprintf("250 Roger, accepting mail from <%v>", from)) ss.enterState(MAIL) } else { @@ -259,24 +259,24 @@ func (ss *Session) mailHandler(cmd string, arg string) { case "RCPT": if (len(arg) < 4) || (strings.ToUpper(arg[0:3]) != "TO:") { ss.send("501 Was expecting RCPT arg syntax of TO:
") - ss.warn("Bad RCPT argument: '%v'", arg) + ss.logWarn("Bad RCPT argument: '%v'", arg) return } // This trim is probably too forgiving recip := strings.Trim(arg[3:], "<> ") if ss.recipients.Len() >= ss.server.maxRecips { - ss.warn("Maximum limit of %v recipients reached", ss.server.maxRecips) + ss.logWarn("Maximum limit of %v recipients reached", ss.server.maxRecips) ss.send(fmt.Sprintf("552 Maximum limit of %v recipients reached", ss.server.maxRecips)) return } ss.recipients.PushBack(recip) - ss.info("Recipient: %v", recip) + ss.logInfo("Recipient: %v", recip) ss.send(fmt.Sprintf("250 I'll make sure <%v> gets this", recip)) return case "DATA": if arg != "" { ss.send("501 DATA command should not have any arguments") - ss.warn("Got unexpected args on DATA: '%v'", arg) + ss.logWarn("Got unexpected args on DATA: '%v'", arg) return } if ss.recipients.Len() > 0 { @@ -307,7 +307,7 @@ func (ss *Session) dataHandler() { // Not our "no store" domain, so store the message mb, err := ss.server.dataStore.MailboxFor(recip) if err != nil { - ss.error("Failed to open mailbox for %v", recip) + ss.logError("Failed to open mailbox for %v", recip) ss.send(fmt.Sprintf("451 Failed to open mailbox for %v", recip)) ss.reset() return @@ -315,7 +315,7 @@ func (ss *Session) dataHandler() { mailboxes[i] = mb messages[i] = mb.NewMessage() } else { - log.Trace("Not storing message for '%v'", recip) + log.LogTrace("Not storing message for '%v'", recip) } i++ } @@ -332,7 +332,7 @@ func (ss *Session) dataHandler() { ss.send("221 Idle timeout, bye bye") } } - ss.warn("Error: %v while reading", err) + ss.logWarn("Error: %v while reading", err) ss.enterState(QUIT) return } @@ -350,7 +350,7 @@ func (ss *Session) dataHandler() { expReceivedTotal.Add(1) } ss.send("250 Mail accepted for delivery") - ss.info("Message size %v bytes", msgSize) + ss.logInfo("Message size %v bytes", msgSize) ss.reset() return } @@ -362,7 +362,7 @@ func (ss *Session) dataHandler() { if msgSize > ss.server.maxMessageBytes { // Max message size exceeded ss.send("552 Maximum message size exceeded") - ss.warn("Max message size exceeded while in DATA") + ss.logWarn("Max message size exceeded while in DATA") ss.reset() // TODO: Should really cleanup the crap on filesystem... return @@ -372,7 +372,7 @@ func (ss *Session) dataHandler() { for i, m := range messages { if m != nil { if err := m.Append(line); err != nil { - ss.error("Failed to append to mailbox %v: %v", mailboxes[i], err) + ss.logError("Failed to append to mailbox %v: %v", mailboxes[i], err) ss.send("554 Something went wrong") ss.reset() // TODO: Should really cleanup the crap on filesystem... @@ -386,7 +386,7 @@ func (ss *Session) dataHandler() { func (ss *Session) enterState(state State) { ss.state = state - ss.trace("Entering state %v", state) + ss.logTrace("Entering state %v", state) } func (ss *Session) greet() { @@ -406,10 +406,10 @@ func (ss *Session) send(msg string) { } if _, err := fmt.Fprint(ss.conn, msg+"\r\n"); err != nil { ss.sendError = err - ss.warn("Failed to send: '%v'", msg) + ss.logWarn("Failed to send: '%v'", msg) return } - ss.trace(">> %v >>", msg) + ss.logTrace(">> %v >>", msg) } // readByteLine reads a line of input into the provided buffer. Does @@ -437,7 +437,6 @@ func (ss *Session) readByteLine(buf *bytes.Buffer) error { // Else, keep looking } // Should be unreachable - return nil } // Reads a line of input @@ -449,7 +448,7 @@ func (ss *Session) readLine() (line string, err error) { if err != nil { return "", err } - ss.trace("<< %v <<", strings.TrimRight(line, "\r\n")) + ss.logTrace("<< %v <<", strings.TrimRight(line, "\r\n")) return line, nil } @@ -460,19 +459,19 @@ func (ss *Session) parseCmd(line string) (cmd string, arg string, ok bool) { case l == 0: return "", "", true case l < 4: - ss.warn("Command too short: '%v'", line) + ss.logWarn("Command too short: '%v'", line) return "", "", false case l == 4: return strings.ToUpper(line), "", true case l == 5: // Too long to be only command, too short to have args - ss.warn("Mangled command: '%v'", line) + ss.logWarn("Mangled command: '%v'", line) return "", "", false } // If we made it here, command is long enough to have args if line[4] != ' ' { // There wasn't a space after the command? - ss.warn("Mangled command: '%v'", line) + ss.logWarn("Mangled command: '%v'", line) return "", "", false } // I'm not sure if we should trim the args or not, but we will for now @@ -489,13 +488,13 @@ func (ss *Session) parseArgs(arg string) (args map[string]string, ok bool) { re := regexp.MustCompile(" (\\w+)=(\\w+)") pm := re.FindAllStringSubmatch(arg, -1) if pm == nil { - ss.warn("Failed to parse arg string: '%v'") + ss.logWarn("Failed to parse arg string: '%v'") return nil, false } for _, m := range pm { args[strings.ToUpper(m[1])] = m[2] } - ss.trace("ESMTP params: %v", args) + ss.logTrace("ESMTP params: %v", args) return args, true } @@ -507,26 +506,26 @@ func (ss *Session) reset() { func (ss *Session) ooSeq(cmd string) { ss.send(fmt.Sprintf("503 Command %v is out of sequence", cmd)) - ss.warn("Wasn't expecting %v here", cmd) + ss.logWarn("Wasn't expecting %v here", cmd) } // Session specific logging methods -func (ss *Session) trace(msg string, args ...interface{}) { - log.Trace("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...)) +func (ss *Session) logTrace(msg string, args ...interface{}) { + log.LogTrace("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...)) } -func (ss *Session) info(msg string, args ...interface{}) { - log.Info("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...)) +func (ss *Session) logInfo(msg string, args ...interface{}) { + log.LogInfo("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...)) } -func (ss *Session) warn(msg string, args ...interface{}) { +func (ss *Session) logWarn(msg string, args ...interface{}) { // Update metrics expWarnsTotal.Add(1) - log.Warn("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...)) + log.LogWarn("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...)) } -func (ss *Session) error(msg string, args ...interface{}) { +func (ss *Session) logError(msg string, args ...interface{}) { // Update metrics expErrorsTotal.Add(1) - log.Error("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...)) + log.LogError("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...)) } diff --git a/smtpd/listener.go b/smtpd/listener.go index e2110e1..614a576 100644 --- a/smtpd/listener.go +++ b/smtpd/listener.go @@ -61,23 +61,23 @@ func (s *Server) Start() { addr, err := net.ResolveTCPAddr("tcp4", fmt.Sprintf("%v:%v", cfg.Ip4address, cfg.Ip4port)) if err != nil { - log.Error("Failed to build tcp4 address: %v", err) + log.LogError("Failed to build tcp4 address: %v", err) // TODO More graceful early-shutdown procedure panic(err) } - log.Info("SMTP listening on TCP4 %v", addr) + log.LogInfo("SMTP listening on TCP4 %v", addr) s.listener, err = net.ListenTCP("tcp4", addr) if err != nil { - log.Error("SMTP failed to start tcp4 listener: %v", err) + log.LogError("SMTP failed to start tcp4 listener: %v", err) // TODO More graceful early-shutdown procedure panic(err) } if !s.storeMessages { - log.Info("Load test mode active, messages will not be stored") + log.LogInfo("Load test mode active, messages will not be stored") } else if s.domainNoStore != "" { - log.Info("Messages sent to domain '%v' will be discarded", s.domainNoStore) + log.LogInfo("Messages sent to domain '%v' will be discarded", s.domainNoStore) } // Start retention scanner @@ -97,12 +97,12 @@ func (s *Server) Start() { if max := 1 * time.Second; tempDelay > max { tempDelay = max } - log.Error("SMTP accept error: %v; retrying in %v", err, tempDelay) + log.LogError("SMTP accept error: %v; retrying in %v", err, tempDelay) time.Sleep(tempDelay) continue } else { if s.shutdown { - log.Trace("SMTP listener shutting down on request") + log.LogTrace("SMTP listener shutting down on request") return } // TODO Implement a max error counter before shutdown? @@ -120,7 +120,7 @@ func (s *Server) Start() { // Stop requests the SMTP server closes it's listener func (s *Server) Stop() { - log.Trace("SMTP shutdown requested, connections will be drained") + log.LogTrace("SMTP shutdown requested, connections will be drained") s.shutdown = true s.listener.Close() } @@ -128,7 +128,7 @@ func (s *Server) Stop() { // Drain causes the caller to block until all active SMTP sessions have finished func (s *Server) Drain() { s.waitgroup.Wait() - log.Trace("SMTP connections drained") + log.LogTrace("SMTP connections drained") } // When the provided Ticker ticks, we update our metrics history diff --git a/smtpd/retention.go b/smtpd/retention.go index b9dd33a..44c3783 100644 --- a/smtpd/retention.go +++ b/smtpd/retention.go @@ -26,11 +26,11 @@ func StartRetentionScanner(ds DataStore) { expRetentionPeriod.Set(int64(cfg.RetentionMinutes * 60)) if cfg.RetentionMinutes > 0 { // Retention scanning enabled - log.Info("Retention configured for %v minutes", cfg.RetentionMinutes) + log.LogInfo("Retention configured for %v minutes", cfg.RetentionMinutes) go retentionScanner(ds, time.Duration(cfg.RetentionMinutes) * time.Minute, time.Duration(cfg.RetentionSleep) * time.Millisecond) } else { - log.Info("Retention scanner disabled") + log.LogInfo("Retention scanner disabled") } } @@ -41,21 +41,21 @@ func retentionScanner(ds DataStore, maxAge time.Duration, sleep time.Duration) { since := time.Since(start) if since < time.Minute { dur := time.Minute - since - log.Trace("Retention scanner sleeping for %v", dur) + log.LogTrace("Retention scanner sleeping for %v", dur) time.Sleep(dur) } start = time.Now() // Kickoff scan if err := doRetentionScan(ds, maxAge, sleep); err != nil { - log.Error("Error during retention scan: %v", err) + log.LogError("Error during retention scan: %v", err) } } } // doRetentionScan does a single pass of all mailboxes looking for messages that can be purged func doRetentionScan(ds DataStore, maxAge time.Duration, sleep time.Duration) error { - log.Trace("Starting retention scan") + log.LogTrace("Starting retention scan") cutoff := time.Now().Add(-1 * maxAge) mboxes, err := ds.AllMailboxes() if err != nil { @@ -69,11 +69,11 @@ func doRetentionScan(ds DataStore, maxAge time.Duration, sleep time.Duration) er } for _, msg := range messages { if msg.Date().Before(cutoff) { - log.Trace("Purging expired message %v", msg.Id()) + log.LogTrace("Purging expired message %v", msg.Id()) err = msg.Delete() if err != nil { // Log but don't abort - log.Error("Failed to purge message %v: %v", msg.Id(), err) + log.LogError("Failed to purge message %v: %v", msg.Id(), err) } else { expRetentionDeletesTotal.Add(1) } diff --git a/smtpd/retention_test.go b/smtpd/retention_test.go index e2b9210..0eb85da 100644 --- a/smtpd/retention_test.go +++ b/smtpd/retention_test.go @@ -3,7 +3,8 @@ package smtpd import ( "fmt" "github.com/jhillyerd/go.enmime" - "github.com/stretchrcom/testify/mock" + "github.com/stretchr/testify/mock" + "io" "net/mail" "testing" "time" @@ -141,6 +142,16 @@ func (m *MockMessage) ReadRaw() (raw *string, err error) { return args.Get(0).(*string), args.Error(1) } +func (m *MockMessage) RawReader() (reader io.ReadCloser, err error) { + args := m.Called() + return args.Get(0).(io.ReadCloser), args.Error(1) +} + +func (m *MockMessage) Size() (int64) { + args := m.Called() + return int64(args.Int(0)) +} + func (m *MockMessage) Append(data []byte) error { args := m.Called(data) return args.Error(0) diff --git a/smtpd/utils_test.go b/smtpd/utils_test.go index 4ea774e..0c2d198 100644 --- a/smtpd/utils_test.go +++ b/smtpd/utils_test.go @@ -1,7 +1,7 @@ package smtpd import ( - "github.com/stretchrcom/testify/assert" + "github.com/stretchr/testify/assert" "testing" ) diff --git a/web/helpers.go b/web/helpers.go index af98e0e..5f80bf4 100644 --- a/web/helpers.go +++ b/web/helpers.go @@ -39,7 +39,7 @@ func reverse(name string, things ...interface{}) string { // Grab the route u, err := Router.Get(name).URL(strs...) if err != nil { - log.Error("Failed to reverse route: %v", err) + log.LogError("Failed to reverse route: %v", err) return "/ROUTE-ERROR" } return u.Path diff --git a/web/helpers_test.go b/web/helpers_test.go index b50a838..85298eb 100644 --- a/web/helpers_test.go +++ b/web/helpers_test.go @@ -1,7 +1,7 @@ package web import ( - "github.com/stretchrcom/testify/assert" + "github.com/stretchr/testify/assert" "html/template" "testing" ) diff --git a/web/mailbox_controller.go b/web/mailbox_controller.go index 3eec6dd..4decc23 100644 --- a/web/mailbox_controller.go +++ b/web/mailbox_controller.go @@ -35,7 +35,7 @@ func MailboxList(w http.ResponseWriter, req *http.Request, ctx *Context) (err er if err != nil { return fmt.Errorf("Failed to get messages for %v: %v", name, err) } - log.Trace("Got %v messsages", len(messages)) + log.LogTrace("Got %v messsages", len(messages)) return RenderPartial("mailbox/_list.html", w, map[string]interface{}{ "ctx": ctx, diff --git a/web/server.go b/web/server.go index 0e21b52..120a9cd 100644 --- a/web/server.go +++ b/web/server.go @@ -23,8 +23,8 @@ var sessionStore sessions.Store var shutdown bool func setupRoutes(cfg config.WebConfig) { - log.Info("Theme templates mapped to '%v'", cfg.TemplateDir) - log.Info("Theme static content mapped to '%v'", cfg.PublicDir) + log.LogInfo("Theme templates mapped to '%v'", cfg.TemplateDir) + log.LogInfo("Theme static content mapped to '%v'", cfg.PublicDir) r := mux.NewRouter() // Static content @@ -65,30 +65,30 @@ func Start() { } // We don't use ListenAndServe because it lacks a way to close the listener - log.Info("HTTP listening on TCP4 %v", addr) + log.LogInfo("HTTP listening on TCP4 %v", addr) var err error listener, err = net.Listen("tcp", addr) if err != nil { - log.Error("HTTP failed to start TCP4 listener: %v", err) + log.LogError("HTTP failed to start TCP4 listener: %v", err) // TODO More graceful early-shutdown procedure panic(err) } err = server.Serve(listener) if shutdown { - log.Trace("HTTP server shutting down on request") + log.LogTrace("HTTP server shutting down on request") } else if err != nil { - log.Error("HTTP server failed: %v", err) + log.LogError("HTTP server failed: %v", err) } } func Stop() { - log.Trace("HTTP shutdown requested") + log.LogTrace("HTTP shutdown requested") shutdown = true if listener != nil { listener.Close() } else { - log.Error("HTTP listener was nil during shutdown") + log.LogError("HTTP listener was nil during shutdown") } } @@ -97,7 +97,7 @@ func (h handler) ServeHTTP(w http.ResponseWriter, req *http.Request) { // Create the context ctx, err := NewContext(req) if err != nil { - log.Error("Failed to create context: %v", err) + log.LogError("Failed to create context: %v", err) http.Error(w, err.Error(), http.StatusInternalServerError) return } @@ -105,17 +105,17 @@ func (h handler) ServeHTTP(w http.ResponseWriter, req *http.Request) { // Run the handler, grab the error, and report it buf := new(httpbuf.Buffer) - log.Trace("Web: %v %v %v %v", req.RemoteAddr, req.Proto, req.Method, req.RequestURI) + log.LogTrace("Web: %v %v %v %v", req.RemoteAddr, req.Proto, req.Method, req.RequestURI) err = h(buf, req, ctx) if err != nil { - log.Error("Error handling %v: %v", req.RequestURI, err) + log.LogError("Error handling %v: %v", req.RequestURI, err) http.Error(w, err.Error(), http.StatusInternalServerError) return } // Save the session if err = ctx.Session.Save(req, buf); err != nil { - log.Error("Failed to save session: %v", err) + log.LogError("Failed to save session: %v", err) http.Error(w, err.Error(), http.StatusInternalServerError) return } diff --git a/web/template.go b/web/template.go index aff5744..fef8760 100644 --- a/web/template.go +++ b/web/template.go @@ -20,7 +20,7 @@ var cachedPartials = map[string]*template.Template{} func RenderTemplate(name string, w http.ResponseWriter, data interface{}) error { t, err := ParseTemplate(name, false) if err != nil { - log.Error("Error in template '%v': %v", name, err) + log.LogError("Error in template '%v': %v", name, err) return err } w.Header().Set("Expires", "-1") @@ -32,7 +32,7 @@ func RenderTemplate(name string, w http.ResponseWriter, data interface{}) error func RenderPartial(name string, w http.ResponseWriter, data interface{}) error { t, err := ParseTemplate(name, true) if err != nil { - log.Error("Error in template '%v': %v", name, err) + log.LogError("Error in template '%v': %v", name, err) return err } w.Header().Set("Expires", "-1") @@ -52,7 +52,7 @@ func ParseTemplate(name string, partial bool) (*template.Template, error) { cfg := config.GetWebConfig() tempPath := strings.Replace(name, "/", string(filepath.Separator), -1) tempFile := filepath.Join(cfg.TemplateDir, tempPath) - log.Trace("Parsing template %v", tempFile) + log.LogTrace("Parsing template %v", tempFile) var err error var t *template.Template @@ -72,10 +72,10 @@ func ParseTemplate(name string, partial bool) (*template.Template, error) { // Allows us to disable caching for theme development if cfg.TemplateCache { if partial { - log.Trace("Caching partial %v", name) + log.LogTrace("Caching partial %v", name) cachedTemplates[name] = t } else { - log.Trace("Caching template %v", name) + log.LogTrace("Caching template %v", name) cachedTemplates[name] = t } }