maillog: Introduce a special-purpose mail logging package

The default INFO logs are more oriented towards debugging and can be
a bit too verbose when looking for high-level information.

This patch introduces a new "maillog" package, used to log messages of
particular relevance to mail transmission at a higher level.

chasquid.go

@@ -14,6 +14,7 @@ import (
 
 	"blitiri.com.ar/go/chasquid/internal/config"
 	"blitiri.com.ar/go/chasquid/internal/courier"
+	"blitiri.com.ar/go/chasquid/internal/maillog"
 	"blitiri.com.ar/go/chasquid/internal/normalize"
 	"blitiri.com.ar/go/chasquid/internal/smtpsrv"
 	"blitiri.com.ar/go/chasquid/internal/systemd"
@@ -44,7 +45,7 @@ func main() {
 
 	conf, err := config.Load(*configDir + "/chasquid.conf")
 	if err != nil {
-		glog.Fatalf("Error reading config")
+		glog.Fatalf("Error reading config: %v", err)
 	}
 	config.LogConfig(conf)
 
@@ -55,6 +56,8 @@ func main() {
 	// fixes the point of reference.
 	os.Chdir(*configDir)
 
+	initMailLog(conf.MailLogPath)
+
 	if conf.MonitoringAddress != "" {
 		launchMonitoringServer(conf.MonitoringAddress)
 	}
@@ -149,6 +152,23 @@ func loadAddresses(srv *smtpsrv.Server, addrs []string, ls []net.Listener, mode
 	}
 }
 
+func initMailLog(path string) {
+	var err error
+
+	if path == "<syslog>" {
+		maillog.Default, err = maillog.NewSyslog()
+	} else {
+		os.MkdirAll(filepath.Dir(path), 0775)
+		var f *os.File
+		f, err = os.OpenFile(path, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0666)
+		maillog.Default = maillog.New(f)
+	}
+
+	if err != nil {
+		glog.Fatalf("Error opening mail log: %v", err)
+	}
+}
+
 // Helper to load a single domain configuration into the server.
 func loadDomain(name, dir string, s *smtpsrv.Server) {
 	glog.Infof("  %s", name)

internal/config/config.go

@@ -70,6 +70,10 @@ func Load(path string) (*Config, error) {
 		c.DropCharacters = "."
 	}
 
+	if c.MailLogPath == "" {
+		c.MailLogPath = "<syslog>"
+	}
+
 	return c, nil
 }
 
@@ -84,4 +88,5 @@ func LogConfig(c *Config) {
 	glog.Infof("  Data directory: %s", c.DataDir)
 	glog.Infof("  Suffix separators: %s", c.SuffixSeparators)
 	glog.Infof("  Drop characters: %s", c.DropCharacters)
+	glog.Infof("  Mail log: %s", c.MailLogPath)
 }

internal/config/config.pb.go

@@ -68,13 +68,19 @@ type Config struct {
 	// Suffix separator, to perform suffix removal of local users.
 	// For example, if you set this to "-+", email to local user
 	// "user-blah" and "user+blah" will be delivered to "user".
-	// Default: none.
+	// Including "+" is strongly encouraged, as it is assumed for email
+	// forwarding.
+	// Default: "+".
 	SuffixSeparators string `protobuf:"bytes,9,opt,name=suffix_separators,json=suffixSeparators" json:"suffix_separators,omitempty"`
 	// Characters to drop from the user part on local emails.
 	// For example, if you set this to "._", email to local user
 	// "u.se_r" will be delivered to "user".
-	// Default: none.
+	// Default: ".".
 	DropCharacters string `protobuf:"bytes,10,opt,name=drop_characters,json=dropCharacters" json:"drop_characters,omitempty"`
+	// Path where to write the mail log to.
+	// If "<syslog>", log using the syslog (at MAIL|INFO priority).
+	// Default: <syslog>
+	MailLogPath string `protobuf:"bytes,11,opt,name=mail_log_path,json=mailLogPath" json:"mail_log_path,omitempty"`
 }
 
 func (m *Config) Reset()                    { *m = Config{} }
@@ -89,24 +95,25 @@ func init() {
 func init() { proto.RegisterFile("config.proto", fileDescriptor0) }
 
 var fileDescriptor0 = []byte{
-	// 296 bytes of a gzipped FileDescriptorProto
+	// 317 bytes of a gzipped FileDescriptorProto
-	0x1f, 0x8b, 0x08, 0x00, 0x00, 0x09, 0x6e, 0x88, 0x02, 0xff, 0x6c, 0x91, 0x41, 0x4e, 0xeb, 0x30,
+	0x1f, 0x8b, 0x08, 0x00, 0x00, 0x09, 0x6e, 0x88, 0x02, 0xff, 0x6c, 0x91, 0xdf, 0x4e, 0xc2, 0x30,
-	0x10, 0x86, 0xd5, 0x97, 0x47, 0x9a, 0x9a, 0x02, 0xad, 0x05, 0xc2, 0xb0, 0x2a, 0x6c, 0x40, 0x42,
+	0x14, 0xc6, 0x83, 0x53, 0xfe, 0x14, 0x50, 0x68, 0x34, 0x56, 0xaf, 0x90, 0x1b, 0x4d, 0x8c, 0xde,
-	0xb0, 0x41, 0x88, 0x75, 0x68, 0xb6, 0x6c, 0xda, 0x03, 0x58, 0x4e, 0xec, 0xa4, 0x23, 0xd5, 0x76,
+	0x18, 0xe3, 0x35, 0xc2, 0xa5, 0x26, 0x06, 0x1e, 0xa0, 0xe9, 0x58, 0x19, 0x27, 0x59, 0xdb, 0xa5,
-	0x64, 0x1b, 0x54, 0xb8, 0x14, 0x57, 0x64, 0xe2, 0x42, 0x8a, 0x04, 0xcb, 0xf9, 0xfe, 0x6f, 0xec,
+	0xad, 0x06, 0x7d, 0x4d, 0x5f, 0xc8, 0xb3, 0x83, 0x0e, 0x13, 0xbd, 0x3c, 0xbf, 0xef, 0x77, 0xb6,
-	0xf1, 0x98, 0x8c, 0x2b, 0x6b, 0x6a, 0x68, 0xee, 0x5a, 0x67, 0x83, 0xbd, 0xfc, 0x48, 0x48, 0x3a,
+	0x6f, 0x67, 0xac, 0xb7, 0x74, 0x76, 0x05, 0xf9, 0x6d, 0xe9, 0x5d, 0x74, 0xe3, 0xcf, 0x84, 0x35,
-	0x8f, 0x80, 0x9e, 0x93, 0x6c, 0x65, 0x7d, 0x30, 0x42, 0x2b, 0x36, 0x98, 0x0d, 0xae, 0x47, 0x8b,
+	0xa7, 0x04, 0xf8, 0x39, 0x6b, 0xaf, 0x5d, 0x88, 0x56, 0x19, 0x2d, 0x1a, 0xa3, 0xc6, 0x55, 0x67,
-	0xbe, 0xa6, 0x57, 0x64, 0xa2, 0xc5, 0x86, 0x4b, 0x11, 0x04, 0xf7, 0xf0, 0xae, 0xb8, 0x2e, 0xd9,
+	0x5e, 0xcf, 0xfc, 0x92, 0x0d, 0x8c, 0xda, 0xc8, 0x4c, 0x45, 0x25, 0x03, 0x7c, 0x68, 0x69, 0x52,
-	0x3f, 0x74, 0x92, 0xc5, 0x01, 0xf2, 0x02, 0xf1, 0x12, 0xe9, 0x73, 0x49, 0x2f, 0xc8, 0xd8, 0xeb,
+	0xb1, 0x87, 0x4e, 0x32, 0xef, 0x23, 0x9f, 0x21, 0x5e, 0x20, 0x7d, 0x4e, 0xf9, 0x05, 0xeb, 0x05,
-	0xd0, 0x72, 0x21, 0xa5, 0x53, 0xde, 0xb3, 0x64, 0x96, 0xe0, 0x41, 0xfb, 0x1d, 0xcb, 0xb7, 0x88,
+	0x13, 0x4b, 0xa9, 0xb2, 0xcc, 0xeb, 0x10, 0x44, 0x32, 0x4a, 0xf0, 0x41, 0xdd, 0x8a, 0x4d, 0xb6,
-	0xde, 0x12, 0xea, 0x5f, 0x4a, 0x0d, 0xde, 0x83, 0x35, 0xbd, 0xf8, 0x3f, 0x8a, 0xd3, 0x5d, 0xf2,
+	0x88, 0xdf, 0x30, 0x1e, 0x5e, 0x53, 0x03, 0x21, 0x80, 0xb3, 0xb5, 0xb8, 0x4f, 0xe2, 0x70, 0x97,
-	0x43, 0xd7, 0xd6, 0x40, 0xb0, 0x0e, 0x4c, 0xd3, 0xeb, 0x7b, 0x71, 0xc0, 0xe9, 0x2e, 0xf9, 0xd6,
+	0xfc, 0xd2, 0x8d, 0xb3, 0x10, 0x9d, 0x07, 0x9b, 0xd7, 0xfa, 0x01, 0x15, 0x1c, 0xee, 0x92, 0x1f,
-	0x1f, 0xc8, 0xa9, 0x16, 0xb0, 0xe6, 0x52, 0xad, 0xe1, 0x55, 0xb9, 0x37, 0x2e, 0x1a, 0x65, 0x02,
+	0xfd, 0x9e, 0x9d, 0x1a, 0x05, 0x85, 0xcc, 0x74, 0x01, 0x6f, 0xda, 0xbf, 0x4b, 0x95, 0x6b, 0x1b,
-	0x2f, 0xc1, 0xb0, 0x34, 0xf6, 0x1c, 0x77, 0x71, 0xf1, 0x95, 0xe6, 0x5d, 0xf8, 0x04, 0x86, 0x3e,
+	0x65, 0x0a, 0x56, 0x34, 0x69, 0xe7, 0xb8, 0x8a, 0x67, 0xdf, 0xe9, 0xa4, 0x0a, 0x1f, 0xc1, 0xf2,
-	0x12, 0xf6, 0x57, 0x9b, 0x70, 0x8d, 0x67, 0xc3, 0x38, 0xda, 0xc9, 0xaf, 0xbe, 0x1c, 0x43, 0x7a,
+	0x07, 0x26, 0xfe, 0x5b, 0x53, 0x3e, 0x0f, 0xa2, 0x45, 0xd5, 0x4e, 0xfe, 0xec, 0x4d, 0x30, 0xe4,
-	0x46, 0xb2, 0xb8, 0x15, 0x09, 0x8e, 0x65, 0xf1, 0x82, 0x61, 0x57, 0x17, 0xe0, 0xe8, 0x0d, 0xc1,
+	0x67, 0xac, 0x4d, 0x57, 0xc9, 0xc0, 0x8b, 0x36, 0xbd, 0xa0, 0x55, 0xcd, 0x33, 0xf0, 0xfc, 0x9a,
-	0xe7, 0xd4, 0x35, 0x6c, 0xb8, 0x57, 0xad, 0x70, 0x02, 0x07, 0xf5, 0x6c, 0x14, 0x9d, 0xc9, 0x36,
+	0xe1, 0xe7, 0xac, 0x56, 0xb0, 0x91, 0x41, 0x97, 0xca, 0x2b, 0x2c, 0x1a, 0x44, 0x87, 0x9c, 0xc1,
-	0x58, 0xf6, 0x1c, 0x37, 0x7c, 0x24, 0x9d, 0x6d, 0x79, 0xb5, 0x42, 0x52, 0x05, 0x85, 0x2a, 0x89,
+	0x36, 0x58, 0xd4, 0x1c, 0x2f, 0x7c, 0x94, 0x79, 0x57, 0xca, 0xe5, 0x1a, 0xc9, 0x32, 0x6a, 0x54,
-	0xea, 0x61, 0x87, 0xe7, 0x3d, 0x2d, 0xd3, 0xf8, 0x71, 0xf7, 0x9f, 0x01, 0x00, 0x00, 0xff, 0xff,
+	0x19, 0xa9, 0x87, 0x15, 0x9e, 0xd6, 0x94, 0x8f, 0x59, 0x9f, 0x9a, 0x16, 0x2e, 0x97, 0xa5, 0x8a,
-	0xd1, 0x68, 0xa2, 0x22, 0xc8, 0x01, 0x00, 0x00,
+	0x6b, 0xd1, 0x25, 0xad, 0x5b, 0xc1, 0x27, 0x97, 0xbf, 0x20, 0x4a, 0x9b, 0xf4, 0x73, 0xef, 0xbe,
+	0x02, 0x00, 0x00, 0xff, 0xff, 0x04, 0x0f, 0xa4, 0xff, 0xec, 0x01, 0x00, 0x00,
 }

internal/config/config.proto

@@ -59,5 +59,10 @@ message Config {
 	// "u.se_r" will be delivered to "user".
 	// Default: ".".
 	string drop_characters = 10;
+
+	// Path where to write the mail log to.
+	// If "<syslog>", log using the syslog (at MAIL|INFO priority).
+	// Default: <syslog>
+	string mail_log_path = 11;
 }
 

internal/maillog/maillog.go

@@ -0,0 +1,136 @@
+// Package maillog implements a log specifically for email.
+package maillog
+
+import (
+	"fmt"
+	"io"
+	"io/ioutil"
+	"log/syslog"
+	"net"
+	"sync"
+	"time"
+
+	"github.com/golang/glog"
+
+	"blitiri.com.ar/go/chasquid/internal/trace"
+)
+
+// Global event logs.
+var (
+	authLog = trace.NewEventLog("Authentication", "Incoming SMTP")
+)
+
+// A writer that prepends timing information.
+type timedWriter struct {
+	w io.Writer
+}
+
+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)
+}
+
+type Logger struct {
+	w    io.Writer
+	once sync.Once
+}
+
+func New(w io.Writer) *Logger {
+	return &Logger{w: timedWriter{w}}
+}
+
+func NewSyslog() (*Logger, error) {
+	w, err := syslog.New(syslog.LOG_INFO|syslog.LOG_MAIL, "chasquid")
+	if err != nil {
+		return nil, err
+	}
+
+	l := &Logger{w: w}
+	return l, nil
+}
+
+func (l *Logger) printf(format string, args ...interface{}) {
+	_, err := fmt.Fprintf(l.w, format, args...)
+	if err != nil {
+		l.once.Do(func() {
+			glog.Errorf("failed to write to maillog: %v", err)
+			glog.Error("(will not report this again)")
+		})
+	}
+}
+
+func (l *Logger) Listening(a string) {
+	l.printf("daemon listening on %s\n", a)
+}
+
+func (l *Logger) Auth(netAddr net.Addr, user string, successful bool) {
+	res := "successful"
+	if !successful {
+		res = "failed"
+	}
+	msg := fmt.Sprintf("%s authentication %s for %s\n", netAddr, res, user)
+	l.printf(msg)
+	authLog.Debugf(msg)
+}
+
+func (l *Logger) Rejected(netAddr net.Addr, from string, to []string, err string) {
+	if from != "" {
+		from = fmt.Sprintf(" from=%s", from)
+	}
+	toStr := ""
+	if len(to) > 0 {
+		toStr = fmt.Sprintf(" to=%v", to)
+	}
+	l.printf("%s rejected%s%s - %v\n", netAddr, from, toStr, err)
+}
+
+func (l *Logger) Queued(netAddr net.Addr, from string, to []string, id string) {
+	l.printf("%s from=%s queued ip=%s to=%v\n", id, from, netAddr, to)
+}
+
+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)
+	} else {
+		t := "(temporary)"
+		if permanent {
+			t = "(permanent)"
+		}
+		l.printf("%s from=%s to=%s sent failed %s: %v\n", id, from, to, t, err)
+	}
+}
+
+func (l *Logger) QueueLoop(id string, nextDelay time.Duration) {
+	if nextDelay > 0 {
+		l.printf("%s completed loop, next in %v\n", id, nextDelay)
+	} else {
+		l.printf("%s all done\n", id)
+	}
+}
+
+// The default logger used in the following top-level functions.
+var Default *Logger = New(ioutil.Discard)
+
+func Listening(a string) {
+	Default.Listening(a)
+}
+
+func Auth(netAddr net.Addr, user string, successful bool) {
+	Default.Auth(netAddr, user, successful)
+}
+
+func Rejected(netAddr net.Addr, from string, to []string, err string) {
+	Default.Rejected(netAddr, from, to, err)
+}
+
+func Queued(netAddr net.Addr, from string, to []string, id string) {
+	Default.Queued(netAddr, from, to, id)
+}
+
+func SendAttempt(id, from, to string, err error, permanent bool) {
+	Default.SendAttempt(id, from, to, err, permanent)
+}
+
+func QueueLoop(id string, nextDelay time.Duration) {
+	Default.QueueLoop(id, nextDelay)
+}

internal/maillog/maillog_test.go

@@ -0,0 +1,116 @@
+package maillog
+
+import (
+	"bytes"
+	"fmt"
+	"net"
+	"strings"
+	"testing"
+	"time"
+)
+
+var netAddr = &net.TCPAddr{
+	IP:   net.ParseIP("1.2.3.4"),
+	Port: 4321,
+}
+
+func expect(t *testing.T, buf *bytes.Buffer, s string) {
+	if strings.Contains(buf.String(), s) {
+		return
+	}
+	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.Listening("1.2.3.4:4321")
+	expect(t, buf, "daemon listening on 1.2.3.4:4321")
+	buf.Reset()
+
+	l.Auth(netAddr, "user@domain", false)
+	expect(t, buf, "1.2.3.4:4321 authentication 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")
+	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")
+	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]")
+	buf.Reset()
+
+	l.SendAttempt("qid", "from", "to", nil, false)
+	expect(t, buf, "qid from=from to=to sent successfully")
+	buf.Reset()
+
+	l.SendAttempt("qid", "from", "to", fmt.Errorf("error"), false)
+	expect(t, buf, "qid from=from to=to sent 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")
+	buf.Reset()
+
+	l.QueueLoop("qid", 17*time.Second)
+	expect(t, buf, "qid completed loop, next in 17s")
+	buf.Reset()
+
+	l.QueueLoop("qid", 0)
+	expect(t, buf, "qid all done")
+	buf.Reset()
+}
+
+// Test that the default actions go reasonably to the default logger.
+// Unfortunately this is almost the same as TestLogger.
+func TestDefault(t *testing.T) {
+	buf := &bytes.Buffer{}
+	Default = New(buf)
+
+	Listening("1.2.3.4:4321")
+	expect(t, buf, "daemon listening on 1.2.3.4:4321")
+	buf.Reset()
+
+	Auth(netAddr, "user@domain", false)
+	expect(t, buf, "1.2.3.4:4321 authentication failed for user@domain")
+	buf.Reset()
+
+	Auth(netAddr, "user@domain", true)
+	expect(t, buf, "1.2.3.4:4321 authentication successful for user@domain")
+	buf.Reset()
+
+	Rejected(netAddr, "from", []string{"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]")
+	buf.Reset()
+
+	SendAttempt("qid", "from", "to", nil, false)
+	expect(t, buf, "qid from=from to=to sent successfully")
+	buf.Reset()
+
+	SendAttempt("qid", "from", "to", fmt.Errorf("error"), false)
+	expect(t, buf, "qid from=from to=to sent 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")
+	buf.Reset()
+
+	QueueLoop("qid", 17*time.Second)
+	expect(t, buf, "qid completed loop, next in 17s")
+	buf.Reset()
+
+	QueueLoop("qid", 0)
+	expect(t, buf, "qid all done")
+	buf.Reset()
+}

internal/queue/queue.go

@@ -23,6 +23,7 @@ import (
 	"blitiri.com.ar/go/chasquid/internal/aliases"
 	"blitiri.com.ar/go/chasquid/internal/courier"
 	"blitiri.com.ar/go/chasquid/internal/envelope"
+	"blitiri.com.ar/go/chasquid/internal/maillog"
 	"blitiri.com.ar/go/chasquid/internal/protoio"
 	"blitiri.com.ar/go/chasquid/internal/set"
 	"blitiri.com.ar/go/chasquid/internal/trace"
@@ -328,6 +329,7 @@ func (item *Item) SendLoop(q *Queue) {
 
 		delay = nextDelay(delay)
 		tr.Printf("waiting for %v", delay)
+		maillog.QueueLoop(item.ID, delay)
 		time.Sleep(delay)
 	}
 
@@ -337,6 +339,7 @@ func (item *Item) SendLoop(q *Queue) {
 	}
 
 	tr.Printf("all done")
+	maillog.QueueLoop(item.ID, 0)
 	q.Remove(item.ID)
 }
 
@@ -353,12 +356,15 @@ func (item *Item) sendOneRcpt(wg *sync.WaitGroup, tr *trace.Trace, q *Queue, rcp
 		rcpt.LastFailureMessage = err.Error()
 		if permanent {
 			tr.Errorf("%s permanent error: %v", to, err)
+			maillog.SendAttempt(item.ID, item.From, to, err, true)
 			rcpt.Status = Recipient_FAILED
 		} else {
 			tr.Printf("%s temporary error: %v", to, err)
+			maillog.SendAttempt(item.ID, item.From, to, err, false)
 		}
 	} else {
 		tr.Printf("%s sent", to)
+		maillog.SendAttempt(item.ID, item.From, to, nil, false)
 		rcpt.Status = Recipient_SENT
 	}
 	item.Unlock()

internal/smtpsrv/conn.go

@@ -22,6 +22,7 @@ import (
 	"blitiri.com.ar/go/chasquid/internal/auth"
 	"blitiri.com.ar/go/chasquid/internal/domaininfo"
 	"blitiri.com.ar/go/chasquid/internal/envelope"
+	"blitiri.com.ar/go/chasquid/internal/maillog"
 	"blitiri.com.ar/go/chasquid/internal/normalize"
 	"blitiri.com.ar/go/chasquid/internal/queue"
 	"blitiri.com.ar/go/chasquid/internal/set"
@@ -42,11 +43,6 @@ var (
 	hookResults       = expvar.NewMap("chasquid/smtpIn/hookResults")
 )
 
-// Global event logs.
-var (
-	authLog = trace.NewEventLog("Authentication", "Incoming SMTP")
-)
-
 // Mode for a socket (listening or connection).
 // We keep them distinct, as policies can differ between them.
 type SocketMode string
@@ -351,16 +347,22 @@ func (c *Conn) MAIL(params string) (code int, msg string) {
 		c.spfResult, c.spfError = c.checkSPF(addr)
 		if c.spfResult == spf.Fail {
 			// https://tools.ietf.org/html/rfc7208#section-8.4
+			maillog.Rejected(c.conn.RemoteAddr(), addr, nil,
+				fmt.Sprintf("failed SPF: %v", c.spfError))
 			return 550, fmt.Sprintf(
 				"SPF check failed: %v", c.spfError)
 		}
 
 		if !c.secLevelCheck(addr) {
+			maillog.Rejected(c.conn.RemoteAddr(), addr, nil,
+				"security level check failed")
 			return 550, "security level check failed"
 		}
 
 		addr, err = normalize.DomainToUnicode(addr)
 		if err != nil {
+			maillog.Rejected(c.conn.RemoteAddr(), addr, nil,
+				fmt.Sprintf("malformed address: %v", err))
 			return 501, "malformed address (IDNA conversion failed)"
 		}
 	}
@@ -461,16 +463,22 @@ func (c *Conn) RCPT(params string) (code int, msg string) {
 
 	localDst := envelope.DomainIn(addr, c.localDomains)
 	if !localDst && !c.completedAuth {
+		maillog.Rejected(c.conn.RemoteAddr(), c.mailFrom, []string{addr},
+			"relay not allowed")
 		return 503, "relay not allowed"
 	}
 
 	if localDst {
 		addr, err = normalize.Addr(addr)
 		if err != nil {
+			maillog.Rejected(c.conn.RemoteAddr(), c.mailFrom, []string{addr},
+				fmt.Sprintf("invalid address: %v", err))
 			return 550, "recipient invalid, please check the address for typos"
 		}
 
 		if !c.userExists(addr) {
+			maillog.Rejected(c.conn.RemoteAddr(), c.mailFrom, []string{addr},
+				"local user does not exist")
 			return 550, "recipient unknown, please check the address for typos"
 		}
 	}
@@ -516,6 +524,7 @@ func (c *Conn) DATA(params string) (code int, msg string) {
 	c.tr.Debugf("-> ... %d bytes of data", len(c.data))
 
 	if err := checkData(c.data); err != nil {
+		maillog.Rejected(c.conn.RemoteAddr(), c.mailFrom, c.rcptTo, err.Error())
 		return 554, err.Error()
 	}
 
@@ -523,6 +532,7 @@ func (c *Conn) DATA(params string) (code int, msg string) {
 
 	hookOut, err := c.runPostDataHook(c.data)
 	if err != nil {
+		maillog.Rejected(c.conn.RemoteAddr(), c.mailFrom, c.rcptTo, err.Error())
 		return 554, err.Error()
 	}
 	c.data = append(hookOut, c.data...)
@@ -535,6 +545,7 @@ func (c *Conn) DATA(params string) (code int, msg string) {
 	}
 
 	c.tr.Printf("Queued from %s to %s - %s", c.mailFrom, c.rcptTo, msgID)
+	maillog.Queued(c.conn.RemoteAddr(), 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.
@@ -825,13 +836,11 @@ func (c *Conn) AUTH(params string) (code int, msg string) {
 		c.authUser = user
 		c.authDomain = domain
 		c.completedAuth = true
-		authLog.Debugf("%s successful for %s@%s",
+		maillog.Auth(c.conn.RemoteAddr(), user+"@"+domain, true)
-			c.conn.RemoteAddr().String(), user, domain)
 		return 235, ""
 	}
 
-	authLog.Debugf("%s failed for %s@%s",
+	maillog.Auth(c.conn.RemoteAddr(), user+"@"+domain, false)
-		c.conn.RemoteAddr().String(), user, domain)
 	return 535, "Incorrect user or password"
 }
 

internal/smtpsrv/server.go

@@ -11,6 +11,7 @@ import (
 	"blitiri.com.ar/go/chasquid/internal/aliases"
 	"blitiri.com.ar/go/chasquid/internal/courier"
 	"blitiri.com.ar/go/chasquid/internal/domaininfo"
+	"blitiri.com.ar/go/chasquid/internal/maillog"
 	"blitiri.com.ar/go/chasquid/internal/queue"
 	"blitiri.com.ar/go/chasquid/internal/set"
 	"blitiri.com.ar/go/chasquid/internal/userdb"
@@ -168,6 +169,7 @@ func (s *Server) ListenAndServe() {
 			}
 
 			glog.Infof("Server listening on %s (%v)", addr, m)
+			maillog.Listening(addr)
 			go s.serve(l, m)
 		}
 	}
@@ -175,6 +177,7 @@ func (s *Server) ListenAndServe() {
 	for m, ls := range s.listeners {
 		for _, l := range ls {
 			glog.Infof("Server listening on %s (%v, via systemd)", l.Addr(), m)
+			maillog.Listening(l.Addr().String())
 			go s.serve(l, m)
 		}
 	}

test/t-01-simple_local/config/chasquid.conf

@@ -6,3 +6,4 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data"
+mail_log_path: "../.logs/mail_log"

test/t-02-exim/config/chasquid.conf

@@ -6,3 +6,4 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data"
+mail_log_path: "../.logs/mail_log"

test/t-03-queue_persistency/config/chasquid.conf

@@ -6,3 +6,4 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data"
+mail_log_path: "../.logs/mail_log"

test/t-04-aliases/config/chasquid.conf

@@ -6,6 +6,7 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data"
+mail_log_path: "../.logs/mail_log"
 
 suffix_separators: "+-"
 drop_characters: "._"

test/t-05-null_address/config/chasquid.conf

@@ -8,6 +8,7 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data"
+mail_log_path: "../.logs/mail_log"
 
 suffix_separators: "+-"
 drop_characters: "._"

test/t-06-idna/A/chasquid.conf

@@ -6,3 +6,4 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data-A"
+mail_log_path: "../.logs/mail_log-A"

test/t-06-idna/B/chasquid.conf

@@ -6,3 +6,4 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data-B"
+mail_log_path: "../.logs/mail_log-B"

test/t-07-smtputf8/config/chasquid.conf

@@ -6,3 +6,4 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data"
+mail_log_path: "../.logs/mail_log"

test/t-09-loop/A/chasquid.conf

@@ -6,3 +6,4 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data-A"
+mail_log_path: "../.logs/mail_log-A"

test/t-09-loop/B/chasquid.conf

@@ -6,3 +6,4 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data-B"
+mail_log_path: "../.logs/mail_log-B"

test/t-10-hooks/config/chasquid.conf

@@ -6,3 +6,4 @@ mail_delivery_agent_bin: "test-mda"
 mail_delivery_agent_args: "%to%"
 
 data_dir: "../.data"
+mail_log_path: "../.logs/mail_log"