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{"": LevelDebug})

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

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

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

432 // empty string.

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

434 first := true

435 b := &strings.Builder{}

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

437 fv := rv.Field(i)

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

439 continue

440 }

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

442 // Don't recurse.

443 continue

444 }

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

446 if vs == "" {

447 continue

448 }

449 if !first {

450 b.WriteByte(' ')

451 }

452 first = false

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

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

455 }

456 rs := b.String()

457 if rs != "" {

458 return rs

459 }

460 }

461 return ""

462}

463

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

465 switch a.Value.Kind() {

466 case slog.KindGroup:

467 if group != "" {

468 group += "."

469 }

470 group += a.Key

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

472 writeAttr(w, separator, group, a)

473 }

474 return

475 default:

476 var vv any

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

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

479 } else {

480 vv = a.Value.Any()

481 }

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

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

484 }

485}

486

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

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

489 var buf []byte

490 select {

491 case buf = <-logBuffers:

492 defer func() {

493 logBuffers <- buf

494 }()

495 default:

496 buf = make([]byte, 128)

497 }

498

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

500 eb := &errWriter{b, nil}

501

502 if Logfmt {

503 var wrotePkgs bool

504 ensurePkgs := func() {

505 if !wrotePkgs {

506 wrotePkgs = true

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

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

509 }

510 }

511 }

512

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

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

515 n := 0

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

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

518 ensurePkgs()

519 }

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

521 n++

522 return true

523 })

524 ensurePkgs()

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

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

527 }

528 if h.Fn != nil {

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

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

531 }

532 }

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

534 } else {

535 var wrotePkgs bool

536 ensurePkgs := func() {

537 if !wrotePkgs {

538 wrotePkgs = true

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

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

541 }

542 }

543 }

544

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

546 n := 0

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

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

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

550 ensurePkgs()

551 } else {

552 ensurePkgs()

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

554 }

555 n++

556 return true

557 })

558 ensurePkgs()

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

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

561 }

562 if h.Fn != nil {

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

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

565 n++

566 }

567 }

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

569 }

570 if eb.Err != nil {

571 return eb.Err

572 }

573

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

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

576 return err

577}

578

579type errWriter struct {

580 Writer *bytes.Buffer

581 Err error

582}

583

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

585 if w.Err != nil {

586 return 0, w.Err

587 }

588 var n int

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

590 return n, w.Err

591}

592

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

594 nh := *h

595 if h.Attrs != nil {

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

597 }

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

599 return &nh

600}

601

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

603 if name == "" {

604 return h

605 }

606 nh := *h

607 nh.Group += name + "."

608 return &nh

609}

610

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

612 nh := *h

613 if nh.Pkgs != nil {

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

615 }

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

617 return &nh

618}

619

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

621 nh := *h

622 nh.Fn = fn

623 return &nh

624}

625

626type logWriter struct {

627 log Log

628 level slog.Level

629 msg string

630}

631

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

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

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

635 return len(buf), nil

636}

637

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

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

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

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

642 return logWriter{log, level, msg}

643}

644