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

smtp, pop3: Use zerolog for session logging #90

Browse Source
This commit is contained in:
James Hillyerd
2018-03-27 21:52:28 -07:00
parent 6f25a1320e
commit 779b1e63af
2 changed files with 105 additions and 139 deletions
Download Patch File Download Diff File Expand all files Collapse all files

140
pkg/server/pop3/handler.go
View File

@@ -11,8 +11,9 @@ import (
"strings" "strings"
"time" "time"
"github.com/jhillyerd/inbucket/pkg/log"
"github.com/jhillyerd/inbucket/pkg/storage" "github.com/jhillyerd/inbucket/pkg/storage"
"github.com/rs/zerolog"
"github.com/rs/zerolog/log"
) )
// State tracks the current mode of our POP3 state machine // State tracks the current mode of our POP3 state machine
@@ -68,14 +69,15 @@ type Session struct {
messages []storage.Message // Slice of messages in mailbox messages []storage.Message // Slice of messages in mailbox
retain []bool // Messages to retain upon UPDATE (true=retain) retain []bool // Messages to retain upon UPDATE (true=retain)
msgCount int // Number of undeleted messages msgCount int // Number of undeleted messages
logger zerolog.Logger
} }
// NewSession creates a new POP3 session // NewSession creates a new POP3 session
func NewSession(server *Server, id int, conn net.Conn) *Session { func NewSession(server *Server, id int, conn net.Conn, logger zerolog.Logger) *Session {
reader := bufio.NewReader(conn) reader := bufio.NewReader(conn)
host, _, _ := net.SplitHostPort(conn.RemoteAddr().String()) host, _, _ := net.SplitHostPort(conn.RemoteAddr().String())
return &Session{server: server, id: id, conn: conn, state: AUTHORIZATION, return &Session{server: server, id: id, conn: conn, state: AUTHORIZATION,
reader: reader, remoteHost: host} reader: reader, remoteHost: host, logger: logger}
} }
func (s *Session) String() string { func (s *Session) String() string {
@@ -90,17 +92,17 @@ func (s *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.Infof("POP3 connection from %v, starting session <%v>", conn.RemoteAddr(), id) logger := log.With().Str("module", "pop3").Str("remote", conn.RemoteAddr().String()).
//expConnectsCurrent.Add(1) Int("session", id).Logger()
logger.Info().Msg("Starting POP3 session")
defer func() { defer func() {
if err := conn.Close(); err != nil { if err := conn.Close(); err != nil {
log.Errorf("Error closing POP3 connection for <%v>: %v", id, err) logger.Warn().Err(err).Msg("Closing connection")
} }
s.waitgroup.Done() s.waitgroup.Done()
//expConnectsCurrent.Add(-1)
}() }()
ssn := NewSession(s, id, conn) ssn := NewSession(s, id, conn, logger)
ssn.send(fmt.Sprintf("+OK Inbucket POP3 server ready <%v.%v@%v>", os.Getpid(), ssn.send(fmt.Sprintf("+OK Inbucket POP3 server ready <%v.%v@%v>", os.Getpid(),
time.Now().Unix(), s.domain)) time.Now().Unix(), s.domain))
@@ -116,7 +118,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
} }
if !commands[cmd] { if !commands[cmd] {
ssn.send(fmt.Sprintf("-ERR Syntax error, %v command unrecognized", cmd)) ssn.send(fmt.Sprintf("-ERR Syntax error, %v command unrecognized", cmd))
ssn.logWarn("Unrecognized command: %v", cmd) ssn.logger.Warn().Msgf("Unrecognized command: %v", cmd)
continue continue
} }
@@ -142,7 +144,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
ssn.transactionHandler(cmd, arg) ssn.transactionHandler(cmd, arg)
continue continue
} }
ssn.logError("Session entered unexpected state %v", ssn.state) ssn.logger.Error().Msgf("Session entered unexpected state %v", ssn.state)
break break
} else { } else {
ssn.send("-ERR Syntax error, command garbled") ssn.send("-ERR Syntax error, command garbled")
@@ -153,14 +155,14 @@ func (s *Server) startSession(id int, conn net.Conn) {
switch ssn.state { switch ssn.state {
case AUTHORIZATION: case AUTHORIZATION:
// EOF is common here // EOF is common here
ssn.logInfo("Client closed connection (state %v)", ssn.state) ssn.logger.Info().Msgf("Client closed connection (state %v)", ssn.state)
default: default:
ssn.logWarn("Got EOF while in state %v", ssn.state) ssn.logger.Warn().Msgf("Got EOF while in state %v", ssn.state)
} }
break break
} }
// not an EOF // not an EOF
ssn.logWarn("Connection error: %v", err) ssn.logger.Warn().Msgf("Connection error: %v", err)
if netErr, ok := err.(net.Error); ok { if netErr, ok := err.(net.Error); ok {
if netErr.Timeout() { if netErr.Timeout() {
ssn.send("-ERR Idle timeout, bye bye") ssn.send("-ERR Idle timeout, bye bye")
@@ -172,9 +174,9 @@ func (s *Server) startSession(id int, conn net.Conn) {
} }
} }
if ssn.sendError != nil { if ssn.sendError != nil {
ssn.logWarn("Network send error: %v", ssn.sendError) ssn.logger.Warn().Msgf("Network send error: %v", ssn.sendError)
} }
ssn.logInfo("Closing connection") ssn.logger.Info().Msgf("Closing connection")
} }
// AUTHORIZATION state // AUTHORIZATION state
@@ -200,7 +202,7 @@ func (s *Session) authorizationHandler(cmd string, args []string) {
} }
case "APOP": case "APOP":
if len(args) != 2 { if len(args) != 2 {
s.logWarn("Expected two arguments for APOP") s.logger.Warn().Msgf("Expected two arguments for APOP")
s.send("-ERR APOP requires two arguments") s.send("-ERR APOP requires two arguments")
return return
} }
@@ -218,7 +220,7 @@ func (s *Session) transactionHandler(cmd string, args []string) {
switch cmd { switch cmd {
case "STAT": case "STAT":
if len(args) != 0 { if len(args) != 0 {
s.logWarn("STAT got an unexpected argument") s.logger.Warn().Msgf("STAT got an unexpected argument")
s.send("-ERR STAT command must have no arguments") s.send("-ERR STAT command must have no arguments")
return return
} }
@@ -233,29 +235,29 @@ func (s *Session) transactionHandler(cmd string, args []string) {
s.send(fmt.Sprintf("+OK %v %v", count, size)) s.send(fmt.Sprintf("+OK %v %v", count, size))
case "LIST": case "LIST":
if len(args) > 1 { if len(args) > 1 {
s.logWarn("LIST command had more than 1 argument") s.logger.Warn().Msgf("LIST command had more than 1 argument")
s.send("-ERR LIST command must have zero or one argument") s.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 {
s.logWarn("LIST command argument was not an integer") s.logger.Warn().Msgf("LIST command argument was not an integer")
s.send("-ERR LIST command requires an integer argument") s.send("-ERR LIST command requires an integer argument")
return return
} }
if msgNum < 1 { if msgNum < 1 {
s.logWarn("LIST command argument was less than 1") s.logger.Warn().Msgf("LIST command argument was less than 1")
s.send("-ERR LIST argument must be greater than 0") s.send("-ERR LIST argument must be greater than 0")
return return
} }
if int(msgNum) > len(s.messages) { if int(msgNum) > len(s.messages) {
s.logWarn("LIST command argument was greater than number of messages") s.logger.Warn().Msgf("LIST command argument was greater than number of messages")
s.send("-ERR LIST argument must not exceed the number of messages") s.send("-ERR LIST argument must not exceed the number of messages")
return return
} }
if !s.retain[msgNum-1] { if !s.retain[msgNum-1] {
s.logWarn("Client tried to LIST a message it had deleted") s.logger.Warn().Msgf("Client tried to LIST a message it had deleted")
s.send(fmt.Sprintf("-ERR You deleted message %v", msgNum)) s.send(fmt.Sprintf("-ERR You deleted message %v", msgNum))
return return
} }
@@ -271,29 +273,29 @@ func (s *Session) transactionHandler(cmd string, args []string) {
} }
case "UIDL": case "UIDL":
if len(args) > 1 { if len(args) > 1 {
s.logWarn("UIDL command had more than 1 argument") s.logger.Warn().Msgf("UIDL command had more than 1 argument")
s.send("-ERR UIDL command must have zero or one argument") s.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 {
s.logWarn("UIDL command argument was not an integer") s.logger.Warn().Msgf("UIDL command argument was not an integer")
s.send("-ERR UIDL command requires an integer argument") s.send("-ERR UIDL command requires an integer argument")
return return
} }
if msgNum < 1 { if msgNum < 1 {
s.logWarn("UIDL command argument was less than 1") s.logger.Warn().Msgf("UIDL command argument was less than 1")
s.send("-ERR UIDL argument must be greater than 0") s.send("-ERR UIDL argument must be greater than 0")
return return
} }
if int(msgNum) > len(s.messages) { if int(msgNum) > len(s.messages) {
s.logWarn("UIDL command argument was greater than number of messages") s.logger.Warn().Msgf("UIDL command argument was greater than number of messages")
s.send("-ERR UIDL argument must not exceed the number of messages") s.send("-ERR UIDL argument must not exceed the number of messages")
return return
} }
if !s.retain[msgNum-1] { if !s.retain[msgNum-1] {
s.logWarn("Client tried to UIDL a message it had deleted") s.logger.Warn().Msgf("Client tried to UIDL a message it had deleted")
s.send(fmt.Sprintf("-ERR You deleted message %v", msgNum)) s.send(fmt.Sprintf("-ERR You deleted message %v", msgNum))
return return
} }
@@ -309,23 +311,23 @@ func (s *Session) transactionHandler(cmd string, args []string) {
} }
case "DELE": case "DELE":
if len(args) != 1 { if len(args) != 1 {
s.logWarn("DELE command had invalid number of arguments") s.logger.Warn().Msgf("DELE command had invalid number of arguments")
s.send("-ERR DELE command requires a single argument") s.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 {
s.logWarn("DELE command argument was not an integer") s.logger.Warn().Msgf("DELE command argument was not an integer")
s.send("-ERR DELE command requires an integer argument") s.send("-ERR DELE command requires an integer argument")
return return
} }
if msgNum < 1 { if msgNum < 1 {
s.logWarn("DELE command argument was less than 1") s.logger.Warn().Msgf("DELE command argument was less than 1")
s.send("-ERR DELE argument must be greater than 0") s.send("-ERR DELE argument must be greater than 0")
return return
} }
if int(msgNum) > len(s.messages) { if int(msgNum) > len(s.messages) {
s.logWarn("DELE command argument was greater than number of messages") s.logger.Warn().Msgf("DELE command argument was greater than number of messages")
s.send("-ERR DELE argument must not exceed the number of messages") s.send("-ERR DELE argument must not exceed the number of messages")
return return
} }
@@ -334,28 +336,28 @@ func (s *Session) transactionHandler(cmd string, args []string) {
s.msgCount-- s.msgCount--
s.send(fmt.Sprintf("+OK Deleted message %v", msgNum)) s.send(fmt.Sprintf("+OK Deleted message %v", msgNum))
} else { } else {
s.logWarn("Client tried to DELE an already deleted message") s.logger.Warn().Msgf("Client tried to DELE an already deleted message")
s.send(fmt.Sprintf("-ERR Message %v has already been deleted", msgNum)) s.send(fmt.Sprintf("-ERR Message %v has already been deleted", msgNum))
} }
case "RETR": case "RETR":
if len(args) != 1 { if len(args) != 1 {
s.logWarn("RETR command had invalid number of arguments") s.logger.Warn().Msgf("RETR command had invalid number of arguments")
s.send("-ERR RETR command requires a single argument") s.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 {
s.logWarn("RETR command argument was not an integer") s.logger.Warn().Msgf("RETR command argument was not an integer")
s.send("-ERR RETR command requires an integer argument") s.send("-ERR RETR command requires an integer argument")
return return
} }
if msgNum < 1 { if msgNum < 1 {
s.logWarn("RETR command argument was less than 1") s.logger.Warn().Msgf("RETR command argument was less than 1")
s.send("-ERR RETR argument must be greater than 0") s.send("-ERR RETR argument must be greater than 0")
return return
} }
if int(msgNum) > len(s.messages) { if int(msgNum) > len(s.messages) {
s.logWarn("RETR command argument was greater than number of messages") s.logger.Warn().Msgf("RETR command argument was greater than number of messages")
s.send("-ERR RETR argument must not exceed the number of messages") s.send("-ERR RETR argument must not exceed the number of messages")
return return
} }
@@ -363,23 +365,23 @@ func (s *Session) transactionHandler(cmd string, args []string) {
s.sendMessage(s.messages[msgNum-1]) s.sendMessage(s.messages[msgNum-1])
case "TOP": case "TOP":
if len(args) != 2 { if len(args) != 2 {
s.logWarn("TOP command had invalid number of arguments") s.logger.Warn().Msgf("TOP command had invalid number of arguments")
s.send("-ERR TOP command requires two arguments") s.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 {
s.logWarn("TOP command first argument was not an integer") s.logger.Warn().Msgf("TOP command first argument was not an integer")
s.send("-ERR TOP command requires an integer argument") s.send("-ERR TOP command requires an integer argument")
return return
} }
if msgNum < 1 { if msgNum < 1 {
s.logWarn("TOP command first argument was less than 1") s.logger.Warn().Msgf("TOP command first argument was less than 1")
s.send("-ERR TOP first argument must be greater than 0") s.send("-ERR TOP first argument must be greater than 0")
return return
} }
if int(msgNum) > len(s.messages) { if int(msgNum) > len(s.messages) {
s.logWarn("TOP command first argument was greater than number of messages") s.logger.Warn().Msgf("TOP command first argument was greater than number of messages")
s.send("-ERR TOP first argument must not exceed the number of messages") s.send("-ERR TOP first argument must not exceed the number of messages")
return return
} }
@@ -387,12 +389,12 @@ func (s *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 {
s.logWarn("TOP command second argument was not an integer") s.logger.Warn().Msgf("TOP command second argument was not an integer")
s.send("-ERR TOP command requires an integer argument") s.send("-ERR TOP command requires an integer argument")
return return
} }
if lines < 0 { if lines < 0 {
s.logWarn("TOP command second argument was negative") s.logger.Warn().Msgf("TOP command second argument was negative")
s.send("-ERR TOP second argument must be non-negative") s.send("-ERR TOP second argument must be non-negative")
return return
} }
@@ -406,7 +408,7 @@ func (s *Session) transactionHandler(cmd string, args []string) {
s.send("+OK I have sucessfully done nothing") s.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
s.logTrace("Resetting session state on RSET request") s.logger.Debug().Msgf("Resetting session state on RSET request")
s.reset() s.reset()
s.send("+OK Session reset") s.send("+OK Session reset")
default: default:
@@ -418,13 +420,13 @@ func (s *Session) transactionHandler(cmd string, args []string) {
func (s *Session) sendMessage(msg storage.Message) { func (s *Session) sendMessage(msg storage.Message) {
reader, err := msg.Source() reader, err := msg.Source()
if err != nil { if err != nil {
s.logError("Failed to read message for RETR command") s.logger.Error().Msgf("Failed to read message for RETR command")
s.send("-ERR Failed to RETR that message, internal error") s.send("-ERR Failed to RETR that message, internal error")
return return
} }
defer func() { defer func() {
if err := reader.Close(); err != nil { if err := reader.Close(); err != nil {
s.logError("Failed to close message: %v", err) s.logger.Error().Msgf("Failed to close message: %v", err)
} }
}() }()
@@ -439,7 +441,7 @@ func (s *Session) sendMessage(msg storage.Message) {
} }
if err = scanner.Err(); err != nil { if err = scanner.Err(); err != nil {
s.logError("Failed to read message for RETR command") s.logger.Error().Msgf("Failed to read message for RETR command")
s.send(".") s.send(".")
s.send("-ERR Failed to RETR that message, internal error") s.send("-ERR Failed to RETR that message, internal error")
return return
@@ -451,13 +453,13 @@ func (s *Session) sendMessage(msg storage.Message) {
func (s *Session) sendMessageTop(msg storage.Message, lineCount int) { func (s *Session) sendMessageTop(msg storage.Message, lineCount int) {
reader, err := msg.Source() reader, err := msg.Source()
if err != nil { if err != nil {
s.logError("Failed to read message for RETR command") s.logger.Error().Msgf("Failed to read message for RETR command")
s.send("-ERR Failed to RETR that message, internal error") s.send("-ERR Failed to RETR that message, internal error")
return return
} }
defer func() { defer func() {
if err := reader.Close(); err != nil { if err := reader.Close(); err != nil {
s.logError("Failed to close message: %v", err) s.logger.Error().Msgf("Failed to close message: %v", err)
} }
}() }()
@@ -486,7 +488,7 @@ func (s *Session) sendMessageTop(msg storage.Message, lineCount int) {
} }
if err = scanner.Err(); err != nil { if err = scanner.Err(); err != nil {
s.logError("Failed to read message for RETR command") s.logger.Error().Msgf("Failed to read message for RETR command")
s.send(".") s.send(".")
s.send("-ERR Failed to RETR that message, internal error") s.send("-ERR Failed to RETR that message, internal error")
return return
@@ -496,9 +498,10 @@ func (s *Session) sendMessageTop(msg storage.Message, lineCount int) {
// Load the users mailbox // Load the users mailbox
func (s *Session) loadMailbox() { func (s *Session) loadMailbox() {
s.logger = s.logger.With().Str("mailbox", s.user).Logger()
m, err := s.server.store.GetMessages(s.user) m, err := s.server.store.GetMessages(s.user)
if err != nil { if err != nil {
s.logError("Failed to load messages for %v: %v", s.user, err) s.logger.Error().Msgf("Failed to load messages for %v: %v", s.user, err)
} }
s.messages = m s.messages = m
s.retainAll() s.retainAll()
@@ -518,12 +521,12 @@ func (s *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 (s *Session) processDeletes() { func (s *Session) processDeletes() {
s.logInfo("Processing deletes") s.logger.Info().Msgf("Processing deletes")
for i, msg := range s.messages { for i, msg := range s.messages {
if !s.retain[i] { if !s.retain[i] {
s.logTrace("Deleting %v", msg) s.logger.Debug().Str("id", msg.ID()).Msg("Deleting message")
if err := s.server.store.RemoveMessage(s.user, msg.ID()); err != nil { if err := s.server.store.RemoveMessage(s.user, msg.ID()); err != nil {
s.logWarn("Error deleting %v: %v", msg, err) s.logger.Warn().Str("id", msg.ID()).Err(err).Msg("Error deleting message")
} }
} }
} }
@@ -531,7 +534,7 @@ func (s *Session) processDeletes() {
func (s *Session) enterState(state State) { func (s *Session) enterState(state State) {
s.state = state s.state = state
s.logTrace("Entering state %v", state) s.logger.Debug().Msgf("Entering state %v", state)
} }
// Calculate the next read or write deadline based on maxIdleSeconds // Calculate the next read or write deadline based on maxIdleSeconds
@@ -547,10 +550,10 @@ func (s *Session) send(msg string) {
} }
if _, err := fmt.Fprint(s.conn, msg+"\r\n"); err != nil { if _, err := fmt.Fprint(s.conn, msg+"\r\n"); err != nil {
s.sendError = err s.sendError = err
s.logWarn("Failed to send: '%v'", msg) s.logger.Warn().Msgf("Failed to send: '%v'", msg)
return return
} }
s.logTrace(">> %v >>", msg) s.logger.Debug().Msgf(">> %v >>", msg)
} }
// readByteLine reads a line of input into the provided buffer. Does // readByteLine reads a line of input into the provided buffer. Does
@@ -593,7 +596,7 @@ func (s *Session) readLine() (line string, err error) {
if err != nil { if err != nil {
return "", err return "", err
} }
s.logTrace("<< %v <<", strings.TrimRight(line, "\r\n")) s.logger.Debug().Msgf("<< %v <<", strings.TrimRight(line, "\r\n"))
return line, nil return line, nil
} }
@@ -613,26 +616,5 @@ func (s *Session) reset() {
func (s *Session) ooSeq(cmd string) { func (s *Session) ooSeq(cmd string) {
s.send(fmt.Sprintf("-ERR Command %v is out of sequence", cmd)) s.send(fmt.Sprintf("-ERR Command %v is out of sequence", cmd))
s.logWarn("Wasn't expecting %v here", cmd) s.logger.Warn().Msgf("Wasn't expecting %v here", cmd)
}
// Session specific logging methods
func (s *Session) logTrace(msg string, args ...interface{}) {
log.Tracef("POP3[%v]<%v> %v", s.remoteHost, s.id, fmt.Sprintf(msg, args...))
}
func (s *Session) logInfo(msg string, args ...interface{}) {
log.Infof("POP3[%v]<%v> %v", s.remoteHost, s.id, fmt.Sprintf(msg, args...))
}
func (s *Session) logWarn(msg string, args ...interface{}) {
// Update metrics
//expWarnsTotal.Add(1)
log.Warnf("POP3[%v]<%v> %v", s.remoteHost, s.id, fmt.Sprintf(msg, args...))
}
func (s *Session) logError(msg string, args ...interface{}) {
// Update metrics
//expErrorsTotal.Add(1)
log.Errorf("POP3[%v]<%v> %v", s.remoteHost, s.id, fmt.Sprintf(msg, args...))
} }

104
pkg/server/smtp/handler.go
View File

@@ -11,8 +11,9 @@ import (
"strings" "strings"
"time" "time"
"github.com/jhillyerd/inbucket/pkg/log"
"github.com/jhillyerd/inbucket/pkg/policy" "github.com/jhillyerd/inbucket/pkg/policy"
"github.com/rs/zerolog"
"github.com/rs/zerolog/log"
) )
// State tracks the current mode of our SMTP state machine // State tracks the current mode of our SMTP state machine
@@ -79,10 +80,11 @@ type Session struct {
reader *bufio.Reader reader *bufio.Reader
from string from string
recipients []*policy.Recipient recipients []*policy.Recipient
logger zerolog.Logger
} }
// NewSession creates a new Session for the given connection // NewSession creates a new Session for the given connection
func NewSession(server *Server, id int, conn net.Conn) *Session { func NewSession(server *Server, id int, conn net.Conn, logger zerolog.Logger) *Session {
reader := bufio.NewReader(conn) reader := bufio.NewReader(conn)
host, _, _ := net.SplitHostPort(conn.RemoteAddr().String()) host, _, _ := net.SplitHostPort(conn.RemoteAddr().String())
return &Session{ return &Session{
@@ -93,6 +95,7 @@ func NewSession(server *Server, id int, conn net.Conn) *Session {
reader: reader, reader: reader,
remoteHost: host, remoteHost: host,
recipients: make([]*policy.Recipient, 0), recipients: make([]*policy.Recipient, 0),
logger: logger,
} }
} }
@@ -108,17 +111,19 @@ func (s *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.Infof("SMTP Connection from %v, starting session <%v>", conn.RemoteAddr(), id) logger := log.With().Str("module", "smtp").Str("remote", conn.RemoteAddr().String()).
Int("session", id).Logger()
logger.Info().Msg("Starting SMTP session")
expConnectsCurrent.Add(1) expConnectsCurrent.Add(1)
defer func() { defer func() {
if err := conn.Close(); err != nil { if err := conn.Close(); err != nil {
log.Errorf("Error closing connection for <%v>: %v", id, err) logger.Warn().Err(err).Msg("Closing connection")
} }
s.waitgroup.Done() s.waitgroup.Done()
expConnectsCurrent.Add(-1) expConnectsCurrent.Add(-1)
}() }()
ssn := NewSession(s, id, conn) ssn := NewSession(s, id, conn, logger)
ssn.greet() ssn.greet()
// This is our command reading loop // This is our command reading loop
@@ -138,7 +143,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
} }
if !commands[cmd] { if !commands[cmd] {
ssn.send(fmt.Sprintf("500 Syntax error, %v command unrecognized", cmd)) ssn.send(fmt.Sprintf("500 Syntax error, %v command unrecognized", cmd))
ssn.logWarn("Unrecognized command: %v", cmd) ssn.logger.Warn().Msgf("Unrecognized command: %v", cmd)
continue continue
} }
@@ -147,7 +152,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
ssn.send(fmt.Sprintf("502 %v command not implemented", cmd)) ssn.send(fmt.Sprintf("502 %v command not implemented", cmd))
ssn.logWarn("Command %v not implemented by Inbucket", cmd) ssn.logger.Warn().Msgf("Command %v not implemented by Inbucket", cmd)
continue continue
case "VRFY": case "VRFY":
ssn.send("252 Cannot VRFY user, but will accept message") ssn.send("252 Cannot VRFY user, but will accept message")
@@ -157,7 +162,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
continue continue
case "RSET": case "RSET":
// Reset session // Reset session
ssn.logTrace("Resetting session state on RSET request") ssn.logger.Debug().Msgf("Resetting session state on RSET request")
ssn.reset() ssn.reset()
ssn.send("250 Session reset") ssn.send("250 Session reset")
continue continue
@@ -179,7 +184,7 @@ func (s *Server) startSession(id int, conn net.Conn) {
ssn.mailHandler(cmd, arg) ssn.mailHandler(cmd, arg)
continue continue
} }
ssn.logError("Session entered unexpected state %v", ssn.state) ssn.logger.Error().Msgf("Session entered unexpected state %v", ssn.state)
break break
} else { } else {
ssn.send("500 Syntax error, command garbled") ssn.send("500 Syntax error, command garbled")
@@ -190,14 +195,14 @@ func (s *Server) startSession(id int, conn net.Conn) {
switch ssn.state { switch ssn.state {
case GREET, READY: case GREET, READY:
// EOF is common here // EOF is common here
ssn.logInfo("Client closed connection (state %v)", ssn.state) ssn.logger.Info().Msgf("Client closed connection (state %v)", ssn.state)
default: default:
ssn.logWarn("Got EOF while in state %v", ssn.state) ssn.logger.Warn().Msgf("Got EOF while in state %v", ssn.state)
} }
break break
} }
// not an EOF // not an EOF
ssn.logWarn("Connection error: %v", err) ssn.logger.Warn().Msgf("Connection error: %v", err)
if netErr, ok := err.(net.Error); ok { if netErr, ok := err.(net.Error); ok {
if netErr.Timeout() { if netErr.Timeout() {
ssn.send("221 Idle timeout, bye bye") ssn.send("221 Idle timeout, bye bye")
@@ -209,9 +214,9 @@ func (s *Server) startSession(id int, conn net.Conn) {
} }
} }
if ssn.sendError != nil { if ssn.sendError != nil {
ssn.logWarn("Network send error: %v", ssn.sendError) ssn.logger.Warn().Msgf("Network send error: %v", ssn.sendError)
} }
ssn.logInfo("Closing connection") ssn.logger.Info().Msgf("Closing connection")
} }
// GREET state -> waiting for HELO // GREET state -> waiting for HELO
@@ -262,13 +267,13 @@ func (s *Session) readyHandler(cmd string, arg string) {
m := re.FindStringSubmatch(arg) m := re.FindStringSubmatch(arg)
if m == nil { if m == nil {
s.send("501 Was expecting MAIL arg syntax of FROM:<address>") s.send("501 Was expecting MAIL arg syntax of FROM:<address>")
s.logWarn("Bad MAIL argument: %q", arg) s.logger.Warn().Msgf("Bad MAIL argument: %q", arg)
return return
} }
from := m[1] from := m[1]
if _, _, err := policy.ParseEmailAddress(from); err != nil { if _, _, err := policy.ParseEmailAddress(from); err != nil {
s.send("501 Bad sender address syntax") s.send("501 Bad sender address syntax")
s.logWarn("Bad address as MAIL arg: %q, %s", from, err) s.logger.Warn().Msgf("Bad address as MAIL arg: %q, %s", from, err)
return return
} }
// This is where the client may put BODY=8BITMIME, but we already // This is where the client may put BODY=8BITMIME, but we already
@@ -277,25 +282,25 @@ func (s *Session) readyHandler(cmd string, arg string) {
args, ok := s.parseArgs(m[2]) args, ok := s.parseArgs(m[2])
if !ok { if !ok {
s.send("501 Unable to parse MAIL ESMTP parameters") s.send("501 Unable to parse MAIL ESMTP parameters")
s.logWarn("Bad MAIL argument: %q", arg) s.logger.Warn().Msgf("Bad MAIL argument: %q", 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 {
s.send("501 Unable to parse SIZE as an integer") s.send("501 Unable to parse SIZE as an integer")
s.logWarn("Unable to parse SIZE %q as an integer", args["SIZE"]) s.logger.Warn().Msgf("Unable to parse SIZE %q as an integer", args["SIZE"])
return return
} }
if int(size) > s.server.maxMessageBytes { if int(size) > s.server.maxMessageBytes {
s.send("552 Max message size exceeded") s.send("552 Max message size exceeded")
s.logWarn("Client wanted to send oversized message: %v", args["SIZE"]) s.logger.Warn().Msgf("Client wanted to send oversized message: %v", args["SIZE"])
return return
} }
} }
} }
s.from = from s.from = from
s.logInfo("Mail from: %v", from) s.logger.Info().Msgf("Mail from: %v", from)
s.send(fmt.Sprintf("250 Roger, accepting mail from <%v>", from)) s.send(fmt.Sprintf("250 Roger, accepting mail from <%v>", from))
s.enterState(MAIL) s.enterState(MAIL)
} else { } else {
@@ -309,7 +314,7 @@ func (s *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:") {
s.send("501 Was expecting RCPT arg syntax of TO:<address>") s.send("501 Was expecting RCPT arg syntax of TO:<address>")
s.logWarn("Bad RCPT argument: %q", arg) s.logger.Warn().Msgf("Bad RCPT argument: %q", arg)
return return
} }
// This trim is probably too forgiving // This trim is probably too forgiving
@@ -317,22 +322,22 @@ func (s *Session) mailHandler(cmd string, arg string) {
recip, err := s.server.apolicy.NewRecipient(addr) recip, err := s.server.apolicy.NewRecipient(addr)
if err != nil { if err != nil {
s.send("501 Bad recipient address syntax") s.send("501 Bad recipient address syntax")
s.logWarn("Bad address as RCPT arg: %q, %s", addr, err) s.logger.Warn().Msgf("Bad address as RCPT arg: %q, %s", addr, err)
return return
} }
if len(s.recipients) >= s.server.maxRecips { if len(s.recipients) >= s.server.maxRecips {
s.logWarn("Maximum limit of %v recipients reached", s.server.maxRecips) s.logger.Warn().Msgf("Maximum limit of %v recipients reached", s.server.maxRecips)
s.send(fmt.Sprintf("552 Maximum limit of %v recipients reached", s.server.maxRecips)) s.send(fmt.Sprintf("552 Maximum limit of %v recipients reached", s.server.maxRecips))
return return
} }
s.recipients = append(s.recipients, recip) s.recipients = append(s.recipients, recip)
s.logInfo("Recipient: %v", addr) s.logger.Info().Msgf("Recipient: %v", addr)
s.send(fmt.Sprintf("250 I'll make sure <%v> gets this", addr)) s.send(fmt.Sprintf("250 I'll make sure <%v> gets this", addr))
return return
case "DATA": case "DATA":
if arg != "" { if arg != "" {
s.send("501 DATA command should not have any arguments") s.send("501 DATA command should not have any arguments")
s.logWarn("Got unexpected args on DATA: %q", arg) s.logger.Warn().Msgf("Got unexpected args on DATA: %q", arg)
return return
} }
if len(s.recipients) > 0 { if len(s.recipients) > 0 {
@@ -359,7 +364,7 @@ func (s *Session) dataHandler() {
s.send("221 Idle timeout, bye bye") s.send("221 Idle timeout, bye bye")
} }
} }
s.logWarn("Error: %v while reading", err) s.logger.Warn().Msgf("Error: %v while reading", err)
s.enterState(QUIT) s.enterState(QUIT)
return return
} }
@@ -376,7 +381,7 @@ func (s *Session) dataHandler() {
_, err := s.server.manager.Deliver( _, err := s.server.manager.Deliver(
recip, s.from, s.recipients, prefix, msgBuf.Bytes()) recip, s.from, s.recipients, prefix, msgBuf.Bytes())
if err != nil { if err != nil {
s.logError("delivery for %v: %v", recip.LocalPart, err) s.logger.Error().Msgf("delivery for %v: %v", recip.LocalPart, err)
s.send(fmt.Sprintf("451 Failed to store message for %v", recip.LocalPart)) s.send(fmt.Sprintf("451 Failed to store message for %v", recip.LocalPart))
s.reset() s.reset()
return return
@@ -385,7 +390,7 @@ func (s *Session) dataHandler() {
expReceivedTotal.Add(1) expReceivedTotal.Add(1)
} }
s.send("250 Mail accepted for delivery") s.send("250 Mail accepted for delivery")
s.logInfo("Message size %v bytes", msgBuf.Len()) s.logger.Info().Msgf("Message size %v bytes", msgBuf.Len())
s.reset() s.reset()
return return
} }
@@ -396,7 +401,7 @@ func (s *Session) dataHandler() {
msgBuf.Write(lineBuf) msgBuf.Write(lineBuf)
if msgBuf.Len() > s.server.maxMessageBytes { if msgBuf.Len() > s.server.maxMessageBytes {
s.send("552 Maximum message size exceeded") s.send("552 Maximum message size exceeded")
s.logWarn("Max message size exceeded while in DATA") s.logger.Warn().Msgf("Max message size exceeded while in DATA")
s.reset() s.reset()
return return
} }
@@ -405,7 +410,7 @@ func (s *Session) dataHandler() {
func (s *Session) enterState(state State) { func (s *Session) enterState(state State) {
s.state = state s.state = state
s.logTrace("Entering state %v", state) s.logger.Debug().Msgf("Entering state %v", state)
} }
func (s *Session) greet() { func (s *Session) greet() {
@@ -425,10 +430,10 @@ func (s *Session) send(msg string) {
} }
if _, err := fmt.Fprint(s.conn, msg+"\r\n"); err != nil { if _, err := fmt.Fprint(s.conn, msg+"\r\n"); err != nil {
s.sendError = err s.sendError = err
s.logWarn("Failed to send: %q", msg) s.logger.Warn().Msgf("Failed to send: %q", msg)
return return
} }
s.logTrace(">> %v >>", msg) s.logger.Debug().Msgf(">> %v >>", msg)
} }
// readByteLine reads a line of input, returns byte slice. // readByteLine reads a line of input, returns byte slice.
@@ -448,7 +453,7 @@ func (s *Session) readLine() (line string, err error) {
if err != nil { if err != nil {
return "", err return "", err
} }
s.logTrace("<< %v <<", strings.TrimRight(line, "\r\n")) s.logger.Debug().Msgf("<< %v <<", strings.TrimRight(line, "\r\n"))
return line, nil return line, nil
} }
@@ -459,19 +464,19 @@ func (s *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:
s.logWarn("Command too short: %q", line) s.logger.Warn().Msgf("Command too short: %q", 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
s.logWarn("Mangled command: %q", line) s.logger.Warn().Msgf("Mangled command: %q", 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?
s.logWarn("Mangled command: %q", line) s.logger.Warn().Msgf("Mangled command: %q", 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
@@ -488,13 +493,13 @@ func (s *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 {
s.logWarn("Failed to parse arg string: %q") s.logger.Warn().Msgf("Failed to parse arg string: %q")
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]
} }
s.logTrace("ESMTP params: %v", args) s.logger.Debug().Msgf("ESMTP params: %v", args)
return args, true return args, true
} }
@@ -506,26 +511,5 @@ func (s *Session) reset() {
func (s *Session) ooSeq(cmd string) { func (s *Session) ooSeq(cmd string) {
s.send(fmt.Sprintf("503 Command %v is out of sequence", cmd)) s.send(fmt.Sprintf("503 Command %v is out of sequence", cmd))
s.logWarn("Wasn't expecting %v here", cmd) s.logger.Warn().Msgf("Wasn't expecting %v here", cmd)
}
// Session specific logging methods
func (s *Session) logTrace(msg string, args ...interface{}) {
log.Tracef("SMTP[%v]<%v> %v", s.remoteHost, s.id, fmt.Sprintf(msg, args...))
}
func (s *Session) logInfo(msg string, args ...interface{}) {
log.Infof("SMTP[%v]<%v> %v", s.remoteHost, s.id, fmt.Sprintf(msg, args...))
}
func (s *Session) logWarn(msg string, args ...interface{}) {
// Update metrics
expWarnsTotal.Add(1)
log.Warnf("SMTP[%v]<%v> %v", s.remoteHost, s.id, fmt.Sprintf(msg, args...))
}
func (s *Session) logError(msg string, args ...interface{}) {
// Update metrics
expErrorsTotal.Add(1)
log.Errorf("SMTP[%v]<%v> %v", s.remoteHost, s.id, fmt.Sprintf(msg, args...))
} }