maillog: Use blitiri.com.ar/go/log for mail log

In preparation for supporting log rotation, this patch makes the maillog
package to use blitiri.com.ar/go/log instead of its own writer.

Some of the tests are made more strict, to better test the log format.

Amended-by: Alberto Bertogli <albertito@blitiri.com.ar>
  Fixed build, extended commit message, adjusted to the log options
  API, and added tests.

chasquid.go

@@ -216,9 +216,7 @@ func initMailLog(path string) {
 		maillog.Default, err = maillog.NewSyslog()
 	} else {
 		_ = os.MkdirAll(filepath.Dir(path), 0775)
-		var f *os.File
+		maillog.Default, err = maillog.NewFile(path)
-		f, err = os.OpenFile(path, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0664)
-		maillog.Default = maillog.New(f)
 	}
 
 	if err != nil {

internal/maillog/maillog.go

@@ -19,43 +19,60 @@ var (
 	authLog = trace.NewEventLog("Authentication", "Incoming SMTP")
 )
 
-// A writer that prepends timing information.
-type timedWriter struct {
-	w io.Writer
-}
-
-// Write the given buffer, prepending timing information.
-func (t timedWriter) Write(b []byte) (int, error) {
-	fmt.Fprintf(t.w, "%s  ", time.Now().Format("2006-01-02 15:04:05.000000"))
-	return t.w.Write(b)
-}
-
 // Logger contains a backend used to log data to, such as a file or syslog.
 // It implements various user-friendly methods for logging mail information to
 // it.
 type Logger struct {
-	w    io.Writer
+	inner *log.Logger
-	once sync.Once
+	once  sync.Once
 }
 
 // New creates a new Logger which will write messages to the given writer.
-func New(w io.Writer) *Logger {
+func New(w io.WriteCloser) *Logger {
-	return &Logger{w: timedWriter{w}}
+	inner := log.New(w)
+
+	// Don't include level or caller in the output, it doesn't add value for
+	// this type of log.
+	inner.LogLevel = false
+	inner.LogCaller = false
+
+	return &Logger{inner: inner}
 }
 
-// NewSyslog creates a new Logger which will write messages to syslog.
+// NewFile creates a new Logger which will write messages to the file at the
-func NewSyslog() (*Logger, error) {
+// given path.
-	w, err := syslog.New(syslog.LOG_INFO|syslog.LOG_MAIL, "chasquid")
+func NewFile(path string) (*Logger, error) {
+	inner, err := log.NewFile(path)
 	if err != nil {
 		return nil, err
 	}
 
-	l := &Logger{w: w}
+	// Don't include level or caller in the output, it doesn't add value for
-	return l, nil
+	// this type of log.
+	inner.LogLevel = false
+	inner.LogCaller = false
+
+	return &Logger{inner: inner}, nil
+}
+
+// NewSyslog creates a new Logger which will write messages to syslog.
+func NewSyslog() (*Logger, error) {
+	inner, err := log.NewSyslog(syslog.LOG_INFO|syslog.LOG_MAIL, "chasquid")
+	if err != nil {
+		return nil, err
+	}
+
+	// Like NewFile, we skip level and caller. In addition, we skip time, as
+	// syslog usually adds that on its own.
+	inner.LogLevel = false
+	inner.LogCaller = false
+	inner.LogTime = false
+
+	return &Logger{inner: inner}, nil
 }
 
 func (l *Logger) printf(format string, args ...interface{}) {
-	_, err := fmt.Fprintf(l.w, format, args...)
+	err := l.inner.Log(log.Info, 2, format, args...)
 	if err != nil {
 		l.once.Do(func() {
 			log.Errorf("failed to write to maillog: %v", err)
@@ -119,8 +136,14 @@ func (l *Logger) QueueLoop(id, from string, nextDelay time.Duration) {
 	}
 }
 
+type nopCloser struct {
+	io.Writer
+}
+
+func (nopCloser) Close() error { return nil }
+
 // Default logger, used in the following top-level functions.
-var Default = New(ioutil.Discard)
+var Default *Logger = New(nopCloser{ioutil.Discard})
 
 // Listening logs that the daemon is listening on the given address.
 func Listening(a string) {

internal/maillog/maillog_test.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"io"
 	"net"
+	"regexp"
 	"strings"
 	"testing"
 	"time"
@@ -18,17 +19,17 @@ var netAddr = &net.TCPAddr{
 }
 
 func expect(t *testing.T, buf *bytes.Buffer, s string) {
-	if strings.Contains(buf.String(), s) {
+	t.Helper()
-		return
+	re := regexp.MustCompile(`^....-..-.. ..:..:..\.\d{6} ` + s + "\n")
+	if !re.Match(buf.Bytes()) {
+		t.Errorf("mismatch:\n  regexp: %q\n  string: %q",
+			re, buf.String())
 	}
-	t.Errorf("buffer mismatch:")
-	t.Errorf("  expected to contain: %q", s)
-	t.Errorf("  got: %q", buf.String())
 }
 
 func TestLogger(t *testing.T) {
 	buf := &bytes.Buffer{}
-	l := New(buf)
+	l := New(nopCloser{buf})
 
 	l.Listening("1.2.3.4:4321")
 	expect(t, buf, "daemon listening on 1.2.3.4:4321")
@@ -43,11 +44,11 @@ func TestLogger(t *testing.T) {
 	buf.Reset()
 
 	l.Rejected(netAddr, "from", []string{"to1", "to2"}, "error")
-	expect(t, buf, "1.2.3.4:4321 rejected from=from to=[to1 to2] - error")
+	expect(t, buf, `1.2.3.4:4321 rejected from=from to=\[to1 to2\] - error`)
 	buf.Reset()
 
 	l.Queued(netAddr, "from", []string{"to1", "to2"}, "qid")
-	expect(t, buf, "qid from=from queued ip=1.2.3.4:4321 to=[to1 to2]")
+	expect(t, buf, `qid from=from queued ip=1.2.3.4:4321 to=\[to1 to2\]`)
 	buf.Reset()
 
 	l.SendAttempt("qid", "from", "to", nil, false)
@@ -55,11 +56,11 @@ func TestLogger(t *testing.T) {
 	buf.Reset()
 
 	l.SendAttempt("qid", "from", "to", fmt.Errorf("error"), false)
-	expect(t, buf, "qid from=from to=to 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 failed (permanent): error")
+	expect(t, buf, `qid from=from to=to failed \(permanent\): error`)
 	buf.Reset()
 
 	l.QueueLoop("qid", "from", 17*time.Second)
@@ -75,7 +76,7 @@ func TestLogger(t *testing.T) {
 // Unfortunately this is almost the same as TestLogger.
 func TestDefault(t *testing.T) {
 	buf := &bytes.Buffer{}
-	Default = New(buf)
+	Default = New(nopCloser{buf})
 
 	Listening("1.2.3.4:4321")
 	expect(t, buf, "daemon listening on 1.2.3.4:4321")
@@ -90,11 +91,11 @@ func TestDefault(t *testing.T) {
 	buf.Reset()
 
 	Rejected(netAddr, "from", []string{"to1", "to2"}, "error")
-	expect(t, buf, "1.2.3.4:4321 rejected from=from to=[to1 to2] - error")
+	expect(t, buf, `1.2.3.4:4321 rejected from=from to=\[to1 to2\] - error`)
 	buf.Reset()
 
 	Queued(netAddr, "from", []string{"to1", "to2"}, "qid")
-	expect(t, buf, "qid from=from queued ip=1.2.3.4:4321 to=[to1 to2]")
+	expect(t, buf, `qid from=from queued ip=1.2.3.4:4321 to=\[to1 to2\]`)
 	buf.Reset()
 
 	SendAttempt("qid", "from", "to", nil, false)
@@ -102,11 +103,11 @@ func TestDefault(t *testing.T) {
 	buf.Reset()
 
 	SendAttempt("qid", "from", "to", fmt.Errorf("error"), false)
-	expect(t, buf, "qid from=from to=to 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 failed (permanent): error")
+	expect(t, buf, `qid from=from to=to failed \(permanent\): error`)
 	buf.Reset()
 
 	QueueLoop("qid", "from", 17*time.Second)
@@ -125,14 +126,7 @@ func (w *failedWriter) Write(p []byte) (int, error) {
 	return 0, fmt.Errorf("test error")
 }
 
-// nopCloser adds a Close method to an io.Writer, to turn it into a
+func (w *failedWriter) Close() error { return nil }
-// io.WriteCloser. This is the equivalent of ioutil.NopCloser but for
-// io.Writer.
-type nopCloser struct {
-	io.Writer
-}
-
-func (nopCloser) Close() error { return nil }
 
 // Test that we complain (only once) when we can't log.
 func TestFailedLogger(t *testing.T) {