1// Package mlog providers helpers on top of slog.Logger.
2//
3// Packages of mox that are fit or use by external code take an *slog.Logger as
4// parameter for logging. Internally, and packages not intended for reuse,
5// logging is done with mlog.Log. It providers convenience functions for:
6// logging error values, tracing (protocol messages), uncoditional printing
7// optionally exiting.
8//
9// An mlog provides a handler for an mlog.Log for formatting log lines. Lines are
10// logged as "logfmt" lines for "mox serve". For command-line tools, the lines are
11// printed with colon-separated level, message and error, followed by
12// semicolon-separated attributes.
13package mlog
14
15import (
16 "bytes"
17 "context"
18 "encoding/base64"
19 "fmt"
20 "io"
21 "log/slog"
22 "os"
23 "reflect"
24 "strconv"
25 "strings"
26 "sync/atomic"
27 "time"
28)
29
30var noctx = context.Background()
31
32// Logfmt enabled output in logfmt, instead of output more suitable for
33// command-line tools. Must be set early in a program lifecycle.
34var Logfmt bool
35
36// LogStringer is used when formatting field values during logging. If a value
37// implements it, LogString is called for the value to log.
38type LogStringer interface {
39 LogString() string
40}
41
42var lowestLevel atomic.Int32 // For quick initial check.
43var config atomic.Pointer[map[string]slog.Level] // For secondary complete check for match.
44
45func init() {
46 SetConfig(map[string]slog.Level{"": LevelInfo})
47}
48
49// SetConfig atomically sets the new log levels used by all Log instances.
50func SetConfig(c map[string]slog.Level) {
51 lowest := c[""]
52 for _, l := range c {
53 if l < lowest {
54 lowest = l
55 }
56 }
57 lowestLevel.Store(int32(lowest))
58 config.Store(&c)
59}
60
61var (
62 // When the configured log level is any of the Trace levels, all protocol messages
63 // are printed. But protocol "data" (like an email message in the SMTP DATA
64 // command) is replaced with "..." unless the configured level is LevelTracedata.
65 // Likewise, protocol messages with authentication data (e.g. plaintext base64
66 // passwords) are replaced with "***" unless the configured level is LevelTraceauth
67 // or LevelTracedata.
68 LevelTracedata = slog.LevelDebug - 8
69 LevelTraceauth = slog.LevelDebug - 6
70 LevelTrace = slog.LevelDebug - 4
71 LevelDebug = slog.LevelDebug
72 LevelInfo = slog.LevelInfo
73 LevelWarn = slog.LevelWarn
74 LevelError = slog.LevelError
75 LevelFatal = slog.LevelError + 4 // Printed regardless of configured log level.
76 LevelPrint = slog.LevelError + 8 // Printed regardless of configured log level.
77)
78
79// Levelstrings map log levels to human-readable names.
80var LevelStrings = map[slog.Level]string{
81 LevelTracedata: "tracedata",
82 LevelTraceauth: "traceauth",
83 LevelTrace: "trace",
84 LevelDebug: "debug",
85 LevelInfo: "info",
86 LevelWarn: "warn",
87 LevelError: "error",
88 LevelFatal: "fatal",
89 LevelPrint: "print",
90}
91
92// Levels map the human-readable log level to a level.
93var Levels = map[string]slog.Level{
94 "tracedata": LevelTracedata,
95 "traceauth": LevelTraceauth,
96 "trace": LevelTrace,
97 "debug": LevelDebug,
98 "info": LevelInfo,
99 "warn": LevelWarn,
100 "error": LevelError,
101 "fatal": LevelFatal,
102 "print": LevelPrint,
103}
104
105// Log wraps an slog.Logger, providing convenience functions.
106type Log struct {
107 *slog.Logger
108}
109
110// New returns a Log that adds a "pkg" attribute. If logger is nil, a new
111// Logger is created with a custom handler.
112func New(pkg string, logger *slog.Logger) Log {
113 if logger == nil {
114 logger = slog.New(&handler{})
115 }
116 return Log{logger}.WithPkg(pkg)
117}
118
119// WithCid adds a attribute "cid".
120// Also see WithContext.
121func (l Log) WithCid(cid int64) Log {
122 return l.With(slog.Int64("cid", cid))
123}
124
125type key string
126
127// CidKey can be used with context.WithValue to store a "cid" in a context, for logging.
128var CidKey key = "cid"
129
130// WithContext adds cid from context, if present. Context are often passed to
131// functions, especially between packages, to pass a "cid" for an operation. At the
132// start of a function (especially if exported) a variable "log" is often
133// instantiated from a package-level logger, with WithContext for its cid.
134// Ideally, a Log could be passed instead, but contexts are more pervasive. For the same
135// reason WithContext is more common than WithCid.
136func (l Log) WithContext(ctx context.Context) Log {
137 cidv := ctx.Value(CidKey)
138 if cidv == nil {
139 return l
140 }
141 cid := cidv.(int64)
142 return l.WithCid(cid)
143}
144
145// With adds attributes to to each logged line.
146func (l Log) With(attrs ...slog.Attr) Log {
147 return Log{slog.New(l.Logger.Handler().WithAttrs(attrs))}
148}
149
150// WithPkg ensures pkg is added as attribute to logged lines. If the handler is
151// an mlog handler, pkg is only added if not already the last added package.
152func (l Log) WithPkg(pkg string) Log {
153 h := l.Logger.Handler()
154 if ph, ok := h.(*handler); ok {
155 if len(ph.Pkgs) > 0 && ph.Pkgs[len(ph.Pkgs)-1] == pkg {
156 return l
157 }
158 return Log{slog.New(ph.WithPkg(pkg))}
159 }
160 return Log{slog.New(h.WithAttrs([]slog.Attr{slog.String("pkg", pkg)}))}
161}
162
163// WithFunc sets fn to be called for additional attributes. Fn is only called
164// when the line is logged.
165// If the underlying handler is not an mlog.handler, this method has no effect.
166// Caller must take care of preventing data races.
167func (l Log) WithFunc(fn func() []slog.Attr) Log {
168 h := l.Logger.Handler()
169 if ph, ok := h.(*handler); ok {
170 return Log{slog.New(ph.WithFunc(fn))}
171 }
172 // Ignored for other handlers, only used internally (smtpserver, imapserver).
173 return l
174}
175
176// Check logs an error if err is not nil. Intended for logging errors that are good
177// to know, but would not influence program flow.
178func (l Log) Check(err error, msg string, attrs ...slog.Attr) {
179 if err != nil {
180 l.Errorx(msg, err, attrs...)
181 }
182}
183
184func errAttr(err error) slog.Attr {
185 return slog.Any("err", err)
186}
187
188// todo: consider taking a context parameter. it would require all code be refactored. we may want to do this if callers really depend on passing attrs through context. the mox code base does not do that. it makes all call sites more tedious, and requires passing around ctx everywhere, so consider carefully.
189
190func (l Log) Debug(msg string, attrs ...slog.Attr) {
191 l.Logger.LogAttrs(noctx, LevelDebug, msg, attrs...)
192}
193
194func (l Log) Debugx(msg string, err error, attrs ...slog.Attr) {
195 if err != nil {
196 attrs = append([]slog.Attr{errAttr(err)}, attrs...)
197 }
198 l.Logger.LogAttrs(noctx, LevelDebug, msg, attrs...)
199}
200
201func (l Log) Info(msg string, attrs ...slog.Attr) {
202 l.Logger.LogAttrs(noctx, LevelInfo, msg, attrs...)
203}
204
205func (l Log) Infox(msg string, err error, attrs ...slog.Attr) {
206 if err != nil {
207 attrs = append([]slog.Attr{errAttr(err)}, attrs...)
208 }
209 l.Logger.LogAttrs(noctx, LevelInfo, msg, attrs...)
210}
211
212func (l Log) Warn(msg string, attrs ...slog.Attr) {
213 l.Logger.LogAttrs(noctx, LevelWarn, msg, attrs...)
214}
215
216func (l Log) Warnx(msg string, err error, attrs ...slog.Attr) {
217 if err != nil {
218 attrs = append([]slog.Attr{errAttr(err)}, attrs...)
219 }
220 l.Logger.LogAttrs(noctx, LevelWarn, msg, attrs...)
221}
222
223func (l Log) Error(msg string, attrs ...slog.Attr) {
224 l.Logger.LogAttrs(noctx, LevelError, msg, attrs...)
225}
226
227func (l Log) Errorx(msg string, err error, attrs ...slog.Attr) {
228 if err != nil {
229 attrs = append([]slog.Attr{errAttr(err)}, attrs...)
230 }
231 l.Logger.LogAttrs(noctx, LevelError, msg, attrs...)
232}
233
234func (l Log) Fatal(msg string, attrs ...slog.Attr) {
235 l.Logger.LogAttrs(noctx, LevelFatal, msg, attrs...)
236 os.Exit(1)
237}
238
239func (l Log) Fatalx(msg string, err error, attrs ...slog.Attr) {
240 if err != nil {
241 attrs = append([]slog.Attr{errAttr(err)}, attrs...)
242 }
243 l.Logger.LogAttrs(noctx, LevelFatal, msg, attrs...)
244 os.Exit(1)
245}
246
247func (l Log) Print(msg string, attrs ...slog.Attr) {
248 l.Logger.LogAttrs(noctx, LevelPrint, msg, attrs...)
249}
250
251func (l Log) Printx(msg string, err error, attrs ...slog.Attr) {
252 if err != nil {
253 attrs = append([]slog.Attr{errAttr(err)}, attrs...)
254 }
255 l.Logger.LogAttrs(noctx, LevelPrint, msg, attrs...)
256}
257
258// Trace logs at trace/traceauth/tracedata level.
259// If the active log level is any of the trace levels, the data is logged.
260// If level is for tracedata, but the active level doesn't trace data, data is replaced with "...".
261// If level is for traceauth, but the active level doesn't trace auth, data is replaced with "***".
262func (l Log) Trace(level slog.Level, prefix string, data []byte) {
263 h := l.Handler()
264 if !h.Enabled(noctx, level) {
265 return
266 }
267 ph, ok := h.(*handler)
268 if !ok {
269 msg := prefix + string(data)
270 r := slog.NewRecord(time.Now(), level, msg, 0)
271 h.Handle(noctx, r)
272 return
273 }
274 filterLevel, ok := ph.configMatch(level)
275 if !ok {
276 return
277 }
278
279 var msg string
280 if hideData, hideAuth := traceLevel(filterLevel, level); hideData {
281 msg = prefix + "..."
282 } else if hideAuth {
283 msg = prefix + "***"
284 } else {
285 msg = prefix + string(data)
286 }
287 r := slog.NewRecord(time.Time{}, level, msg, 0)
288 ph.write(filterLevel, r)
289}
290
291func traceLevel(level, recordLevel slog.Level) (hideData, hideAuth bool) {
292 hideData = recordLevel == LevelTracedata && level > LevelTracedata
293 hideAuth = recordLevel == LevelTraceauth && level > LevelTraceauth
294 return
295}
296
297type handler struct {
298 Pkgs []string
299 Attrs []slog.Attr
300 Group string // Empty or with dot-separated names, ending with a dot.
301 Fn func() []slog.Attr // Only called when record is actually being logged.
302}
303
304func match(minLevel, level slog.Level) bool {
305 return level >= LevelFatal || level >= minLevel || minLevel <= LevelTrace && level <= LevelTrace
306}
307
308func (h *handler) Enabled(ctx context.Context, level slog.Level) bool {
309 return match(slog.Level(lowestLevel.Load()), level)
310}
311
312func (h *handler) configMatch(level slog.Level) (slog.Level, bool) {
313 c := *config.Load()
314 for i := len(h.Pkgs) - 1; i >= 0; i-- {
315 if l, ok := c[h.Pkgs[i]]; ok {
316 return l, match(l, level)
317 }
318 }
319 l := c[""]
320 return l, match(l, level)
321}
322
323func (h *handler) Handle(ctx context.Context, r slog.Record) error {
324 l, ok := h.configMatch(r.Level)
325 if !ok {
326 return nil
327 }
328 if hideData, hideAuth := traceLevel(l, r.Level); hideData {
329 r.Message = "..."
330 } else if hideAuth {
331 r.Message = "***"
332 }
333 return h.write(l, r)
334}
335
336// Reuse buffers to format log lines into.
337var logBuffersStore [32][256]byte
338var logBuffers = make(chan []byte, 200)
339
340func init() {
341 for i := range logBuffersStore {
342 logBuffers <- logBuffersStore[i][:]
343 }
344}
345
346// escape logfmt string if required, otherwise return original string.
347func formatString(s string) string {
348 for _, c := range s {
349 if c <= ' ' || c == '"' || c == '\\' || c == '=' || c >= 0x7f {
350 return fmt.Sprintf("%q", s)
351 }
352 }
353 return s
354}
355
356func stringValue(iscid, nested bool, v any) string {
357 // Handle some common types first.
358 if v == nil {
359 return ""
360 }
361 switch r := v.(type) {
362 case string:
363 return r
364 case int:
365 return strconv.Itoa(r)
366 case int64:
367 if iscid {
368 return fmt.Sprintf("%x", v)
369 }
370 return strconv.FormatInt(r, 10)
371 case bool:
372 if r {
373 return "true"
374 }
375 return "false"
376 case float64:
377 return fmt.Sprintf("%v", v)
378 case []byte:
379 return base64.RawURLEncoding.EncodeToString(r)
380 case []string:
381 if nested && len(r) == 0 {
382 // Drop field from logging.
383 return ""
384 }
385 return "[" + strings.Join(r, ",") + "]"
386 case error:
387 return r.Error()
388 case time.Time:
389 return r.Format(time.RFC3339)
390 }
391
392 rv := reflect.ValueOf(v)
393 if rv.Kind() == reflect.Ptr && rv.IsNil() {
394 return ""
395 }
396
397 if r, ok := v.(LogStringer); ok {
398 return r.LogString()
399 }
400 if r, ok := v.(fmt.Stringer); ok {
401 return r.String()
402 }
403
404 if rv.Kind() == reflect.Ptr {
405 rv = rv.Elem()
406 return stringValue(iscid, nested, rv.Interface())
407 }
408 if rv.Kind() == reflect.Slice {
409 n := rv.Len()
410 if nested && n == 0 {
411 // Drop field.
412 return ""
413 }
414 b := &strings.Builder{}
415 b.WriteString("[")
416 for i := 0; i < n; i++ {
417 if i > 0 {
418 b.WriteString(";")
419 }
420 b.WriteString(stringValue(false, true, rv.Index(i).Interface()))
421 }
422 b.WriteString("]")
423 return b.String()
424 } else if rv.Kind() != reflect.Struct {
425 return fmt.Sprintf("%v", v)
426 }
427 n := rv.NumField()
428 t := rv.Type()
429 b := &strings.Builder{}
430 first := true
431 for i := 0; i < n; i++ {
432 fv := rv.Field(i)
433 if !t.Field(i).IsExported() {
434 continue
435 }
436 if fv.Kind() == reflect.Struct || fv.Kind() == reflect.Ptr || fv.Kind() == reflect.Interface {
437 // Don't recurse.
438 continue
439 }
440 vs := stringValue(false, true, fv.Interface())
441 if vs == "" {
442 continue
443 }
444 if !first {
445 b.WriteByte(' ')
446 }
447 first = false
448 k := strings.ToLower(t.Field(i).Name)
449 b.WriteString(k + "=" + vs)
450 }
451 return b.String()
452}
453
454func writeAttr(w io.Writer, separator, group string, a slog.Attr) {
455 switch a.Value.Kind() {
456 case slog.KindGroup:
457 if group != "" {
458 group += "."
459 }
460 group += a.Key
461 for _, a := range a.Value.Group() {
462 writeAttr(w, separator, group, a)
463 }
464 return
465 default:
466 var vv any
467 if a.Value.Kind() == slog.KindLogValuer {
468 vv = a.Value.Resolve().Any()
469 } else {
470 vv = a.Value.Any()
471 }
472 s := stringValue(a.Key == "cid", false, vv)
473 fmt.Fprint(w, separator, group, a.Key, "=", formatString(s))
474 }
475}
476
477func (h *handler) write(l slog.Level, r slog.Record) error {
478 // Reuse a buffer, or temporarily allocate a new one.
479 var buf []byte
480 select {
481 case buf = <-logBuffers:
482 defer func() {
483 logBuffers <- buf
484 }()
485 default:
486 buf = make([]byte, 128)
487 }
488
489 b := bytes.NewBuffer(buf[:0])
490 eb := &errWriter{b, nil}
491
492 if Logfmt {
493 var wrotePkgs bool
494 ensurePkgs := func() {
495 if !wrotePkgs {
496 wrotePkgs = true
497 for _, pkg := range h.Pkgs {
498 writeAttr(eb, " ", "", slog.String("pkg", pkg))
499 }
500 }
501 }
502
503 fmt.Fprint(eb, "l=", LevelStrings[r.Level], " m=")
504 fmt.Fprintf(eb, "%q", r.Message)
505 n := 0
506 r.Attrs(func(a slog.Attr) bool {
507 if n > 0 || a.Key != "err" || h.Group != "" {
508 ensurePkgs()
509 }
510 writeAttr(eb, " ", h.Group, a)
511 n++
512 return true
513 })
514 ensurePkgs()
515 for _, a := range h.Attrs {
516 writeAttr(eb, " ", h.Group, a)
517 }
518 if h.Fn != nil {
519 for _, a := range h.Fn() {
520 writeAttr(eb, " ", h.Group, a)
521 }
522 }
523 fmt.Fprint(eb, "\n")
524 } else {
525 var wrotePkgs bool
526 ensurePkgs := func() {
527 if !wrotePkgs {
528 wrotePkgs = true
529 for _, pkg := range h.Pkgs {
530 writeAttr(eb, "; ", "", slog.String("pkg", pkg))
531 }
532 }
533 }
534
535 fmt.Fprint(eb, LevelStrings[r.Level], ": ", r.Message)
536 n := 0
537 r.Attrs(func(a slog.Attr) bool {
538 if n == 0 && a.Key == "err" && h.Group == "" {
539 fmt.Fprint(eb, ": ", a.Value.String())
540 ensurePkgs()
541 } else {
542 ensurePkgs()
543 writeAttr(eb, "; ", h.Group, a)
544 }
545 n++
546 return true
547 })
548 ensurePkgs()
549 for _, a := range h.Attrs {
550 writeAttr(eb, "; ", h.Group, a)
551 }
552 if h.Fn != nil {
553 for _, a := range h.Fn() {
554 writeAttr(eb, "; ", h.Group, a)
555 n++
556 }
557 }
558 fmt.Fprint(eb, "\n")
559 }
560 if eb.Err != nil {
561 return eb.Err
562 }
563
564 // todo: for mox serve, do writes in separate goroutine.
565 _, err := os.Stderr.Write(b.Bytes())
566 return err
567}
568
569type errWriter struct {
570 Writer *bytes.Buffer
571 Err error
572}
573
574func (w *errWriter) Write(buf []byte) (int, error) {
575 if w.Err != nil {
576 return 0, w.Err
577 }
578 var n int
579 n, w.Err = w.Writer.Write(buf)
580 return n, w.Err
581}
582
583func (h *handler) WithAttrs(attrs []slog.Attr) slog.Handler {
584 nh := *h
585 if h.Attrs != nil {
586 nh.Attrs = append([]slog.Attr{}, h.Attrs...)
587 }
588 nh.Attrs = append(nh.Attrs, attrs...)
589 return &nh
590}
591
592func (h *handler) WithGroup(name string) slog.Handler {
593 if name == "" {
594 return h
595 }
596 nh := *h
597 nh.Group += name + "."
598 return &nh
599}
600
601func (h *handler) WithPkg(pkg string) *handler {
602 nh := *h
603 if nh.Pkgs != nil {
604 nh.Pkgs = append([]string{}, nh.Pkgs...)
605 }
606 nh.Pkgs = append(nh.Pkgs, pkg)
607 return &nh
608}
609
610func (h *handler) WithFunc(fn func() []slog.Attr) *handler {
611 nh := *h
612 nh.Fn = fn
613 return &nh
614}
615
616type logWriter struct {
617 log Log
618 level slog.Level
619 msg string
620}
621
622func (w logWriter) Write(buf []byte) (int, error) {
623 err := strings.TrimSpace(string(buf))
624 w.log.LogAttrs(noctx, w.level, w.msg, slog.String("err", err))
625 return len(buf), nil
626}
627
628// LogWriter returns a writer that turns each write into a logging call on "log"
629// with given "level" and "msg" and the written content as an error.
630// Can be used for making a Go log.Logger for use in http.Server.ErrorLog.
631func LogWriter(log Log, level slog.Level, msg string) io.Writer {
632 return logWriter{log, level, msg}
633}
634