Mirrors/go-inbucket
1
0
Fork 0
mirror of https://github.com/jhillyerd/inbucket.git synced 2025-12-17 17:47:03 +00:00
Code Issues Releases Wiki Activity

Logging and unit test changes

Browse Source 
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.
This commit is contained in:
James Hillyerd
2013-09-13 14:06:57 -07:00
parent f50061ac82
commit 2e78e4e6f7
16 changed files with 180 additions and 171 deletions
Download Patch File Download Diff File Expand all files Collapse all files

16
inbucket.go
View File

@@ -87,7 +87,7 @@ func main() {
if *pidfile != "none" { if *pidfile != "none" {
pidf, err := os.Create(*pidfile) pidf, err := os.Create(*pidfile)
if err != nil { if err != nil {
log.Error("Failed to create %v: %v", *pidfile, err) log.LogError("Failed to create %v: %v", *pidfile, err)
os.Exit(1) os.Exit(1)
} }
defer pidf.Close() defer pidf.Close()
@@ -119,13 +119,13 @@ func openLogFile() error {
return fmt.Errorf("Failed to create %v: %v\n", *logfile, err) return fmt.Errorf("Failed to create %v: %v\n", *logfile, err)
} }
golog.SetOutput(logf) golog.SetOutput(logf)
log.Trace("Opened new logfile") log.LogTrace("Opened new logfile")
return nil return nil
} }
// closeLogFile closes the current logfile // closeLogFile closes the current logfile
func closeLogFile() error { func closeLogFile() error {
log.Trace("Closing logfile") log.LogTrace("Closing logfile")
return logf.Close() return logf.Close()
} }
@@ -137,21 +137,21 @@ func signalProcessor(c <-chan os.Signal) {
case syscall.SIGHUP: case syscall.SIGHUP:
// Rotate logs if configured // Rotate logs if configured
if logf != nil { if logf != nil {
log.Info("Recieved SIGHUP, cycling logfile") log.LogInfo("Recieved SIGHUP, cycling logfile")
closeLogFile() closeLogFile()
openLogFile() openLogFile()
} else { } else {
log.Info("Ignoring SIGHUP, logfile not configured") log.LogInfo("Ignoring SIGHUP, logfile not configured")
} }
case syscall.SIGTERM: case syscall.SIGTERM:
// Initiate shutdown // Initiate shutdown
log.Info("Received SIGTERM, shutting down") log.LogInfo("Received SIGTERM, shutting down")
go timedExit() go timedExit()
web.Stop() web.Stop()
if smtpServer != nil { if smtpServer != nil {
smtpServer.Stop() smtpServer.Stop()
} else { } 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 // timedExit is called as a goroutine during shutdown, it will force an exit after 15 seconds
func timedExit() { func timedExit() {
time.Sleep(15 * time.Second) 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) os.Exit(0)
} }

10
log/logging.go
View File

@@ -28,20 +28,20 @@ func SetLogLevel(level string) (ok bool) {
case "TRACE": case "TRACE":
MaxLogLevel = TRACE MaxLogLevel = TRACE
default: default:
Error("Unknown log level requested: %v", level) LogError("Unknown log level requested: %v", level)
return false return false
} }
return true return true
} }
// Error logs a message to the 'standard' Logger (always) // Error logs a message to the 'standard' Logger (always)
func Error(msg string, args ...interface{}) { func LogError(msg string, args ...interface{}) {
msg = "[ERROR] " + msg msg = "[ERROR] " + msg
log.Printf(msg, args...) log.Printf(msg, args...)
} }
// Warn logs a message to the 'standard' Logger if MaxLogLevel is >= WARN // 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 { if MaxLogLevel >= WARN {
msg = "[WARN ] " + msg msg = "[WARN ] " + msg
log.Printf(msg, args...) 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 // 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 { if MaxLogLevel >= INFO {
msg = "[INFO ] " + msg msg = "[INFO ] " + msg
log.Printf(msg, args...) 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 // 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 { if MaxLogLevel >= TRACE {
msg = "[TRACE] " + msg msg = "[TRACE] " + msg
log.Printf(msg, args...) log.Printf(msg, args...)

117
pop3d/handler.go
View File

@@ -84,7 +84,7 @@ func (ses *Session) String() string {
* 5. Goto 2 * 5. Goto 2
*/ */
func (s *Server) startSession(id int, conn net.Conn) { 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) //expConnectsCurrent.Add(1)
defer func() { defer func() {
conn.Close() conn.Close()
@@ -108,7 +108,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
} }
if !commands[cmd] { if !commands[cmd] {
ses.send(fmt.Sprintf("-ERR Syntax error, %v command unrecognized", 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 continue
} }
@@ -134,7 +134,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
ses.transactionHandler(cmd, arg) ses.transactionHandler(cmd, arg)
continue continue
} }
ses.error("Session entered unexpected state %v", ses.state) ses.logError("Session entered unexpected state %v", ses.state)
break break
} else { } else {
ses.send("-ERR Syntax error, command garbled") ses.send("-ERR Syntax error, command garbled")
@@ -145,14 +145,14 @@ func (s *Server) startSession(id int, conn net.Conn) {
switch ses.state { switch ses.state {
case AUTHORIZATION: case AUTHORIZATION:
// EOF is common here // EOF is common here
ses.info("Client closed connection (state %v)", ses.state) ses.logInfo("Client closed connection (state %v)", ses.state)
default: default:
ses.warn("Got EOF while in state %v", ses.state) ses.logWarn("Got EOF while in state %v", ses.state)
} }
break break
} }
// not an EOF // not an EOF
ses.warn("Connection error: %v", err) ses.logWarn("Connection error: %v", err)
if netErr, ok := err.(net.Error); ok { if netErr, ok := err.(net.Error); ok {
if netErr.Timeout() { if netErr.Timeout() {
ses.send("-ERR Idle timeout, bye bye") ses.send("-ERR Idle timeout, bye bye")
@@ -164,9 +164,9 @@ func (s *Server) startSession(id int, conn net.Conn) {
} }
} }
if ses.sendError != nil { 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 // AUTHORIZATION state
@@ -189,7 +189,7 @@ func (ses *Session) authorizationHandler(cmd string, args []string) {
var err error var err error
ses.mailbox, err = ses.server.dataStore.MailboxFor(ses.user) ses.mailbox, err = ses.server.dataStore.MailboxFor(ses.user)
if err != nil { 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.send(fmt.Sprintf("-ERR Failed to open mailbox for %v", ses.user))
ses.enterState(QUIT) ses.enterState(QUIT)
return return
@@ -200,7 +200,7 @@ func (ses *Session) authorizationHandler(cmd string, args []string) {
} }
case "APOP": case "APOP":
if len(args) != 2 { 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") ses.send("-ERR APOP requires two arguments")
return return
} }
@@ -208,7 +208,7 @@ func (ses *Session) authorizationHandler(cmd string, args []string) {
var err error var err error
ses.mailbox, err = ses.server.dataStore.MailboxFor(ses.user) ses.mailbox, err = ses.server.dataStore.MailboxFor(ses.user)
if err != nil { 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.send(fmt.Sprintf("-ERR Failed to open mailbox for %v", ses.user))
ses.enterState(QUIT) ses.enterState(QUIT)
return return
@@ -226,7 +226,7 @@ func (ses *Session) transactionHandler(cmd string, args []string) {
switch cmd { switch cmd {
case "STAT": case "STAT":
if len(args) != 0 { 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") ses.send("-ERR STAT command must have no arguments")
return return
} }
@@ -241,29 +241,29 @@ func (ses *Session) transactionHandler(cmd string, args []string) {
ses.send(fmt.Sprintf("+OK %v %v", count, size)) ses.send(fmt.Sprintf("+OK %v %v", count, size))
case "LIST": case "LIST":
if len(args) > 1 { 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") ses.send("-ERR LIST command must have zero or one argument")
return return
} }
if len(args) == 1 { if len(args) == 1 {
msgNum, err := strconv.ParseInt(args[0], 10, 32) msgNum, err := strconv.ParseInt(args[0], 10, 32)
if err != nil { 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") ses.send("-ERR LIST command requires an integer argument")
return return
} }
if msgNum < 1 { 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") ses.send("-ERR LIST argument must be greater than 0")
return return
} }
if int(msgNum) > len(ses.messages) { 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") ses.send("-ERR LIST argument must not exceed the number of messages")
return return
} }
if !ses.retain[msgNum-1] { 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)) ses.send(fmt.Sprintf("-ERR You deleted message %v", msgNum))
return return
} }
@@ -279,29 +279,29 @@ func (ses *Session) transactionHandler(cmd string, args []string) {
} }
case "UIDL": case "UIDL":
if len(args) > 1 { 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") ses.send("-ERR UIDL command must have zero or one argument")
return return
} }
if len(args) == 1 { if len(args) == 1 {
msgNum, err := strconv.ParseInt(args[0], 10, 32) msgNum, err := strconv.ParseInt(args[0], 10, 32)
if err != nil { 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") ses.send("-ERR UIDL command requires an integer argument")
return return
} }
if msgNum < 1 { 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") ses.send("-ERR UIDL argument must be greater than 0")
return return
} }
if int(msgNum) > len(ses.messages) { 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") ses.send("-ERR UIDL argument must not exceed the number of messages")
return return
} }
if !ses.retain[msgNum-1] { 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)) ses.send(fmt.Sprintf("-ERR You deleted message %v", msgNum))
return return
} }
@@ -317,23 +317,23 @@ func (ses *Session) transactionHandler(cmd string, args []string) {
} }
case "DELE": case "DELE":
if len(args) != 1 { 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") ses.send("-ERR DELE command requires a single argument")
return return
} }
msgNum, err := strconv.ParseInt(args[0], 10, 32) msgNum, err := strconv.ParseInt(args[0], 10, 32)
if err != nil { 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") ses.send("-ERR DELE command requires an integer argument")
return return
} }
if msgNum < 1 { 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") ses.send("-ERR DELE argument must be greater than 0")
return return
} }
if int(msgNum) > len(ses.messages) { 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") ses.send("-ERR DELE argument must not exceed the number of messages")
return return
} }
@@ -342,28 +342,28 @@ func (ses *Session) transactionHandler(cmd string, args []string) {
ses.msgCount -= 1 ses.msgCount -= 1
ses.send(fmt.Sprintf("+OK Deleted message %v", msgNum)) ses.send(fmt.Sprintf("+OK Deleted message %v", msgNum))
} else { } 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)) ses.send(fmt.Sprintf("-ERR Message %v has already been deleted", msgNum))
} }
case "RETR": case "RETR":
if len(args) != 1 { 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") ses.send("-ERR RETR command requires a single argument")
return return
} }
msgNum, err := strconv.ParseInt(args[0], 10, 32) msgNum, err := strconv.ParseInt(args[0], 10, 32)
if err != nil { 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") ses.send("-ERR RETR command requires an integer argument")
return return
} }
if msgNum < 1 { 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") ses.send("-ERR RETR argument must be greater than 0")
return return
} }
if int(msgNum) > len(ses.messages) { 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") ses.send("-ERR RETR argument must not exceed the number of messages")
return return
} }
@@ -371,23 +371,23 @@ func (ses *Session) transactionHandler(cmd string, args []string) {
ses.sendMessage(ses.messages[msgNum-1]) ses.sendMessage(ses.messages[msgNum-1])
case "TOP": case "TOP":
if len(args) != 2 { 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") ses.send("-ERR TOP command requires two arguments")
return return
} }
msgNum, err := strconv.ParseInt(args[0], 10, 32) msgNum, err := strconv.ParseInt(args[0], 10, 32)
if err != nil { 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") ses.send("-ERR TOP command requires an integer argument")
return return
} }
if msgNum < 1 { 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") ses.send("-ERR TOP first argument must be greater than 0")
return return
} }
if int(msgNum) > len(ses.messages) { 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") ses.send("-ERR TOP first argument must not exceed the number of messages")
return return
} }
@@ -395,12 +395,12 @@ func (ses *Session) transactionHandler(cmd string, args []string) {
var lines int64 var lines int64
lines, err = strconv.ParseInt(args[1], 10, 32) lines, err = strconv.ParseInt(args[1], 10, 32)
if err != nil { 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") ses.send("-ERR TOP command requires an integer argument")
return return
} }
if lines < 0 { 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") ses.send("-ERR TOP second argument must be non-negative")
return return
} }
@@ -414,7 +414,7 @@ func (ses *Session) transactionHandler(cmd string, args []string) {
ses.send("+OK I have sucessfully done nothing") ses.send("+OK I have sucessfully done nothing")
case "RSET": case "RSET":
// Reset session, don't actually delete anything I told you to // 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.reset()
ses.send("+OK Session reset") ses.send("+OK Session reset")
default: default:
@@ -427,7 +427,7 @@ func (ses *Session) sendMessage(msg smtpd.Message) {
reader, err := msg.RawReader() reader, err := msg.RawReader()
defer reader.Close() defer reader.Close()
if err != nil { 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") ses.send("-ERR Failed to RETR that message, internal error")
return return
} }
@@ -442,7 +442,7 @@ func (ses *Session) sendMessage(msg smtpd.Message) {
} }
if err = scanner.Err(); err != nil { 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(".")
ses.send("-ERR Failed to RETR that message, internal error") ses.send("-ERR Failed to RETR that message, internal error")
return return
@@ -455,7 +455,7 @@ func (ses *Session) sendMessageTop(msg smtpd.Message, lineCount int) {
reader, err := msg.RawReader() reader, err := msg.RawReader()
defer reader.Close() defer reader.Close()
if err != nil { 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") ses.send("-ERR Failed to RETR that message, internal error")
return return
} }
@@ -484,7 +484,7 @@ func (ses *Session) sendMessageTop(msg smtpd.Message, lineCount int) {
} }
if err = scanner.Err(); err != nil { 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(".")
ses.send("-ERR Failed to RETR that message, internal error") ses.send("-ERR Failed to RETR that message, internal error")
return return
@@ -497,7 +497,7 @@ func (ses *Session) loadMailbox() {
var err error var err error
ses.messages, err = ses.mailbox.GetMessages() ses.messages, err = ses.mailbox.GetMessages()
if err != nil { 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() ses.retainAll()
@@ -517,10 +517,10 @@ func (ses *Session) retainAll() {
// indicates that the session was closed cleanly and that deletes should be // indicates that the session was closed cleanly and that deletes should be
// processed. // processed.
func (ses *Session) processDeletes() { func (ses *Session) processDeletes() {
ses.info("Processing deletes") ses.logInfo("Processing deletes")
for i, msg := range ses.messages { for i, msg := range ses.messages {
if !ses.retain[i] { if !ses.retain[i] {
ses.trace("Deleting %v", msg) ses.logTrace("Deleting %v", msg)
msg.Delete() msg.Delete()
} }
} }
@@ -528,7 +528,7 @@ func (ses *Session) processDeletes() {
func (ses *Session) enterState(state State) { func (ses *Session) enterState(state State) {
ses.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 // 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 { if _, err := fmt.Fprint(ses.conn, msg+"\r\n"); err != nil {
ses.sendError = err ses.sendError = err
ses.warn("Failed to send: '%v'", msg) ses.logWarn("Failed to send: '%v'", msg)
return return
} }
ses.trace(">> %v >>", msg) ses.logTrace(">> %v >>", msg)
} }
// readByteLine reads a line of input into the provided buffer. Does // 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 // Else, keep looking
} }
// Should be unreachable // Should be unreachable
return nil
} }
// Reads a line of input // Reads a line of input
@@ -587,7 +586,7 @@ func (ses *Session) readLine() (line string, err error) {
if err != nil { if err != nil {
return "", err return "", err
} }
ses.trace("<< %v <<", strings.TrimRight(line, "\r\n")) ses.logTrace("<< %v <<", strings.TrimRight(line, "\r\n"))
return line, nil return line, nil
} }
@@ -607,26 +606,26 @@ func (ses *Session) reset() {
func (ses *Session) ooSeq(cmd string) { func (ses *Session) ooSeq(cmd string) {
ses.send(fmt.Sprintf("-ERR Command %v is out of sequence", cmd)) 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 // Session specific logging methods
func (ses *Session) trace(msg string, args ...interface{}) { func (ses *Session) logTrace(msg string, args ...interface{}) {
log.Trace("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...)) log.LogTrace("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...))
} }
func (ses *Session) info(msg string, args ...interface{}) { func (ses *Session) logInfo(msg string, args ...interface{}) {
log.Info("POP3<%v> %v", ses.id, fmt.Sprintf(msg, args...)) 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 // Update metrics
//expWarnsTotal.Add(1) //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 // Update metrics
//expErrorsTotal.Add(1) //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...))
} }

14
pop3d/listener.go
View File

@@ -35,15 +35,15 @@ func (s *Server) Start() {
addr, err := net.ResolveTCPAddr("tcp4", fmt.Sprintf("%v:%v", addr, err := net.ResolveTCPAddr("tcp4", fmt.Sprintf("%v:%v",
cfg.Ip4address, cfg.Ip4port)) cfg.Ip4address, cfg.Ip4port))
if err != nil { 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 // TODO More graceful early-shutdown procedure
panic(err) 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) s.listener, err = net.ListenTCP("tcp4", addr)
if err != nil { 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 // TODO More graceful early-shutdown procedure
panic(err) panic(err)
} }
@@ -62,12 +62,12 @@ func (s *Server) Start() {
if max := 1 * time.Second; tempDelay > max { if max := 1 * time.Second; tempDelay > max {
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) time.Sleep(tempDelay)
continue continue
} else { } else {
if s.shutdown { if s.shutdown {
log.Trace("POP3 listener shutting down on request") log.LogTrace("POP3 listener shutting down on request")
return return
} }
// TODO Implement a max error counter before shutdown? // 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 // Stop requests the POP3 server closes it's listener
func (s *Server) Stop() { 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.shutdown = true
s.listener.Close() s.listener.Close()
} }
@@ -92,5 +92,5 @@ func (s *Server) Stop() {
// Drain causes the caller to block until all active POP3 sessions have finished // Drain causes the caller to block until all active POP3 sessions have finished
func (s *Server) Drain() { func (s *Server) Drain() {
s.waitgroup.Wait() s.waitgroup.Wait()
log.Trace("POP3 connections drained") log.LogTrace("POP3 connections drained")
} }

18
smtpd/filestore.go
View File

@@ -46,11 +46,11 @@ type FileDataStore struct {
func NewFileDataStore() DataStore { func NewFileDataStore() DataStore {
path, err := config.Config.String("datastore", "path") path, err := config.Config.String("datastore", "path")
if err != nil { if err != nil {
log.Error("Error getting datastore path: %v", err) log.LogError("Error getting datastore path: %v", err)
return nil return nil
} }
if path == "" { if path == "" {
log.Error("No value configured for datastore path") log.LogError("No value configured for datastore path")
return nil return nil
} }
mailPath := filepath.Join(path, "mail") mailPath := filepath.Join(path, "mail")
@@ -66,7 +66,7 @@ func (ds *FileDataStore) MailboxFor(emailAddress string) (Mailbox, error) {
s2 := dir[0:6] s2 := dir[0:6]
path := filepath.Join(ds.mailPath, s1, s2, dir) path := filepath.Join(ds.mailPath, s1, s2, dir)
if err := os.MkdirAll(path, 0770); err != nil { 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 nil, err
} }
return &FileMailbox{store: ds, name: name, dirName: dir, path: path}, nil return &FileMailbox{store: ds, name: name, dirName: dir, path: path}, nil
@@ -132,7 +132,7 @@ func (mb *FileMailbox) GetMessages() ([]Message, error) {
if err != nil { if err != nil {
return nil, err 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)) messages := make([]Message, 0, len(files))
for _, f := range files { for _, f := range files {
@@ -149,7 +149,7 @@ func (mb *FileMailbox) GetMessages() ([]Message, error) {
} }
file.Close() file.Close()
msg.mailbox = mb msg.mailbox = mb
log.Trace("Found: %v", msg) log.LogTrace("Found: %v", msg)
messages = append(messages, msg) messages = append(messages, msg)
} }
} }
@@ -170,7 +170,7 @@ func (mb *FileMailbox) GetMessage(id string) (Message, error) {
} }
file.Close() file.Close()
msg.mailbox = mb msg.mailbox = mb
log.Trace("Found: %v", msg) log.LogTrace("Found: %v", msg)
return msg, nil return msg, nil
} }
@@ -335,7 +335,7 @@ func (m *FileMessage) Close() error {
err := m.createGob() err := m.createGob()
if err != nil { if err != nil {
log.Error("Failed to create gob: %v", err) log.LogError("Failed to create gob: %v", err)
return 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 // Delete this Message from disk by removing both the gob and raw files
func (m *FileMessage) Delete() error { func (m *FileMessage) Delete() error {
log.Trace("Deleting %v", m.gobPath()) log.LogTrace("Deleting %v", m.gobPath())
err := os.Remove(m.gobPath()) err := os.Remove(m.gobPath())
if err != nil { if err != nil {
return err return err
} }
log.Trace("Deleting %v", m.rawPath()) log.LogTrace("Deleting %v", m.rawPath())
return os.Remove(m.rawPath()) return os.Remove(m.rawPath())
} }

2
smtpd/filestore_test.go
View File

@@ -1,7 +1,7 @@
package smtpd package smtpd
import ( import (
"github.com/stretchrcom/testify/assert" "github.com/stretchr/testify/assert"
"io/ioutil" "io/ioutil"
"os" "os"
"path/filepath" "path/filepath"

87
smtpd/handler.go
View File

@@ -88,7 +88,7 @@ func (ss *Session) String() string {
* 5. Goto 2 * 5. Goto 2
*/ */
func (s *Server) startSession(id int, conn net.Conn) { 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) expConnectsCurrent.Add(1)
defer func() { defer func() {
conn.Close() conn.Close()
@@ -116,7 +116,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
} }
if !commands[cmd] { if !commands[cmd] {
ss.send(fmt.Sprintf("500 Syntax error, %v command unrecognized", 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 continue
} }
@@ -125,7 +125,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
case "SEND", "SOML", "SAML", "EXPN", "HELP", "TURN": case "SEND", "SOML", "SAML", "EXPN", "HELP", "TURN":
// These commands are not implemented in any state // These commands are not implemented in any state
ss.send(fmt.Sprintf("502 %v command not implemented", cmd)) 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 continue
case "VRFY": case "VRFY":
ss.send("252 Cannot VRFY user, but will accept message") ss.send("252 Cannot VRFY user, but will accept message")
@@ -135,7 +135,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
continue continue
case "RSET": case "RSET":
// Reset session // Reset session
ss.trace("Resetting session state on RSET request") ss.logTrace("Resetting session state on RSET request")
ss.reset() ss.reset()
ss.send("250 Session reset") ss.send("250 Session reset")
continue continue
@@ -157,7 +157,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
ss.mailHandler(cmd, arg) ss.mailHandler(cmd, arg)
continue continue
} }
ss.error("Session entered unexpected state %v", ss.state) ss.logError("Session entered unexpected state %v", ss.state)
break break
} else { } else {
ss.send("500 Syntax error, command garbled") ss.send("500 Syntax error, command garbled")
@@ -168,14 +168,14 @@ func (s *Server) startSession(id int, conn net.Conn) {
switch ss.state { switch ss.state {
case GREET, READY: case GREET, READY:
// EOF is common here // EOF is common here
ss.info("Client closed connection (state %v)", ss.state) ss.logInfo("Client closed connection (state %v)", ss.state)
default: default:
ss.warn("Got EOF while in state %v", ss.state) ss.logWarn("Got EOF while in state %v", ss.state)
} }
break break
} }
// not an EOF // not an EOF
ss.warn("Connection error: %v", err) ss.logWarn("Connection error: %v", err)
if netErr, ok := err.(net.Error); ok { if netErr, ok := err.(net.Error); ok {
if netErr.Timeout() { if netErr.Timeout() {
ss.send("221 Idle timeout, bye bye") ss.send("221 Idle timeout, bye bye")
@@ -187,9 +187,9 @@ func (s *Server) startSession(id int, conn net.Conn) {
} }
} }
if ss.sendError != nil { 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 // GREET state -> waiting for HELO
@@ -216,7 +216,7 @@ func (ss *Session) readyHandler(cmd string, arg string) {
m := re.FindStringSubmatch(arg) m := re.FindStringSubmatch(arg)
if m == nil { if m == nil {
ss.send("501 Was expecting MAIL arg syntax of FROM:<address>") ss.send("501 Was expecting MAIL arg syntax of FROM:<address>")
ss.warn("Bad MAIL argument: '%v'", arg) ss.logWarn("Bad MAIL argument: '%v'", arg)
return return
} }
from := m[1] from := m[1]
@@ -226,26 +226,26 @@ func (ss *Session) readyHandler(cmd string, arg string) {
args, ok := ss.parseArgs(m[2]) args, ok := ss.parseArgs(m[2])
if !ok { if !ok {
ss.send("501 Unable to parse MAIL ESMTP parameters") ss.send("501 Unable to parse MAIL ESMTP parameters")
ss.warn("Bad MAIL argument: '%v'", arg) ss.logWarn("Bad MAIL argument: '%v'", arg)
return return
} }
if args["SIZE"] != "" { if args["SIZE"] != "" {
size, err := strconv.ParseInt(args["SIZE"], 10, 32) size, err := strconv.ParseInt(args["SIZE"], 10, 32)
if err != nil { if err != nil {
ss.send("501 Unable to parse SIZE as an integer") 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 return
} }
if int(size) > ss.server.maxMessageBytes { if int(size) > ss.server.maxMessageBytes {
ss.send("552 Max message size exceeded") 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 return
} }
} }
} }
ss.from = from ss.from = from
ss.recipients = list.New() 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.send(fmt.Sprintf("250 Roger, accepting mail from <%v>", from))
ss.enterState(MAIL) ss.enterState(MAIL)
} else { } else {
@@ -259,24 +259,24 @@ func (ss *Session) mailHandler(cmd string, arg string) {
case "RCPT": case "RCPT":
if (len(arg) < 4) || (strings.ToUpper(arg[0:3]) != "TO:") { if (len(arg) < 4) || (strings.ToUpper(arg[0:3]) != "TO:") {
ss.send("501 Was expecting RCPT arg syntax of TO:<address>") ss.send("501 Was expecting RCPT arg syntax of TO:<address>")
ss.warn("Bad RCPT argument: '%v'", arg) ss.logWarn("Bad RCPT argument: '%v'", arg)
return return
} }
// This trim is probably too forgiving // This trim is probably too forgiving
recip := strings.Trim(arg[3:], "<> ") recip := strings.Trim(arg[3:], "<> ")
if ss.recipients.Len() >= ss.server.maxRecips { 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)) ss.send(fmt.Sprintf("552 Maximum limit of %v recipients reached", ss.server.maxRecips))
return return
} }
ss.recipients.PushBack(recip) 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)) ss.send(fmt.Sprintf("250 I'll make sure <%v> gets this", recip))
return return
case "DATA": case "DATA":
if arg != "" { if arg != "" {
ss.send("501 DATA command should not have any arguments") 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 return
} }
if ss.recipients.Len() > 0 { if ss.recipients.Len() > 0 {
@@ -307,7 +307,7 @@ func (ss *Session) dataHandler() {
// Not our "no store" domain, so store the message // Not our "no store" domain, so store the message
mb, err := ss.server.dataStore.MailboxFor(recip) mb, err := ss.server.dataStore.MailboxFor(recip)
if err != nil { 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.send(fmt.Sprintf("451 Failed to open mailbox for %v", recip))
ss.reset() ss.reset()
return return
@@ -315,7 +315,7 @@ func (ss *Session) dataHandler() {
mailboxes[i] = mb mailboxes[i] = mb
messages[i] = mb.NewMessage() messages[i] = mb.NewMessage()
} else { } else {
log.Trace("Not storing message for '%v'", recip) log.LogTrace("Not storing message for '%v'", recip)
} }
i++ i++
} }
@@ -332,7 +332,7 @@ func (ss *Session) dataHandler() {
ss.send("221 Idle timeout, bye bye") ss.send("221 Idle timeout, bye bye")
} }
} }
ss.warn("Error: %v while reading", err) ss.logWarn("Error: %v while reading", err)
ss.enterState(QUIT) ss.enterState(QUIT)
return return
} }
@@ -350,7 +350,7 @@ func (ss *Session) dataHandler() {
expReceivedTotal.Add(1) expReceivedTotal.Add(1)
} }
ss.send("250 Mail accepted for delivery") ss.send("250 Mail accepted for delivery")
ss.info("Message size %v bytes", msgSize) ss.logInfo("Message size %v bytes", msgSize)
ss.reset() ss.reset()
return return
} }
@@ -362,7 +362,7 @@ func (ss *Session) dataHandler() {
if msgSize > ss.server.maxMessageBytes { if msgSize > ss.server.maxMessageBytes {
// Max message size exceeded // Max message size exceeded
ss.send("552 Maximum 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() ss.reset()
// TODO: Should really cleanup the crap on filesystem... // TODO: Should really cleanup the crap on filesystem...
return return
@@ -372,7 +372,7 @@ func (ss *Session) dataHandler() {
for i, m := range messages { for i, m := range messages {
if m != nil { if m != nil {
if err := m.Append(line); err != 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.send("554 Something went wrong")
ss.reset() ss.reset()
// TODO: Should really cleanup the crap on filesystem... // TODO: Should really cleanup the crap on filesystem...
@@ -386,7 +386,7 @@ func (ss *Session) dataHandler() {
func (ss *Session) enterState(state State) { func (ss *Session) enterState(state State) {
ss.state = state ss.state = state
ss.trace("Entering state %v", state) ss.logTrace("Entering state %v", state)
} }
func (ss *Session) greet() { 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 { if _, err := fmt.Fprint(ss.conn, msg+"\r\n"); err != nil {
ss.sendError = err ss.sendError = err
ss.warn("Failed to send: '%v'", msg) ss.logWarn("Failed to send: '%v'", msg)
return return
} }
ss.trace(">> %v >>", msg) ss.logTrace(">> %v >>", msg)
} }
// readByteLine reads a line of input into the provided buffer. Does // 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 // Else, keep looking
} }
// Should be unreachable // Should be unreachable
return nil
} }
// Reads a line of input // Reads a line of input
@@ -449,7 +448,7 @@ func (ss *Session) readLine() (line string, err error) {
if err != nil { if err != nil {
return "", err return "", err
} }
ss.trace("<< %v <<", strings.TrimRight(line, "\r\n")) ss.logTrace("<< %v <<", strings.TrimRight(line, "\r\n"))
return line, nil return line, nil
} }
@@ -460,19 +459,19 @@ func (ss *Session) parseCmd(line string) (cmd string, arg string, ok bool) {
case l == 0: case l == 0:
return "", "", true return "", "", true
case l < 4: case l < 4:
ss.warn("Command too short: '%v'", line) ss.logWarn("Command too short: '%v'", line)
return "", "", false return "", "", false
case l == 4: case l == 4:
return strings.ToUpper(line), "", true return strings.ToUpper(line), "", true
case l == 5: case l == 5:
// Too long to be only command, too short to have args // 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 return "", "", false
} }
// If we made it here, command is long enough to have args // If we made it here, command is long enough to have args
if line[4] != ' ' { if line[4] != ' ' {
// There wasn't a space after the command? // There wasn't a space after the command?
ss.warn("Mangled command: '%v'", line) ss.logWarn("Mangled command: '%v'", line)
return "", "", false return "", "", false
} }
// I'm not sure if we should trim the args or not, but we will for now // 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+)") re := regexp.MustCompile(" (\\w+)=(\\w+)")
pm := re.FindAllStringSubmatch(arg, -1) pm := re.FindAllStringSubmatch(arg, -1)
if pm == nil { if pm == nil {
ss.warn("Failed to parse arg string: '%v'") ss.logWarn("Failed to parse arg string: '%v'")
return nil, false return nil, false
} }
for _, m := range pm { for _, m := range pm {
args[strings.ToUpper(m[1])] = m[2] args[strings.ToUpper(m[1])] = m[2]
} }
ss.trace("ESMTP params: %v", args) ss.logTrace("ESMTP params: %v", args)
return args, true return args, true
} }
@@ -507,26 +506,26 @@ func (ss *Session) reset() {
func (ss *Session) ooSeq(cmd string) { func (ss *Session) ooSeq(cmd string) {
ss.send(fmt.Sprintf("503 Command %v is out of sequence", cmd)) 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 // Session specific logging methods
func (ss *Session) trace(msg string, args ...interface{}) { func (ss *Session) logTrace(msg string, args ...interface{}) {
log.Trace("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...)) log.LogTrace("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...))
} }
func (ss *Session) info(msg string, args ...interface{}) { func (ss *Session) logInfo(msg string, args ...interface{}) {
log.Info("SMTP<%v> %v", ss.id, fmt.Sprintf(msg, args...)) 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 // Update metrics
expWarnsTotal.Add(1) 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 // Update metrics
expErrorsTotal.Add(1) 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...))
} }

18
smtpd/listener.go
View File

@@ -61,23 +61,23 @@ func (s *Server) Start() {
addr, err := net.ResolveTCPAddr("tcp4", fmt.Sprintf("%v:%v", addr, err := net.ResolveTCPAddr("tcp4", fmt.Sprintf("%v:%v",
cfg.Ip4address, cfg.Ip4port)) cfg.Ip4address, cfg.Ip4port))
if err != nil { 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 // TODO More graceful early-shutdown procedure
panic(err) 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) s.listener, err = net.ListenTCP("tcp4", addr)
if err != nil { 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 // TODO More graceful early-shutdown procedure
panic(err) panic(err)
} }
if !s.storeMessages { 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 != "" { } 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 // Start retention scanner
@@ -97,12 +97,12 @@ func (s *Server) Start() {
if max := 1 * time.Second; tempDelay > max { if max := 1 * time.Second; tempDelay > max {
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) time.Sleep(tempDelay)
continue continue
} else { } else {
if s.shutdown { if s.shutdown {
log.Trace("SMTP listener shutting down on request") log.LogTrace("SMTP listener shutting down on request")
return return
} }
// TODO Implement a max error counter before shutdown? // 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 // Stop requests the SMTP server closes it's listener
func (s *Server) Stop() { 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.shutdown = true
s.listener.Close() s.listener.Close()
} }
@@ -128,7 +128,7 @@ func (s *Server) Stop() {
// Drain causes the caller to block until all active SMTP sessions have finished // Drain causes the caller to block until all active SMTP sessions have finished
func (s *Server) Drain() { func (s *Server) Drain() {
s.waitgroup.Wait() s.waitgroup.Wait()
log.Trace("SMTP connections drained") log.LogTrace("SMTP connections drained")
} }
// When the provided Ticker ticks, we update our metrics history // When the provided Ticker ticks, we update our metrics history

14
smtpd/retention.go
View File

@@ -26,11 +26,11 @@ func StartRetentionScanner(ds DataStore) {
expRetentionPeriod.Set(int64(cfg.RetentionMinutes * 60)) expRetentionPeriod.Set(int64(cfg.RetentionMinutes * 60))
if cfg.RetentionMinutes > 0 { if cfg.RetentionMinutes > 0 {
// Retention scanning enabled // 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, go retentionScanner(ds, time.Duration(cfg.RetentionMinutes) * time.Minute,
time.Duration(cfg.RetentionSleep) * time.Millisecond) time.Duration(cfg.RetentionSleep) * time.Millisecond)
} else { } 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) since := time.Since(start)
if since < time.Minute { if since < time.Minute {
dur := time.Minute - since dur := time.Minute - since
log.Trace("Retention scanner sleeping for %v", dur) log.LogTrace("Retention scanner sleeping for %v", dur)
time.Sleep(dur) time.Sleep(dur)
} }
start = time.Now() start = time.Now()
// Kickoff scan // Kickoff scan
if err := doRetentionScan(ds, maxAge, sleep); err != nil { 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 // 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 { 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) cutoff := time.Now().Add(-1 * maxAge)
mboxes, err := ds.AllMailboxes() mboxes, err := ds.AllMailboxes()
if err != nil { if err != nil {
@@ -69,11 +69,11 @@ func doRetentionScan(ds DataStore, maxAge time.Duration, sleep time.Duration) er
} }
for _, msg := range messages { for _, msg := range messages {
if msg.Date().Before(cutoff) { if msg.Date().Before(cutoff) {
log.Trace("Purging expired message %v", msg.Id()) log.LogTrace("Purging expired message %v", msg.Id())
err = msg.Delete() err = msg.Delete()
if err != nil { if err != nil {
// Log but don't abort // 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 { } else {
expRetentionDeletesTotal.Add(1) expRetentionDeletesTotal.Add(1)
} }

13
smtpd/retention_test.go
View File

@@ -3,7 +3,8 @@ package smtpd
import ( import (
"fmt" "fmt"
"github.com/jhillyerd/go.enmime" "github.com/jhillyerd/go.enmime"
"github.com/stretchrcom/testify/mock" "github.com/stretchr/testify/mock"
"io"
"net/mail" "net/mail"
"testing" "testing"
"time" "time"
@@ -141,6 +142,16 @@ func (m *MockMessage) ReadRaw() (raw *string, err error) {
return args.Get(0).(*string), args.Error(1) 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 { func (m *MockMessage) Append(data []byte) error {
args := m.Called(data) args := m.Called(data)
return args.Error(0) return args.Error(0)

2
smtpd/utils_test.go
View File

@@ -1,7 +1,7 @@
package smtpd package smtpd
import ( import (
"github.com/stretchrcom/testify/assert" "github.com/stretchr/testify/assert"
"testing" "testing"
) )

2
web/helpers.go
View File

@@ -39,7 +39,7 @@ func reverse(name string, things ...interface{}) string {
// Grab the route // Grab the route
u, err := Router.Get(name).URL(strs...) u, err := Router.Get(name).URL(strs...)
if err != nil { if err != nil {
log.Error("Failed to reverse route: %v", err) log.LogError("Failed to reverse route: %v", err)
return "/ROUTE-ERROR" return "/ROUTE-ERROR"
} }
return u.Path return u.Path

2
web/helpers_test.go
View File

@@ -1,7 +1,7 @@
package web package web
import ( import (
"github.com/stretchrcom/testify/assert" "github.com/stretchr/testify/assert"
"html/template" "html/template"
"testing" "testing"
) )

2
web/mailbox_controller.go
View File

@@ -35,7 +35,7 @@ func MailboxList(w http.ResponseWriter, req *http.Request, ctx *Context) (err er
if err != nil { if err != nil {
return fmt.Errorf("Failed to get messages for %v: %v", name, err) 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{}{ return RenderPartial("mailbox/_list.html", w, map[string]interface{}{
"ctx": ctx, "ctx": ctx,

24
web/server.go
View File

@@ -23,8 +23,8 @@ var sessionStore sessions.Store
var shutdown bool var shutdown bool
func setupRoutes(cfg config.WebConfig) { func setupRoutes(cfg config.WebConfig) {
log.Info("Theme templates mapped to '%v'", cfg.TemplateDir) log.LogInfo("Theme templates mapped to '%v'", cfg.TemplateDir)
log.Info("Theme static content mapped to '%v'", cfg.PublicDir) log.LogInfo("Theme static content mapped to '%v'", cfg.PublicDir)
r := mux.NewRouter() r := mux.NewRouter()
// Static content // Static content
@@ -65,30 +65,30 @@ func Start() {
} }
// We don't use ListenAndServe because it lacks a way to close the listener // 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 var err error
listener, err = net.Listen("tcp", addr) listener, err = net.Listen("tcp", addr)
if err != nil { 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 // TODO More graceful early-shutdown procedure
panic(err) panic(err)
} }
err = server.Serve(listener) err = server.Serve(listener)
if shutdown { if shutdown {
log.Trace("HTTP server shutting down on request") log.LogTrace("HTTP server shutting down on request")
} else if err != nil { } else if err != nil {
log.Error("HTTP server failed: %v", err) log.LogError("HTTP server failed: %v", err)
} }
} }
func Stop() { func Stop() {
log.Trace("HTTP shutdown requested") log.LogTrace("HTTP shutdown requested")
shutdown = true shutdown = true
if listener != nil { if listener != nil {
listener.Close() listener.Close()
} else { } 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 // Create the context
ctx, err := NewContext(req) ctx, err := NewContext(req)
if err != nil { 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) http.Error(w, err.Error(), http.StatusInternalServerError)
return return
} }
@@ -105,17 +105,17 @@ func (h handler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
// Run the handler, grab the error, and report it // Run the handler, grab the error, and report it
buf := new(httpbuf.Buffer) 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) err = h(buf, req, ctx)
if err != nil { 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) http.Error(w, err.Error(), http.StatusInternalServerError)
return return
} }
// Save the session // Save the session
if err = ctx.Session.Save(req, buf); err != nil { 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) http.Error(w, err.Error(), http.StatusInternalServerError)
return return
} }

10
web/template.go
View File

@@ -20,7 +20,7 @@ var cachedPartials = map[string]*template.Template{}
func RenderTemplate(name string, w http.ResponseWriter, data interface{}) error { func RenderTemplate(name string, w http.ResponseWriter, data interface{}) error {
t, err := ParseTemplate(name, false) t, err := ParseTemplate(name, false)
if err != nil { if err != nil {
log.Error("Error in template '%v': %v", name, err) log.LogError("Error in template '%v': %v", name, err)
return err return err
} }
w.Header().Set("Expires", "-1") 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 { func RenderPartial(name string, w http.ResponseWriter, data interface{}) error {
t, err := ParseTemplate(name, true) t, err := ParseTemplate(name, true)
if err != nil { if err != nil {
log.Error("Error in template '%v': %v", name, err) log.LogError("Error in template '%v': %v", name, err)
return err return err
} }
w.Header().Set("Expires", "-1") w.Header().Set("Expires", "-1")
@@ -52,7 +52,7 @@ func ParseTemplate(name string, partial bool) (*template.Template, error) {
cfg := config.GetWebConfig() cfg := config.GetWebConfig()
tempPath := strings.Replace(name, "/", string(filepath.Separator), -1) tempPath := strings.Replace(name, "/", string(filepath.Separator), -1)
tempFile := filepath.Join(cfg.TemplateDir, tempPath) tempFile := filepath.Join(cfg.TemplateDir, tempPath)
log.Trace("Parsing template %v", tempFile) log.LogTrace("Parsing template %v", tempFile)
var err error var err error
var t *template.Template 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 // Allows us to disable caching for theme development
if cfg.TemplateCache { if cfg.TemplateCache {
if partial { if partial {
log.Trace("Caching partial %v", name) log.LogTrace("Caching partial %v", name)
cachedTemplates[name] = t cachedTemplates[name] = t
} else { } else {
log.Trace("Caching template %v", name) log.LogTrace("Caching template %v", name)
cachedTemplates[name] = t cachedTemplates[name] = t
} }
} }