diff --git a/config/config.go b/config/config.go index 764c8a2..43bbe50 100644 --- a/config/config.go +++ b/config/config.go @@ -29,7 +29,7 @@ func Port(port, fallback int) int { // into a mox.Config after additional processing. type Static struct { DataDir string `sconf-doc:"Directory where all data is stored, e.g. queue, accounts and messages, ACME TLS certs/keys. If this is a relative path, it is relative to the directory of mox.conf."` - LogLevel string `sconf-doc:"Default log level, one of: error, info, debug, trace. Trace logs full SMTP and IMAP protocol transcripts, which can be a large amount of data."` + LogLevel string `sconf-doc:"Default log level, one of: error, info, debug, trace, traceauth, tracedata. Trace logs SMTP and IMAP protocol transcripts, with traceauth also messages with passwords, and tracedata on top of that also the full data exchanges (full messages), which can be a large amount of data."` PackageLogLevels map[string]string `sconf:"optional" sconf-doc:"Overrides of log level per package (e.g. queue, smtpclient, smtpserver, imapserver, spf, dkim, dmarc, dmarcdb, autotls, junk, mtasts, tlsrpt)."` Hostname string `sconf-doc:"Full hostname of system, e.g. mail."` HostnameDomain dns.Domain `sconf:"-" json:"-"` // Parsed form of hostname. diff --git a/config/doc.go b/config/doc.go index 2c33f7c..e725101 100644 --- a/config/doc.go +++ b/config/doc.go @@ -13,8 +13,10 @@ describe-static" and "mox config describe-domains": # mox.conf. DataDir: - # Default log level, one of: error, info, debug, trace. Trace logs full SMTP and - # IMAP protocol transcripts, which can be a large amount of data. + # Default log level, one of: error, info, debug, trace, traceauth, tracedata. + # Trace logs SMTP and IMAP protocol transcripts, with traceauth also messages with + # passwords, and tracedata on top of that also the full data exchanges (full + # messages), which can be a large amount of data. LogLevel: # Overrides of log level per package (e.g. queue, smtpclient, smtpserver, diff --git a/doc.go b/doc.go index d9ba99e..ac17d41 100644 --- a/doc.go +++ b/doc.go @@ -144,7 +144,7 @@ By default, a single log level applies to all logging in mox. But for each smtpserver, smtpclient, queue, imapserver, spf, dkim, dmarc, junk, message, etc. -Valid labels: error, info, debug, trace. +Valid labels: error, info, debug, trace, traceauth, tracedata. usage: mox loglevels [level [pkg]] diff --git a/imapserver/pack.go b/imapserver/pack.go index beb0575..bdcd77e 100644 --- a/imapserver/pack.go +++ b/imapserver/pack.go @@ -3,6 +3,8 @@ package imapserver import ( "fmt" "io" + + "github.com/mjl-/mox/mlog" ) type token interface { @@ -107,6 +109,7 @@ func (t readerSizeSyncliteral) pack(c *conn) string { func (t readerSizeSyncliteral) writeTo(c *conn, w io.Writer) { fmt.Fprintf(w, "{%d}\r\n", t.size) + defer c.xtrace(mlog.LevelTracedata)() if _, err := io.Copy(w, io.LimitReader(t.r, t.size)); err != nil { panic(err) } @@ -131,6 +134,7 @@ func (t readerSyncliteral) writeTo(c *conn, w io.Writer) { panic(err) } fmt.Fprintf(w, "{%d}\r\n", len(buf)) + defer c.xtrace(mlog.LevelTracedata)() _, err = w.Write(buf) if err != nil { panic(err) diff --git a/imapserver/server.go b/imapserver/server.go index cd379f0..e532759 100644 --- a/imapserver/server.go +++ b/imapserver/server.go @@ -121,13 +121,15 @@ type conn struct { cid int64 state state conn net.Conn - tls bool // Whether TLS has been initialized. - br *bufio.Reader // From remote, with TLS unwrapped in case of TLS. - line chan lineErr // If set, instead of reading from br, a line is read from this channel. For reading a line in IDLE while also waiting for mailbox/account updates. - lastLine string // For detecting if syntax error is fatal, i.e. if this ends with a literal. Without crlf. - bw *bufio.Writer // To remote, with TLS added in case of TLS. - lastlog time.Time // For printing time since previous log line. - tlsConfig *tls.Config // TLS config to use for handshake. + tls bool // Whether TLS has been initialized. + br *bufio.Reader // From remote, with TLS unwrapped in case of TLS. + line chan lineErr // If set, instead of reading from br, a line is read from this channel. For reading a line in IDLE while also waiting for mailbox/account updates. + lastLine string // For detecting if syntax error is fatal, i.e. if this ends with a literal. Without crlf. + bw *bufio.Writer // To remote, with TLS added in case of TLS. + tr *moxio.TraceReader // Kept to change trace level when reading/writing cmd/auth/data. + tw *moxio.TraceWriter + lastlog time.Time // For printing time since previous log line. + tlsConfig *tls.Config // TLS config to use for handshake. noRequireSTARTTLS bool cmd string // Currently executing, for deciding to applyChanges and logging. cmdMetric string // Currently executing, for metrics. @@ -352,6 +354,17 @@ func (c *conn) Write(buf []byte) (int, error) { return n, err } +func (c *conn) xtrace(level mlog.Level) func() { + c.xflush() + c.tr.SetTrace(level) + c.tw.SetTrace(level) + return func() { + c.xflush() + c.tr.SetTrace(mlog.LevelTrace) + c.tw.SetTrace(mlog.LevelTrace) + } +} + // Cache of line buffers for reading commands. var bufpool = moxio.NewBufpool(8, 16*1024) @@ -511,8 +524,10 @@ func serve(listenerName string, cid int64, tlsConfig *tls.Config, nc net.Conn, x } return l }) - c.br = bufio.NewReader(moxio.NewTraceReader(c.log, "C: ", c.conn)) - c.bw = bufio.NewWriter(moxio.NewTraceWriter(c.log, "S: ", c)) + c.tr = moxio.NewTraceReader(c.log, "C: ", c.conn) + c.tw = moxio.NewTraceWriter(c.log, "S: ", c) + c.br = bufio.NewReader(c.tr) + c.bw = bufio.NewWriter(c.tw) // Many IMAP connections use IDLE to wait for new incoming messages. We'll enable // keepalive to get a higher chance of the connection staying alive, or otherwise @@ -1272,8 +1287,10 @@ func (c *conn) cmdStarttls(tag, cmd string, p *parser) { c.log.Debug("tls server handshake done", mlog.Field("tls", tlsversion), mlog.Field("ciphersuite", ciphersuite)) c.conn = tlsConn - c.br = bufio.NewReader(moxio.NewTraceReader(c.log, "C: ", c.conn)) - c.bw = bufio.NewWriter(moxio.NewTraceWriter(c.log, "S: ", c)) + c.tr = moxio.NewTraceReader(c.log, "C: ", c.conn) + c.tw = moxio.NewTraceWriter(c.log, "S: ", c) + c.br = bufio.NewReader(c.tr) + c.bw = bufio.NewWriter(c.tw) c.tls = true } @@ -1344,7 +1361,10 @@ func (c *conn) cmdAuthenticate(tag, cmd string, p *parser) { xusercodeErrorf("PRIVACYREQUIRED", "tls required for login") } + // Plain text passwords, mark as traceauth. + defer c.xtrace(mlog.LevelTraceauth)() buf := xreadInitial() + c.xtrace(mlog.LevelTrace) // Restore. plain := bytes.Split(buf, []byte{0}) if len(plain) != 3 { xsyntaxErrorf("bad plain auth data, expected 3 nul-separated tokens, got %d tokens", len(plain)) @@ -1374,6 +1394,8 @@ func (c *conn) cmdAuthenticate(tag, cmd string, p *parser) { authVariant = "scram-sha-256" + // No plaintext credentials, we can log these normally. + c0 := xreadInitial() ss, err := scram.NewServer(c0) if err != nil { @@ -1454,6 +1476,8 @@ func (c *conn) cmdLogin(tag, cmd string, p *parser) { metrics.AuthenticationInc("imap", "login", authResult) }() + // todo: get this line logged with traceauth. the plaintext password is included on the command line, which we've already read (before dispatching to this function). + // Request syntax: ../rfc/9051:6667 ../rfc/3501:4804 p.xspace() userid := p.xastring() @@ -2239,8 +2263,10 @@ func (c *conn) cmdAppend(tag, cmd string, p *parser) { c.xsanity(err, "closing APPEND temporary file") } }() + defer c.xtrace(mlog.LevelTracedata)() mw := &message.Writer{Writer: msgFile} msize, err := io.Copy(mw, io.LimitReader(c.br, size)) + c.xtrace(mlog.LevelTrace) // Restore. if err != nil { // Cannot use xcheckf due to %w handling of errIO. panic(fmt.Errorf("reading literal message: %s (%w)", err, errIO)) diff --git a/main.go b/main.go index 2f4a8a0..0a2d275 100644 --- a/main.go +++ b/main.go @@ -745,7 +745,7 @@ By default, a single log level applies to all logging in mox. But for each smtpserver, smtpclient, queue, imapserver, spf, dkim, dmarc, junk, message, etc. -Valid labels: error, info, debug, trace. +Valid labels: error, info, debug, trace, traceauth, tracedata. ` args := c.Parse() if len(args) > 2 { diff --git a/mlog/log.go b/mlog/log.go index 10f2b2b..49d5eb5 100644 --- a/mlog/log.go +++ b/mlog/log.go @@ -39,30 +39,36 @@ var Logfmt bool type Level int var LevelStrings = map[Level]string{ - LevelPrint: "print", - LevelFatal: "fatal", - LevelError: "error", - LevelInfo: "info", - LevelDebug: "debug", - LevelTrace: "trace", + LevelPrint: "print", + LevelFatal: "fatal", + LevelError: "error", + LevelInfo: "info", + LevelDebug: "debug", + LevelTrace: "trace", + LevelTraceauth: "traceauth", + LevelTracedata: "tracedata", } var Levels = map[string]Level{ - "print": LevelPrint, - "fatal": LevelFatal, - "error": LevelError, - "info": LevelInfo, - "debug": LevelDebug, - "trace": LevelTrace, + "print": LevelPrint, + "fatal": LevelFatal, + "error": LevelError, + "info": LevelInfo, + "debug": LevelDebug, + "trace": LevelTrace, + "traceauth": LevelTraceauth, + "tracedata": LevelTracedata, } const ( - LevelPrint Level = 0 // Printed regardless of configured log level. - LevelFatal Level = 1 // Printed regardless of configured log level. - LevelError Level = 2 - LevelInfo Level = 3 - LevelDebug Level = 4 - LevelTrace Level = 5 + LevelPrint Level = 0 // Printed regardless of configured log level. + LevelFatal Level = 1 // Printed regardless of configured log level. + LevelError Level = 2 + LevelInfo Level = 3 + LevelDebug Level = 4 + LevelTrace Level = 5 + LevelTraceauth Level = 6 + LevelTracedata Level = 7 ) // Holds a map[string]Level, mapping a package (field pkg in logs) to a log level. @@ -144,8 +150,8 @@ func (l *Log) MoreFields(fn func() []Pair) *Log { return &nl } -func (l *Log) Trace(text string) bool { - return l.logx(LevelTrace, nil, text) +func (l *Log) Trace(traceLevel Level, text string) bool { + return l.logx(traceLevel, nil, text) } func (l *Log) Fatal(text string, fields ...Pair) { l.Fatalx(text, nil, fields...) } @@ -181,9 +187,18 @@ func (l *Log) Errorx(text string, err error, fields ...Pair) bool { } func (l *Log) logx(level Level, err error, text string, fields ...Pair) bool { - if !l.match(level) { + if ok, high := l.match(level); ok { + // Nothing. + } else if high >= LevelTrace && level == LevelTraceauth { + text = "***" + } else if high >= LevelTrace && level == LevelTracedata { + text = "..." + } else { return false } + if level > LevelTrace { + level = LevelTrace + } l.plog(level, err, text, fields...) return true } @@ -327,14 +342,15 @@ func (l *Log) plog(level Level, err error, text string, fields ...Pair) { os.Stderr.Write(b.Bytes()) } -func (l *Log) match(level Level) bool { +func (l *Log) match(level Level) (bool, Level) { if level == LevelPrint || level == LevelFatal { - return true + return true, level } cl := config.Load().(map[string]Level) seen := false + var high Level for _, kv := range l.fields { if kv.key != "pkg" { continue @@ -344,16 +360,22 @@ func (l *Log) match(level Level) bool { continue } v, ok := cl[pkg] + if v > high { + high = v + } if ok && v >= level { - return true + return true, high } seen = seen || ok } if seen { - return false + return false, high } v, ok := cl[""] - return ok && v >= level + if v > high { + high = v + } + return ok && v >= level, v } type errWriter struct { diff --git a/moxio/trace.go b/moxio/trace.go index cdd0d1d..7bb6941 100644 --- a/moxio/trace.go +++ b/moxio/trace.go @@ -6,43 +6,53 @@ import ( "github.com/mjl-/mox/mlog" ) -type writer struct { +type TraceWriter struct { log *mlog.Log prefix string w io.Writer + level mlog.Level } // NewTraceWriter wraps "w" into a writer that logs all writes to "log" with // log level trace, prefixed with "prefix". -func NewTraceWriter(log *mlog.Log, prefix string, w io.Writer) io.Writer { - return writer{log, prefix, w} +func NewTraceWriter(log *mlog.Log, prefix string, w io.Writer) *TraceWriter { + return &TraceWriter{log, prefix, w, mlog.LevelTrace} } // Write logs a trace line for writing buf to the client, then writes to the // client. -func (w writer) Write(buf []byte) (int, error) { - w.log.Trace(w.prefix + string(buf)) +func (w *TraceWriter) Write(buf []byte) (int, error) { + w.log.Trace(w.level, w.prefix+string(buf)) return w.w.Write(buf) } -type reader struct { +func (w *TraceWriter) SetTrace(level mlog.Level) { + w.level = level +} + +type TraceReader struct { log *mlog.Log prefix string r io.Reader + level mlog.Level } // NewTraceReader wraps reader "r" into a reader that logs all reads to "log" // with log level trace, prefixed with "prefix". -func NewTraceReader(log *mlog.Log, prefix string, r io.Reader) io.Reader { - return reader{log, prefix, r} +func NewTraceReader(log *mlog.Log, prefix string, r io.Reader) *TraceReader { + return &TraceReader{log, prefix, r, mlog.LevelTrace} } // Read does a single Read on its underlying reader, logs data of successful // reads, and returns the data read. -func (r reader) Read(buf []byte) (int, error) { +func (r *TraceReader) Read(buf []byte) (int, error) { n, err := r.r.Read(buf) if n > 0 { - r.log.Trace(r.prefix + string(buf[:n])) + r.log.Trace(r.level, r.prefix+string(buf[:n])) } return n, err } + +func (r *TraceReader) SetTrace(level mlog.Level) { + r.level = level +} diff --git a/smtpclient/client.go b/smtpclient/client.go index 884c66f..722abe0 100644 --- a/smtpclient/client.go +++ b/smtpclient/client.go @@ -79,6 +79,8 @@ type Client struct { r *bufio.Reader w *bufio.Writer + tr *moxio.TraceReader // Kept for changing trace levels between cmd/auth/data. + tw *moxio.TraceWriter log *mlog.Log lastlog time.Time // For adding delta timestamps between log lines. cmds []string // Last or active command, for generating errors and metrics. @@ -183,10 +185,12 @@ func New(ctx context.Context, log *mlog.Log, conn net.Conn, tlsMode TLSMode, rem // We don't wrap reads in a timeoutReader for fear of an optional TLS wrapper doing // reads without the client asking for it. Such reads could result in a timeout // error. - c.r = bufio.NewReader(moxio.NewTraceReader(c.log, "RS: ", c.conn)) + c.tr = moxio.NewTraceReader(c.log, "RS: ", c.conn) + c.r = bufio.NewReader(c.tr) // We use a single write timeout of 30 seconds. // todo future: use different timeouts ../rfc/5321:3610 - c.w = bufio.NewWriter(moxio.NewTraceWriter(c.log, "LC: ", timeoutWriter{c.conn, 30 * time.Second, c.log})) + c.tw = moxio.NewTraceWriter(c.log, "LC: ", timeoutWriter{c.conn, 30 * time.Second, c.log}) + c.w = bufio.NewWriter(c.tw) if err := c.hello(ctx, tlsMode, remoteHostname, auth); err != nil { return nil, err @@ -240,6 +244,17 @@ func (c *Client) xreadline() string { return line } +func (c *Client) xtrace(level mlog.Level) func() { + c.xflush() + c.tr.SetTrace(level) + c.tw.SetTrace(level) + return func() { + c.xflush() + c.tr.SetTrace(mlog.LevelTrace) + c.tw.SetTrace(mlog.LevelTrace) + } +} + func (c *Client) xwritelinef(format string, args ...any) { c.xbwritelinef(format, args...) c.xflush() @@ -496,8 +511,10 @@ func (c *Client) hello(ctx context.Context, tlsMode TLSMode, remoteHostname, aut c.xerrorf(false, 0, "", "", "%w: STARTTLS TLS handshake: %s", ErrTLS, err) } cancel() - c.r = bufio.NewReader(moxio.NewTraceReader(c.log, "RS: ", c.conn)) - c.w = bufio.NewWriter(moxio.NewTraceWriter(c.log, "LC: ", c.conn)) // No need to wrap in timeoutWriter, it would just set the timeout on the underlying connection, which is still active. + c.tr = moxio.NewTraceReader(c.log, "RS: ", c.conn) + c.tw = moxio.NewTraceWriter(c.log, "LC: ", c.conn) // No need to wrap in timeoutWriter, it would just set the timeout on the underlying connection, which is still active. + c.r = bufio.NewReader(c.tr) + c.w = bufio.NewWriter(c.tw) tlsversion, ciphersuite := mox.TLSInfo(nconn) c.log.Debug("tls client handshake done", mlog.Field("tls", tlsversion), mlog.Field("ciphersuite", ciphersuite)) @@ -509,7 +526,9 @@ func (c *Client) hello(ctx context.Context, tlsMode TLSMode, remoteHostname, aut // No metrics, only used for tests. c.cmds[0] = "auth" c.cmdStart = time.Now() + defer c.xtrace(mlog.LevelTraceauth)() c.xwriteline(auth) + c.xtrace(mlog.LevelTrace) // Restore. code, secode, lastLine, _ := c.xread() if code != smtp.C235AuthSuccess { c.xerrorf(code/100 == 5, code, secode, lastLine, "%w: auth: got %d, expected 2xx", ErrStatus, code) @@ -652,11 +671,13 @@ func (c *Client) Deliver(ctx context.Context, mailFrom string, rcptTo string, ms // For a DATA write, the suggested timeout is 3 minutes, we use 30 seconds for all // writes through timeoutWriter. ../rfc/5321:3651 + defer c.xtrace(mlog.LevelTracedata)() err := smtp.DataWrite(c.w, msg) if err != nil { c.xbotchf(0, "", "", "writing message as smtp data: %w", err) } c.xflush() + c.xtrace(mlog.LevelTrace) // Restore. code, secode, lastline, _ := c.xread() if code != smtp.C250Completed { c.xerrorf(code/100 == 5, code, secode, lastline, "%w: got %d, expected 2xx", ErrStatus, code) diff --git a/smtpserver/server.go b/smtpserver/server.go index 1e3e2d0..8ffa5f9 100644 --- a/smtpserver/server.go +++ b/smtpserver/server.go @@ -203,6 +203,8 @@ type conn struct { resolver dns.Resolver r *bufio.Reader w *bufio.Writer + tr *moxio.TraceReader // Kept for changing trace level during cmd/auth/data. + tw *moxio.TraceWriter lastlog time.Time // Used for printing the delta time since the previous logging for this connection. submission bool // ../rfc/6409:19 applies tlsConfig *tls.Config @@ -292,6 +294,17 @@ func (c *conn) xcheckAuth() { } } +func (c *conn) xtrace(level mlog.Level) func() { + c.xflush() + c.tr.SetTrace(level) + c.tw.SetTrace(level) + return func() { + c.xflush() + c.tr.SetTrace(mlog.LevelTrace) + c.tw.SetTrace(mlog.LevelTrace) + } +} + // Write writes to the connection. It panics on i/o errors, which is handled by the // connection command loop. func (c *conn) Write(buf []byte) (int, error) { @@ -447,8 +460,10 @@ func serve(listenerName string, cid int64, hostname dns.Domain, tlsConfig *tls.C } return l }) - c.r = bufio.NewReader(moxio.NewTraceReader(c.log, "RC: ", c)) - c.w = bufio.NewWriter(moxio.NewTraceWriter(c.log, "LS: ", c)) + c.tr = moxio.NewTraceReader(c.log, "RC: ", c) + c.tw = moxio.NewTraceWriter(c.log, "LS: ", c) + c.r = bufio.NewReader(c.tr) + c.w = bufio.NewWriter(c.tw) metricConnection.WithLabelValues(c.kind()).Inc() c.log.Info("new connection", mlog.Field("remote", c.conn.RemoteAddr()), mlog.Field("local", c.conn.LocalAddr()), mlog.Field("submission", submission), mlog.Field("tls", tls), mlog.Field("listener", listenerName)) @@ -714,8 +729,10 @@ func (c *conn) cmdStarttls(p *parser) { tlsversion, ciphersuite := mox.TLSInfo(tlsConn) c.log.Debug("tls server handshake done", mlog.Field("tls", tlsversion), mlog.Field("ciphersuite", ciphersuite)) c.conn = tlsConn - c.r = bufio.NewReader(moxio.NewTraceReader(c.log, "RC: ", c)) - c.w = bufio.NewWriter(moxio.NewTraceWriter(c.log, "LS: ", c)) + c.tr = moxio.NewTraceReader(c.log, "RC: ", c) + c.tw = moxio.NewTraceWriter(c.log, "LS: ", c) + c.r = bufio.NewReader(c.tr) + c.w = bufio.NewWriter(c.tw) c.reset() // ../rfc/3207:210 c.tls = true @@ -814,7 +831,10 @@ func (c *conn) cmdAuth(p *parser) { xsmtpUserErrorf(smtp.C538EncReqForAuth, smtp.SePol7EncReqForAuth11, "authentication requires tls") } + // Password is in line in plain text, so hide it. + defer c.xtrace(mlog.LevelTraceauth)() buf := xreadInitial() + c.xtrace(mlog.LevelTrace) // Restore. plain := bytes.Split(buf, []byte{0}) if len(plain) != 3 { xsmtpUserErrorf(smtp.C501BadParamSyntax, smtp.SeProto5BadParams4, "auth data should have 3 nul-separated tokens, got %d", len(plain)) @@ -847,6 +867,8 @@ func (c *conn) cmdAuth(p *parser) { authVariant = "scram-sha-256" + // Passwords cannot be retrieved or replayed from the trace. + c0 := xreadInitial() ss, err := scram.NewServer(c0) xcheckf(err, "starting scram") @@ -1208,6 +1230,9 @@ func (c *conn) cmdData(p *parser) { // ../rfc/5321:1994 c.writelinef("354 see you at the bare dot") + // Mark as tracedata. + defer c.xtrace(mlog.LevelTracedata)() + // We read the data into a temporary file. We limit the size and do basic analysis while reading. dataFile, err := store.CreateMessageTemp("smtp-deliver") if err != nil { @@ -1223,7 +1248,9 @@ func (c *conn) cmdData(p *parser) { }() msgWriter := &message.Writer{Writer: dataFile} dr := smtp.NewDataReader(c.r) - if n, err := io.Copy(&limitWriter{maxSize: c.maxMessageSize, w: msgWriter}, dr); err != nil { + n, err := io.Copy(&limitWriter{maxSize: c.maxMessageSize, w: msgWriter}, dr) + c.xtrace(mlog.LevelTrace) // Restore. + if err != nil { if errors.Is(err, errMessageTooLarge) { // ../rfc/1870:136 and ../rfc/3463:382 ecode := smtp.SeSys3MsgLimitExceeded4