import (
"bytes"
"context"
+ "internal/race"
+ "internal/testenv"
"io"
"log"
+ loginternal "log/internal"
"path/filepath"
"regexp"
"runtime"
"time"
)
-const timeRE = `\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}(Z|[+-]\d{2}:\d{2})`
+// textTimeRE is a regexp to match log timestamps for Text handler.
+// This is RFC3339Nano with the fixed 3 digit sub-second precision.
+const textTimeRE = `\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}(Z|[+-]\d{2}:\d{2})`
+
+// jsonTimeRE is a regexp to match log timestamps for Text handler.
+// This is RFC3339Nano with an arbitrary sub-second precision.
+const jsonTimeRE = `\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d+)?(Z|[+-]\d{2}:\d{2})`
func TestLogTextHandler(t *testing.T) {
+ ctx := context.Background()
var buf bytes.Buffer
- l := New(NewTextHandler(&buf))
+ l := New(NewTextHandler(&buf, nil))
check := func(want string) {
t.Helper()
if want != "" {
- want = "time=" + timeRE + " " + want
+ want = "time=" + textTimeRE + " " + want
}
checkLogOutput(t, buf.String(), want)
buf.Reset()
l.Error("bad", "a", 1)
check(`level=ERROR msg=bad a=1`)
- l.Log(nil, LevelWarn+1, "w", Int("a", 1), String("b", "two"))
+ l.Log(ctx, LevelWarn+1, "w", Int("a", 1), String("b", "two"))
check(`level=WARN\+1 msg=w a=1 b=two`)
- l.LogAttrs(nil, LevelInfo+1, "a b c", Int("a", 1), String("b", "two"))
+ l.LogAttrs(ctx, LevelInfo+1, "a b c", Int("a", 1), String("b", "two"))
check(`level=INFO\+1 msg="a b c" a=1 b=two`)
l.Info("info", "a", []Attr{Int("i", 1)})
// tests might change the default logger using SetDefault. Also ensure we
// restore the default logger at the end of the test.
currentLogger := Default()
- SetDefault(New(newDefaultHandler(log.Output)))
+ currentLogWriter := log.Writer()
+ currentLogFlags := log.Flags()
+ SetDefault(New(newDefaultHandler(loginternal.DefaultOutput)))
t.Cleanup(func() {
SetDefault(currentLogger)
+ log.SetOutput(currentLogWriter)
+ log.SetFlags(currentLogFlags)
})
// The default slog.Logger's handler uses the log package's default output.
Info("msg", "a", 1)
checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg a=1`)
logbuf.Reset()
+ Info("msg", "p", nil)
+ checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg p=<nil>`)
+ logbuf.Reset()
+ var r *regexp.Regexp
+ Info("msg", "r", r)
+ checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg r=<nil>`)
+ logbuf.Reset()
Warn("msg", "b", 2)
checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: WARN msg b=2`)
logbuf.Reset()
t.Run("wrap default handler", func(t *testing.T) {
// It should be possible to wrap the default handler and get the right output.
- // But because the call depth to log.Output is hard-coded, the source line is wrong.
- // We want to use the pc inside the Record, but there is no way to give that to
- // the log package.
- //
- // TODO(jba): when slog lives under log in the standard library, we can
- // move the bulk of log.Logger.Output to a function in an internal
- // package, so both log and slog can call it.
- //
- // While slog lives in exp, we punt.
- t.Skip("skip until this package is in the standard library")
+ // This works because the default handler uses the pc in the Record
+ // to get the source line, rather than a call depth.
logger := New(wrappingHandler{Default().Handler()})
logger.Info("msg", "d", 4)
checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg d=4`)
// Once slog.SetDefault is called, the direction is reversed: the default
// log.Logger's output goes through the handler.
- SetDefault(New(HandlerOptions{AddSource: true}.NewTextHandler(&slogbuf)))
+ SetDefault(New(NewTextHandler(&slogbuf, &HandlerOptions{AddSource: true})))
log.Print("msg2")
- checkLogOutput(t, slogbuf.String(), "time="+timeRE+` level=INFO source=.*logger_test.go:\d{3} msg=msg2`)
+ checkLogOutput(t, slogbuf.String(), "time="+textTimeRE+` level=INFO source=.*logger_test.go:\d{3}"? msg=msg2`)
// The default log.Logger always outputs at Info level.
slogbuf.Reset()
- SetDefault(New(HandlerOptions{Level: LevelWarn}.NewTextHandler(&slogbuf)))
+ SetDefault(New(NewTextHandler(&slogbuf, &HandlerOptions{Level: LevelWarn})))
log.Print("should not appear")
if got := slogbuf.String(); got != "" {
t.Errorf("got %q, want empty", got)
check(attrsSlice(h.r), Int("c", 3))
}
-func sourceLine(r Record) (string, int) {
- f := r.frame()
- return f.File, f.Line
-}
-
func TestCallDepth(t *testing.T) {
+ ctx := context.Background()
h := &captureHandler{}
var startLine int
check := func(count int) {
t.Helper()
+ const wantFunc = "log/slog.TestCallDepth"
const wantFile = "logger_test.go"
wantLine := startLine + count*2
- gotFile, gotLine := sourceLine(h.r)
- gotFile = filepath.Base(gotFile)
- if gotFile != wantFile || gotLine != wantLine {
- t.Errorf("got (%s, %d), want (%s, %d)", gotFile, gotLine, wantFile, wantLine)
+ got := h.r.source()
+ gotFile := filepath.Base(got.File)
+ if got.Function != wantFunc || gotFile != wantFile || got.Line != wantLine {
+ t.Errorf("got (%s, %s, %d), want (%s, %s, %d)",
+ got.Function, gotFile, got.Line, wantFunc, wantFile, wantLine)
}
}
+ defer SetDefault(Default()) // restore
logger := New(h)
SetDefault(logger)
startLine = f.Line + 4
// Do not change the number of lines between here and the call to check(0).
- logger.Log(nil, LevelInfo, "")
+ logger.Log(ctx, LevelInfo, "")
check(0)
- logger.LogAttrs(nil, LevelInfo, "")
+ logger.LogAttrs(ctx, LevelInfo, "")
check(1)
logger.Debug("")
check(2)
check(8)
Error("")
check(9)
- Log(nil, LevelInfo, "")
+ Log(ctx, LevelInfo, "")
check(10)
- LogAttrs(nil, LevelInfo, "")
+ LogAttrs(ctx, LevelInfo, "")
check(11)
}
func TestAlloc(t *testing.T) {
+ ctx := context.Background()
dl := New(discardHandler{})
- defer func(d *Logger) { SetDefault(d) }(Default())
+ defer SetDefault(Default()) // restore
SetDefault(dl)
t.Run("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(nil, LevelDebug, "hello") })
+ wantAllocs(t, 0, func() { dl.Log(ctx, LevelDebug, "hello") })
})
t.Run("2 pairs", func(t *testing.T) {
s := "abc"
s := "abc"
i := 2000
wantAllocs(t, 2, func() {
- l.Log(nil, LevelInfo, "hello",
+ l.Log(ctx, LevelInfo, "hello",
"n", i,
"s", s,
)
s := "abc"
i := 2000
wantAllocs(t, 0, func() {
- if l.Enabled(nil, LevelInfo) {
- l.Log(nil, LevelInfo, "hello",
+ if l.Enabled(ctx, LevelInfo) {
+ l.Log(ctx, LevelInfo, "hello",
"n", i,
"s", s,
)
s := "abc"
i := 2000
d := time.Second
- wantAllocs(t, 11, func() {
+ wantAllocs(t, 10, func() {
dl.Info("hello",
"n", i, "s", s, "d", d,
"n", i, "s", s, "d", d,
wantAllocs(t, 0, func() { dl.Info("", "error", io.EOF) })
})
t.Run("attrs1", func(t *testing.T) {
- wantAllocs(t, 0, func() { dl.LogAttrs(nil, LevelInfo, "", Int("a", 1)) })
- wantAllocs(t, 0, func() { dl.LogAttrs(nil, LevelInfo, "", Any("error", io.EOF)) })
+ wantAllocs(t, 0, func() { dl.LogAttrs(ctx, LevelInfo, "", Int("a", 1)) })
+ wantAllocs(t, 0, func() { dl.LogAttrs(ctx, LevelInfo, "", Any("error", io.EOF)) })
})
t.Run("attrs3", func(t *testing.T) {
wantAllocs(t, 0, func() {
- dl.LogAttrs(nil, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second))
+ dl.LogAttrs(ctx, LevelInfo, "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(nil, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second))
+ logger.LogAttrs(ctx, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second))
})
})
t.Run("attrs6", func(t *testing.T) {
wantAllocs(t, 1, func() {
- dl.LogAttrs(nil, LevelInfo, "hello",
+ dl.LogAttrs(ctx, LevelInfo, "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(nil, LevelInfo, "hello",
+ dl.LogAttrs(ctx, LevelInfo, "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))
}
}
+// Test defaultHandler minimum level without calling slog.SetDefault.
+func TestLogLoggerLevelForDefaultHandler(t *testing.T) {
+ // Revert any changes to the default logger, flags, and level of log and slog.
+ currentLogLoggerLevel := logLoggerLevel.Level()
+ currentLogWriter := log.Writer()
+ currentLogFlags := log.Flags()
+ t.Cleanup(func() {
+ logLoggerLevel.Set(currentLogLoggerLevel)
+ log.SetOutput(currentLogWriter)
+ log.SetFlags(currentLogFlags)
+ })
+
+ var logBuf bytes.Buffer
+ log.SetOutput(&logBuf)
+ log.SetFlags(0)
+
+ for _, test := range []struct {
+ logLevel Level
+ logFn func(string, ...any)
+ want string
+ }{
+ {LevelDebug, Debug, "DEBUG a"},
+ {LevelDebug, Info, "INFO a"},
+ {LevelInfo, Debug, ""},
+ {LevelInfo, Info, "INFO a"},
+ } {
+ SetLogLoggerLevel(test.logLevel)
+ test.logFn("a")
+ checkLogOutput(t, logBuf.String(), test.want)
+ logBuf.Reset()
+ }
+}
+
+// Test handlerWriter minimum level by calling slog.SetDefault.
+func TestLogLoggerLevelForHandlerWriter(t *testing.T) {
+ removeTime := func(_ []string, a Attr) Attr {
+ if a.Key == TimeKey {
+ return Attr{}
+ }
+ return a
+ }
+
+ // Revert any changes to the default logger. This is important because other
+ // tests might change the default logger using SetDefault. Also ensure we
+ // restore the default logger at the end of the test.
+ currentLogger := Default()
+ currentLogLoggerLevel := logLoggerLevel.Level()
+ currentLogWriter := log.Writer()
+ currentFlags := log.Flags()
+ t.Cleanup(func() {
+ SetDefault(currentLogger)
+ logLoggerLevel.Set(currentLogLoggerLevel)
+ log.SetOutput(currentLogWriter)
+ log.SetFlags(currentFlags)
+ })
+
+ var logBuf bytes.Buffer
+ log.SetOutput(&logBuf)
+ log.SetFlags(0)
+ SetLogLoggerLevel(LevelError)
+ SetDefault(New(NewTextHandler(&logBuf, &HandlerOptions{ReplaceAttr: removeTime})))
+ log.Print("error")
+ checkLogOutput(t, logBuf.String(), `level=ERROR msg=error`)
+}
+
func TestLoggerError(t *testing.T) {
var buf bytes.Buffer
}
return a
}
- l := New(HandlerOptions{ReplaceAttr: removeTime}.NewTextHandler(&buf))
+ l := New(NewTextHandler(&buf, &HandlerOptions{ReplaceAttr: removeTime}))
l.Error("msg", "err", io.EOF, "a", 1)
checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF a=1`)
buf.Reset()
- l.Error("msg", "err", io.EOF, "a")
+ // use local var 'args' to defeat vet check
+ args := []any{"err", io.EOF, "a"}
+ l.Error("msg", args...)
checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF !BADKEY=a`)
}
func TestNewLogLogger(t *testing.T) {
var buf bytes.Buffer
- h := NewTextHandler(&buf)
+ h := NewTextHandler(&buf, nil)
ll := NewLogLogger(h, LevelWarn)
ll.Print("hello")
- checkLogOutput(t, buf.String(), "time="+timeRE+` level=WARN msg=hello`)
+ checkLogOutput(t, buf.String(), "time="+textTimeRE+` level=WARN msg=hello`)
+}
+
+func TestLoggerNoOps(t *testing.T) {
+ l := Default()
+ if l.With() != l {
+ t.Error("wanted receiver, didn't get it")
+ }
+ if With() != l {
+ t.Error("wanted receiver, didn't get it")
+ }
+ if l.WithGroup("") != l {
+ t.Error("wanted receiver, didn't get it")
+ }
+}
+
+func TestContext(t *testing.T) {
+ // Verify that the context argument to log output methods is passed to the handler.
+ // Also check the level.
+ h := &captureHandler{}
+ l := New(h)
+ defer SetDefault(Default()) // restore
+ SetDefault(l)
+
+ for _, test := range []struct {
+ f func(context.Context, string, ...any)
+ wantLevel Level
+ }{
+ {l.DebugContext, LevelDebug},
+ {l.InfoContext, LevelInfo},
+ {l.WarnContext, LevelWarn},
+ {l.ErrorContext, LevelError},
+ {DebugContext, LevelDebug},
+ {InfoContext, LevelInfo},
+ {WarnContext, LevelWarn},
+ {ErrorContext, LevelError},
+ } {
+ h.clear()
+ ctx := context.WithValue(context.Background(), "L", test.wantLevel)
+
+ test.f(ctx, "msg")
+ if gv := h.ctx.Value("L"); gv != test.wantLevel || h.r.Level != test.wantLevel {
+ t.Errorf("got context value %v, level %s; want %s for both", gv, h.r.Level, test.wantLevel)
+ }
+ }
}
func checkLogOutput(t *testing.T, got, wantRegexp string) {
type captureHandler struct {
mu sync.Mutex
+ ctx context.Context
r Record
attrs []Attr
groups []string
func (h *captureHandler) Handle(ctx context.Context, r Record) error {
h.mu.Lock()
defer h.mu.Unlock()
+ h.ctx = ctx
h.r = r
return nil
}
return &c2
}
+func (c *captureHandler) clear() {
+ c.mu.Lock()
+ defer c.mu.Unlock()
+ c.ctx = nil
+ c.r = Record{}
+}
+
type discardHandler struct {
disabled bool
attrs []Attr
b.Run("no attrs", func(b *testing.B) {
b.ReportAllocs()
for i := 0; i < b.N; i++ {
- l.LogAttrs(nil, LevelInfo, "msg")
+ l.LogAttrs(ctx, LevelInfo, "msg")
}
})
b.Run("attrs", func(b *testing.B) {
b.ReportAllocs()
for i := 0; i < b.N; i++ {
- l.LogAttrs(nil, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
+ l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
}
})
b.Run("attrs-parallel", func(b *testing.B) {
b.ReportAllocs()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
- l.LogAttrs(nil, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
+ l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
}
})
})
b.Run("keys-values", func(b *testing.B) {
b.ReportAllocs()
for i := 0; i < b.N; i++ {
- l.Log(nil, LevelInfo, "msg", "a", 1, "b", "two", "c", true)
+ l.Log(ctx, LevelInfo, "msg", "a", 1, "b", "two", "c", true)
}
})
b.Run("WithContext", func(b *testing.B) {
runtime.Callers(depth, pcs[:])
return pcs[0]
}
+
+func wantAllocs(t *testing.T, want int, f func()) {
+ if race.Enabled {
+ t.Skip("skipping test in race mode")
+ }
+ testenv.SkipIfOptimizationOff(t)
+ t.Helper()
+ got := int(testing.AllocsPerRun(5, f))
+ if got != want {
+ t.Errorf("got %d allocs, want %d", got, want)
+ }
+}
+
+// panicTextAndJsonMarshaler is a type that panics in MarshalText and MarshalJSON.
+type panicTextAndJsonMarshaler struct {
+ msg any
+}
+
+func (p panicTextAndJsonMarshaler) MarshalText() ([]byte, error) {
+ panic(p.msg)
+}
+
+func (p panicTextAndJsonMarshaler) MarshalJSON() ([]byte, error) {
+ panic(p.msg)
+}
+
+func TestPanics(t *testing.T) {
+ // Revert any changes to the default logger. This is important because other
+ // tests might change the default logger using SetDefault. Also ensure we
+ // restore the default logger at the end of the test.
+ currentLogger := Default()
+ currentLogWriter := log.Writer()
+ currentLogFlags := log.Flags()
+ t.Cleanup(func() {
+ SetDefault(currentLogger)
+ log.SetOutput(currentLogWriter)
+ log.SetFlags(currentLogFlags)
+ })
+
+ var logBuf bytes.Buffer
+ log.SetOutput(&logBuf)
+ log.SetFlags(log.Lshortfile &^ log.LstdFlags)
+
+ SetDefault(New(newDefaultHandler(loginternal.DefaultOutput)))
+ for _, pt := range []struct {
+ in any
+ out string
+ }{
+ {(*panicTextAndJsonMarshaler)(nil), `logger_test.go:\d+: INFO msg p=<nil>`},
+ {panicTextAndJsonMarshaler{io.ErrUnexpectedEOF}, `logger_test.go:\d+: INFO msg p="!PANIC: unexpected EOF"`},
+ {panicTextAndJsonMarshaler{"panicking"}, `logger_test.go:\d+: INFO msg p="!PANIC: panicking"`},
+ {panicTextAndJsonMarshaler{42}, `logger_test.go:\d+: INFO msg p="!PANIC: 42"`},
+ } {
+ Info("msg", "p", pt.in)
+ checkLogOutput(t, logBuf.String(), pt.out)
+ logBuf.Reset()
+ }
+
+ SetDefault(New(NewJSONHandler(&logBuf, nil)))
+ for _, pt := range []struct {
+ in any
+ out string
+ }{
+ {(*panicTextAndJsonMarshaler)(nil), `{"time":"` + jsonTimeRE + `","level":"INFO","msg":"msg","p":null}`},
+ {panicTextAndJsonMarshaler{io.ErrUnexpectedEOF}, `{"time":"` + jsonTimeRE + `","level":"INFO","msg":"msg","p":"!PANIC: unexpected EOF"}`},
+ {panicTextAndJsonMarshaler{"panicking"}, `{"time":"` + jsonTimeRE + `","level":"INFO","msg":"msg","p":"!PANIC: panicking"}`},
+ {panicTextAndJsonMarshaler{42}, `{"time":"` + jsonTimeRE + `","level":"INFO","msg":"msg","p":"!PANIC: 42"}`},
+ } {
+ Info("msg", "p", pt.in)
+ checkLogOutput(t, logBuf.String(), pt.out)
+ logBuf.Reset()
+ }
+}