diff --git a/slog/logger.go b/slog/logger.go new file mode 100644 index 000000000..e653e27dd --- /dev/null +++ b/slog/logger.go @@ -0,0 +1,237 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "log" + "sync/atomic" + "time" +) + +var defaultLogger atomic.Value + +func init() { + defaultLogger.Store(&Logger{ + handler: &defaultHandler{}, + }) +} + +// Default returns the default Logger. +func Default() *Logger { return defaultLogger.Load().(*Logger) } + +// SetDefault makes l the default Logger. +// After this call, output from the log package's default Logger +// (as with [log.Print], etc.) will be logged at InfoLevel using l's Handler. +func SetDefault(l *Logger) { + defaultLogger.Store(l) + log.SetOutput(&handlerWriter{l.Handler(), log.Flags()}) + log.SetFlags(0) // we want just the log message, no time or location +} + +// handlerWriter is an io.Writer that calls a Handler. +// It is used to link the default log.Logger to the default slog.Logger. +type handlerWriter struct { + h Handler + flags int +} + +func (w *handlerWriter) Write(buf []byte) (int, error) { + var depth int + if w.flags&(log.Lshortfile|log.Llongfile) != 0 { + depth = 2 + } + // Remove final newline. + origLen := len(buf) // Report that the entire buf was written. + if len(buf) > 0 && buf[len(buf)-1] == '\n' { + buf = buf[:len(buf)-1] + } + r := MakeRecord(time.Now(), InfoLevel, string(buf), depth) + return origLen, w.h.Handle(r) +} + +// A Logger records structured information about each call to its +// Log, Debug, Info, Warn, and Error methods. +// For each call, it creates a Record and passes it to a Handler. +// +// Loggers are immutable; to create a new one, call [New] or [Logger.With]. +type Logger struct { + handler Handler // for structured logging +} + +// Handler returns l's Handler. +func (l *Logger) Handler() Handler { return l.handler } + +// With returns a new Logger whose handler's attributes are a concatenation of +// l's attributes and the given arguments, converted to Attrs as in +// [Logger.Log]. +func (l *Logger) With(attrs ...any) *Logger { + return &Logger{handler: l.handler.With(argsToAttrs(attrs))} +} + +func argsToAttrs(args []any) []Attr { + var r Record + setAttrs(&r, args) + return r.Attrs() +} + +// New creates a new Logger with the given Handler. +func New(h Handler) *Logger { return &Logger{handler: h} } + +// With calls Logger.With on the default logger. +func With(attrs ...any) *Logger { + return Default().With(attrs...) +} + +// Enabled reports whether l emits log records at the given level. +func (l *Logger) Enabled(level Level) bool { + return l.Handler().Enabled(level) +} + +// Log emits a log record with the current time and the given level and message. +// The Record's Attrs consist of the Logger's attributes followed by +// the Attrs specified by args. +// +// The attribute arguments are processed as follows: +// - If an argument is an Attr, it is used as is. +// - If an argument is a string and this is not the last argument, +// the following argument is treated as the value and the two are combined +// into an Attr. +// - Otherwise, the argument is treated as a value with key "!BADKEY". +func (l *Logger) Log(level Level, msg string, args ...any) { + l.LogDepth(0, level, msg, args...) +} + +// LogDepth is like [Logger.Log], but accepts a call depth to adjust the +// file and line number in the log record. 0 refers to the caller +// of LogDepth; 1 refers to the caller's caller; and so on. +func (l *Logger) LogDepth(calldepth int, level Level, msg string, args ...any) { + if !l.Enabled(level) { + return + } + r := l.makeRecord(msg, level, calldepth) + setAttrs(&r, args) + _ = l.Handler().Handle(r) +} + +var useSourceLine = true + +// Temporary, for benchmarking. +// Eventually, getting the pc should be fast. +func disableSourceLine() { useSourceLine = false } + +func (l *Logger) makeRecord(msg string, level Level, depth int) Record { + if useSourceLine { + depth += 5 + } + return MakeRecord(time.Now(), level, msg, depth) +} + +const badKey = "!BADKEY" + +func setAttrs(r *Record, args []any) { + var attr Attr + for len(args) > 0 { + attr, args = argsToAttr(args) + r.AddAttr(attr) + } +} + +// argsToAttrs turns a prefix of the args slice into an Attr and returns +// the unused portion of the slice. +// If args[0] is an Attr, it returns it. +// If args[0] is a string, it treats the first two elements as +// a key-value pair. +// Otherwise, it treats args[0] as a value with a missing key. +func argsToAttr(args []any) (Attr, []any) { + switch x := args[0].(type) { + case string: + if len(args) == 1 { + return String(badKey, x), nil + } + return Any(x, args[1]), args[2:] + + case Attr: + return x, args[1:] + + default: + return Any(badKey, x), args[1:] + } +} + +// LogAttrs is a more efficient version of [Logger.Log] that accepts only Attrs. +func (l *Logger) LogAttrs(level Level, msg string, attrs ...Attr) { + l.LogAttrsDepth(0, level, msg, attrs...) +} + +// LogAttrsDepth is like [Logger.LogAttrs], but accepts a call depth argument +// which it interprets like [Logger.LogDepth]. +func (l *Logger) LogAttrsDepth(calldepth int, level Level, msg string, attrs ...Attr) { + if !l.Enabled(level) { + return + } + r := l.makeRecord(msg, level, calldepth) + r.addAttrs(attrs) + _ = l.Handler().Handle(r) +} + +// Debug logs at DebugLevel. +func (l *Logger) Debug(msg string, args ...any) { + l.LogDepth(0, DebugLevel, msg, args...) +} + +// Info logs at InfoLevel. +func (l *Logger) Info(msg string, args ...any) { + l.LogDepth(0, InfoLevel, msg, args...) +} + +// Warn logs at WarnLevel. +func (l *Logger) Warn(msg string, args ...any) { + l.LogDepth(0, WarnLevel, msg, args...) +} + +// Error logs at ErrorLevel. +// If err is non-nil, Error appends Any("err", err) +// to the list of attributes. +func (l *Logger) Error(msg string, err error, args ...any) { + if err != nil { + // TODO: avoid the copy. + args = append(args[:len(args):len(args)], Any("err", err)) + } + l.LogDepth(0, ErrorLevel, msg, args...) +} + +// Debug calls Logger.Debug on the default logger. +func Debug(msg string, args ...any) { + Default().LogDepth(0, DebugLevel, msg, args...) +} + +// Info calls Logger.Info on the default logger. +func Info(msg string, args ...any) { + Default().LogDepth(0, InfoLevel, msg, args...) +} + +// Warn calls Logger.Warn on the default logger. +func Warn(msg string, args ...any) { + Default().LogDepth(0, WarnLevel, msg, args...) +} + +// Error calls Logger.Error on the default logger. +func Error(msg string, err error, args ...any) { + if err != nil { + // TODO: avoid the copy. + args = append(args[:len(args):len(args)], Any("err", err)) + } + Default().LogDepth(0, ErrorLevel, msg, args...) +} + +// Log calls Logger.Log on the default logger. +func Log(level Level, msg string, args ...any) { + Default().LogDepth(0, level, msg, args...) +} + +// LogAttrs calls Logger.LogAttrs on the default logger. +func LogAttrs(level Level, msg string, attrs ...Attr) { + Default().LogAttrsDepth(0, level, msg, attrs...) +} diff --git a/slog/logger_test.go b/slog/logger_test.go new file mode 100644 index 000000000..acee8d543 --- /dev/null +++ b/slog/logger_test.go @@ -0,0 +1,338 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "bytes" + "io" + "log" + "path/filepath" + "regexp" + "runtime" + "strings" + "testing" + "time" +) + +const timeRE = `\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}-\d{2}:\d{2}` + +func TestLogTextHandler(t *testing.T) { + var buf bytes.Buffer + + l := New(NewTextHandler(&buf)) + + check := func(want string) { + t.Helper() + want = "time=" + timeRE + " " + want + checkLogOutput(t, buf.String(), want) + buf.Reset() + } + + l.Info("msg", "a", 1, "b", 2) + check(`level=INFO msg=msg a=1 b=2`) + + l.Debug("bg", Int("a", 1), "b", 2) + check(`level=DEBUG msg=bg a=1 b=2`) + + l.Warn("w", Duration("dur", 3*time.Second)) + check(`level=WARN msg=w dur=3s`) + + l.Error("bad", io.EOF, "a", 1) + check(`level=ERROR msg=bad a=1 err=EOF`) + + l.Log(WarnLevel-1, "w", Int("a", 1), String("b", "two")) + check(`level=WARN-1 msg=w a=1 b=two`) + + l.LogAttrs(InfoLevel-1, "a b c", Int("a", 1), String("b", "two")) + check(`level=INFO-1 msg="a b c" a=1 b=two`) +} + +func TestConnections(t *testing.T) { + var logbuf, slogbuf bytes.Buffer + + // The default slog.Logger's handler uses the log package's default output. + log.SetOutput(&logbuf) + log.SetFlags(log.Flags() | log.Lshortfile) + Info("msg", "a", 1) + checkLogOutput(t, logbuf.String(), + `\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} logger_test.go:\d\d: INFO a=1 msg`) + + // Once slog.SetDefault is called, the direction is reversed: the default + // log.Logger's output goes through the handler. + SetDefault(New(NewTextHandler(&slogbuf))) + log.Print("msg2") + checkLogOutput(t, slogbuf.String(), "time="+timeRE+` level=INFO msg=msg2`) + + // Setting log's output again breaks the connection. + logbuf.Reset() + slogbuf.Reset() + log.SetOutput(&logbuf) + log.SetFlags(log.LstdFlags) + log.Print("msg3") + checkLogOutput(t, logbuf.String(), + `\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} msg3`) + if got := slogbuf.String(); got != "" { + t.Errorf("got %q, want empty", got) + } +} + +func TestAttrs(t *testing.T) { + check := func(got []Attr, want ...Attr) { + t.Helper() + if !attrsEqual(got, want) { + t.Errorf("got %v, want %v", got, want) + } + } + + l1 := New(&captureHandler{}).With("a", 1) + l2 := New(l1.Handler()).With("b", 2) + l2.Info("m", "c", 3) + h := l2.Handler().(*captureHandler) + check(h.attrs, Int("a", 1), Int("b", 2)) + check(h.r.Attrs(), Int("c", 3)) +} + +func TestCallDepth(t *testing.T) { + h := &captureHandler{} + var startLine int + + check := func(count int) { + t.Helper() + const wantFile = "logger_test.go" + wantLine := startLine + count*2 + gotFile, gotLine := h.r.SourceLine() + gotFile = filepath.Base(gotFile) + if gotFile != wantFile || gotLine != wantLine { + t.Errorf("got (%s, %d), want (%s, %d)", gotFile, gotLine, wantFile, wantLine) + } + } + + logger := New(h) + SetDefault(logger) + + // Calls to check must be one line apart. + // Determine line where calls start. + f, _ := runtime.CallersFrames([]uintptr{pc(2)}).Next() + startLine = f.Line + 4 + // Do not change the number of lines between here and the call to check(0). + + logger.Log(InfoLevel, "") + check(0) + logger.LogAttrs(InfoLevel, "") + check(1) + logger.Debug("") + check(2) + logger.Info("") + check(3) + logger.Warn("") + check(4) + logger.Error("", nil) + check(5) + Debug("") + check(6) + Info("") + check(7) + Warn("") + check(8) + Error("", nil) + check(9) + Log(InfoLevel, "") + check(10) + LogAttrs(InfoLevel, "") + check(11) +} + +func TestAlloc(t *testing.T) { + dl := New(discardHandler{}) + defer func(d *Logger) { SetDefault(d) }(Default()) + SetDefault(dl) + + t.Run("Info", func(t *testing.T) { + wantAllocs(t, 0, func() { Info("hello") }) + }) + // t.Run("Error", func(t *testing.T) { + // wantAllocs(t, 0, func() { Error("hello", io.EOF) }) + // }) + t.Run("logger.Info", func(t *testing.T) { + wantAllocs(t, 0, func() { dl.Info("hello") }) + }) + t.Run("logger.Log", func(t *testing.T) { + wantAllocs(t, 0, func() { dl.Log(DebugLevel, "hello") }) + }) + t.Run("2 pairs", func(t *testing.T) { + s := "abc" + i := 2000 + wantAllocs(t, 2, func() { + dl.Info("hello", + "n", i, + "s", s, + ) + }) + }) + t.Run("2 pairs disabled inline", func(t *testing.T) { + l := New(discardHandler{disabled: true}) + s := "abc" + i := 2000 + wantAllocs(t, 2, func() { + l.Log(InfoLevel, "hello", + "n", i, + "s", s, + ) + }) + }) + t.Run("2 pairs disabled", func(t *testing.T) { + l := New(discardHandler{disabled: true}) + s := "abc" + i := 2000 + wantAllocs(t, 0, func() { + if l.Enabled(InfoLevel) { + l.Log(InfoLevel, "hello", + "n", i, + "s", s, + ) + } + }) + }) + t.Run("9 kvs", func(t *testing.T) { + s := "abc" + i := 2000 + d := time.Second + wantAllocs(t, 10, func() { + dl.Info("hello", + "n", i, "s", s, "d", d, + "n", i, "s", s, "d", d, + "n", i, "s", s, "d", d) + }) + }) + t.Run("pairs", func(t *testing.T) { + wantAllocs(t, 0, func() { dl.Info("", "error", io.EOF) }) + }) + t.Run("attrs1", func(t *testing.T) { + wantAllocs(t, 0, func() { dl.LogAttrs(InfoLevel, "", Int("a", 1)) }) + wantAllocs(t, 0, func() { dl.LogAttrs(InfoLevel, "", Any("error", io.EOF)) }) + }) + t.Run("attrs3", func(t *testing.T) { + wantAllocs(t, 0, func() { + dl.LogAttrs(InfoLevel, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second)) + }) + }) + t.Run("attrs3 disabled", func(t *testing.T) { + logger := New(discardHandler{disabled: true}) + wantAllocs(t, 0, func() { + logger.LogAttrs(InfoLevel, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second)) + }) + }) + t.Run("attrs6", func(t *testing.T) { + wantAllocs(t, 1, func() { + dl.LogAttrs(InfoLevel, "hello", + Int("a", 1), String("b", "two"), Duration("c", time.Second), + Int("d", 1), String("e", "two"), Duration("f", time.Second)) + }) + }) + t.Run("attrs9", func(t *testing.T) { + wantAllocs(t, 1, func() { + dl.LogAttrs(InfoLevel, "hello", + Int("a", 1), String("b", "two"), Duration("c", time.Second), + Int("d", 1), String("e", "two"), Duration("f", time.Second), + Int("d", 1), String("e", "two"), Duration("f", time.Second)) + }) + }) +} + +func TestSetAttrs(t *testing.T) { + for _, test := range []struct { + args []any + want []Attr + }{ + {nil, nil}, + {[]any{"a", 1}, []Attr{Int("a", 1)}}, + {[]any{"a", 1, "b", "two"}, []Attr{Int("a", 1), String("b", "two")}}, + {[]any{"a"}, []Attr{String(badKey, "a")}}, + {[]any{"a", 1, "b"}, []Attr{Int("a", 1), String(badKey, "b")}}, + {[]any{"a", 1, 2, 3}, []Attr{Int("a", 1), Int(badKey, 2), Int(badKey, 3)}}, + } { + r := MakeRecord(time.Time{}, 0, "", 0) + setAttrs(&r, test.args) + got := r.Attrs() + if !attrsEqual(got, test.want) { + t.Errorf("%v:\ngot %v\nwant %v", test.args, got, test.want) + } + } +} + +func checkLogOutput(t *testing.T, got, wantRegexp string) { + t.Helper() + got = clean(got) + wantRegexp = "^" + wantRegexp + "$" + matched, err := regexp.MatchString(wantRegexp, got) + if err != nil { + t.Fatal(err) + } + if !matched { + t.Errorf("\ngot %s\nwant %s", got, wantRegexp) + } +} + +// clean prepares log output for comparison. +func clean(s string) string { + if len(s) > 0 && s[len(s)-1] == '\n' { + s = s[:len(s)-1] + } + return strings.ReplaceAll(s, "\n", "~") +} + +type captureHandler struct { + r Record + attrs []Attr +} + +func (h *captureHandler) Handle(r Record) error { + h.r = r + return nil +} + +func (*captureHandler) Enabled(Level) bool { return true } + +func (c *captureHandler) With(as []Attr) Handler { + c2 := *c + c2.attrs = concat(c2.attrs, as) + return &c2 +} + +type discardHandler struct { + disabled bool + attrs []Attr +} + +func (d discardHandler) Enabled(Level) bool { return !d.disabled } +func (discardHandler) Handle(Record) error { return nil } +func (d discardHandler) With(as []Attr) Handler { + d.attrs = concat(d.attrs, as) + return d +} + +// This is a simple benchmark. See the benchmarks subdirectory for more extensive ones. +func BenchmarkNopLog(b *testing.B) { + b.ReportAllocs() + disableSourceLine() + l := New(&captureHandler{}) + b.Run("attrs", func(b *testing.B) { + for i := 0; i < b.N; i++ { + l.LogAttrs(InfoLevel, "msg", Int("a", 1), String("b", "two"), Bool("c", true)) + } + }) + b.Run("attrs-parallel", func(b *testing.B) { + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + l.LogAttrs(InfoLevel, "msg", Int("a", 1), String("b", "two"), Bool("c", true)) + } + }) + }) + b.Run("keys-values", func(b *testing.B) { + for i := 0; i < b.N; i++ { + l.Log(InfoLevel, "msg", "a", 1, "b", "two", "c", true) + } + }) +} diff --git a/slog/record.go b/slog/record.go index ffeb7c978..0f78a9634 100644 --- a/slog/record.go +++ b/slog/record.go @@ -125,3 +125,10 @@ func (r *Record) AddAttr(a Attr) { r.tail[r.nTail] = a r.nTail++ } + +func (r *Record) addAttrs(attrs []Attr) { + // TODO: be cleverer. + for _, a := range attrs { + r.AddAttr(a) + } +}