From 3a855915ef974c8357d72af0f210a73980b140e1 Mon Sep 17 00:00:00 2001 From: Kees van Voorthuizen Date: Wed, 22 Feb 2023 15:29:37 +0100 Subject: [PATCH 1/6] feat: add ErrFormat & FormatErrorField --- error.go | 37 +++++++++++++++++++++++++++++++++++++ 1 file changed, 37 insertions(+) create mode 100644 error.go diff --git a/error.go b/error.go new file mode 100644 index 0000000..db5d1dc --- /dev/null +++ b/error.go @@ -0,0 +1,37 @@ +package zapdriver + +import ( + "bytes" + "fmt" + + "github.com/pkg/errors" + "go.uber.org/zap/zapcore" +) + +func ErrFormat(err error) string { + if err == nil { + return "" + } + type stackTracer interface { + StackTrace() errors.StackTrace + } + cause := errors.Cause(err) + if stackTrace, ok := cause.(stackTracer); ok { + buf := bytes.Buffer{} + for i, frame := range stackTrace.StackTrace() { + if i == 0 { + buf.WriteByte('\n') + } + + buf.WriteString(fmt.Sprintf("\n%+v", frame)) + } + return err.Error() + buf.String() + } + return err.Error() +} + +func FormatErrorField(field *zapcore.Field) { + if err, ok := field.Interface.(error); ok { + field.Interface = ErrFormat(err) + } +} From 53e38b4e2de0441834b8e73e5bb267468413787d Mon Sep 17 00:00:00 2001 From: Kees van Voorthuizen Date: Wed, 22 Feb 2023 15:30:52 +0100 Subject: [PATCH 2/6] feat: format error fields on Write --- core.go | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/core.go b/core.go index bcb7660..37e71c9 100644 --- a/core.go +++ b/core.go @@ -110,6 +110,12 @@ func (c *core) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.Check } func (c *core) Write(ent zapcore.Entry, fields []zapcore.Field) error { + for i, field := range fields { + if field.Type == zapcore.ErrorType { + FormatErrorField(&fields[i]) + } + } + var lbls *labels lbls, fields = c.extractLabels(fields) From ecfe12f34f8065fa77ae7cca6c50bc1cd44a25e3 Mon Sep 17 00:00:00 2001 From: Kees van Voorthuizen Date: Fri, 24 Feb 2023 14:26:52 +0100 Subject: [PATCH 3/6] feat(stack): correctly format stacktraces --- core.go | 29 ++++++++++++++++----- error.go | 48 +++++++++++++++++++---------------- error_test.go | 70 +++++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 119 insertions(+), 28 deletions(-) create mode 100644 error_test.go diff --git a/core.go b/core.go index 37e71c9..a707c76 100644 --- a/core.go +++ b/core.go @@ -15,6 +15,10 @@ type driverConfig struct { // ServiceName is added as `ServiceContext()` to all logs when set ServiceName string + + // Correct stack traces for errors logged with zap.Error() so that + // they get formatted correctly in stackdriver + FmtStackTraces bool } // Core is a zapdriver specific core wrapped around the default zap core. It @@ -50,6 +54,14 @@ func ReportAllErrors(report bool) func(*core) { } } +// zapdriver core option to enable outputting stack traces compatible with +// stackdriver when set to true +func FmtStackTraces(fmt bool) func(*core) { + return func(c *core) { + c.config.FmtStackTraces = fmt + } +} + // zapdriver core option to add `ServiceContext()` to all logs with `name` as // service name func ServiceName(name string) func(*core) { @@ -110,12 +122,6 @@ func (c *core) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.Check } func (c *core) Write(ent zapcore.Entry, fields []zapcore.Field) error { - for i, field := range fields { - if field.Type == zapcore.ErrorType { - FormatErrorField(&fields[i]) - } - } - var lbls *labels lbls, fields = c.extractLabels(fields) @@ -140,6 +146,17 @@ func (c *core) Write(ent zapcore.Entry, fields []zapcore.Field) error { fields = c.withServiceContext("unknown", fields) } } + if c.config.FmtStackTraces { + for i, field := range fields { + if field.Type == zapcore.ErrorType { + // remove stackdriver-incompatible zap stack trace + ent.Stack = "" + fields[i].Key = "exception" + fields[i].Interface = stackdriverFmtError{field.Interface.(error)} + break + } + } + } c.tempLabels.reset() diff --git a/error.go b/error.go index db5d1dc..550871f 100644 --- a/error.go +++ b/error.go @@ -3,35 +3,39 @@ package zapdriver import ( "bytes" "fmt" + "runtime" "github.com/pkg/errors" - "go.uber.org/zap/zapcore" ) -func ErrFormat(err error) string { - if err == nil { +type stackdriverFmtError struct{ err error } + +type stackTracer interface { + StackTrace() errors.StackTrace +} + +// see https://github.com/googleapis/google-cloud-go/issues/1084#issuecomment-474565019 +// this is a hack to get stackdriver to parse the stacktrace +func (e stackdriverFmtError) Error() string { + if e.err == nil { return "" } - type stackTracer interface { - StackTrace() errors.StackTrace - } - cause := errors.Cause(err) - if stackTrace, ok := cause.(stackTracer); ok { - buf := bytes.Buffer{} - for i, frame := range stackTrace.StackTrace() { - if i == 0 { - buf.WriteByte('\n') - } + if stackTrace, ok := errors.Cause(e.err).(stackTracer); ok { + buf := bytes.NewBufferString(e.err.Error()) + // routine id and state aren't available in pure go, so we hard-coded these + // required for stackdrivers runtime.Stack() format parsing + buf.WriteString("\n\ngoroutine 1 [running]:") + for _, frame := range stackTrace.StackTrace() { + buf.WriteByte('\n') - buf.WriteString(fmt.Sprintf("\n%+v", frame)) + pc := uintptr(frame) - 1 + fn := runtime.FuncForPC(pc) + if fn != nil { + file, line := fn.FileLine(pc) + buf.WriteString(fmt.Sprintf("%s()\n\t%s:%d +%#x", fn.Name(), file, line, fn.Entry())) + } } - return err.Error() + buf.String() - } - return err.Error() -} - -func FormatErrorField(field *zapcore.Field) { - if err, ok := field.Interface.(error); ok { - field.Interface = ErrFormat(err) + return buf.String() } + return e.err.Error() } diff --git a/error_test.go b/error_test.go new file mode 100644 index 0000000..d19cff0 --- /dev/null +++ b/error_test.go @@ -0,0 +1,70 @@ +package zapdriver + +import ( + "fmt" + "net/url" + "os" + "regexp" + "runtime" + "testing" + + "github.com/pkg/errors" + "github.com/stretchr/testify/assert" + "go.uber.org/zap" +) + +type fakeErr struct{} + +// manually set the frames to allow asserting stacktraces +func (fakeErr) StackTrace() errors.StackTrace { + var pcs = make([]uintptr, 2) + runtime.Callers(3, pcs) + + return []errors.Frame{ + errors.Frame(pcs[0]), + errors.Frame(pcs[1]), + } +} +func (fakeErr) Error() string { + return "fake error: underlying error" +} + +func TestFmtStack(t *testing.T) { + stacktrace := stackdriverFmtError{fakeErr{}}.Error() + assert.Equal(t, `fake error: underlying error + +goroutine 1 [running]: +github.com/blendle/zapdriver.TestFmtStack() + /error_test.go:42 +0x1337 +testing.tRunner() + /testing.go:42 +0x1337`, makeStackTraceStable(stacktrace)) +} + +func ExampleUseFmtStackTracing() { + zap.RegisterSink("example", func(u *url.URL) (zap.Sink, error) { + return os.Stdout, nil + }) + conf := NewDevelopmentConfig() + conf.OutputPaths = []string{"stdout"} // to generate example output + z, err := conf.Build(WrapCore( + FmtStackTraces(true), + ReportAllErrors(true), + ServiceName("my-service"), + )) + + if err != nil { + panic(err) + } + + z.Error("An error occurred", zap.Error(erroring())) + // Output: foo +} + +func erroring() error { + return errors.Wrap(fmt.Errorf("foo"), "bar") +} + +func makeStackTraceStable(str string) string { + re := regexp.MustCompile(`(?m)^\t.+(\/\S+):\d+ \+0x.+$`) + return re.ReplaceAllString(str, "\t${1}:42 +0x1337") +} From a453894830d4f4162ea783819ee4526cd3e552c5 Mon Sep 17 00:00:00 2001 From: Herman Date: Fri, 24 Feb 2023 14:52:53 +0100 Subject: [PATCH 4/6] example test outputting to "Output: ..." --- error.go | 6 +++++- error_test.go | 46 +++++++++++++++++++++++++++++++++++----------- 2 files changed, 40 insertions(+), 12 deletions(-) diff --git a/error.go b/error.go index 550871f..5531f2e 100644 --- a/error.go +++ b/error.go @@ -20,7 +20,11 @@ func (e stackdriverFmtError) Error() string { if e.err == nil { return "" } - if stackTrace, ok := errors.Cause(e.err).(stackTracer); ok { + stackTrace, ok := errors.Cause(e.err).(stackTracer) + if !ok { + stackTrace, ok = e.err.(stackTracer) + } + if ok { buf := bytes.NewBufferString(e.err.Error()) // routine id and state aren't available in pure go, so we hard-coded these // required for stackdrivers runtime.Stack() format parsing diff --git a/error_test.go b/error_test.go index d19cff0..f710b38 100644 --- a/error_test.go +++ b/error_test.go @@ -1,11 +1,14 @@ package zapdriver import ( + "bytes" "fmt" + "io" "net/url" "os" "regexp" "runtime" + "strings" "testing" "github.com/pkg/errors" @@ -41,23 +44,29 @@ testing.tRunner() } func ExampleUseFmtStackTracing() { - zap.RegisterSink("example", func(u *url.URL) (zap.Sink, error) { - return os.Stdout, nil - }) + z, b := testZap() + z.Error("An error occurred", zap.Error(erroring())) + + fmt.Println(makeStackTraceStable(b.String())) + // Output: {"severity":"ERROR","caller":"zapdriver/error_test.go:48","message":"An error occurred","exception":"bar: foo","logging.googleapis.com/labels":{},"logging.googleapis.com/sourceLocation":{"file":"/error_test.go","line":"48","function":"github.com/blendle/zapdriver.ExampleUseFmtStackTracing"}} +} + +func testZap() (*zap.Logger, *bytes.Buffer) { + var b = bytes.NewBuffer(nil) conf := NewDevelopmentConfig() - conf.OutputPaths = []string{"stdout"} // to generate example output + conf.EncoderConfig.TimeKey = "" + zap.RegisterSink("example", func(u *url.URL) (zap.Sink, error) { return testSink{b}, nil }) + conf.OutputPaths = []string{"example://"} // to generate example output + z, err := conf.Build(WrapCore( FmtStackTraces(true), - ReportAllErrors(true), - ServiceName("my-service"), + ReportAllErrors(false), )) if err != nil { panic(err) } - - z.Error("An error occurred", zap.Error(erroring())) - // Output: foo + return z, b } func erroring() error { @@ -65,6 +74,21 @@ func erroring() error { } func makeStackTraceStable(str string) string { - re := regexp.MustCompile(`(?m)^\t.+(\/\S+):\d+ \+0x.+$`) - return re.ReplaceAllString(str, "\t${1}:42 +0x1337") + re := regexp.MustCompile(`(?m)^[\t\\t].+(\/\S+):\d+ \+0x.+$`) + str = re.ReplaceAllString(str, "\t${1}:42 +0x1337") + dir, _ := os.Getwd() + str = strings.ReplaceAll(str, dir, "") + return str +} + +type testSink struct { + io.Writer +} + +func (testSink) Close() error { + return nil +} + +func (testSink) Sync() error { + return nil } From d49a32141dee48179d6fd6eeaa86ec0d3898dc2b Mon Sep 17 00:00:00 2001 From: Herman Date: Fri, 24 Feb 2023 14:56:22 +0100 Subject: [PATCH 5/6] remove dead end of example file --- error_test.go | 69 ++++++++------------------------------------------- 1 file changed, 11 insertions(+), 58 deletions(-) diff --git a/error_test.go b/error_test.go index f710b38..6835597 100644 --- a/error_test.go +++ b/error_test.go @@ -1,10 +1,6 @@ package zapdriver import ( - "bytes" - "fmt" - "io" - "net/url" "os" "regexp" "runtime" @@ -13,19 +9,17 @@ import ( "github.com/pkg/errors" "github.com/stretchr/testify/assert" - "go.uber.org/zap" ) type fakeErr struct{} // manually set the frames to allow asserting stacktraces func (fakeErr) StackTrace() errors.StackTrace { - var pcs = make([]uintptr, 2) - runtime.Callers(3, pcs) - + pc1, _, _, _ := runtime.Caller(0) + pc2, _, _, _ := runtime.Caller(0) return []errors.Frame{ - errors.Frame(pcs[0]), - errors.Frame(pcs[1]), + errors.Frame(pc1), + errors.Frame(pc2), } } func (fakeErr) Error() string { @@ -37,58 +31,17 @@ func TestFmtStack(t *testing.T) { assert.Equal(t, `fake error: underlying error goroutine 1 [running]: -github.com/blendle/zapdriver.TestFmtStack() - /error_test.go:42 +0x1337 -testing.tRunner() - /testing.go:42 +0x1337`, makeStackTraceStable(stacktrace)) -} - -func ExampleUseFmtStackTracing() { - z, b := testZap() - z.Error("An error occurred", zap.Error(erroring())) - - fmt.Println(makeStackTraceStable(b.String())) - // Output: {"severity":"ERROR","caller":"zapdriver/error_test.go:48","message":"An error occurred","exception":"bar: foo","logging.googleapis.com/labels":{},"logging.googleapis.com/sourceLocation":{"file":"/error_test.go","line":"48","function":"github.com/blendle/zapdriver.ExampleUseFmtStackTracing"}} -} - -func testZap() (*zap.Logger, *bytes.Buffer) { - var b = bytes.NewBuffer(nil) - conf := NewDevelopmentConfig() - conf.EncoderConfig.TimeKey = "" - zap.RegisterSink("example", func(u *url.URL) (zap.Sink, error) { return testSink{b}, nil }) - conf.OutputPaths = []string{"example://"} // to generate example output - - z, err := conf.Build(WrapCore( - FmtStackTraces(true), - ReportAllErrors(false), - )) - - if err != nil { - panic(err) - } - return z, b -} - -func erroring() error { - return errors.Wrap(fmt.Errorf("foo"), "bar") +github.com/blendle/zapdriver.fakeErr.StackTrace() + /error_test.go:18 +0x1337 +github.com/blendle/zapdriver.fakeErr.StackTrace() + /error_test.go:19 +0x1337`, makeStackTraceStable(stacktrace)) } +// cleanup local paths & local function pointers func makeStackTraceStable(str string) string { - re := regexp.MustCompile(`(?m)^[\t\\t].+(\/\S+):\d+ \+0x.+$`) - str = re.ReplaceAllString(str, "\t${1}:42 +0x1337") + re := regexp.MustCompile(`(?m)^\t.+(\/\S+:\d+) \+0x.+$`) + str = re.ReplaceAllString(str, "\t${1} +0x1337") dir, _ := os.Getwd() str = strings.ReplaceAll(str, dir, "") return str } - -type testSink struct { - io.Writer -} - -func (testSink) Close() error { - return nil -} - -func (testSink) Sync() error { - return nil -} From db613697c7e61f6ab5249360ae193689925aeb5c Mon Sep 17 00:00:00 2001 From: Herman Date: Fri, 24 Feb 2023 16:51:46 +0100 Subject: [PATCH 6/6] feat: automatically perform improved formatting by default when error is reported --- core.go | 40 ++++++++++++++++++++++++++++------------ error_test.go | 14 ++++++++++++++ 2 files changed, 42 insertions(+), 12 deletions(-) diff --git a/core.go b/core.go index a707c76..9411d53 100644 --- a/core.go +++ b/core.go @@ -18,7 +18,7 @@ type driverConfig struct { // Correct stack traces for errors logged with zap.Error() so that // they get formatted correctly in stackdriver - FmtStackTraces bool + SkipFmtStackTraces bool } // Core is a zapdriver specific core wrapped around the default zap core. It @@ -56,9 +56,9 @@ func ReportAllErrors(report bool) func(*core) { // zapdriver core option to enable outputting stack traces compatible with // stackdriver when set to true -func FmtStackTraces(fmt bool) func(*core) { +func SkipFmtStackTraces(skipFmt bool) func(*core) { return func(c *core) { - c.config.FmtStackTraces = fmt + c.config.SkipFmtStackTraces = skipFmt } } @@ -146,15 +146,15 @@ func (c *core) Write(ent zapcore.Entry, fields []zapcore.Field) error { fields = c.withServiceContext("unknown", fields) } } - if c.config.FmtStackTraces { - for i, field := range fields { - if field.Type == zapcore.ErrorType { - // remove stackdriver-incompatible zap stack trace - ent.Stack = "" - fields[i].Key = "exception" - fields[i].Interface = stackdriverFmtError{field.Interface.(error)} - break - } + + if !c.config.SkipFmtStackTraces { + // only improve the stacktrace if the error is reported to stackdriver + reported, errorField := reportedError(fields) + if reported && errorField != nil { + // remove stackdriver-incompatible zap stack trace + ent.Stack = "" + errorField.Key = "exception" + errorField.Interface = stackdriverFmtError{errorField.Interface.(error)} } } @@ -163,6 +163,22 @@ func (c *core) Write(ent zapcore.Entry, fields []zapcore.Field) error { return c.Core.Write(ent, fields) } +func reportedError(fields []zapcore.Field) (reported bool, field *zapcore.Field) { + var errorField int = -1 + for i, field := range fields { + if field.Key == contextKey { + reported = true + } + if field.Type == zapcore.ErrorType { + errorField = i + } + } + if errorField >= 0 { + return reported, &fields[errorField] + } + return reported, nil +} + // Sync flushes buffered logs (if any). func (c *core) Sync() error { return c.Core.Sync() diff --git a/error_test.go b/error_test.go index 6835597..d95f7e2 100644 --- a/error_test.go +++ b/error_test.go @@ -9,6 +9,7 @@ import ( "github.com/pkg/errors" "github.com/stretchr/testify/assert" + "go.uber.org/zap" ) type fakeErr struct{} @@ -45,3 +46,16 @@ func makeStackTraceStable(str string) string { str = strings.ReplaceAll(str, dir, "") return str } + +func ExampleSkipFmtStackTraces() { + logger, _ := NewProduction() + logger.Error("with exception", zap.Error(errors.New("internal error")), ErrorReport(runtime.Caller(0))) + + logger, _ = NewProduction(WrapCore(ServiceName("service"), ReportAllErrors(true))) + logger.Error("with exception", zap.Error(errors.New("internal error"))) + + logger, _ = NewProduction(WrapCore(ServiceName("service"), SkipFmtStackTraces(true))) + logger.Error("without exception", zap.Error(errors.New("internal error"))) + + // Output: +}