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 "errors"

20 "fmt"

21 "io"

22 "log/slog"

23 "os"

24 "reflect"

25 "strconv"

26 "strings"

27 "sync/atomic"

28 "time"

29

30 "github.com/prometheus/client_golang/prometheus"

31 "github.com/prometheus/client_golang/prometheus/promauto"

32 "slices"

33)

34

35var noctx = context.Background()

36

37var (

38 metricLogInfo = promauto.NewCounter(

39 prometheus.CounterOpts{

40 Name: "mox_logging_level_info_total",

41 Help: "Total number of logging events at level info.",

42 },

43 )

44 metricLogWarn = promauto.NewCounter(

45 prometheus.CounterOpts{

46 Name: "mox_logging_level_warn_total",

47 Help: "Total number of logging events at level warn.",

48 },

49 )

50 metricLogError = promauto.NewCounter(

51 prometheus.CounterOpts{

52 Name: "mox_logging_level_error_total",

53 Help: "Total number of logging events at level error.",

54 },

55 )

56)

57

58// Logfmt enabled output in logfmt, instead of output more suitable for

59// command-line tools. Must be set early in a program lifecycle.

60var Logfmt bool

61

62// LogStringer is used when formatting field values during logging. If a value

63// implements it, LogString is called for the value to log.

64type LogStringer interface {

65 LogString() string

66}

67

68var lowestLevel atomic.Int32 // For quick initial check.

69var config atomic.Pointer[map[string]slog.Level] // For secondary complete check for match.

70

71func init() {

72 SetConfig(map[string]slog.Level{"": LevelDebug})

73}

74

75// SetConfig atomically sets the new log levels used by all Log instances.

76func SetConfig(c map[string]slog.Level) {

77 lowest := c[""]

78 for _, l := range c {

79 if l < lowest {

80 lowest = l

81 }

82 }

83 lowestLevel.Store(int32(lowest))

84 config.Store(&c)

85}

86

87var (

88 // When the configured log level is any of the Trace levels, all protocol messages

89 // are printed. But protocol "data" (like an email message in the SMTP DATA

90 // command) is replaced with "..." unless the configured level is LevelTracedata.

91 // Likewise, protocol messages with authentication data (e.g. plaintext base64

92 // passwords) are replaced with "***" unless the configured level is LevelTraceauth

93 // or LevelTracedata.

94 LevelTracedata = slog.LevelDebug - 8

95 LevelTraceauth = slog.LevelDebug - 6

96 LevelTrace = slog.LevelDebug - 4

97 LevelDebug = slog.LevelDebug

98 LevelInfo = slog.LevelInfo

99 LevelWarn = slog.LevelWarn

100 LevelError = slog.LevelError

101 LevelFatal = slog.LevelError + 4 // Printed regardless of configured log level.

102 LevelPrint = slog.LevelError + 8 // Printed regardless of configured log level.

103)

104

105// Levelstrings map log levels to human-readable names.

106var LevelStrings = map[slog.Level]string{

107 LevelTracedata: "tracedata",

108 LevelTraceauth: "traceauth",

109 LevelTrace: "trace",

110 LevelDebug: "debug",

111 LevelInfo: "info",

112 LevelWarn: "warn",

113 LevelError: "error",

114 LevelFatal: "fatal",

115 LevelPrint: "print",

116}

117

118// Levels map the human-readable log level to a level.

119var Levels = map[string]slog.Level{

120 "tracedata": LevelTracedata,

121 "traceauth": LevelTraceauth,

122 "trace": LevelTrace,

123 "debug": LevelDebug,

124 "info": LevelInfo,

125 "warn": LevelWarn,

126 "error": LevelError,

127 "fatal": LevelFatal,

128 "print": LevelPrint,

129}

130

131// Log wraps an slog.Logger, providing convenience functions.

132type Log struct {

133 *slog.Logger

134}

135

136// New returns a Log that adds a "pkg" attribute. If logger is nil, a new

137// Logger is created with a custom handler.

138func New(pkg string, logger *slog.Logger) Log {

139 if logger == nil {

140 logger = slog.New(&handler{})

141 }

142 return Log{logger}.WithPkg(pkg)

143}

144

145// WithCid adds a attribute "cid".

146// Also see WithContext.

147func (l Log) WithCid(cid int64) Log {

148 return l.With(slog.Int64("cid", cid))

149}

150

151type key string

152

153// CidKey can be used with context.WithValue to store a "cid" in a context, for logging.

154var CidKey key = "cid"

155

156// WithContext adds cid from context, if present. Context are often passed to

157// functions, especially between packages, to pass a "cid" for an operation. At the

158// start of a function (especially if exported) a variable "log" is often

159// instantiated from a package-level logger, with WithContext for its cid.

160// Ideally, a Log could be passed instead, but contexts are more pervasive. For the same

161// reason WithContext is more common than WithCid.

162func (l Log) WithContext(ctx context.Context) Log {

163 cidv := ctx.Value(CidKey)

164 if cidv == nil {

165 return l

166 }

167 cid := cidv.(int64)

168 return l.WithCid(cid)

169}

170

171// With adds attributes to to each logged line.

172func (l Log) With(attrs ...slog.Attr) Log {

173 return Log{slog.New(l.Logger.Handler().WithAttrs(attrs))}

174}

175

176// WithPkg ensures pkg is added as attribute to logged lines. If the handler is

177// an mlog handler, pkg is only added if not already the last added package.

178func (l Log) WithPkg(pkg string) Log {

179 h := l.Logger.Handler()

180 if ph, ok := h.(*handler); ok {

181 if len(ph.Pkgs) > 0 && ph.Pkgs[len(ph.Pkgs)-1] == pkg {

182 return l

183 }

184 return Log{slog.New(ph.WithPkg(pkg))}

185 }

186 return Log{slog.New(h.WithAttrs([]slog.Attr{slog.String("pkg", pkg)}))}

187}

188

189// WithFunc sets fn to be called for additional attributes. Fn is only called

190// when the line is logged.

191// If the underlying handler is not an mlog.handler, this method has no effect.

192// Caller must take care of preventing data races.

193func (l Log) WithFunc(fn func() []slog.Attr) Log {

194 h := l.Logger.Handler()

195 if ph, ok := h.(*handler); ok {

196 return Log{slog.New(ph.WithFunc(fn))}

197 }

198 // Ignored for other handlers, only used internally (smtpserver, imapserver).

199 return l

200}

201

202// Check logs an error if err is not nil. Intended for logging errors that are good

203// to know, but would not influence program flow. Context deadline/cancelation

204// errors and timeouts are logged at "info" level. Closed remote connections are

205// logged at "debug" level. Other errors at "error" level.

206func (l Log) Check(err error, msg string, attrs ...slog.Attr) {

207 if err == nil {

208 return

209 }

210 level := LevelError

211 if errors.Is(err, context.DeadlineExceeded) || errors.Is(err, context.Canceled) || errors.Is(err, os.ErrDeadlineExceeded) {

212 level = LevelInfo

213 } else if IsClosed(err) {

214 level = LevelDebug

215 }

216 attrs = append([]slog.Attr{errAttr(err)}, attrs...)

217 l.Logger.LogAttrs(noctx, level, msg, attrs...)

218}

219

220func errAttr(err error) slog.Attr {

221 return slog.Any("err", err)

222}

223

224// 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.

225

226func (l Log) Debug(msg string, attrs ...slog.Attr) {

227 l.Logger.LogAttrs(noctx, LevelDebug, msg, attrs...)

228}

229

230func (l Log) Debugx(msg string, err error, attrs ...slog.Attr) {

231 if err != nil {

232 attrs = append([]slog.Attr{errAttr(err)}, attrs...)

233 }

234 l.Logger.LogAttrs(noctx, LevelDebug, msg, attrs...)

235}

236

237func (l Log) Info(msg string, attrs ...slog.Attr) {

238 l.Logger.LogAttrs(noctx, LevelInfo, msg, attrs...)

239}

240

241func (l Log) Infox(msg string, err error, attrs ...slog.Attr) {

242 if err != nil {

243 attrs = append([]slog.Attr{errAttr(err)}, attrs...)

244 }

245 l.Logger.LogAttrs(noctx, LevelInfo, msg, attrs...)

246}

247

248func (l Log) Warn(msg string, attrs ...slog.Attr) {

249 l.Logger.LogAttrs(noctx, LevelWarn, msg, attrs...)

250}

251

252func (l Log) Warnx(msg string, err error, attrs ...slog.Attr) {

253 if err != nil {

254 attrs = append([]slog.Attr{errAttr(err)}, attrs...)

255 }

256 l.Logger.LogAttrs(noctx, LevelWarn, msg, attrs...)

257}

258

259func (l Log) Error(msg string, attrs ...slog.Attr) {

260 l.Logger.LogAttrs(noctx, LevelError, msg, attrs...)

261}

262

263func (l Log) Errorx(msg string, err error, attrs ...slog.Attr) {

264 if err != nil {

265 attrs = append([]slog.Attr{errAttr(err)}, attrs...)

266 }

267 l.Logger.LogAttrs(noctx, LevelError, msg, attrs...)

268}

269

270func (l Log) Fatal(msg string, attrs ...slog.Attr) {

271 l.Logger.LogAttrs(noctx, LevelFatal, msg, attrs...)

272 os.Exit(1)

273}

274

275func (l Log) Fatalx(msg string, err error, attrs ...slog.Attr) {

276 if err != nil {

277 attrs = append([]slog.Attr{errAttr(err)}, attrs...)

278 }

279 l.Logger.LogAttrs(noctx, LevelFatal, msg, attrs...)

280 os.Exit(1)

281}

282

283func (l Log) Print(msg string, attrs ...slog.Attr) {

284 l.Logger.LogAttrs(noctx, LevelPrint, msg, attrs...)

285}

286

287func (l Log) Printx(msg string, err error, attrs ...slog.Attr) {

288 if err != nil {

289 attrs = append([]slog.Attr{errAttr(err)}, attrs...)

290 }

291 l.Logger.LogAttrs(noctx, LevelPrint, msg, attrs...)

292}

293

294// Trace logs at trace/traceauth/tracedata level.

295// If the active log level is any of the trace levels, the data is logged.

296// If level is for tracedata, but the active level doesn't trace data, data is replaced with "...".

297// If level is for traceauth, but the active level doesn't trace auth, data is replaced with "***".

298func (l Log) Trace(level slog.Level, prefix string, data []byte) {

299 h := l.Handler()

300 if !h.Enabled(noctx, level) {

301 return

302 }

303 ph, ok := h.(*handler)

304 if !ok {

305 msg := prefix + string(data)

306 r := slog.NewRecord(time.Now(), level, msg, 0)

307 h.Handle(noctx, r)

308 return

309 }

310 filterLevel, ok := ph.configMatch(level)

311 if !ok {

312 return

313 }

314

315 var msg string

316 size := -1

317 if hideData, hideAuth := traceLevel(filterLevel, level); hideData {

318 msg = prefix + "..."

319 size = len(data)

320 } else if hideAuth {

321 msg = prefix + "***"

322 } else {

323 msg = prefix + string(data)

324 size = len(data)

325 }

326 r := slog.NewRecord(time.Time{}, level, msg, 0)

327 if size >= 0 {

328 r.AddAttrs(slog.Int("size", size))

329 }

330 ph.write(filterLevel, r)

331}

332

333func traceLevel(level, recordLevel slog.Level) (hideData, hideAuth bool) {

334 hideData = recordLevel == LevelTracedata && level > LevelTracedata

335 hideAuth = recordLevel == LevelTraceauth && level > LevelTraceauth

336 return

337}

338

339type handler struct {

340 Pkgs []string

341 Attrs []slog.Attr

342 Group string // Empty or with dot-separated names, ending with a dot.

343 Fn func() []slog.Attr // Only called when record is actually being logged.

344}

345

346func match(minLevel, level slog.Level) bool {

347 return level >= LevelFatal || level >= minLevel || minLevel <= LevelTrace && level <= LevelTrace

348}

349

350func (h *handler) Enabled(ctx context.Context, level slog.Level) bool {

351 return match(slog.Level(lowestLevel.Load()), level)

352}

353

354func (h *handler) configMatch(level slog.Level) (slog.Level, bool) {

355 c := *config.Load()

356 for i := len(h.Pkgs) - 1; i >= 0; i-- {

357 if l, ok := c[h.Pkgs[i]]; ok {

358 return l, match(l, level)

359 }

360 }

361 l := c[""]

362 return l, match(l, level)

363}

364

365func (h *handler) Handle(ctx context.Context, r slog.Record) error {

366 l, ok := h.configMatch(r.Level)

367 if !ok {

368 return nil

369 }

370 if r.Level >= LevelInfo {

371 if r.Level == LevelInfo {

372 metricLogInfo.Inc()

373 } else if r.Level <= LevelWarn {

374 metricLogWarn.Inc()

375 } else if r.Level <= LevelError {

376 metricLogError.Inc()

377 }

378 }

379 if hideData, hideAuth := traceLevel(l, r.Level); hideData {

380 r.Message = "..."

381 } else if hideAuth {

382 r.Message = "***"

383 }

384 return h.write(l, r)

385}

386

387// Reuse buffers to format log lines into.

388var logBuffersStore [32][256]byte

389var logBuffers = make(chan []byte, 200)

390

391func init() {

392 for i := range logBuffersStore {

393 logBuffers <- logBuffersStore[i][:]

394 }

395}

396

397// escape logfmt string if required, otherwise return original string.

398func formatString(s string) string {

399 for _, c := range s {

400 if c <= ' ' || c == '"' || c == '\\' || c == '=' || c >= 0x7f {

401 return fmt.Sprintf("%q", s)

402 }

403 }

404 return s

405}

406

407var typeTime = reflect.TypeFor[time.Time]()

408

409func stringValue(iscid, nested bool, v any) string {

410 // Handle some common types first.

411 if v == nil {

412 return ""

413 }

414 switch r := v.(type) {

415 case string:

416 return r

417 case int:

418 return strconv.Itoa(r)

419 case int64:

420 if iscid {

421 return fmt.Sprintf("%x", v)

422 }

423 return strconv.FormatInt(r, 10)

424 case bool:

425 if r {

426 return "true"

427 }

428 return "false"

429 case float64:

430 return fmt.Sprintf("%v", v)

431 case []byte:

432 return base64.RawURLEncoding.EncodeToString(r)

433 case []string:

434 if nested && len(r) == 0 {

435 // Drop field from logging.

436 return ""

437 }

438 return "[" + strings.Join(r, ",") + "]"

439 case error:

440 return r.Error()

441 case time.Time:

442 return r.Format(time.RFC3339)

443 }

444

445 rv := reflect.ValueOf(v)

446 if rv.Kind() == reflect.Ptr && rv.IsNil() {

447 return ""

448 }

449

450 if r, ok := v.(LogStringer); ok {

451 return r.LogString()

452 }

453 if r, ok := v.(fmt.Stringer); ok {

454 return r.String()

455 }

456

457 if rv.Kind() == reflect.Ptr {

458 rv = rv.Elem()

459 return stringValue(iscid, nested, rv.Interface())

460 }

461 if rv.Kind() == reflect.Slice {

462 n := rv.Len()

463 if nested && n == 0 {

464 // Drop field.

465 return ""

466 }

467 b := &strings.Builder{}

468 b.WriteString("[")

469 for i := range n {

470 if i > 0 {

471 b.WriteString(";")

472 }

473 b.WriteString(stringValue(false, true, rv.Index(i).Interface()))

474 }

475 b.WriteString("]")

476 return b.String()

477 } else if rv.Kind() != reflect.Struct {

478 return fmt.Sprintf("%v", v)

479 }

480 n := rv.NumField()

481 t := rv.Type()

482

483 // We first try making a string without recursing into structs/pointers/interfaces,

484 // but will try again with those fields if we otherwise would otherwise log an

485 // empty string.

486 for j := range 2 {

487 first := true

488 b := &strings.Builder{}

489 for i := range n {

490 fv := rv.Field(i)

491 if !t.Field(i).IsExported() {

492 continue

493 }

494 // todo: decide on better approach about which fields to include while preventing recursion

495 if j == 0 && (fv.Kind() == reflect.Struct || fv.Kind() == reflect.Ptr || fv.Kind() == reflect.Interface) && fv.Type() != typeTime {

496 // Don't recurse.

497 continue

498 }

499 vs := stringValue(false, true, fv.Interface())

500 if vs == "" {

501 continue

502 }

503 if !first {

504 b.WriteByte(' ')

505 }

506 first = false

507 k := strings.ToLower(t.Field(i).Name)

508 b.WriteString(k + "=" + vs)

509 }

510 rs := b.String()

511 if rs != "" {

512 return rs

513 }

514 }

515 return ""

516}

517

518func writeAttr(w io.Writer, separator, group string, a slog.Attr) {

519 switch a.Value.Kind() {

520 case slog.KindGroup:

521 if group != "" {

522 group += "."

523 }

524 group += a.Key

525 for _, a := range a.Value.Group() {

526 writeAttr(w, separator, group, a)

527 }

528 return

529 default:

530 var vv any

531 if a.Value.Kind() == slog.KindLogValuer {

532 vv = a.Value.Resolve().Any()

533 } else {

534 vv = a.Value.Any()

535 }

536 s := stringValue(a.Key == "cid", false, vv)

537 fmt.Fprint(w, separator, group, a.Key, "=", formatString(s))

538 }

539}

540

541func (h *handler) write(l slog.Level, r slog.Record) error {

542 // Reuse a buffer, or temporarily allocate a new one.

543 var buf []byte

544 select {

545 case buf = <-logBuffers:

546 defer func() {

547 logBuffers <- buf

548 }()

549 default:

550 buf = make([]byte, 128)

551 }

552

553 b := bytes.NewBuffer(buf[:0])

554 eb := &errWriter{b, nil}

555

556 if Logfmt {

557 var wrotePkgs bool

558 ensurePkgs := func() {

559 if !wrotePkgs {

560 wrotePkgs = true

561 for _, pkg := range h.Pkgs {

562 writeAttr(eb, " ", "", slog.String("pkg", pkg))

563 }

564 }

565 }

566

567 fmt.Fprint(eb, "l=", LevelStrings[r.Level], " m=")

568 fmt.Fprintf(eb, "%q", r.Message)

569 n := 0

570 r.Attrs(func(a slog.Attr) bool {

571 if n > 0 || a.Key != "err" || h.Group != "" {

572 ensurePkgs()

573 }

574 writeAttr(eb, " ", h.Group, a)

575 n++

576 return true

577 })

578 ensurePkgs()

579 for _, a := range h.Attrs {

580 writeAttr(eb, " ", h.Group, a)

581 }

582 if h.Fn != nil {

583 for _, a := range h.Fn() {

584 writeAttr(eb, " ", h.Group, a)

585 }

586 }

587 fmt.Fprint(eb, "\n")

588 } else {

589 var wrotePkgs bool

590 ensurePkgs := func() {

591 if !wrotePkgs {

592 wrotePkgs = true

593 for _, pkg := range h.Pkgs {

594 writeAttr(eb, "; ", "", slog.String("pkg", pkg))

595 }

596 }

597 }

598

599 msg := r.Message

600 if r.Level <= LevelTrace {

601 msg = fmt.Sprintf("%q", msg)

602 }

603 fmt.Fprint(eb, LevelStrings[r.Level], ": ", msg)

604 n := 0

605 r.Attrs(func(a slog.Attr) bool {

606 if n == 0 && a.Key == "err" && h.Group == "" {

607 fmt.Fprint(eb, ": ", a.Value.String())

608 ensurePkgs()

609 } else {

610 ensurePkgs()

611 writeAttr(eb, "; ", h.Group, a)

612 }

613 n++

614 return true

615 })

616 ensurePkgs()

617 for _, a := range h.Attrs {

618 writeAttr(eb, "; ", h.Group, a)

619 }

620 if h.Fn != nil {

621 for _, a := range h.Fn() {

622 writeAttr(eb, "; ", h.Group, a)

623 n++

624 }

625 }

626 fmt.Fprint(eb, "\n")

627 }

628 if eb.Err != nil {

629 return eb.Err

630 }

631

632 // todo: for mox serve, do writes in separate goroutine.

633 _, err := os.Stderr.Write(b.Bytes())

634 return err

635}

636

637type errWriter struct {

638 Writer *bytes.Buffer

639 Err error

640}

641

642func (w *errWriter) Write(buf []byte) (int, error) {

643 if w.Err != nil {

644 return 0, w.Err

645 }

646 var n int

647 n, w.Err = w.Writer.Write(buf)

648 return n, w.Err

649}

650

651func (h *handler) WithAttrs(attrs []slog.Attr) slog.Handler {

652 nh := *h

653 if h.Attrs != nil {

654 nh.Attrs = slices.Clone(h.Attrs)

655 }

656 nh.Attrs = append(nh.Attrs, attrs...)

657 return &nh

658}

659

660func (h *handler) WithGroup(name string) slog.Handler {

661 if name == "" {

662 return h

663 }

664 nh := *h

665 nh.Group += name + "."

666 return &nh

667}

668

669func (h *handler) WithPkg(pkg string) *handler {

670 nh := *h

671 if nh.Pkgs != nil {

672 nh.Pkgs = slices.Clone(nh.Pkgs)

673 }

674 nh.Pkgs = append(nh.Pkgs, pkg)

675 return &nh

676}

677

678func (h *handler) WithFunc(fn func() []slog.Attr) *handler {

679 nh := *h

680 nh.Fn = fn

681 return &nh

682}

683

684type logWriter struct {

685 log Log

686 level slog.Level

687 msg string

688}

689

690func (w logWriter) Write(buf []byte) (int, error) {

691 err := strings.TrimSpace(string(buf))

692 w.log.LogAttrs(noctx, w.level, w.msg, slog.String("err", err))

693 return len(buf), nil

694}

695

696// LogWriter returns a writer that turns each write into a logging call on "log"

697// with given "level" and "msg" and the written content as an error.

698// Can be used for making a Go log.Logger for use in http.Server.ErrorLog.

699func LogWriter(log Log, level slog.Level, msg string) io.Writer {

700 return logWriter{log, level, msg}

701}

702