serv/mox
1
0
Fork 0
mirror of https://github.com/mjl-/mox.git synced 2024-12-26 08:23:48 +03:00
Code Issues Projects Releases Packages Wiki Activity Actions 1

add two new log levels for tracing sensitive auth protocol messages, and bulk data messages

Browse source 
named "traceauth" and "tracedata".

with this, you can (almost) enable trace logging without fear of logging
sensitive data or ddos'ing your log server.

the caveat is that the imap login command has already printed the line as
regular trace before we can decide it should not be. can be fixed soon.
This commit is contained in:
Mechiel Lukkien 2023-02-03 20:33:19 +01:00
parent ae60cdac7e
commit ffb2a10a4e
No known key found for this signature in database
10 changed files with 173 additions and 61 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
config/config.go
View file

@ -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.<domain>"`
HostnameDomain dns.Domain `sconf:"-" json:"-"` // Parsed form of hostname.

6
config/doc.go
View file

@ -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,

2
doc.go
View file

@ -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]]

4
imapserver/pack.go
View file

@ -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)

48
imapserver/server.go
View file

@ -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))

2
main.go
View file

@ -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 {

74
mlog/log.go
View file

@ -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 {

30
moxio/trace.go
View file

@ -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
}

29
smtpclient/client.go
View file

@ -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)

37
smtpserver/server.go
View file

@ -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