mox!

mlog/log.go

@@ -0,0 +1,376 @@
+// Package mlog provides logging with log levels and fields.
+//
+// Each log level has a function to log with and without error.
+// Each such function takes a varargs list of fields (key value pairs) to log.
+// Variable data should be in fields. Logging strings themselves should be
+// constant, for easier log processing (e.g. building metrics based on log
+// messages).
+//
+// The log levels can be configured per originating package, e.g. smtpclient,
+// imapserver. The configuration is application-global, so each Log instance
+// uses the same log levels.
+//
+// Print* should be used for lines that always should be printed, regardless of
+// configured log levels. Useful for startup logging and subcommands.
+//
+// Fatal* stops the program. Its log text is always printed.
+package mlog
+
+// todo: log with source=path:linenumber? and/or stacktrace (perhaps optional)
+// todo: should we turn errors logged with an context.Canceled from a level error into level info?
+// todo: rethink format. perhaps simply using %#v is more useful for many types?
+
+import (
+	"bytes"
+	"context"
+	"encoding/base64"
+	"errors"
+	"fmt"
+	"io"
+	"os"
+	"reflect"
+	"strconv"
+	"strings"
+	"sync/atomic"
+)
+
+var Logfmt bool
+
+type Level int
+
+var LevelStrings = map[Level]string{
+	LevelPrint: "print",
+	LevelFatal: "fatal",
+	LevelError: "error",
+	LevelInfo:  "info",
+	LevelDebug: "debug",
+	LevelTrace: "trace",
+}
+
+var Levels = map[string]Level{
+	"print": LevelPrint,
+	"fatal": LevelFatal,
+	"error": LevelError,
+	"info":  LevelInfo,
+	"debug": LevelDebug,
+	"trace": LevelTrace,
+}
+
+const (
+	LevelPrint Level = 0 // Printed regardless of configured log level.
+	LevelFatal Level = 1 // Printed regardless of configured log level.
+	LevelError Level = 2
+	LevelInfo  Level = 3
+	LevelDebug Level = 4
+	LevelTrace Level = 5
+)
+
+// Holds a map[string]Level, mapping a package (field pkg in logs) to a log level.
+// The empty string is the default/fallback log level.
+var config atomic.Value
+
+func init() {
+	config.Store(map[string]Level{"": LevelError})
+}
+
+// SetConfig atomically sets the new log levels used by all Log instances.
+func SetConfig(c map[string]Level) {
+	config.Store(c)
+}
+
+// Pair is a field/value pair, for use in logged lines.
+type Pair struct {
+	key   string
+	value any
+}
+
+// Field is a shorthand for making a Pair.
+func Field(k string, v any) Pair {
+	return Pair{k, v}
+}
+
+// Log is an instance potentially with its own field/value pair added to any
+// logging output.
+type Log struct {
+	fields     []Pair
+	moreFields func() []Pair
+}
+
+// New returns a new Log instance. Each log invocation adds field "pkg".
+func New(pkg string) *Log {
+	return &Log{
+		fields: []Pair{{"pkg", pkg}},
+	}
+}
+
+type key string
+
+// CidKey can be used with context.WithValue to store a "cid" in a context, for logging.
+var CidKey key = "cid"
+
+// WithCid adds a field "cid".
+// Also see WithContext.
+func (l *Log) WithCid(cid int64) *Log {
+	return l.Fields(Pair{"cid", cid})
+}
+
+// WithContext adds cid from context, if present. Context are often passed to
+// functions, especially between packages, to pass a "cid" for an operation. At the
+// start of a function (especially if exported) a variable "log" is often
+// instantiated from a package-level variable "xlog", with WithContext for its cid.
+// A *Log could be passed instead, but contexts are more pervasive. For the same
+// reason WithContext is more common than WithCid.
+func (l *Log) WithContext(ctx context.Context) *Log {
+	cidv := ctx.Value(CidKey)
+	if cidv == nil {
+		return l
+	}
+	cid := cidv.(int64)
+	return l.WithCid(cid)
+}
+
+// Field adds fields to the logger. Each logged line adds these fields.
+func (l *Log) Fields(fields ...Pair) *Log {
+	nl := *l
+	nl.fields = append(fields, nl.fields...)
+	return &nl
+}
+
+// MoreFields sets a function on the logger that is called just before logging,
+// to retrieve additional fields to log.
+func (l *Log) MoreFields(fn func() []Pair) *Log {
+	nl := *l
+	nl.moreFields = fn
+	return &nl
+}
+
+func (l *Log) Trace(text string) bool {
+	return l.logx(LevelTrace, nil, text)
+}
+
+func (l *Log) Fatal(text string, fields ...Pair) { l.Fatalx(text, nil, fields...) }
+func (l *Log) Fatalx(text string, err error, fields ...Pair) {
+	l.plog(LevelFatal, err, text, fields...)
+	os.Exit(1)
+}
+
+func (l *Log) Print(text string, fields ...Pair) bool {
+	return l.logx(LevelPrint, nil, text, fields...)
+}
+func (l *Log) Printx(text string, err error, fields ...Pair) bool {
+	return l.logx(LevelPrint, err, text, fields...)
+}
+
+func (l *Log) Debug(text string, fields ...Pair) bool {
+	return l.logx(LevelDebug, nil, text, fields...)
+}
+func (l *Log) Debugx(text string, err error, fields ...Pair) bool {
+	return l.logx(LevelDebug, err, text, fields...)
+}
+
+func (l *Log) Info(text string, fields ...Pair) bool { return l.logx(LevelInfo, nil, text, fields...) }
+func (l *Log) Infox(text string, err error, fields ...Pair) bool {
+	return l.logx(LevelInfo, err, text, fields...)
+}
+
+func (l *Log) Error(text string, fields ...Pair) bool {
+	return l.logx(LevelError, nil, text, fields...)
+}
+func (l *Log) Errorx(text string, err error, fields ...Pair) bool {
+	return l.logx(LevelError, err, text, fields...)
+}
+
+func (l *Log) logx(level Level, err error, text string, fields ...Pair) bool {
+	if !l.match(level) {
+		return false
+	}
+	l.plog(level, err, text, fields...)
+	return true
+}
+
+// escape logfmt string if required, otherwise return original string.
+func logfmtValue(s string) string {
+	for _, c := range s {
+		if c == '"' || c == '\\' || c <= ' ' || c == '=' || c >= 0x7f {
+			return fmt.Sprintf("%q", s)
+		}
+	}
+	return s
+}
+
+func stringValue(iscid, nested bool, v any) string {
+	// Handle some common types first.
+	if v == nil {
+		return ""
+	}
+	switch r := v.(type) {
+	case string:
+		return r
+	case int:
+		return strconv.Itoa(r)
+	case int64:
+		if iscid {
+			return fmt.Sprintf("%x", v)
+		}
+		return strconv.FormatInt(r, 10)
+	case bool:
+		if r {
+			return "true"
+		}
+		return "false"
+	case float64:
+		return fmt.Sprintf("%v", v)
+	case []byte:
+		return base64.RawURLEncoding.EncodeToString(r)
+	case []string:
+		if nested && len(r) == 0 {
+			// Drop field from logging.
+			return ""
+		}
+		return "[" + strings.Join(r, ",") + "]"
+	}
+
+	rv := reflect.ValueOf(v)
+	if rv.Kind() == reflect.Ptr && rv.IsNil() {
+		return ""
+	}
+
+	if r, ok := v.(fmt.Stringer); ok {
+		return r.String()
+	}
+
+	if rv.Kind() == reflect.Ptr {
+		rv = rv.Elem()
+		return stringValue(iscid, nested, rv.Interface())
+	}
+	if rv.Kind() == reflect.Slice {
+		n := rv.Len()
+		if nested && n == 0 {
+			// Drop field.
+			return ""
+		}
+		b := &strings.Builder{}
+		b.WriteString("[")
+		for i := 0; i < n; i++ {
+			if i > 0 {
+				b.WriteString(";")
+			}
+			b.WriteString(stringValue(false, true, rv.Index(i).Interface()))
+		}
+		b.WriteString("]")
+		return b.String()
+	} else if rv.Kind() != reflect.Struct {
+		return fmt.Sprintf("%v", v)
+	}
+	n := rv.NumField()
+	t := rv.Type()
+	b := &strings.Builder{}
+	first := true
+	for i := 0; i < n; i++ {
+		fv := rv.Field(i)
+		if !t.Field(i).IsExported() {
+			continue
+		}
+		if fv.Kind() == reflect.Struct || fv.Kind() == reflect.Ptr || fv.Kind() == reflect.Interface {
+			// Don't recurse.
+			continue
+		}
+		vs := stringValue(false, true, fv.Interface())
+		if vs == "" {
+			continue
+		}
+		if !first {
+			b.WriteByte(' ')
+		}
+		first = false
+		k := strings.ToLower(t.Field(i).Name)
+		b.WriteString(k + "=" + logfmtValue(vs))
+	}
+	return b.String()
+}
+
+func (l *Log) plog(level Level, err error, text string, fields ...Pair) {
+	fields = append(l.fields, fields...)
+	if l.moreFields != nil {
+		fields = append(fields, l.moreFields()...)
+	}
+	// We build up a buffer so we can do a single atomic write of the data. Otherwise partial log lines may interleaf.
+	b := &bytes.Buffer{}
+	if Logfmt {
+		fmt.Fprintf(b, "l=%s m=%s", LevelStrings[level], logfmtValue(text))
+		if err != nil {
+			fmt.Fprintf(b, " err=%s", logfmtValue(err.Error()))
+		}
+		for i := 0; i < len(fields); i++ {
+			kv := fields[i]
+			fmt.Fprintf(b, " %s=%s", kv.key, logfmtValue(stringValue(kv.key == "cid", false, kv.value)))
+		}
+		b.WriteString("\n")
+	} else {
+		fmt.Fprintf(b, "%s: %s", LevelStrings[level], logfmtValue(text))
+		if err != nil {
+			fmt.Fprintf(b, ": %s", logfmtValue(err.Error()))
+		}
+		if len(fields) > 0 {
+			fmt.Fprint(b, " (")
+			for i := 0; i < len(fields); i++ {
+				if i > 0 {
+					fmt.Fprint(b, "; ")
+				}
+				kv := fields[i]
+				fmt.Fprintf(b, "%s: %s", kv.key, logfmtValue(stringValue(kv.key == "cid", false, kv.value)))
+			}
+			fmt.Fprint(b, ")")
+		}
+		b.WriteString("\n")
+	}
+	os.Stderr.Write(b.Bytes())
+}
+
+func (l *Log) match(level Level) bool {
+	if level == LevelPrint || level == LevelFatal {
+		return true
+	}
+
+	cl := config.Load().(map[string]Level)
+
+	seen := false
+	for _, kv := range l.fields {
+		if kv.key != "pkg" {
+			continue
+		}
+		pkg, ok := kv.value.(string)
+		if !ok {
+			continue
+		}
+		v, ok := cl[pkg]
+		if ok && v >= level {
+			return true
+		}
+		seen = seen || ok
+	}
+	if seen {
+		return false
+	}
+	v, ok := cl[""]
+	return ok && v >= level
+}
+
+type errWriter struct {
+	log   *Log
+	level Level
+	msg   string
+}
+
+func (w *errWriter) Write(buf []byte) (int, error) {
+	err := errors.New(strings.TrimSpace(string(buf)))
+	w.log.logx(w.level, err, w.msg)
+	return len(buf), nil
+}
+
+// ErrWriter returns a writer that turns each write into a logging call on "log"
+// with given "level" and "msg" and the written content as an error.
+// Can be used for making a Go log.Logger for use in http.Server.ErrorLog.
+func ErrWriter(log *Log, level Level, msg string) io.Writer {
+	return &errWriter{log, level, msg}
+}