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