author | Alberto Bertogli
<albertito@blitiri.com.ar> 2016-10-16 16:52:10 UTC |
committer | Alberto Bertogli
<albertito@blitiri.com.ar> 2016-10-21 21:20:47 UTC |
parent | cda11e03a5c1b1cab6a6e628807462feb1f24cb7 |
chasquid.go | +21 | -1 |
internal/config/config.go | +5 | -0 |
internal/config/config.pb.go | +29 | -22 |
internal/config/config.proto | +5 | -0 |
internal/maillog/maillog.go | +136 | -0 |
internal/maillog/maillog_test.go | +116 | -0 |
internal/queue/queue.go | +6 | -0 |
internal/smtpsrv/conn.go | +18 | -9 |
internal/smtpsrv/server.go | +3 | -0 |
test/t-01-simple_local/config/chasquid.conf | +1 | -0 |
test/t-02-exim/config/chasquid.conf | +1 | -0 |
test/t-03-queue_persistency/config/chasquid.conf | +1 | -0 |
test/t-04-aliases/config/chasquid.conf | +1 | -0 |
test/t-05-null_address/config/chasquid.conf | +1 | -0 |
test/t-06-idna/A/chasquid.conf | +1 | -0 |
test/t-06-idna/B/chasquid.conf | +1 | -0 |
test/t-07-smtputf8/config/chasquid.conf | +1 | -0 |
test/t-09-loop/A/chasquid.conf | +1 | -0 |
test/t-09-loop/B/chasquid.conf | +1 | -0 |
test/t-10-hooks/config/chasquid.conf | +1 | -0 |
diff --git a/chasquid.go b/chasquid.go index 1946a79..3d34785 100644 --- a/chasquid.go +++ b/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) diff --git a/internal/config/config.go b/internal/config/config.go index dfa8a79..85b284b 100644 --- a/internal/config/config.go +++ b/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) } diff --git a/internal/config/config.pb.go b/internal/config/config.pb.go index e37e6c0..e7a6c5e 100644 --- a/internal/config/config.pb.go +++ b/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 - 0x1f, 0x8b, 0x08, 0x00, 0x00, 0x09, 0x6e, 0x88, 0x02, 0xff, 0x6c, 0x91, 0x41, 0x4e, 0xeb, 0x30, - 0x10, 0x86, 0xd5, 0x97, 0x47, 0x9a, 0x9a, 0x02, 0xad, 0x05, 0xc2, 0xb0, 0x2a, 0x6c, 0x40, 0x42, - 0xb0, 0x41, 0x88, 0x75, 0x68, 0xb6, 0x6c, 0xda, 0x03, 0x58, 0x4e, 0xec, 0xa4, 0x23, 0xd5, 0x76, - 0x64, 0x1b, 0x54, 0xb8, 0x14, 0x57, 0x64, 0xe2, 0x42, 0x8a, 0x04, 0xcb, 0xf9, 0xfe, 0x6f, 0xec, - 0xf1, 0x98, 0x8c, 0x2b, 0x6b, 0x6a, 0x68, 0xee, 0x5a, 0x67, 0x83, 0xbd, 0xfc, 0x48, 0x48, 0x3a, - 0x8f, 0x80, 0x9e, 0x93, 0x6c, 0x65, 0x7d, 0x30, 0x42, 0x2b, 0x36, 0x98, 0x0d, 0xae, 0x47, 0x8b, - 0xbe, 0xa6, 0x57, 0x64, 0xa2, 0xc5, 0x86, 0x4b, 0x11, 0x04, 0xf7, 0xf0, 0xae, 0xb8, 0x2e, 0xd9, - 0x3f, 0x74, 0x92, 0xc5, 0x01, 0xf2, 0x02, 0xf1, 0x12, 0xe9, 0x73, 0x49, 0x2f, 0xc8, 0xd8, 0xeb, - 0xd0, 0x72, 0x21, 0xa5, 0x53, 0xde, 0xb3, 0x64, 0x96, 0xe0, 0x41, 0xfb, 0x1d, 0xcb, 0xb7, 0x88, - 0xde, 0x12, 0xea, 0x5f, 0x4a, 0x0d, 0xde, 0x83, 0x35, 0xbd, 0xf8, 0x3f, 0x8a, 0xd3, 0x5d, 0xf2, - 0x43, 0xd7, 0xd6, 0x40, 0xb0, 0x0e, 0x4c, 0xd3, 0xeb, 0x7b, 0x71, 0xc0, 0xe9, 0x2e, 0xf9, 0xd6, - 0x1f, 0xc8, 0xa9, 0x16, 0xb0, 0xe6, 0x52, 0xad, 0xe1, 0x55, 0xb9, 0x37, 0x2e, 0x1a, 0x65, 0x02, - 0x2f, 0xc1, 0xb0, 0x34, 0xf6, 0x1c, 0x77, 0x71, 0xf1, 0x95, 0xe6, 0x5d, 0xf8, 0x04, 0x86, 0x3e, - 0x12, 0xf6, 0x57, 0x9b, 0x70, 0x8d, 0x67, 0xc3, 0x38, 0xda, 0xc9, 0xaf, 0xbe, 0x1c, 0x43, 0x7a, - 0x46, 0xb2, 0xb8, 0x15, 0x09, 0x8e, 0x65, 0xf1, 0x82, 0x61, 0x57, 0x17, 0xe0, 0xe8, 0x0d, 0xc1, - 0xe7, 0xd4, 0x35, 0x6c, 0xb8, 0x57, 0xad, 0x70, 0x02, 0x07, 0xf5, 0x6c, 0x14, 0x9d, 0xc9, 0x36, - 0x58, 0xf6, 0x1c, 0x37, 0x7c, 0x24, 0x9d, 0x6d, 0x79, 0xb5, 0x42, 0x52, 0x05, 0x85, 0x2a, 0x89, - 0xea, 0x61, 0x87, 0xe7, 0x3d, 0x2d, 0xd3, 0xf8, 0x71, 0xf7, 0x9f, 0x01, 0x00, 0x00, 0xff, 0xff, - 0xd1, 0x68, 0xa2, 0x22, 0xc8, 0x01, 0x00, 0x00, + // 317 bytes of a gzipped FileDescriptorProto + 0x1f, 0x8b, 0x08, 0x00, 0x00, 0x09, 0x6e, 0x88, 0x02, 0xff, 0x6c, 0x91, 0xdf, 0x4e, 0xc2, 0x30, + 0x14, 0xc6, 0x83, 0x53, 0xfe, 0x14, 0x50, 0x68, 0x34, 0x56, 0xaf, 0x90, 0x1b, 0x4d, 0x8c, 0xde, + 0x18, 0xe3, 0x35, 0xc2, 0xa5, 0x26, 0x06, 0x1e, 0xa0, 0xe9, 0x58, 0x19, 0x27, 0x59, 0xdb, 0xa5, + 0xad, 0x06, 0x7d, 0x4d, 0x5f, 0xc8, 0xb3, 0x83, 0x0e, 0x13, 0xbd, 0x3c, 0xbf, 0xef, 0x77, 0xb6, + 0x6f, 0x67, 0xac, 0xb7, 0x74, 0x76, 0x05, 0xf9, 0x6d, 0xe9, 0x5d, 0x74, 0xe3, 0xcf, 0x84, 0x35, + 0xa7, 0x04, 0xf8, 0x39, 0x6b, 0xaf, 0x5d, 0x88, 0x56, 0x19, 0x2d, 0x1a, 0xa3, 0xc6, 0x55, 0x67, + 0x5e, 0xcf, 0xfc, 0x92, 0x0d, 0x8c, 0xda, 0xc8, 0x4c, 0x45, 0x25, 0x03, 0x7c, 0x68, 0x69, 0x52, + 0xb1, 0x87, 0x4e, 0x32, 0xef, 0x23, 0x9f, 0x21, 0x5e, 0x20, 0x7d, 0x4e, 0xf9, 0x05, 0xeb, 0x05, + 0x13, 0x4b, 0xa9, 0xb2, 0xcc, 0xeb, 0x10, 0x44, 0x32, 0x4a, 0xf0, 0x41, 0xdd, 0x8a, 0x4d, 0xb6, + 0x88, 0xdf, 0x30, 0x1e, 0x5e, 0x53, 0x03, 0x21, 0x80, 0xb3, 0xb5, 0xb8, 0x4f, 0xe2, 0x70, 0x97, + 0xfc, 0xd2, 0x8d, 0xb3, 0x10, 0x9d, 0x07, 0x9b, 0xd7, 0xfa, 0x01, 0x15, 0x1c, 0xee, 0x92, 0x1f, + 0xfd, 0x9e, 0x9d, 0x1a, 0x05, 0x85, 0xcc, 0x74, 0x01, 0x6f, 0xda, 0xbf, 0x4b, 0x95, 0x6b, 0x1b, + 0x65, 0x0a, 0x56, 0x34, 0x69, 0xe7, 0xb8, 0x8a, 0x67, 0xdf, 0xe9, 0xa4, 0x0a, 0x1f, 0xc1, 0xf2, + 0x07, 0x26, 0xfe, 0x5b, 0x53, 0x3e, 0x0f, 0xa2, 0x45, 0xd5, 0x4e, 0xfe, 0xec, 0x4d, 0x30, 0xe4, + 0x67, 0xac, 0x4d, 0x57, 0xc9, 0xc0, 0x8b, 0x36, 0xbd, 0xa0, 0x55, 0xcd, 0x33, 0xf0, 0xfc, 0x9a, + 0xe1, 0xe7, 0xac, 0x56, 0xb0, 0x91, 0x41, 0x97, 0xca, 0x2b, 0x2c, 0x1a, 0x44, 0x87, 0x9c, 0xc1, + 0x36, 0x58, 0xd4, 0x1c, 0x2f, 0x7c, 0x94, 0x79, 0x57, 0xca, 0xe5, 0x1a, 0xc9, 0x32, 0x6a, 0x54, + 0x19, 0xa9, 0x87, 0x15, 0x9e, 0xd6, 0x94, 0x8f, 0x59, 0x9f, 0x9a, 0x16, 0x2e, 0x97, 0xa5, 0x8a, + 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, } diff --git a/internal/config/config.proto b/internal/config/config.proto index 601302a..bedaba9 100644 --- a/internal/config/config.proto +++ b/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; } diff --git a/internal/maillog/maillog.go b/internal/maillog/maillog.go new file mode 100644 index 0000000..4632793 --- /dev/null +++ b/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) +} diff --git a/internal/maillog/maillog_test.go b/internal/maillog/maillog_test.go new file mode 100644 index 0000000..e8256b6 --- /dev/null +++ b/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() +} diff --git a/internal/queue/queue.go b/internal/queue/queue.go index eb74266..d598d93 100644 --- a/internal/queue/queue.go +++ b/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() diff --git a/internal/smtpsrv/conn.go b/internal/smtpsrv/conn.go index 7bac16f..23e6b08 100644 --- a/internal/smtpsrv/conn.go +++ b/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", - c.conn.RemoteAddr().String(), user, domain) + maillog.Auth(c.conn.RemoteAddr(), user+"@"+domain, true) return 235, "" } - authLog.Debugf("%s failed for %s@%s", - c.conn.RemoteAddr().String(), user, domain) + maillog.Auth(c.conn.RemoteAddr(), user+"@"+domain, false) return 535, "Incorrect user or password" } diff --git a/internal/smtpsrv/server.go b/internal/smtpsrv/server.go index 60fb008..c366b70 100644 --- a/internal/smtpsrv/server.go +++ b/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) } } diff --git a/test/t-01-simple_local/config/chasquid.conf b/test/t-01-simple_local/config/chasquid.conf index a805eae..2da8942 100644 --- a/test/t-01-simple_local/config/chasquid.conf +++ b/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" diff --git a/test/t-02-exim/config/chasquid.conf b/test/t-02-exim/config/chasquid.conf index a805eae..2da8942 100644 --- a/test/t-02-exim/config/chasquid.conf +++ b/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" diff --git a/test/t-03-queue_persistency/config/chasquid.conf b/test/t-03-queue_persistency/config/chasquid.conf index a805eae..2da8942 100644 --- a/test/t-03-queue_persistency/config/chasquid.conf +++ b/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" diff --git a/test/t-04-aliases/config/chasquid.conf b/test/t-04-aliases/config/chasquid.conf index 9ee5fef..bb91f39 100644 --- a/test/t-04-aliases/config/chasquid.conf +++ b/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: "._" diff --git a/test/t-05-null_address/config/chasquid.conf b/test/t-05-null_address/config/chasquid.conf index f994c10..b3011f9 100644 --- a/test/t-05-null_address/config/chasquid.conf +++ b/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: "._" diff --git a/test/t-06-idna/A/chasquid.conf b/test/t-06-idna/A/chasquid.conf index 2b10846..6f0db35 100644 --- a/test/t-06-idna/A/chasquid.conf +++ b/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" diff --git a/test/t-06-idna/B/chasquid.conf b/test/t-06-idna/B/chasquid.conf index 0c73544..ef7a0da 100644 --- a/test/t-06-idna/B/chasquid.conf +++ b/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" diff --git a/test/t-07-smtputf8/config/chasquid.conf b/test/t-07-smtputf8/config/chasquid.conf index a805eae..2da8942 100644 --- a/test/t-07-smtputf8/config/chasquid.conf +++ 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" diff --git a/test/t-09-loop/A/chasquid.conf b/test/t-09-loop/A/chasquid.conf index 2b10846..6f0db35 100644 --- a/test/t-09-loop/A/chasquid.conf +++ b/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" diff --git a/test/t-09-loop/B/chasquid.conf b/test/t-09-loop/B/chasquid.conf index 0c73544..ef7a0da 100644 --- a/test/t-09-loop/B/chasquid.conf +++ b/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" diff --git a/test/t-10-hooks/config/chasquid.conf b/test/t-10-hooks/config/chasquid.conf index a805eae..2da8942 100644 --- a/test/t-10-hooks/config/chasquid.conf +++ 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"