More metrics, better logging

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

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:<address>")
-			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:<address>")
-			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...))
 }

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)

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.</p>
       <td class="sparkline"><span id="s-smtpDeliveredTotal">.</span></td>
       <td>(60s)</td>
     </tr>
+    <tr>
+      <th>Errors Logged:</th>
+      <td><span id="m-smtpErrorsTotal">.</span></td>
+      <td class="sparkline"><span id="s-smtpErrorsTotal"></span></td>
+      <td>(60s)</td>
+    </tr>
+    <tr>
+      <th>Warnings Logged:</th>
+      <td><span id="m-smtpWarnsTotal">.</span></td>
+      <td class="sparkline"><span id="s-smtpWarnsTotal"></span></td>
+      <td>(60s)</td>
+    </tr>
   </table>
   <p class="last">&nbsp;</p>
 </div>

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))
 

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
 	}