Improve the readability of some log messages

This patch contains a few changes to logging messages, to improve log
readability.

While at it, an obsolete TODO in the SMTP courier is removed.

internal/courier/procmail.go

@@ -26,7 +26,7 @@ type Procmail struct {
 }
 
 func (p *Procmail) Deliver(from string, to string, data []byte) (error, bool) {
-	tr := trace.New("Procmail.Courier", to)
+	tr := trace.New("Courier.Procmail", to)
 	defer tr.Finish()
 
 	// Sanitize, just in case.
@@ -50,18 +50,15 @@ func (p *Procmail) Deliver(from string, to string, data []byte) (error, bool) {
 	for _, a := range p.Args {
 		args = append(args, replacer.Replace(a))
 	}
+	tr.Debugf("%s %q", p.Binary, args)
 
 	ctx, cancel := context.WithDeadline(context.Background(),
 		time.Now().Add(p.Timeout))
 	defer cancel()
 	cmd := exec.CommandContext(ctx, p.Binary, args...)
-
 	cmd.Stdin = bytes.NewReader(data)
-	output := &bytes.Buffer{}
-	cmd.Stdout = output
-	cmd.Stderr = output
 
-	err := cmd.Run()
+	output, err := cmd.CombinedOutput()
 	if ctx.Err() == context.DeadlineExceeded {
 		return tr.Error(errTimeout), false
 	}
@@ -76,7 +73,7 @@ func (p *Procmail) Deliver(from string, to string, data []byte) (error, bool) {
 				permanent = status.ExitStatus() != 75
 			}
 		}
-		err = tr.Errorf("Procmail failed: %v - %q", err, output.String())
+		err = tr.Errorf("Procmail failed: %v - %q", err, string(output))
 		return err, permanent
 	}
 

internal/courier/smtp.go

@@ -42,7 +42,7 @@ type SMTP struct {
 }
 
 func (s *SMTP) Deliver(from string, to string, data []byte) (error, bool) {
-	tr := trace.New("SMTP.Courier", to)
+	tr := trace.New("Courier.SMTP", to)
 	defer tr.Finish()
 	tr.Debugf("%s  ->  %s", from, to)
 
@@ -55,7 +55,6 @@ 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.Debugf("MX: %s", mx)
 
 	// Issue an EHLO with a valid domain; otherwise, some servers like postfix
 	// will complain.
@@ -90,8 +89,6 @@ retry:
 		return tr.Errorf("Error saying hello: %v", err), false
 	}
 
-	// TODO: Keep track of hosts and MXs that we've successfully done TLS
-	// against, and enforce it.
 	if ok, _ := c.Extension("STARTTLS"); ok {
 		config := &tls.Config{
 			ServerName:         mx,
@@ -174,11 +171,11 @@ func lookupMX(tr *trace.Trace, domain string) (string, error) {
 	mxs, err := net.LookupMX(domain)
 	if err == nil {
 		if len(mxs) == 0 {
-			tr.Printf("domain %q has no MX, falling back to A", domain)
+			tr.Debugf("domain %q has no MX, falling back to A", domain)
 			return domain, nil
 		}
 
-		tr.Printf("MX %s", mxs[0].Host)
+		tr.Debugf("MX %s", mxs[0].Host)
 		return mxs[0].Host, nil
 	}
 
@@ -188,14 +185,16 @@ func lookupMX(tr *trace.Trace, domain string) (string, error) {
 	// For now, if the error is permanent, we assume it's because there was no
 	// MX and fall back, otherwise we return.
 	// TODO: Find a better way to do this.
-	tr.Errorf("MX lookup error: %v", err)
 	dnsErr, ok := err.(*net.DNSError)
 	if !ok {
+		tr.Debugf("MX lookup error: %v", err)
 		return "", err
 	} else if dnsErr.Temporary() {
+		tr.Debugf("temporary DNS error: %v", dnsErr)
 		return "", err
 	}
 
 	// Permanent error, we assume MX does not exist and fall back to A.
+	tr.Debugf("failed to resolve MX for %s, falling back to A", domain)
 	return domain, nil
 }

internal/domaininfo/domaininfo.go

@@ -33,7 +33,7 @@ func New(dir string) (*DB, error) {
 		store: st,
 		info:  map[string]*Domain{},
 	}
-	l.ev = trace.NewEventLog("DomainInfo", fmt.Sprintf("%p", l))
+	l.ev = trace.NewEventLog("DomainInfo", dir)
 
 	return l, nil
 }
@@ -55,7 +55,7 @@ func (db *DB) Load() error {
 		db.info[d.Name] = d
 	}
 
-	db.ev.Debugf("loaded: %s", ids)
+	db.ev.Debugf("loaded %d domains", len(ids))
 	return nil
 }
 

internal/maillog/maillog.go

@@ -63,11 +63,11 @@ func (l *Logger) Listening(a string) {
 }
 
 func (l *Logger) Auth(netAddr net.Addr, user string, successful bool) {
-	res := "successful"
+	res := "succeeded"
 	if !successful {
 		res = "failed"
 	}
-	msg := fmt.Sprintf("%s authentication %s for %s\n", netAddr, res, user)
+	msg := fmt.Sprintf("%s auth %s for %s\n", netAddr, res, user)
 	l.printf(msg)
 	authLog.Debugf(msg)
 }
@@ -89,21 +89,21 @@ func (l *Logger) Queued(netAddr net.Addr, from string, to []string, id string) {
 
 func (l *Logger) SendAttempt(id, from, to string, err error, permanent bool) {
 	if err == nil {
-		l.printf("%s from=%s to=%s sent successfully\n", id, from, to)
+		l.printf("%s from=%s to=%s sent\n", id, from, to)
 	} else {
 		t := "(temporary)"
 		if permanent {
 			t = "(permanent)"
 		}
-		l.printf("%s from=%s to=%s sent failed %s: %v\n", id, from, to, t, err)
+		l.printf("%s from=%s to=%s failed %s: %v\n", id, from, to, t, err)
 	}
 }
 
-func (l *Logger) QueueLoop(id string, nextDelay time.Duration) {
+func (l *Logger) QueueLoop(id, from string, nextDelay time.Duration) {
 	if nextDelay > 0 {
-		l.printf("%s completed loop, next in %v\n", id, nextDelay)
+		l.printf("%s from=%s completed loop, next in %v\n", id, from, nextDelay)
 	} else {
-		l.printf("%s all done\n", id)
+		l.printf("%s from=%s all done\n", id, from)
 	}
 }
 
@@ -130,6 +130,6 @@ func SendAttempt(id, from, to string, err error, permanent bool) {
 	Default.SendAttempt(id, from, to, err, permanent)
 }
 
-func QueueLoop(id string, nextDelay time.Duration) {
+func QueueLoop(id, from string, nextDelay time.Duration) {
-	Default.QueueLoop(id, nextDelay)
+	Default.QueueLoop(id, from, nextDelay)
 }

internal/maillog/maillog_test.go

@@ -32,11 +32,11 @@ func TestLogger(t *testing.T) {
 	buf.Reset()
 
 	l.Auth(netAddr, "user@domain", false)
-	expect(t, buf, "1.2.3.4:4321 authentication failed for user@domain")
+	expect(t, buf, "1.2.3.4:4321 auth failed for user@domain")
 	buf.Reset()
 
 	l.Auth(netAddr, "user@domain", true)
-	expect(t, buf, "1.2.3.4:4321 authentication successful for user@domain")
+	expect(t, buf, "1.2.3.4:4321 auth succeeded for user@domain")
 	buf.Reset()
 
 	l.Rejected(netAddr, "from", []string{"to1", "to2"}, "error")
@@ -48,23 +48,23 @@ func TestLogger(t *testing.T) {
 	buf.Reset()
 
 	l.SendAttempt("qid", "from", "to", nil, false)
-	expect(t, buf, "qid from=from to=to sent successfully")
+	expect(t, buf, "qid from=from to=to sent")
 	buf.Reset()
 
 	l.SendAttempt("qid", "from", "to", fmt.Errorf("error"), false)
-	expect(t, buf, "qid from=from to=to sent failed (temporary): error")
+	expect(t, buf, "qid from=from to=to failed (temporary): error")
 	buf.Reset()
 
 	l.SendAttempt("qid", "from", "to", fmt.Errorf("error"), true)
-	expect(t, buf, "qid from=from to=to sent failed (permanent): error")
+	expect(t, buf, "qid from=from to=to failed (permanent): error")
 	buf.Reset()
 
-	l.QueueLoop("qid", 17*time.Second)
+	l.QueueLoop("qid", "from", 17*time.Second)
-	expect(t, buf, "qid completed loop, next in 17s")
+	expect(t, buf, "qid from=from completed loop, next in 17s")
 	buf.Reset()
 
-	l.QueueLoop("qid", 0)
+	l.QueueLoop("qid", "from", 0)
-	expect(t, buf, "qid all done")
+	expect(t, buf, "qid from=from all done")
 	buf.Reset()
 }
 
@@ -79,11 +79,11 @@ func TestDefault(t *testing.T) {
 	buf.Reset()
 
 	Auth(netAddr, "user@domain", false)
-	expect(t, buf, "1.2.3.4:4321 authentication failed for user@domain")
+	expect(t, buf, "1.2.3.4:4321 auth failed for user@domain")
 	buf.Reset()
 
 	Auth(netAddr, "user@domain", true)
-	expect(t, buf, "1.2.3.4:4321 authentication successful for user@domain")
+	expect(t, buf, "1.2.3.4:4321 auth succeeded for user@domain")
 	buf.Reset()
 
 	Rejected(netAddr, "from", []string{"to1", "to2"}, "error")
@@ -95,22 +95,22 @@ func TestDefault(t *testing.T) {
 	buf.Reset()
 
 	SendAttempt("qid", "from", "to", nil, false)
-	expect(t, buf, "qid from=from to=to sent successfully")
+	expect(t, buf, "qid from=from to=to sent")
 	buf.Reset()
 
 	SendAttempt("qid", "from", "to", fmt.Errorf("error"), false)
-	expect(t, buf, "qid from=from to=to sent failed (temporary): error")
+	expect(t, buf, "qid from=from to=to failed (temporary): error")
 	buf.Reset()
 
 	SendAttempt("qid", "from", "to", fmt.Errorf("error"), true)
-	expect(t, buf, "qid from=from to=to sent failed (permanent): error")
+	expect(t, buf, "qid from=from to=to failed (permanent): error")
 	buf.Reset()
 
-	QueueLoop("qid", 17*time.Second)
+	QueueLoop("qid", "from", 17*time.Second)
-	expect(t, buf, "qid completed loop, next in 17s")
+	expect(t, buf, "qid from=from completed loop, next in 17s")
 	buf.Reset()
 
-	QueueLoop("qid", 0)
+	QueueLoop("qid", "from", 0)
-	expect(t, buf, "qid all done")
+	expect(t, buf, "qid from=from all done")
 	buf.Reset()
 }

internal/queue/queue.go

@@ -329,7 +329,7 @@ func (item *Item) SendLoop(q *Queue) {
 
 		delay := nextDelay(item.CreatedAt)
 		tr.Printf("waiting for %v", delay)
-		maillog.QueueLoop(item.ID, delay)
+		maillog.QueueLoop(item.ID, item.From, delay)
 		time.Sleep(delay)
 	}
 
@@ -339,7 +339,7 @@ func (item *Item) SendLoop(q *Queue) {
 	}
 
 	tr.Printf("all done")
-	maillog.QueueLoop(item.ID, 0)
+	maillog.QueueLoop(item.ID, item.From, 0)
 	q.Remove(item.ID)
 }