From b90012881de282809444123f305689edc93a00ec Mon Sep 17 00:00:00 2001 From: Vincent Le Goff Date: Fri, 1 Sep 2023 22:01:58 +0200 Subject: [PATCH] feat(zapslog): implement stack trace handling (#1339) fix: https://github.com/uber-go/zap/issues/1329 As discussed in the issue, replacing the `HandlersOptions` with functional options, i also renamed `addSource` to `addCaller` to properly match the `zap` semantic. --------- Co-authored-by: Abhinav Gupta --- exp/go.mod | 3 +- exp/go.sum | 9 ++--- exp/zapslog/example_test.go | 2 +- exp/zapslog/handler.go | 51 ++++++++++++-------------- exp/zapslog/handler_test.go | 28 ++++++++++++--- exp/zapslog/options.go | 72 +++++++++++++++++++++++++++++++++++++ 6 files changed, 123 insertions(+), 42 deletions(-) create mode 100644 exp/zapslog/options.go diff --git a/exp/go.mod b/exp/go.mod index 162b00e27..28c5a95a7 100644 --- a/exp/go.mod +++ b/exp/go.mod @@ -10,7 +10,8 @@ require ( require ( github.com/davecgh/go-spew v1.1.1 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect - go.uber.org/atomic v1.10.0 // indirect go.uber.org/multierr v1.10.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) + +replace go.uber.org/zap => ../ diff --git a/exp/go.sum b/exp/go.sum index f333d47c4..96489348a 100644 --- a/exp/go.sum +++ b/exp/go.sum @@ -1,8 +1,7 @@ -github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8= +github.com/benbjohnson/clock v1.3.0 h1:ip6w0uFQkncKQ979AypyG0ER7mqUSBdKLOgAle/AT8A= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= -github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= @@ -12,13 +11,9 @@ github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/ github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU= github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk= github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4= -go.uber.org/atomic v1.10.0 h1:9qC72Qh0+3MqyJbAn8YU5xVq1frD8bn3JtD2oXtafVQ= -go.uber.org/atomic v1.10.0/go.mod h1:LUxbIzbOniOlMKjJjyPfpl4v+PKK2cNJn91OQbhoJI0= -go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI= +go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk= go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ= go.uber.org/multierr v1.10.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y= -go.uber.org/zap v1.24.0 h1:FiJd5l1UOLj0wCgbSE0rwwXHzEdAZS6hiiSnxJN/D60= -go.uber.org/zap v1.24.0/go.mod h1:2kMP+WWQ8aoFoedH3T2sq6iJ2yDWpHbP0f6MQbS9Gkg= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/exp/zapslog/example_test.go b/exp/zapslog/example_test.go index 7a18fc84b..da3c63458 100644 --- a/exp/zapslog/example_test.go +++ b/exp/zapslog/example_test.go @@ -42,7 +42,7 @@ func Example_slog() { logger := zap.NewExample(zap.IncreaseLevel(zap.InfoLevel)) defer logger.Sync() - sl := slog.New(zapslog.NewHandler(logger.Core(), nil /* options */)) + sl := slog.New(zapslog.NewHandler(logger.Core())) ctx := context.Background() sl.Info("user", "name", "Al", "secret", Password("secret")) diff --git a/exp/zapslog/handler.go b/exp/zapslog/handler.go index e8ad81c43..6791a262c 100644 --- a/exp/zapslog/handler.go +++ b/exp/zapslog/handler.go @@ -28,41 +28,30 @@ import ( "runtime" "go.uber.org/zap" + "go.uber.org/zap/internal/stacktrace" "go.uber.org/zap/zapcore" ) // Handler implements the slog.Handler by writing to a zap Core. type Handler struct { - core zapcore.Core - name string // logger name - addSource bool -} - -// HandlerOptions are options for a Zap-based [slog.Handler]. -type HandlerOptions struct { - // LoggerName is used for log entries received from slog. - // - // Defaults to empty. - LoggerName string - - // AddSource configures the handler to annotate each message with the filename, - // line number, and function name. - // AddSource is false by default to skip the cost of computing - // this information. - AddSource bool + core zapcore.Core + name string // logger name + addCaller bool + addStackAt slog.Level + callerSkip int } // NewHandler builds a [Handler] that writes to the supplied [zapcore.Core] -// with the default options. -func NewHandler(core zapcore.Core, opts *HandlerOptions) *Handler { - if opts == nil { - opts = &HandlerOptions{} +// with options. +func NewHandler(core zapcore.Core, opts ...Option) *Handler { + h := &Handler{ + core: core, + addStackAt: slog.LevelError, } - return &Handler{ - core: core, - name: opts.LoggerName, - addSource: opts.AddSource, + for _, v := range opts { + v.apply(h) } + return h } var _ slog.Handler = (*Handler)(nil) @@ -136,15 +125,13 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error { Time: record.Time, Message: record.Message, LoggerName: h.name, - // TODO: do we need to set the following fields? - // Stack: } ce := h.core.Check(ent, nil) if ce == nil { return nil } - if h.addSource && record.PC != 0 { + if h.addCaller && record.PC != 0 { frame, _ := runtime.CallersFrames([]uintptr{record.PC}).Next() if frame.PC != 0 { ce.Caller = zapcore.EntryCaller{ @@ -157,6 +144,14 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error { } } + if record.Level >= h.addStackAt { + // Skipping 3: + // zapslog/handler log/slog.(*Logger).log + // slog/logger log/slog.(*Logger).log + // slog/logger log/slog.(*Logger). + ce.Stack = stacktrace.Take(3 + h.callerSkip) + } + fields := make([]zapcore.Field, 0, record.NumAttrs()) record.Attrs(func(attr slog.Attr) bool { if attr.Equal(slog.Attr{}) { diff --git a/exp/zapslog/handler_test.go b/exp/zapslog/handler_test.go index 2bee658fb..a0f97e73b 100644 --- a/exp/zapslog/handler_test.go +++ b/exp/zapslog/handler_test.go @@ -32,13 +32,11 @@ import ( "go.uber.org/zap/zaptest/observer" ) -func TestAddSource(t *testing.T) { +func TestAddCaller(t *testing.T) { t.Parallel() fac, logs := observer.New(zapcore.DebugLevel) - sl := slog.New(NewHandler(fac, &HandlerOptions{ - AddSource: true, - })) + sl := slog.New(NewHandler(fac, WithCaller(true))) sl.Info("msg") require.Len(t, logs.AllUntimed(), 1, "Expected exactly one entry to be logged") @@ -51,11 +49,31 @@ func TestAddSource(t *testing.T) { ) } +func TestAddStack(t *testing.T) { + fac, logs := observer.New(zapcore.DebugLevel) + sl := slog.New(NewHandler(fac, AddStacktraceAt(slog.LevelDebug))) + sl.Info("msg") + + require.Len(t, logs.AllUntimed(), 1, "Expected exactly one entry to be logged") + entry := logs.AllUntimed()[0] + require.Equal(t, "msg", entry.Message, "Unexpected message") + assert.Regexp(t, + `^go.uber.org/zap/exp/zapslog.TestAddStack`, + entry.Stack, + "Unexpected stack trace annotation.", + ) + assert.Regexp(t, + `/zapslog/handler_test.go:\d+`, + entry.Stack, + "Unexpected stack trace annotation.", + ) +} + func TestEmptyAttr(t *testing.T) { t.Parallel() fac, observedLogs := observer.New(zapcore.DebugLevel) - sl := slog.New(NewHandler(fac, nil)) + sl := slog.New(NewHandler(fac)) t.Run("Handle", func(t *testing.T) { sl.Info( diff --git a/exp/zapslog/options.go b/exp/zapslog/options.go new file mode 100644 index 000000000..0eb5c8c0e --- /dev/null +++ b/exp/zapslog/options.go @@ -0,0 +1,72 @@ +// Copyright (c) 2023 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +//go:build go1.21 + +package zapslog + +import "log/slog" + +// An Option configures a slog Handler. +type Option interface { + apply(*Handler) +} + +// optionFunc wraps a func so it satisfies the Option interface. +type optionFunc func(*Handler) + +func (f optionFunc) apply(handler *Handler) { + f(handler) +} + +// WithName configures the Logger to annotate each message with the logger name. +func WithName(name string) Option { + return optionFunc(func(h *Handler) { + h.name = name + }) +} + +// WithCaller configures the Logger to include the filename and line number +// of the caller in log messages--if available. +func WithCaller(enabled bool) Option { + return optionFunc(func(handler *Handler) { + handler.addCaller = enabled + }) +} + +// WithCallerSkip increases the number of callers skipped by caller annotation +// (as enabled by the [WithCaller] option). +// +// When building wrappers around the Logger, +// supplying this Option prevents Zap from always reporting +// the wrapper code as the caller. +func WithCallerSkip(skip int) Option { + return optionFunc(func(log *Handler) { + log.callerSkip += skip + }) +} + +// AddStacktraceAt configures the Logger to record a stack trace +// for all messages at or above a given level. +func AddStacktraceAt(lvl slog.Level) Option { + return optionFunc(func(log *Handler) { + log.addStackAt = lvl + }) +}