Improve debugging and tracing information

This patch reviews various debug and informational messages, making more
uniform use of tracing, and extends the monitoring http server with
useful information like an index and a queue dump.

chasquid.go

@@ -9,7 +9,6 @@ import (
 	"io/ioutil"
 	"math/rand"
 	"net"
-	"net/http"
 	"net/mail"
 	"net/textproto"
 	"os"
@@ -32,6 +31,7 @@ import (
 	"blitiri.com.ar/go/chasquid/internal/trace"
 	"blitiri.com.ar/go/chasquid/internal/userdb"
 
+	"net/http"
 	_ "net/http/pprof"
 
 	"github.com/golang/glog"
@@ -67,9 +67,7 @@ func main() {
 	os.Chdir(*configDir)
 
 	if conf.MonitoringAddress != "" {
-		glog.Infof("Monitoring HTTP server listening on %s",
+		launchMonitoringServer(conf.MonitoringAddress)
-			conf.MonitoringAddress)
-		go http.ListenAndServe(conf.MonitoringAddress, nil)
 	}
 
 	s := NewServer()
@@ -301,6 +299,11 @@ func (s *Server) InitQueue(path string, localC, remoteC courier.Courier) {
 		glog.Fatalf("Error loading queue: %v", err)
 	}
 	s.queue = q
+
+	http.HandleFunc("/debug/queue",
+		func(w http.ResponseWriter, r *http.Request) {
+			w.Write([]byte(q.DumpString()))
+		})
 }
 
 // periodicallyReload some of the server's information, such as aliases and
@@ -395,6 +398,9 @@ type Conn struct {
 	mode         SocketMode
 	tlsConnState *tls.ConnectionState
 
+	// Tracer to use.
+	tr *trace.Trace
+
 	// System configuration.
 	config *config.Config
 
@@ -442,9 +448,8 @@ type Conn struct {
 func (c *Conn) Handle() {
 	defer c.netconn.Close()
 
-	tr := trace.New("SMTP", "Connection")
+	c.tr = trace.New("SMTP.Conn", c.netconn.RemoteAddr().String())
-	defer tr.Finish()
+	defer c.tr.Finish()
-	tr.LazyPrintf("RemoteAddr: %s", c.netconn.RemoteAddr())
 
 	c.tc.PrintfLine("220 %s ESMTP chasquid", c.hostname)
 
@@ -454,8 +459,8 @@ func (c *Conn) Handle() {
 loop:
 	for {
 		if time.Since(c.deadline) > 0 {
-			tr.LazyPrintf("connection deadline exceeded")
 			err = fmt.Errorf("connection deadline exceeded")
+			c.tr.Error(err)
 			break
 		}
 
@@ -467,7 +472,7 @@ loop:
 			break
 		}
 
-		tr.LazyPrintf("-> %s %s", cmd, params)
+		c.tr.Debugf("-> %s %s", cmd, params)
 
 		var code int
 		var msg string
@@ -493,11 +498,11 @@ loop:
 			code, msg = c.RCPT(params)
 		case "DATA":
 			// DATA handles the whole sequence.
-			code, msg = c.DATA(params, tr)
+			code, msg = c.DATA(params)
 		case "STARTTLS":
-			code, msg = c.STARTTLS(params, tr)
+			code, msg = c.STARTTLS(params)
 		case "AUTH":
-			code, msg = c.AUTH(params, tr)
+			code, msg = c.AUTH(params)
 		case "QUIT":
 			c.writeResponse(221, "Be seeing you...")
 			break loop
@@ -507,7 +512,12 @@ loop:
 		}
 
 		if code > 0 {
-			tr.LazyPrintf("<- %d  %s", code, msg)
+			c.tr.Debugf("<- %d  %s", code, msg)
+
+			// Be verbose about errors, to help troubleshooting.
+			if code >= 400 {
+				c.tr.Errorf("%s failed: %d  %s", cmd, code, msg)
+			}
 
 			err = c.writeResponse(code, msg)
 			if err != nil {
@@ -517,8 +527,7 @@ loop:
 	}
 
 	if err != nil {
-		tr.LazyPrintf("exiting with error: %v", err)
+		c.tr.Errorf("exiting with error: %v", err)
-		tr.SetError()
 	}
 }
 
@@ -624,6 +633,7 @@ func (c *Conn) MAIL(params string) (code int, msg string) {
 		if tcp, ok := c.netconn.RemoteAddr().(*net.TCPAddr); ok {
 			c.spfResult, c.spfError = spf.CheckHost(
 				tcp.IP, envelope.DomainOf(e.Address))
+			c.tr.Debugf("SPF %v (%v)", c.spfResult, c.spfError)
 			// https://tools.ietf.org/html/rfc7208#section-8
 			// We opt not to fail on errors, to avoid accidents to prevent
 			// delivery.
@@ -688,7 +698,7 @@ func (c *Conn) RCPT(params string) (code int, msg string) {
 	return 250, "You have an eerie feeling..."
 }
 
-func (c *Conn) DATA(params string, tr *trace.Trace) (code int, msg string) {
+func (c *Conn) DATA(params string) (code int, msg string) {
 	if c.mailFrom == "" {
 		return 503, "sender not yet given"
 	}
@@ -703,7 +713,7 @@ func (c *Conn) DATA(params string, tr *trace.Trace) (code int, msg string) {
 		return 554, fmt.Sprintf("error writing DATA response: %v", err)
 	}
 
-	tr.LazyPrintf("<- 354  You experience a strange sense of peace")
+	c.tr.Debugf("<- 354  You experience a strange sense of peace")
 
 	// Increase the deadline for the data transfer to the connection-level
 	// one, we don't want the command timeout to interfere.
@@ -715,7 +725,7 @@ func (c *Conn) DATA(params string, tr *trace.Trace) (code int, msg string) {
 		return 554, fmt.Sprintf("error reading DATA: %v", err)
 	}
 
-	tr.LazyPrintf("-> ... %d bytes of data", len(c.data))
+	c.tr.Debugf("-> ... %d bytes of data", len(c.data))
 
 	c.addReceivedHeader()
 
@@ -723,12 +733,10 @@ func (c *Conn) DATA(params string, tr *trace.Trace) (code int, msg string) {
 	// individual deliveries fail, we report via email.
 	msgID, err := c.queue.Put(c.hostname, c.mailFrom, c.rcptTo, c.data)
 	if err != nil {
-		tr.LazyPrintf("   error queueing: %v", err)
-		tr.SetError()
 		return 554, fmt.Sprintf("Failed to enqueue message: %v", err)
 	}
 
-	tr.LazyPrintf("   ... queued: %q", msgID)
+	c.tr.Printf("Queued from %s to %s - %s", c.mailFrom, c.rcptTo, msgID)
 
 	// It is very important that we reset the envelope before returning,
 	// so clients can send other emails right away without needing to RSET.
@@ -779,7 +787,7 @@ func (c *Conn) addReceivedHeader() {
 	}
 }
 
-func (c *Conn) STARTTLS(params string, tr *trace.Trace) (code int, msg string) {
+func (c *Conn) STARTTLS(params string) (code int, msg string) {
 	if c.onTLS {
 		return 503, "You are already wearing that!"
 	}
@@ -789,7 +797,7 @@ func (c *Conn) STARTTLS(params string, tr *trace.Trace) (code int, msg string) {
 		return 554, fmt.Sprintf("error writing STARTTLS response: %v", err)
 	}
 
-	tr.LazyPrintf("<- 220  You experience a strange sense of peace")
+	c.tr.Debugf("<- 220  You experience a strange sense of peace")
 
 	server := tls.Server(c.netconn, c.tlsConfig)
 	err = server.Handshake()
@@ -797,7 +805,7 @@ func (c *Conn) STARTTLS(params string, tr *trace.Trace) (code int, msg string) {
 		return 554, fmt.Sprintf("error in TLS handshake: %v", err)
 	}
 
-	tr.LazyPrintf("<> ...  jump to TLS was successful")
+	c.tr.Debugf("<> ...  jump to TLS was successful")
 
 	// Override the connections. We don't need the older ones anymore.
 	c.netconn = server
@@ -823,7 +831,7 @@ func (c *Conn) STARTTLS(params string, tr *trace.Trace) (code int, msg string) {
 	return 0, ""
 }
 
-func (c *Conn) AUTH(params string, tr *trace.Trace) (code int, msg string) {
+func (c *Conn) AUTH(params string) (code int, msg string) {
 	if !c.onTLS {
 		return 503, "You feel vulnerable"
 	}
@@ -966,3 +974,69 @@ func writeResponse(w io.Writer, code int, msg string) error {
 
 	return nil
 }
+
+func launchMonitoringServer(addr string) {
+	glog.Infof("Monitoring HTTP server listening on %s", addr)
+
+	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
+		if r.URL.Path != "/" {
+			http.NotFound(w, r)
+			return
+		}
+		w.Write([]byte(monitoringHTMLIndex))
+	})
+
+	flags := dumpFlags()
+	http.HandleFunc("/debug/flags", func(w http.ResponseWriter, r *http.Request) {
+		w.Write([]byte(flags))
+	})
+
+	go http.ListenAndServe(addr, nil)
+}
+
+// Static index for the monitoring website.
+const monitoringHTMLIndex = `<!DOCTYPE html>
+<html>
+  <head>
+    <title>chasquid monitoring</title>
+  </head>
+  <body>
+    <h1>chasquid monitoring</h1>
+    <ul>
+      <li><a href="/debug/queue">queue</a>
+      <li><a href="/debug/requests">requests</a>
+          <small><a href="https://godoc.org/golang.org/x/net/trace">
+            (ref)</a></small>
+      <li><a href="/debug/flags">flags</a>
+      <li><a href="/debug/vars">public variables</a>
+      <li><a href="/debug/pprof">pprof</a>
+          <small><a href="https://golang.org/pkg/net/http/pprof/">
+            (ref)</a></small>
+        <ul>
+          <li><a href="/debug/pprof/goroutine?debug=1">goroutines</a>
+        </ul>
+    </ul>
+  </body>
+</html>
+`
+
+// dumpFlags to a string, for troubleshooting purposes.
+func dumpFlags() string {
+	s := ""
+	visited := make(map[string]bool)
+
+	// Print set flags first, then the rest.
+	flag.Visit(func(f *flag.Flag) {
+		s += fmt.Sprintf("-%s=%s\n", f.Name, f.Value.String())
+		visited[f.Name] = true
+	})
+
+	s += "\n"
+	flag.VisitAll(func(f *flag.Flag) {
+		if !visited[f.Name] {
+			s += fmt.Sprintf("-%s=%s\n", f.Name, f.Value.String())
+		}
+	})
+
+	return s
+}

internal/courier/procmail.go

@@ -26,14 +26,14 @@ type Procmail struct {
 }
 
 func (p *Procmail) Deliver(from string, to string, data []byte) (error, bool) {
-	tr := trace.New("Procmail", "Deliver")
+	tr := trace.New("Procmail.Courier", to)
 	defer tr.Finish()
 
 	// Sanitize, just in case.
 	from = sanitizeForProcmail(from)
 	to = sanitizeForProcmail(to)
 
-	tr.LazyPrintf("%s -> %s", from, to)
+	tr.Debugf("%s -> %s", from, to)
 
 	// Prepare the command, replacing the necessary arguments.
 	replacer := strings.NewReplacer(
@@ -97,6 +97,7 @@ func (p *Procmail) Deliver(from string, to string, data []byte) (error, bool) {
 		return err, permanent
 	}
 
+	tr.Debugf("delivered")
 	return nil, false
 }
 

internal/courier/smtp.go

@@ -34,9 +34,9 @@ type SMTP struct {
 }
 
 func (s *SMTP) Deliver(from string, to string, data []byte) (error, bool) {
-	tr := trace.New("SMTP", "Deliver")
+	tr := trace.New("SMTP.Courier", to)
 	defer tr.Finish()
-	tr.LazyPrintf("%s  ->  %s", from, to)
+	tr.Debugf("%s  ->  %s", from, to)
 
 	mx, err := lookupMX(envelope.DomainOf(to))
 	if err != nil {
@@ -46,7 +46,7 @@ func (s *SMTP) Deliver(from string, to string, data []byte) (error, bool) {
 		// have to make sure we try hard enough on the lookup above.
 		return tr.Errorf("Could not find mail server: %v", err), true
 	}
-	tr.LazyPrintf("MX: %s", mx)
+	tr.Debugf("MX: %s", mx)
 
 	// Do we use insecure TLS?
 	// Set as fallback when retrying.
@@ -94,17 +94,17 @@ retry:
 			}
 
 			insecure = true
-			tr.LazyPrintf("TLS error, retrying insecurely")
+			tr.Debugf("TLS error, retrying insecurely")
 			goto retry
 		}
 
 		if config.InsecureSkipVerify {
-			tr.LazyPrintf("Insecure - self-signed certificate")
+			tr.Debugf("Insecure - using TLS, but cert does not match %s", mx)
 		} else {
-			tr.LazyPrintf("Secure - using TLS")
+			tr.Debugf("Secure - using TLS")
 		}
 	} else {
-		tr.LazyPrintf("Insecure - not using TLS")
+		tr.Debugf("Insecure - NOT using TLS")
 	}
 
 	// c.Mail will add the <> for us when the address is empty.
@@ -130,6 +130,7 @@ retry:
 	}
 
 	c.Quit()
+	tr.Debugf("done")
 
 	return nil, false
 }

internal/queue/queue.go

@@ -24,12 +24,12 @@ import (
 	"blitiri.com.ar/go/chasquid/internal/envelope"
 	"blitiri.com.ar/go/chasquid/internal/protoio"
 	"blitiri.com.ar/go/chasquid/internal/set"
+	"blitiri.com.ar/go/chasquid/internal/trace"
 
 	"github.com/golang/glog"
 	"github.com/golang/protobuf/ptypes"
 	"github.com/golang/protobuf/ptypes/timestamp"
 	"golang.org/x/net/idna"
-	"golang.org/x/net/trace"
 )
 
 const (
@@ -198,8 +198,6 @@ func (q *Queue) Put(hostname, from string, to []string, data []byte) (string, er
 	q.q[item.ID] = item
 	q.mu.Unlock()
 
-	glog.Infof("%s accepted from %q  to  %v", item.ID, from, to)
-
 	// Begin to send it right away.
 	go item.SendLoop(q)
 
@@ -219,8 +217,32 @@ func (q *Queue) Remove(id string) {
 	q.mu.Unlock()
 }
 
-// TODO: http handler for dumping the queue.
+// DumpString returns a human-readable string with the current queue.
-// Register it in main().
+// Useful for debugging purposes.
+func (q *Queue) DumpString() string {
+	q.mu.RLock()
+	defer q.mu.RUnlock()
+	s := fmt.Sprintf("# Queue status\n\n")
+	s += fmt.Sprintf("date: %v\n", time.Now())
+	s += fmt.Sprintf("length: %d\n\n", len(q.q))
+
+	for id, item := range q.q {
+		s += fmt.Sprintf("## Item %s\n", id)
+		item.Lock()
+		s += fmt.Sprintf("created at: %s\n", item.CreatedAt)
+		s += fmt.Sprintf("from: %s\n", item.From)
+		s += fmt.Sprintf("to: %s\n", item.To)
+		for _, rcpt := range item.Rcpt {
+			s += fmt.Sprintf("%s %s (%s)\n", rcpt.Status, rcpt.Address, rcpt.Type)
+			s += fmt.Sprintf("  original address: %s\n", rcpt.OriginalAddress)
+			s += fmt.Sprintf("  last failure: %q\n", rcpt.LastFailureMessage)
+		}
+		item.Unlock()
+		s += fmt.Sprintf("\n")
+	}
+
+	return s
+}
 
 // An item in the queue.
 type Item struct {
@@ -263,9 +285,9 @@ func (item *Item) WriteTo(dir string) error {
 }
 
 func (item *Item) SendLoop(q *Queue) {
-	tr := trace.New("Queue", item.ID)
+	tr := trace.New("Queue.SendLoop", item.ID)
 	defer tr.Finish()
-	tr.LazyPrintf("from: %s", item.From)
+	tr.Printf("from %s", item.From)
 
 	var delay time.Duration
 	for time.Since(item.CreatedAt) < giveUpAfter {
@@ -284,23 +306,19 @@ func (item *Item) SendLoop(q *Queue) {
 			go func(rcpt *Recipient, oldStatus Recipient_Status) {
 				defer wg.Done()
 				to := rcpt.Address
-				tr.LazyPrintf("%s sending", to)
+				tr.Debugf("%s sending", to)
 
 				err, permanent := item.deliver(q, rcpt)
 
 				if err != nil {
 					if permanent {
-						tr.LazyPrintf("permanent error: %v", err)
+						tr.Errorf("%s permanent error: %v", to, err)
-						glog.Infof("%s  -> %q permanent fail: %v", item.ID, to, err)
 						status = Recipient_FAILED
 					} else {
-						tr.LazyPrintf("error: %v", err)
+						tr.Printf("%s temporary error: %v", to, err)
-						glog.Infof("%s  -> %q fail: %v", item.ID, to, err)
 					}
 				} else {
-					tr.LazyPrintf("%s successful", to)
+					tr.Printf("%s sent", to)
-					glog.Infof("%s  -> %q sent", item.ID, to)
-
 					status = Recipient_SENT
 				}
 
@@ -315,8 +333,7 @@ func (item *Item) SendLoop(q *Queue) {
 
 					err = item.WriteTo(q.path)
 					if err != nil {
-						tr.LazyPrintf("failed to write: %v", err)
+						tr.Errorf("failed to write: %v", err)
-						glog.Errorf("%s failed to write: %v", item.ID, err)
 					}
 				}
 			}(rcpt, status)
@@ -338,14 +355,11 @@ func (item *Item) SendLoop(q *Queue) {
 		// that some of the messages have been delayed.
 
 		delay = nextDelay(delay)
-		tr.LazyPrintf("waiting for %v", delay)
+		tr.Printf("waiting for %v", delay)
-		glog.Infof("%s waiting for %v", item.ID, delay)
 		time.Sleep(delay)
 	}
 
 	// Completed to all recipients (some may not have succeeded).
-	tr.LazyPrintf("all done")
-	glog.Infof("%s all done", item.ID)
 
 	failed := 0
 	for _, rcpt := range item.Rcpt {
@@ -358,26 +372,28 @@ func (item *Item) SendLoop(q *Queue) {
 		sendDSN(tr, q, item)
 	}
 
+	tr.Printf("all done")
 	q.Remove(item.ID)
 
 	return
 }
 
-func sendDSN(tr trace.Trace, q *Queue, item *Item) {
+func sendDSN(tr *trace.Trace, q *Queue, item *Item) {
-	tr.LazyPrintf("sending DSN")
+	tr.Debugf("sending DSN")
 
 	msg, err := deliveryStatusNotification(item)
 	if err != nil {
-		tr.LazyPrintf("failed to build DSN: %v", err)
+		tr.Errorf("failed to build DSN: %v", err)
-		glog.Infof("%s: failed to build DSN: %v", item.ID, err)
 		return
 	}
 
-	_, err = q.Put(item.Hostname, "<>", []string{item.From}, msg)
+	id, err := q.Put(item.Hostname, "<>", []string{item.From}, msg)
 	if err != nil {
-		tr.LazyPrintf("failed to queue DSN: %v", err)
+		tr.Errorf("failed to queue DSN: %v", err)
-		glog.Infof("%s: failed to queue DSN: %v", item.ID, err)
+		return
 	}
+
+	tr.Printf("queued DSN: %s", id)
 }
 
 // deliver the item to the given recipient, using the couriers from the queue.

internal/trace/trace.go

@@ -3,6 +3,7 @@ package trace
 
 import (
 	"fmt"
+	"strconv"
 
 	"github.com/golang/glog"
 	nettrace "golang.org/x/net/trace"
@@ -18,16 +19,30 @@ func New(family, title string) *Trace {
 	return &Trace{family, title, nettrace.New(family, title)}
 }
 
-func (t *Trace) LazyPrintf(format string, a ...interface{}) {
+func (t *Trace) Printf(format string, a ...interface{}) {
 	t.t.LazyPrintf(format, a...)
 
-	if glog.V(2) {
+	if glog.V(0) {
-		msg := fmt.Sprintf("%p %s %s: %+q", t, t.family, t.title,
+		msg := fmt.Sprintf("%s %s: %s", t.family, t.title,
-			fmt.Sprintf(format, a...))
+			quote(fmt.Sprintf(format, a...)))
-		glog.InfoDepth(1, msg)
+		glog.InfoDepth(2, msg)
 	}
 }
 
+func (t *Trace) Debugf(format string, a ...interface{}) {
+	if glog.V(2) {
+		t.t.LazyPrintf(format, a...)
+		msg := fmt.Sprintf("%s %s: %s", t.family, t.title,
+			quote(fmt.Sprintf(format, a...)))
+		glog.InfoDepth(2, msg)
+	}
+}
+
+func quote(s string) string {
+	qs := strconv.Quote(s)
+	return qs[1 : len(qs)-1]
+}
+
 func (t *Trace) SetError() {
 	t.t.SetError()
 }
@@ -37,8 +52,8 @@ func (t *Trace) Errorf(format string, a ...interface{}) error {
 	t.t.SetError()
 	t.t.LazyPrintf("error: %v", err)
 
-	if glog.V(2) {
+	if glog.V(0) {
-		msg := fmt.Sprintf("%p %s %s: error: %v", t, t.family, t.title, err)
+		msg := fmt.Sprintf("%s %s: error: %v", t.family, t.title, err)
 		glog.InfoDepth(1, msg)
 	}
 	return err
@@ -48,8 +63,8 @@ func (t *Trace) Error(err error) error {
 	t.t.SetError()
 	t.t.LazyPrintf("error: %v", err)
 
-	if glog.V(2) {
+	if glog.V(0) {
-		msg := fmt.Sprintf("%p %s %s: error: %v", t, t.family, t.title, err)
+		msg := fmt.Sprintf("%s %s: error: %v", t, t.family, t.title, err)
 		glog.InfoDepth(1, msg)
 	}
 	return err