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 "github.com/prometheus/client_golang/prometheus"

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

31)

32

33var noctx = context.Background()

34

35var (

36 metricLogInfo = promauto.NewCounter(

37 prometheus.CounterOpts{

38 Name: "mox_logging_level_info_total",

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

40 },

41 )

42 metricLogWarn = promauto.NewCounter(

43 prometheus.CounterOpts{

44 Name: "mox_logging_level_warn_total",

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

46 },

47 )

48 metricLogError = promauto.NewCounter(

49 prometheus.CounterOpts{

50 Name: "mox_logging_level_error_total",

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

52 },

53 )

54)

55

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

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

58var Logfmt bool

59

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

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

62type LogStringer interface {

63 LogString() string

64}

65

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

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

68

69func init() {

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

71}

72

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

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

75 lowest := c[""]

76 for _, l := range c {

77 if l < lowest {

78 lowest = l

79 }

80 }

81 lowestLevel.Store(int32(lowest))

82 config.Store(&c)

83}

84

85var (

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

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

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

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

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

91 // or LevelTracedata.

92 LevelTracedata = slog.LevelDebug - 8

93 LevelTraceauth = slog.LevelDebug - 6

94 LevelTrace = slog.LevelDebug - 4

95 LevelDebug = slog.LevelDebug

96 LevelInfo = slog.LevelInfo

97 LevelWarn = slog.LevelWarn

98 LevelError = slog.LevelError

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

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

101)

102

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

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

105 LevelTracedata: "tracedata",

106 LevelTraceauth: "traceauth",

107 LevelTrace: "trace",

108 LevelDebug: "debug",

109 LevelInfo: "info",

110 LevelWarn: "warn",

111 LevelError: "error",

112 LevelFatal: "fatal",

113 LevelPrint: "print",

114}

115

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

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

118 "tracedata": LevelTracedata,

119 "traceauth": LevelTraceauth,

120 "trace": LevelTrace,

121 "debug": LevelDebug,

122 "info": LevelInfo,

123 "warn": LevelWarn,

124 "error": LevelError,

125 "fatal": LevelFatal,

126 "print": LevelPrint,

127}

128

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

130type Log struct {

131 *slog.Logger

132}

133

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

135// Logger is created with a custom handler.

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

137 if logger == nil {

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

139 }

140 return Log{logger}.WithPkg(pkg)

141}

142

143// WithCid adds a attribute "cid".

144// Also see WithContext.

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

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

147}

148

149type key string

150

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

152var CidKey key = "cid"

153

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

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

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

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

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

159// reason WithContext is more common than WithCid.

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

161 cidv := ctx.Value(CidKey)

162 if cidv == nil {

163 return l

164 }

165 cid := cidv.(int64)

166 return l.WithCid(cid)

167}

168

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

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

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

172}

173

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

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

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

177 h := l.Logger.Handler()

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

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

180 return l

181 }

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

183 }

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

185}

186

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

188// when the line is logged.

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

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

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

192 h := l.Logger.Handler()

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

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

195 }

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

197 return l

198}

199

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

201// to know, but would not influence program flow.

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

203 if err != nil {

204 l.Errorx(msg, err, attrs...)

205 }

206}

207

208func errAttr(err error) slog.Attr {

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

210}

211

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

213

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

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

216}

217

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

219 if err != nil {

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

221 }

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

223}

224

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

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

227}

228

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

230 if err != nil {

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

232 }

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

234}

235

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

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

238}

239

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

241 if err != nil {

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

243 }

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

245}

246

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

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

249}

250

251func (l Log) Errorx(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, LevelError, msg, attrs...)

256}

257

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

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

260 os.Exit(1)

261}

262

263func (l Log) Fatalx(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, LevelFatal, msg, attrs...)

268 os.Exit(1)

269}

270

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

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

273}

274

275func (l Log) Printx(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, LevelPrint, msg, attrs...)

280}

281

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

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

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

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

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

287 h := l.Handler()

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

289 return

290 }

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

292 if !ok {

293 msg := prefix + string(data)

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

295 h.Handle(noctx, r)

296 return

297 }

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

299 if !ok {

300 return

301 }

302

303 var msg string

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

305 msg = prefix + "..."

306 } else if hideAuth {

307 msg = prefix + "***"

308 } else {

309 msg = prefix + string(data)

310 }

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

312 ph.write(filterLevel, r)

313}

314

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

316 hideData = recordLevel == LevelTracedata && level > LevelTracedata

317 hideAuth = recordLevel == LevelTraceauth && level > LevelTraceauth

318 return

319}

320

321type handler struct {

322 Pkgs []string

323 Attrs []slog.Attr

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

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

326}

327

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

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

330}

331

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

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

334}

335

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

337 c := *config.Load()

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

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

340 return l, match(l, level)

341 }

342 }

343 l := c[""]

344 return l, match(l, level)

345}

346

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

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

349 if !ok {

350 return nil

351 }

352 if r.Level >= LevelInfo {

353 if r.Level == LevelInfo {

354 metricLogInfo.Inc()

355 } else if r.Level <= LevelWarn {

356 metricLogWarn.Inc()

357 } else if r.Level <= LevelError {

358 metricLogError.Inc()

359 }

360 }

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

362 r.Message = "..."

363 } else if hideAuth {

364 r.Message = "***"

365 }

366 return h.write(l, r)

367}

368

369// Reuse buffers to format log lines into.

370var logBuffersStore [32][256]byte

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

372

373func init() {

374 for i := range logBuffersStore {

375 logBuffers <- logBuffersStore[i][:]

376 }

377}

378

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

380func formatString(s string) string {

381 for _, c := range s {

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

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

384 }

385 }

386 return s

387}

388

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

390 // Handle some common types first.

391 if v == nil {

392 return ""

393 }

394 switch r := v.(type) {

395 case string:

396 return r

397 case int:

398 return strconv.Itoa(r)

399 case int64:

400 if iscid {

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

402 }

403 return strconv.FormatInt(r, 10)

404 case bool:

405 if r {

406 return "true"

407 }

408 return "false"

409 case float64:

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

411 case []byte:

412 return base64.RawURLEncoding.EncodeToString(r)

413 case []string:

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

415 // Drop field from logging.

416 return ""

417 }

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

419 case error:

420 return r.Error()

421 case time.Time:

422 return r.Format(time.RFC3339)

423 }

424

425 rv := reflect.ValueOf(v)

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

427 return ""

428 }

429

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

431 return r.LogString()

432 }

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

434 return r.String()

435 }

436

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

438 rv = rv.Elem()

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

440 }

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

442 n := rv.Len()

443 if nested && n == 0 {

444 // Drop field.

445 return ""

446 }

447 b := &strings.Builder{}

448 b.WriteString("[")

449 for i := 0; i < n; i++ {

450 if i > 0 {

451 b.WriteString(";")

452 }

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

454 }

455 b.WriteString("]")

456 return b.String()

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

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

459 }

460 n := rv.NumField()

461 t := rv.Type()

462

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

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

465 // empty string.

466 for j := 0; j < 2; j++ {

467 first := true

468 b := &strings.Builder{}

469 for i := 0; i < n; i++ {

470 fv := rv.Field(i)

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

472 continue

473 }

474 if j == 0 && (fv.Kind() == reflect.Struct || fv.Kind() == reflect.Ptr || fv.Kind() == reflect.Interface) {

475 // Don't recurse.

476 continue

477 }

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

479 if vs == "" {

480 continue

481 }

482 if !first {

483 b.WriteByte(' ')

484 }

485 first = false

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

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

488 }

489 rs := b.String()

490 if rs != "" {

491 return rs

492 }

493 }

494 return ""

495}

496

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

498 switch a.Value.Kind() {

499 case slog.KindGroup:

500 if group != "" {

501 group += "."

502 }

503 group += a.Key

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

505 writeAttr(w, separator, group, a)

506 }

507 return

508 default:

509 var vv any

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

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

512 } else {

513 vv = a.Value.Any()

514 }

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

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

517 }

518}

519

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

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

522 var buf []byte

523 select {

524 case buf = <-logBuffers:

525 defer func() {

526 logBuffers <- buf

527 }()

528 default:

529 buf = make([]byte, 128)

530 }

531

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

533 eb := &errWriter{b, nil}

534

535 if Logfmt {

536 var wrotePkgs bool

537 ensurePkgs := func() {

538 if !wrotePkgs {

539 wrotePkgs = true

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

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

542 }

543 }

544 }

545

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

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

548 n := 0

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

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

551 ensurePkgs()

552 }

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

554 n++

555 return true

556 })

557 ensurePkgs()

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

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

560 }

561 if h.Fn != nil {

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

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

564 }

565 }

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

567 } else {

568 var wrotePkgs bool

569 ensurePkgs := func() {

570 if !wrotePkgs {

571 wrotePkgs = true

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

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

574 }

575 }

576 }

577

578 fmt.Fprint(eb, LevelStrings[r.Level], ": ", r.Message)

579 n := 0

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

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

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

583 ensurePkgs()

584 } else {

585 ensurePkgs()

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

587 }

588 n++

589 return true

590 })

591 ensurePkgs()

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

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

594 }

595 if h.Fn != nil {

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

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

598 n++

599 }

600 }

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

602 }

603 if eb.Err != nil {

604 return eb.Err

605 }

606

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

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

609 return err

610}

611

612type errWriter struct {

613 Writer *bytes.Buffer

614 Err error

615}

616

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

618 if w.Err != nil {

619 return 0, w.Err

620 }

621 var n int

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

623 return n, w.Err

624}

625

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

627 nh := *h

628 if h.Attrs != nil {

629 nh.Attrs = append([]slog.Attr{}, h.Attrs...)

630 }

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

632 return &nh

633}

634

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

636 if name == "" {

637 return h

638 }

639 nh := *h

640 nh.Group += name + "."

641 return &nh

642}

643

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

645 nh := *h

646 if nh.Pkgs != nil {

647 nh.Pkgs = append([]string{}, nh.Pkgs...)

648 }

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

650 return &nh

651}

652

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

654 nh := *h

655 nh.Fn = fn

656 return &nh

657}

658

659type logWriter struct {

660 log Log

661 level slog.Level

662 msg string

663}

664

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

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

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

668 return len(buf), nil

669}

670

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

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

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

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

675 return logWriter{log, level, msg}

676}

677