From 81bb39475553ea7f2346a5e231efca57701d45c8 Mon Sep 17 00:00:00 2001 From: James Hillyerd Date: Wed, 24 Oct 2012 12:40:17 -0700 Subject: [PATCH] More metrics, better logging --- smtpd/datastore.go | 15 ++++++--- smtpd/handler.go | 37 ++++++++++++---------- smtpd/listener.go | 30 ++++++++++++++---- themes/integral/templates/root/status.html | 31 +++++++++++++++--- web/mailbox_controller.go | 5 +-- web/server.go | 1 + 6 files changed, 85 insertions(+), 34 deletions(-) diff --git a/smtpd/datastore.go b/smtpd/datastore.go index 8d2ad62..590f3fd 100644 --- a/smtpd/datastore.go +++ b/smtpd/datastore.go @@ -60,8 +60,9 @@ func NewDataStore() *DataStore { func (ds *DataStore) MailboxFor(emailAddress string) (*Mailbox, error) { name := ParseMailboxName(emailAddress) dir := HashMailboxName(name) - section := dir[0:4] - path := filepath.Join(ds.mailPath, section, dir) + s1 := dir[0:3] + s2 := dir[0:6] + path := filepath.Join(ds.mailPath, s1, s2, dir) if err := os.MkdirAll(path, 0770); err != nil { log.Error("Failed to create directory %v, %v", path, err) return nil, err @@ -102,7 +103,7 @@ func (mb *Mailbox) GetMessages() ([]*Message, error) { dec := gob.NewDecoder(bufio.NewReader(file)) msg := new(Message) if err = dec.Decode(msg); err != nil { - return nil, err + return nil, fmt.Errorf("While decoding message: %v", err) } file.Close() msg.mailbox = mb @@ -257,7 +258,13 @@ func (m *Message) Close() error { } } - return m.createGob() + err := m.createGob() + if err != nil { + log.Error("Failed to create gob: %v", err) + return err + } + + return nil } // Delete this Message from disk by removing both the gob and raw files diff --git a/smtpd/handler.go b/smtpd/handler.go index 518cfb4..85c46f9 100644 --- a/smtpd/handler.go +++ b/smtpd/handler.go @@ -112,6 +112,7 @@ func (s *Server) startSession(id int, conn net.Conn) { } if !commands[cmd] { ss.send(fmt.Sprintf("500 Syntax error, %v command unrecognized", cmd)) + ss.warn("Unrecognized command: %v", cmd) continue } @@ -159,7 +160,7 @@ func (s *Server) startSession(id int, conn net.Conn) { } } else { // readLine() returned an error - ss.error("Connection error: %v", err) + ss.warn("Connection error: %v", err) if netErr, ok := err.(net.Error); ok { if netErr.Timeout() { ss.send("221 Idle timeout, bye bye") @@ -171,7 +172,7 @@ func (s *Server) startSession(id int, conn net.Conn) { } } if ss.sendError != nil { - ss.error("Network send error: %v", ss.sendError) + ss.warn("Network send error: %v", ss.sendError) } ss.info("Closing connection") } @@ -200,7 +201,7 @@ func (ss *Session) readyHandler(cmd string, arg string) { m := re.FindStringSubmatch(arg) if m == nil { ss.send("501 Was expecting MAIL arg syntax of FROM:
") - ss.warn("Bad MAIL argument: \"%v\"", arg) + ss.warn("Bad MAIL argument: '%v'", arg) return } from := m[1] @@ -210,14 +211,14 @@ func (ss *Session) readyHandler(cmd string, arg string) { args, ok := ss.parseArgs(m[2]) if !ok { ss.send("501 Unable to parse MAIL ESMTP parameters") - ss.warn("Bad MAIL argument: \"%v\"", arg) + ss.warn("Bad MAIL argument: '%v'", arg) return } if args["SIZE"] != "" { size, err := strconv.ParseInt(args["SIZE"], 10, 32) if err != nil { ss.send("501 Unable to parse SIZE as an integer") - ss.error("Unable to parse SIZE '%v' as an integer", args["SIZE"]) + ss.warn("Unable to parse SIZE '%v' as an integer", args["SIZE"]) return } if int(size) > ss.server.maxMessageBytes { @@ -243,7 +244,7 @@ func (ss *Session) mailHandler(cmd string, arg string) { case "RCPT": if (len(arg) < 4) || (strings.ToUpper(arg[0:3]) != "TO:") { ss.send("501 Was expecting RCPT arg syntax of TO:
") - ss.warn("Bad RCPT argument: \"%v\"", arg) + ss.warn("Bad RCPT argument: '%v'", arg) return } // This trim is probably too forgiving @@ -260,7 +261,7 @@ func (ss *Session) mailHandler(cmd string, arg string) { case "DATA": if arg != "" { ss.send("501 DATA command should not have any arguments") - ss.warn("Got unexpected args on DATA: \"%v\"", arg) + ss.warn("Got unexpected args on DATA: '%v'", arg) return } if ss.recipients.Len() > 0 { @@ -309,7 +310,7 @@ func (ss *Session) dataHandler() { ss.send("221 Idle timeout, bye bye") } } - ss.error("Error: %v while reading", err) + ss.warn("Error: %v while reading", err) ss.enterState(QUIT) return } @@ -333,7 +334,7 @@ func (ss *Session) dataHandler() { if msgSize > ss.server.maxMessageBytes { // Max message size exceeded ss.send("552 Maximum message size exceeded") - ss.error("Max message size exceeded while in DATA") + ss.warn("Max message size exceeded while in DATA") ss.reset() // TODO: Should really cleanup the crap on filesystem... return @@ -373,10 +374,10 @@ func (ss *Session) send(msg string) { } if _, err := fmt.Fprint(ss.conn, msg+"\r\n"); err != nil { ss.sendError = err - ss.error("Failed to send: \"%v\"", msg) + ss.warn("Failed to send: '%v'", msg) return } - ss.trace("Sent: \"%v\"", msg) + ss.trace(">> %v >>", msg) } // readByteLine reads a line of input into the provided buffer. Does @@ -416,7 +417,7 @@ func (ss *Session) readLine() (line string, err error) { if err != nil { return "", err } - ss.trace("Read: \"%v\"", strings.TrimRight(line, "\r\n")) + ss.trace("<< %v <<", strings.TrimRight(line, "\r\n")) return line, nil } @@ -427,19 +428,19 @@ func (ss *Session) parseCmd(line string) (cmd string, arg string, ok bool) { case l == 0: return "", "", true case l < 4: - ss.error("Command too short: \"%v\"", line) + ss.warn("Command too short: '%v'", line) return "", "", false case l == 4: return strings.ToUpper(line), "", true case l == 5: // Too long to be only command, too short to have args - ss.error("Mangled command: \"%v\"", line) + ss.warn("Mangled command: '%v'", line) return "", "", false } // If we made it here, command is long enough to have args if line[4] != ' ' { // There wasn't a space after the command? - ss.error("Mangled command: \"%v\"", line) + ss.warn("Mangled command: '%v'", line) return "", "", false } // I'm not sure if we should trim the args or not, but we will for now @@ -456,7 +457,7 @@ func (ss *Session) parseArgs(arg string) (args map[string]string, ok bool) { re := regexp.MustCompile(" (\\w+)=(\\w+)") pm := re.FindAllStringSubmatch(arg, -1) if pm == nil { - ss.error("Failed to parse arg string: '%v'") + ss.warn("Failed to parse arg string: '%v'") return nil, false } for _, m := range pm { @@ -487,9 +488,13 @@ func (ss *Session) info(msg string, args ...interface{}) { } func (ss *Session) warn(msg string, args ...interface{}) { + // Update metrics + expWarnsTotal.Add(1) log.Warn("%v<%v> %v", ss.remoteHost, ss.id, fmt.Sprintf(msg, args...)) } func (ss *Session) error(msg string, args ...interface{}) { + // Update metrics + expErrorsTotal.Add(1) log.Error("%v<%v> %v", ss.remoteHost, ss.id, fmt.Sprintf(msg, args...)) } diff --git a/smtpd/listener.go b/smtpd/listener.go index 0deb38b..f0d22af 100644 --- a/smtpd/listener.go +++ b/smtpd/listener.go @@ -19,14 +19,24 @@ type Server struct { dataStore *DataStore } +// Raw stat collectors var expConnectsTotal = new(expvar.Int) var expConnectsCurrent = new(expvar.Int) -var expConnectsHist = new(expvar.String) var expDeliveredTotal = new(expvar.Int) -var expDeliveredHist = new(expvar.String) +var expErrorsTotal = new(expvar.Int) +var expWarnsTotal = new(expvar.Int) +// History of certain stats var deliveredHist = list.New() var connectsHist = list.New() +var errorsHist = list.New() +var warnsHist = list.New() + +// History rendered as comma delim string +var expDeliveredHist = new(expvar.String) +var expConnectsHist = new(expvar.String) +var expErrorsHist = new(expvar.String) +var expWarnsHist = new(expvar.String) // Init a new Server object func New() *Server { @@ -74,6 +84,8 @@ func metricsTicker(t *time.Ticker) { _, ok = <-t.C expDeliveredHist.Set(pushMetric(deliveredHist, expDeliveredTotal)) expConnectsHist.Set(pushMetric(connectsHist, expConnectsTotal)) + expErrorsHist.Set(pushMetric(errorsHist, expErrorsTotal)) + expWarnsHist.Set(pushMetric(warnsHist, expWarnsTotal)) } } @@ -89,11 +101,15 @@ func pushMetric(history *list.List, ev expvar.Var) string { func init() { m := expvar.NewMap("smtp") - m.Set("connectsTotal", expConnectsTotal) - m.Set("connectsHist", expConnectsHist) - m.Set("connectsCurrent", expConnectsCurrent) - m.Set("deliveredTotal", expDeliveredTotal) - m.Set("deliveredHist", expDeliveredHist) + m.Set("ConnectsTotal", expConnectsTotal) + m.Set("ConnectsHist", expConnectsHist) + m.Set("ConnectsCurrent", expConnectsCurrent) + m.Set("DeliveredTotal", expDeliveredTotal) + m.Set("DeliveredHist", expDeliveredHist) + m.Set("ErrorsTotal", expErrorsTotal) + m.Set("ErrorsHist", expErrorsHist) + m.Set("WarnsTotal", expWarnsTotal) + m.Set("WarnsHist", expWarnsHist) t := time.NewTicker(time.Minute) go metricsTicker(t) diff --git a/themes/integral/templates/root/status.html b/themes/integral/templates/root/status.html index 5494934..c69f079 100644 --- a/themes/integral/templates/root/status.html +++ b/themes/integral/templates/root/status.html @@ -83,16 +83,25 @@ } function displayMetrics(data, textStatus, jqXHR) { + // Non graphing metric('uptime', data.uptime, timeFilter, false) + + // JavaScript history metric('memstatsSys', data.memstats.Sys, sizeFilter, true) metric('memstatsHeapAlloc', data.memstats.HeapAlloc, sizeFilter, true) metric('memstatsHeapSys', data.memstats.HeapSys, sizeFilter, true) metric('memstatsHeapObjects', data.memstats.HeapObjects, numberFilter, true) - metric('smtpConnectsTotal', data.smtp.connectsTotal, numberFilter, false) - metric('smtpConnectsCurrent', data.smtp.connectsCurrent, numberFilter, true) - metric('smtpDeliveredTotal', data.smtp.deliveredTotal, numberFilter, false) - setHistory('smtpConnectsTotal', data.smtp.connectsHist) - setHistory('smtpDeliveredTotal', data.smtp.deliveredHist) + metric('smtpConnectsCurrent', data.smtp.ConnectsCurrent, numberFilter, true) + + // Server-side history + metric('smtpDeliveredTotal', data.smtp.DeliveredTotal, numberFilter, false) + setHistory('smtpDeliveredTotal', data.smtp.DeliveredHist) + metric('smtpConnectsTotal', data.smtp.ConnectsTotal, numberFilter, false) + setHistory('smtpConnectsTotal', data.smtp.ConnectsHist) + metric('smtpWarnsTotal', data.smtp.WarnsTotal, numberFilter, false) + setHistory('smtpWarnsTotal', data.smtp.WarnsHist) + metric('smtpErrorsTotal', data.smtp.ErrorsTotal, numberFilter, false) + setHistory('smtpErrorsTotal', data.smtp.ErrorsHist) } function loadMetrics() { @@ -178,6 +187,18 @@ values over time.

. (60s) + + Errors Logged: + . + + (60s) + + + Warnings Logged: + . + + (60s) +

 

diff --git a/web/mailbox_controller.go b/web/mailbox_controller.go index 06edf8e..3ff9dd4 100644 --- a/web/mailbox_controller.go +++ b/web/mailbox_controller.go @@ -1,6 +1,7 @@ package web import ( + "fmt" "github.com/jhillyerd/inbucket/log" "html/template" "io" @@ -31,11 +32,11 @@ func MailboxList(w http.ResponseWriter, req *http.Request, ctx *Context) (err er mb, err := ctx.DataStore.MailboxFor(name) if err != nil { - return err + return fmt.Errorf("Failed to get mailbox for %v: %v", name, err) } messages, err := mb.GetMessages() if err != nil { - return err + return fmt.Errorf("Failed to get messages for %v: %v", name, err) } log.Trace("Got %v messsages", len(messages)) diff --git a/web/server.go b/web/server.go index 0e3c134..534b572 100644 --- a/web/server.go +++ b/web/server.go @@ -83,6 +83,7 @@ func (h handler) ServeHTTP(w http.ResponseWriter, req *http.Request) { log.Trace("Web: %v %v %v %v", req.RemoteAddr, req.Proto, req.Method, req.RequestURI) err = h(buf, req, ctx) if err != nil { + log.Error("Error handling %v: %v", req.RequestURI, err) http.Error(w, err.Error(), http.StatusInternalServerError) return }